robotframework / RIDE

Test data editor for Robot Framework
Apache License 2.0
954 stars 376 forks source link

Settings file can be corrupted making it impossible to start RIDE #307

Closed robotframework-ride closed 9 years ago

robotframework-ride commented 9 years ago

Originally submitted to Google Code by c.martin.taylor on 7 Oct 2009

RIDE has never been particularly quick to launch but it has gotten MUCH WORSE in the past 2 releases. I didn't time it in 0.18 but it was noticeably slower than 0.14 which was the previous version I used.

Now in version 0.19 it was so bad that I did time it. It took 5 minutes to load my (admittedly large and complex) project. During most of this time the CPU on which Python was running on my Dell D620 laptop was fully utilized (see the attached screenshot).

Some of this time may be due to failed attempts by RIDE to import my keyword libraries. Such imports won't work until Issue #256 is fixed, but I can't tell if this is the problem because RIDE doesn't display all the screen output that would normally happen when my libraries get loaded.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by c.martin.taylor on 7 Oct 2009

It also takes an excessive amount of time to exit RIDE. For the project that took 5 minutes to open in RIDE it took 1 minute to exit RIDE. This is totally unreasonable and needs to be fixed ASAP.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @pekkaklarck on 7 Oct 2009

This looks serious and we'll investigate it at some point. Unless the same issue is a huge problem for NSN who pays for RIDE development, this won't get too high priority, though. If you really need to get this, or issue 256 , fixed ASAP, please consider one of the following options:

1) Investigate the problem more thoroughly and provide more information. 2) Create a patch that fixes the problem. 3) Pay someone to investigate and create the patch.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @yanne on 7 Oct 2009

I did some "quick" testing with data that Vesa sent for issue 270 . 0.19 actually did best, whereas 0.16 and 0.18 were almost three times slower.

I suspect that this is very dependent on the structure of data and there are two major bottlenecks:

1) Parsing the data using RF modules. This time of course increases when amount of data increases. You can (roughly) estimate this time by running the tests with pybot. It is the time between issuing the pybot command and first line of console output.

2) Processing of the parsed data by RIDE. Here we try to determine library, resource and variable file imports of different suites and resources. This code could probably be made faster or executed only on demand. This code is probably also responsible for the lag related to issue 270 .

I still think that 1) takes more time than 2) since 1) is heavily disk I/O, whereas 2) happens mostly in memory.

