Reduce test execution overhead

[GoogleCodeExporter]

Robot Framework is already now pretty fast and the extra overhead it adds is 
most often meaningless. If test cases are constructed from thousands or tens of 
thousands low level keywords this overhead adds up, though. One example where 
such tests are pretty common is protocol testing using Rammbock 
<https://github.com/robotframework/Rammbock>.

After some performance measurements we identified two separate places what can 
be optimized without making bigger changes to the framework:

1) Writing XML output. Currently we use Python's SAX modules for writing XML 
and they seem to be pretty slow. Replacing them with our own XML writer seems 
to fasten execution considerably.

When running on Jython we actually use Java's SAX modules that may have better 
performance characteristics than the Python version. We thus need to measure 
performance of the new implementation also against them.

2) Constructing timestamps. Interestingly creating lot of timestamps in format 
"20120605 11:09:42.123" takes quite a bit of time. When there are lot of small 
keywords, hundreds or even thousands are executed during one second. It seems 
we can speed up timestamp creation, and thus the overall execution, by caching 
the previous timestamp without milliseconds, and only adding new milliseconds 
to it if new stamp is needed during the same second.

Original issue reported on code.google.com by pekka.klarck on 5 Jun 2012 at 8:13

[GoogleCodeExporter]

This issue was updated by revision 6329924f6c8b.

Timestamp optimization done. Robottime.py still needs refactoring.

Original comment by to...@asiala.info on 5 Jun 2012 at 10:37

• Changed state: Started

[GoogleCodeExporter]

Original comment by pekka.klarck on 5 Jun 2012 at 7:25

[GoogleCodeExporter]

This issue was updated by revision 1f90a900b4f2.

I will make a separate commit where the old SAX-based writers
are removed.

Other things needed:
1) review for these changes
2) should the new MarkupWriter base class get it's own module?
3) test the effect of this change with Jython
4) check if the illegal xml chars replacing could be done outside of
XmlWriter (now also safe text is run through a regexp replace)

Original comment by janne.t....@gmail.com on 6 Jun 2012 at 5:29

[GoogleCodeExporter]

XML changes look very good! See my review comments in revision 1f90a900b4f2.

Original comment by pekka.klarck on 6 Jun 2012 at 7:20

[GoogleCodeExporter]

I did very simple measurement now that the planned performance enhancements are 
in. I had a test suite that contained only this this case:

*** Test Cases ***
Performace
    :FOR    ${i}    IN RANGE    10000
    \    No Operation

Execution time with RF 2.7.1 was 16.7s and with the current code 12s (both are 
averages of two runs). That is about 30% improvement!

Original comment by pekka.klarck on 6 Jun 2012 at 8:33

[GoogleCodeExporter]

Same measurements with Jython using only 1000 rounds in loop:

RF 2.7.1: 9.8s
Current: 8.9s

In other words also 10% improvement with Jython. Awesome!

My guess why the improvement is smaller than with Python is that Java SAX 
modules aren't as slow as Python SAX modules, and that the timestamp 
improvement doesn't help as much when the overall overhead is bigger and less 
keywords start/end on the same second.

Original comment by pekka.klarck on 6 Jun 2012 at 8:47

[GoogleCodeExporter]

This issue was updated by revision 48a3ee8a9c58.

I made changes suggested in the code review comments here:
http://code.google.com/p/robotframework/source/detail?r=1f90a900b4f233a3b0066c5a
eb994b03c8153888
except for one. The default encoding is still `None`. Changing this
requires some careful work, and I did not feel like doing it right now.

I might even consider leaving it as it is.

Original comment by janne.t....@gmail.com on 6 Jun 2012 at 12:52

[GoogleCodeExporter]

This issue was updated by revision 359261befb6c.

Changed XMLWriter clients to give all attributes as strings to improve 
performance.

Original comment by to...@asiala.info on 6 Jun 2012 at 1:24

[GoogleCodeExporter]

This issue was updated by revision 07e222b3f85e.

Still found one more easy place to performance enhancements. When escaping 
HTML/XML content, it is faster to do

    if name in text:
        text = text.replace(name, value)

than just

    text = text.replace(name, value)

This dropped overhead by another 5-10%.

Original comment by to...@asiala.info on 6 Jun 2012 at 2:12

[GoogleCodeExporter]

This issue was updated by revision c555519d53c9.

Same performance improvement for normalize() as in revision 07e222b3f85e

Original comment by to...@asiala.info on 6 Jun 2012 at 2:39

[GoogleCodeExporter]

After the latest enhancements my simple performance test (see comment 5) now 
gives these numbers:

Python: 9.2s (10000 rounds)
Jython: 8.3s (1000 rounds)

Pretty cool! With Python we are getting closer to 50% enhancement!!

Original comment by pekka.klarck on 6 Jun 2012 at 5:23

[GoogleCodeExporter]

Both of the enhancements mentioned in this issue are now implemented and 
measurements show that they were worthwhile. I consider this now Done.

Original comment by janne.t....@gmail.com on 7 Jun 2012 at 7:13

• Changed state: Done

[GoogleCodeExporter]

This issue was updated by revision 8039594f740b.

Found a trivial enhancement in calculating elapsed times. This dropped the 
execution time of my earlier for loop test to 7.3 seconds. With that data point 
we now have over 50% speed-up.

As a nice bonus, this latest enhancement also ought to fasten processing 
outputs with rebot. Haven't measured how much it affects, though.

Original comment by pekka.klarck on 8 Jun 2012 at 5:59

[GoogleCodeExporter]

We got first field results from a team that uses Rammbock and has a lot of 
small keywords in their test data.

Good news: The improvement compared to RF 2.6 was ~25% which is pretty damn 
good.

Bad news: New XML writing implementation doesn't remove illegal characters from 
attributes. This caused issue 1154 which will require urgent 2.7.3 release.

Original comment by pekka.klarck on 13 Jun 2012 at 10:53

[GoogleCodeExporter]

Issue 1153 is another regression caused by XML writer changes.

Original comment by robotframework@gmail.com on 14 Jun 2012 at 2:41