One way to try to speed up 1) would be not parsing the whole structure at once, instead parsing the files only when they are selected from the tree. This however has (at least) one big problem: we would need to show all files from all directories in same tree hierarchy, also files that are not test data (there's no way determine whether a file is valid test data without trying to parse it)

Of course there are other ways such as trying to do things concurrently, but the effort would be quite big.

I have a hunch where the lag on closing might originate from, and I'll take a quick look at that later.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @yanne on 7 Oct 2009

As a workaround suggestion:

How often do you need to edit all the test case files at the same time? Would it be possible to open only one subdirectory at a time for editing?

All the features, such as automatic discovery of resource files and keyword completion should work just the same.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @pekkaklarck on 7 Oct 2009

Refactoring parsing modules is already planned for RF 2.2 to make more data (e.g. comments) available to RIDE. Although performance improvements aren't the main target we should look is there anything simple we could do to it. It's probably a good idea to time the performance of the old and new modules.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by c.martin.taylor on 7 Oct 2009

In the past I have used RIDE in each suite sub-folder for just that purpose of editing in a restricted scope. I just tried that now to get a time for RIDE launching in a suite sub-folder and got this:

>ride.py . Traceback (most recent call last): File "C:\Python25\Scripts\ride.py", line 22, in <module> main(sys.argv[1:]) File "C:\Python25\Lib\site-packages\robotideinit.py", line 50, in main _run(*args) File "C:\Python25\Lib\site-packages\robotideinit.py", line 60, in _run from robotide.application import RIDE File "C:\Python25\Lib\site-packages\robotide\applicationinit.py", line 15, in <module> from application import RIDE, DataModel File "C:\Python25\Lib\site-packages\robotide\application\application.py", line 19, in <module> from robotide import context File "C:\Python25\Lib\site-packages\robotide\contextinit.py", line 38, in <module> SETTINGS = RideSettings() File "C:\Python25\Lib\site-packages\robotide\contextinit.py", line 28, in init user_path = initialize_settings('ride', default_path) File "C:\Python25\Lib\site-packages\robotide\context\settings.py", line 45, in initialize_settings _merge_settings(source_path, settings_path) File "C:\Python25\Lib\site-packages\robotide\context\settings.py", line 52, in _merge_settings settings.merge(ConfigObj(user_path, unrepr=True)) File "C:\Python25\Lib\site-packages\robotide\context\configobj.py", line 1219, in init self._load(infile, configspec) File "C:\Python25\Lib\site-packages\robotide\context\configobj.py", line 1272, in _load infile = self._handle_bom(infile) File "C:\Python25\Lib\site-packages\robotide\context\configobj.py", line 1447, in _handle_bom return infile.splitlines(True) MemoryError

robotframework-ride commented 9 years ago

Originally submitted to Google Code by c.martin.taylor on 7 Oct 2009

OOPS... I get that EVERYWHERE I try to use RIDE now. Something must have messed up between this morning's try-out of RIDE and now.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by c.martin.taylor on 7 Oct 2009

I just rebuilt RIDE from the original 0.19 downloaded source, instead of from the version I checked into our AccuRev SCM system. Same behaviour. Could it be that once it is used RIDE 0.19 tries to "remember" something and that "memory" is broken?

robotframework-ride commented 9 years ago

Originally submitted to Google Code by c.martin.taylor on 7 Oct 2009

Completely deleting C:\Python25\Lib\site-packages\robotide and rebuilding RIDE 0.19 gets the same error. Completely deleting C:\Python25\Lib\site-packages\robotide and rebuilding RIDE 0.18 gets the same error.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @pekkaklarck on 7 Oct 2009

Could you also try removing old settings file [1]? At least the error seems to be somehow related to reading it. Actually, instead of removing the file just rename it so that if the problem disappears we can still try to reproduce it with old settings.

https://code.google.com/p/robotframework-ride/wiki/Settings

robotframework-ride commented 9 years ago

Originally submitted to Google Code by c.martin.taylor on 7 Oct 2009

That was it, and an artifact of the original "5 minute load" bug. Here's what I found:

Directory of C:\Documents and Settings\A0868050\Application Data\RobotFramework\ride

07-Oct-09 11:35 AM 638 settings.cfg 07-Oct-09 10:59 AM 75,498,187 _CORRUPT_settings.cfg 07-Oct-09 11:39 AM 573 _CORRUPT_Top22Lines_settings.cfg 07-Oct-09 11:26 AM 639 _RIDE_0.18_settings.cfg 07-Oct-09 11:32 AM 639 _RIDE_0.19_SubSuite_settings.cfg

>wc settings.cfg 0 88 638 settings.cfg

>wc _CORRUPT_settings.cfg 25165837 88 75498187 _CORRUPT_settings.cfg

I've attached some of these files to show the differences.

My guess is that something went wrong in the "ride.py ." command that took a long time and its "long time" was generating this 75 Mb settings file. Then, when I tried to use RIDE again, it got the memory error above trying to read this huge corrupted file.

From what I can tell the corrupted file contains the top 22 lines shown in the attached file followed by thousands of blank lines and finally

variable_fg = 'forest green'

as the very last line.

Now that this corrupted file has been deleted and replaced, by RIDE, with a reasonable settings file the time to launch RIDE 0.19 with my biggest multi-suite & sub-suite project is about 10 seconds. Perfectly acceptable!

I do hope you can find the source of the file corruption, though!

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @pekkaklarck on 7 Oct 2009

I don't have any idea what went wrong reading or writing settings but the most important thing is that the cause for long start-up time and memory errors was found. Thanks for including the examples, they'll hopefully help investigating this issue further. Since there's a simple fix this isn't too severe but would definitely be better to find and eliminate the final root cause.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @pekkaklarck on 10 Nov 2009

Issue 293 has been merged into this issue.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @pekkaklarck on 24 Nov 2009

Issue 305 has been merged into this issue.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by c.martin.taylor on 14 Apr 2010

This bug still happens in the latest 0.22.1 version of RIDE. The normal sequence of events is:

  1. Start with a pristine version of settings.cfg
  2. Use RIDE once
  3. settings.cfg now has a blank line between every line.
  4. Use RIDE a few more times
  5. settings.cfg may now have a large random number of blank lines between every line.
  6. Keep using RIDE
  7. Eventually the file gets too big and causes the "long start time" symptom of this bug.
robotframework-ride commented 9 years ago

Originally submitted to Google Code by @pekkaklarck on 14 Apr 2010

Do you only get empty lines but existing lines are fine and no other garbage is added? If so, I assume the problem is related on using wrong line endings and ought to be relatively easy to fix.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by c.martin.taylor on 14 Apr 2010

I've only seen added empty lines.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @pekkaklarck on 14 Apr 2010

Ok, let's see can we find the root cause for this in 0.22.2. Thanks for instructions on how to reproduce this Martin.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @yanne on 9 Aug 2010

Is this still a problem?

I am unable to reproduce this.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @pekkaklarck on 6 Sep 2010

I've used different RIDE versions on my Windows XP machine for several months and the settings file is still OK without empty lines or other garbage. We've also tried reproducing this on other Windows boxes without success.

Í close this issue because we cannot reproduce this and haven't got any more information about it. It can be reopened if more information appears.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by c.martin.taylor on 24 Sep 2010

This is still happening with the latest 0.28 release of RIDE. Here are the steps to reproduce this problem:

  1. Copy a clean settings.cfg file (First attachment) to the following file on your PC: C:\Documents and Settings<User>\Application Data\RobotFramework\ride\
  2. Open RIDE on a current set of test suite folders and files.
  3. Close RIDE
  4. Compare C:\Documents and Settings<User>\Application Data\RobotFramework\ride\settings.cfg to the original file copied there (my example is the 2nd attached file). Observe that extra CR/LF line breaks have been added to the file.

Repeated open/close of RIDE will result in the settings.cfg file growing to unmanagable sizes and RIDE will take longer and longer to start. It happens on all our WinXP SP3 machines at TI.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by spielman... on 25 Sep 2010

It's easy to see that the line endings have changed between the two versions of the file.

First version: mainframe size = (1000, 700)\0xD\0xA Second version: mainframe size = (1000, 700)\0xD\0xD

I've tried to reproduce this by executing the given steps. My test system is Win7 32bit with a regular Python 2.7 and RIDE 0.28, RF 2.5.3. The settings.cfg didn't get messed up when I exited RIDE. Unfortunately I don't have an XP SP3 machine around any more.

Line endings being messed up does remind me of RF issue 510 and RIDE issue 421 though. What's interesting is the fact that this bug seems to be hard to reproduce.

Martin, which combination of versions, Python implementations etc. are you using? Maybe this can be reproduced if someone other than you manages to create an identical setup.

Pekka, would you like to reopen the issue given that Martin has more information on his setup?

robotframework-ride commented 9 years ago

Originally submitted to Google Code by c.martin.taylor on 26 Sep 2010

I've found the problem and have a fix for this issue. I don't have a Unix system where I can use diff to produce patches, but here's a description of the 1 character change:

File: robotide\src\robotide\context\settings.py Line: 57 Old: f = open(user_path, 'w') New: f = open(user_path, 'wb') # Must open as binary because that's what a ConfigObj expects

I don't fully understand the logic in settings.py but from detailed "print" tracing of the code, this is the root cause of the problem. I've fixed it my my local copy of RIDE and it seems to fix the issue. My settings.cfg file is no longer corrupted.

I have no idea why this was so hard for others to reproduce, maybe they just didn't hit this path through the code. A file opened as 'w' instead of 'wb', and then written to with embedded line endings as if it was a binary file, is bound to have line ending problems. Maybe nobody else hand-crafted a settings.cfg file to use when first starting RIDE, but I had to do that to have a local solution to Issue #439 .

I hope this fix can be incorporated into the next RIDE release.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @yanne on 26 Sep 2010

This seems a really likely explanation for the bug. I still wonder why we have never experienced this on our machines. I have to think whether I can do a reliable test for this, but the fix will be incorporated in next release for sure.

Thanks Martin for your persistence in finding the cause.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @pekkaklarck on 27 Sep 2010

I briefly looked at the ConfigObj code (that's an external module our settings implementation uses) and found a possible explanation for this bug not appearing everywhere. ConfigObj detects what newlines the configuration file by looking at the first EOL character it finds. It then joins the config file lines with that newlines when it writes it to given file. It could be that the settings file originally has unix newlines and then it works, but if it is edited with an editor that replaces the newlines with Windows versions then it doesn't.

It could be that in addition to changing 'w'->'wb', we should also override the newline attribute of the parsed configobj ourselves.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @jrantanen on 18 Oct 2010

I were able to create the integration test for this and the change proposed by Martin fixed the problem.

robotframework-ride commented 9 years ago

Originally submitted to Google Code by @pekkaklarck on 4 Nov 2010

Issue 576 has been merged into this issue.