Bug produced by trunk + Randomhits

[UK_Eliter]

Hi guys

I just docked three times with a Seedy Bar. The first two times, I got a message saying that my (quad-core, ssd-d, ram-disked, tweaked-out, decent-ish graphics card!) computer was too slow to display missions. Those two times I had the (new to trunk) weapons safety-switch enabled. Then I turned the weapons back on, and docked, and everything was back to normal. Hence the inference of my title.

By the way: I don't know if I said before, but I'm liking the 1.75 version. It's good - and (/but) seems to make the baddies fly better.

[DaddyHoggy]

I think this is a mod Eric W made to Random Hits so that it tries to time how long it will take to generate X number of randomised Hits to minimise noticeable delay for player when docking, so either something in the Trunk has changed the way the timer runs and/or something combined with Weapons-Safe is interfering with the calculation. (so a JS timing issue?)

[Eric Walch]

Hi guys

I just docked three times with a Seedy Bar. The first two times, I got a message saying that my (quad-core, ssd-d, ram-disked, tweaked-out, decent-ish graphics card!) computer was too slow to display missions.

Yes I have the same message here

This message is quite intentional. And I think you'll see that message only with self compiled trunk, not even with the nighties. Starting with 1.75, Oolite will interrupt JS code that is busy for to long. Main reason is to terminate code that is in a loop. With trunk, compiled in debug mode this time is set short. But for final release (and I think also for the nighties) this time is 1 second. A time that should be long enough for all existing oxps. Oolite only counts the JS time and excludes internal code, like addShips commands, from timing.

This cut-off was a bit frustrating with random hits because it left variables in a undefined state resulting in strange effects during the next docking of a spacebar. Therefor I added a detection of this interruption to the code, so I could reset the undefined variables when it happened. This was mainly for my own convenience in trunk environment, as building the mission pages will never exceed the full second.
It should not happen in the final 1.75 release.

Let me know when you use anything else than self compiled code. Because in that case I must re-look my code for a bug in that message generation.

[DaddyHoggy]

My lord! That means I was almost, basically correct! (Somebody write that down... )

[JensAyton]

This cut-off was a bit frustrating with random hits because it left variables in a undefined state resulting in strange effects during the next docking of a spacebar.

The best fix for this would be to generate the data in a functional style, calling a function that returns an object with all the necessary properties set. Since assignment is atomic, this would either fail completely or succeed. Of course, all code that uses the data then needs to be updated.

For EMMSTRAN, I’ll be looking into adding something similar to Web Workers, so big calculations/data preparation can be done off the main thread – but that will have the limitation that you won’t be able to interact with the game environment except in very restricted ways. (I expect it will be practical to provide read-only access to SystemInfos, but no other Oolite-defined objects except Vector3Ds and Quaternions.)

Nightlies do indeed use a one-second timeout.

[m4r35n357]

Well I've been hit (sic) quite badly by this feature over the past few weeks, regular segfaults on docking, failure to obtain missions etc. This is with version 1.75.

After talking to Eric, he suggested I put in some debug to see if it was a time limit issue, but of course after adding the debug everything was OK again. I think he agreed it was due to my computer being slow, believe it or not So, I've been running with this debug enabled for a couple of weeks and all is fine, until I install a new version of Oolite or random hits (without the println).

So, I have just tried version 1.75.1, and immediately noticed it was really slow compared to 1.75 (evidenced by the gobs of JS debug in the logs), and of course now I can't get missions in random hits any more as my computer is too slow!

Well, I think my computer is just fine thanks (just received my tenth ROC and a couple of stars), but if it really is as slow as Oolite says, perhaps I should claim an honorary ELITE?

Seriously though, I've lost a lot of time and many kills trying to understand this problem, if Oolite really cares about the quality of my hardware (!), could we please have at least have a reasonable or even configurable timer setting?

Thanks for your attention guys, really great game despite my whingeing!

Ian (back on version 1.75 and modded RH).

[Fatleaf]

The way I got round this was to increase the time from 500 to 3500. https://bb.oolite.space/viewtopic.ph ... &start=600
After reading this I gave it a go and from time to time I get a very slight delay after entering a space bar but I always get offered missions.

[Eric Walch]

The way I got round this was to increase the time from 500 to 3500. https://bb.oolite.space/viewtopic.ph ... &start=600
After reading this I gave it a go and from time to time I get a very slight delay after entering a space bar but I always get offered missions.

But that is another time limit. By increasing it, it becomes even possible that you exceed the time Oolite allows and than worsen the problem. I still find it strange that the time limiter it triggered. When I run the profiler on the function in random hits that is responsible for creating those pages, I get:

:time worldScripts["Random_Hits"].setupHitpages()

Code: Select all

Total time: 362.351 ms
JavaScript: 58.2511 ms, native: 304.092 ms
Counted towards limit: 283.815 ms, excluded: 78.5363 ms
Profiler overhead: 25.4452 ms
                                                        NAME  T  COUNT    TOTAL     SELF  TOTAL%   SELF%  SELFMAX
                    -[Universe generateSystemData:useCache:]  N   5106   120.50   120.50    33.3    33.3     0.47
                                       SystemInfoGetProperty  N   9675   213.13    70.80    58.8    19.5     0.03
                      (oolite-randomHits.js:938) <anonymous>  J   2304   277.51    52.68    76.6    14.5     0.12
                             SystemInfoStaticFilteredSystems  N      9   327.95    49.85    90.5    13.8     6.76
                                OOJSNativeObjectFromJSObject  N   9675    17.63    17.63     4.9     4.9     0.01
                                     SystemInfoRouteToSystem  N      9    16.47    15.98     4.5     4.4     2.12
                                  SystemInfoDistanceToSystem  N   4536    15.12    12.98     4.2     3.6     0.01
                                        OOStringFromJSString  N   5317     6.88     6.88     1.9     1.9     0.01
                      (oolite-randomHits.js:965) <anonymous>  J      1   362.23     4.29   100.0     1.2     4.29
                                     GlobalExpandDescription  N    237     6.33     3.95     1.7     1.1     0.06
                                   JSSystemInfoGetSystemInfo  N   9090     2.14     2.14     0.6     0.6     0.00
                                          JSArrayFromNSArray  N     18     0.65     0.64     0.2     0.2     0.08
                      (oolite-randomHits.js:935) <anonymous>  J      9   346.60     0.61    95.7     0.2     0.13
                     (oolite-randomHits.js:1067) <anonymous>  J      9     0.55     0.38     0.2     0.1     0.08
                                    JSObjectFromNSDictionary  N      9     0.47     0.37     0.1     0.1     0.04
                               OOStringFromJSValueEvenIfNull  N    257     0.79     0.35     0.2     0.1     0.00
    -[NSString(OOJavaScriptExtensions) oo_jsValueInContext:]  N    255     0.34     0.34     0.1     0.1     0.01
                                              SunGetProperty  N    387     0.47     0.30     0.1     0.1     0.01
                                    GetJSSystemInfoForSystem  N     36     0.29     0.29     0.1     0.1     0.05
                                           SystemGetProperty  N    414     0.43     0.28     0.1     0.1     0.01
                                           JSSunGetSunEntity  N    387     0.17     0.17     0.0     0.0     0.00
                                 MissionVariablesSetProperty  N     19     0.21     0.13     0.1     0.0     0.01
                      (oolite-randomHits.js:797) <anonymous>  J      9     0.24     0.13     0.1     0.0     0.03
                                         OOStringFromJSValue  N    257     0.92     0.13     0.3     0.0     0.00
                      (oolite-randomHits.js:793) <anonymous>  J      9     0.11     0.11     0.0     0.0     0.03
                                             VectorConstruct  N      9     0.08     0.06     0.0     0.0     0.01
                                     WorldScriptsGetProperty  N      1     0.06     0.06     0.0     0.0     0.06
                          (<console input>) codeToBeProfiled  J      1   362.34     0.05   100.0     0.0     0.05
                                        OoliteCompareVersion  N      1     0.05     0.04     0.0     0.0     0.04
                                 SystemStaticSystemNameForID  N      9     1.12     0.03     0.3     0.0     0.00
                                          JSVectorWithVector  N     18     0.03     0.03     0.0     0.0     0.00
                                           VectorGetProperty  N     36     0.03     0.02     0.0     0.0     0.00
                                           JSNewNSArrayValue  N     18     0.68     0.02     0.2     0.0     0.01
                                   SystemStaticInfoForSystem  N      9     0.16     0.02     0.0     0.0     0.00
    -[NSNumber(OOJavaScriptConversion) oo_jsValueInContext:]  N     57     0.02     0.02     0.0     0.0     0.00
                       VectorFromArgumentListNoErrorInternal  N      9     0.02     0.02     0.0     0.0     0.00
                                             VectorToJSValue  N     18     0.04     0.02     0.0     0.0     0.00
                                      JSNewNSDictionaryValue  N      9     0.48     0.01     0.1     0.0     0.00
                                           JSObjectGetVector  N     45     0.01     0.01     0.0     0.0     0.00
                                           GlobalGetProperty  N     10     0.01     0.01     0.0     0.0     0.00
                                            ClockGetProperty  N      1     0.00     0.00     0.0     0.0     0.00
                                 OOJSNativeObjectFromJSValue  N      1     0.01     0.00     0.0     0.0     0.00

The total time is 362.351 msec, but Oolite only cuts off the code when the JS part exceeds the 1000 msec. And the JS part only takes 58.2511 msec on my computer. So you need a computer that is 17 times slower than mine to hit the limit. Even worse, I my case there were 9 pages generated. On slower computers RH will only generate 3 pages. That means that computer should run 50 times slower than mine to hit the limit. I think that would be un-playable slow. So I am not quite sure what happened. It would interest me what the log writes when that message pops up.

Interesting though, above timing profile. The lines starting with "(oolite-randomHits.js: xxx)" are functions in the RH script. Where xxx is the line number in the script, by which you can find the function. A lot of functions are called 9 times (once for each page). The first one runs 2304 times. That is 9 times comparing with all 256 systems.

[m4r35n357]

The total time is 362.351 msec, but Oolite only cuts off the code when the JS part exceeds the 1000 msec. And the JS part only takes 58.2511 msec on my computer. So you need a computer that is 17 times slower than mine to hit the limit. Even worse, I my case there were 9 pages generated. On slower computers RH will only generate 3 pages. That means that computer should run 50 times slower than mine to hit the limit. I think that would be un-playable slow. So I am not quite sure what happened. It would interest me what the log writes when that message pops up.

Well I'm sure your logic is impeccable, but please be reassured that I am actually able to play the game on my inferior hardware

Seriously though, if you want me to do any more timing experiments just let me know. In the meantime, what should I be doing to ease this problem? At the moment, I have your logging output enabled, and set line 967 to:

var maximumTime = 3000; // time in msec. Oolite 1.75 will be faster with JS

I gather from your last post that this is the wrong approach, but I can at least play the game now . . .

Ian.

[JensAyton]

Random question: are the people seeing time problems using PowerPC Macs?

[another_commander]

At the moment, I have your logging output enabled, and set line 967 to:[snip]

Enabling the logging line does just that: logging. It does not affect the way the game runs nor does it help with the time cutoffs in the script and the engine.

[Eric Walch]

At the moment, I have your logging output enabled, and set line 967 to:

Code: Select all

var maximumTime = 3000; // time in msec. Oolite 1.75 will be faster with JS

I gather from your last post that this is the wrong approach, but I can at least play the game now . . .

3000 is to high, this time should never be set to high. 3000 might be to much and I would suggest 500 as highest. This time was only added to see how fast the first 3 missions were generated. When creation goes fast, a second set of 3 pages is created. I added this code to avoid noticeable pauses during docking on older computers. This was before the JS cut-off code was added to Oolite. I originally had set it at 500 msec. But since the new JS was added to Oolite, my computer could do more JS calculations in 250 msec than the old JS in 500 so I lowered the value to 250. This was done to lower the risk of meeting the limiter added for 1.75.

I am not sure what is triggering the message with you, but I would like to see if there is an explicit Oolite message in your log of the code been cut off and the time it logs for it when you get the 'slow computer' massage. (Both the log lines from random hits as well those by Oolite itself)

[m4r35n357]

I am not sure what is triggering the message with you, but I would like to see if there is an explicit Oolite message in your log of the code been cut off and the time it logs for it when you get the 'slow computer' massage. (Both the log lines from random hits as well those by Oolite itself)

OK, I've gone back to maximumTime = 500 and the logging is still enabled, I'll try a hit later tonight and PM you if I get anything. Thanks,

Ian.

[Eric Walch]

I looked a bit at the above profile log in the mean time. Looking at it, it shows that the most time consuming part is the selection of a random system in a certain range around the seedy bar. It has to check distances between the current system and all other 255 systems. But with 9 pages, it calls that function 9 times. I wondered what would happen if I call it once with the widest needed range, and than use that selection to look for a suitable random system for each page. Profiling that code gave:

Code: Select all

Total time: 121.758 ms
JavaScript: 26.8607 ms, native: 94.8902 ms
Counted towards limit: 87.5992 ms, excluded: 34.1592 ms
Profiler overhead: 9.7893 ms
                                                        NAME  T  COUNT    TOTAL     SELF  TOTAL%   SELF%  SELFMAX
                    -[Universe generateSystemData:useCache:]  N   1882    26.00    26.00    21.3    21.3     0.17
                                       SystemInfoGetProperty  N   3549    57.74    25.30    47.4    20.8     0.07
                                     SystemInfoRouteToSystem  N      9    16.70    16.27    13.7    13.4     2.05
                      (oolite-randomHits.js:949) <anonymous>  J    603    38.30    11.82    31.5     9.7     0.05
                                OOJSNativeObjectFromJSObject  N   3549     6.38     6.38     5.2     5.2     0.01
                             SystemInfoStaticFilteredSystems  N      1    45.66     6.36    37.5     5.2     6.36
                      (oolite-randomHits.js:938) <anonymous>  J    256    39.20     6.31    32.2     5.2     0.08
                                  SystemInfoDistanceToSystem  N   1701     5.68     4.88     4.7     4.0     0.01
                      (oolite-randomHits.js:976) <anonymous>  J      1   121.63     4.30    99.9     3.5     4.30
                                     GlobalExpandDescription  N    249     6.44     4.02     5.3     3.3     0.06
                      (oolite-randomHits.js:946) <anonymous>  J      9    60.13     3.66    49.4     3.0     0.49
                                        OOStringFromJSString  N   2093     2.72     2.72     2.2     2.2     0.00
                                   JSSystemInfoGetSystemInfo  N   3420     0.81     0.81     0.7     0.7     0.00
                     (oolite-randomHits.js:1079) <anonymous>  J      9     0.55     0.38     0.4     0.3     0.07
                               OOStringFromJSValueEvenIfNull  N    269     0.82     0.36     0.7     0.3     0.00
    -[NSString(OOJavaScriptExtensions) oo_jsValueInContext:]  N    267     0.34     0.34     0.3     0.3     0.00
   ..........

The needed total time is now only a third of the former time while the JS time is reduced by a factor 2. Interesting. I always assumed that generating all those randomised text for the screens would be the bottleneck.

[Eric Walch]

OK, I've gone back to maximumTime = 500 and the logging is still enabled, I'll try a hit later tonight and PM you if I get anything. Thanks,

Ian.

Thanks for the log in my PM. Is shows:

Code: Select all

[log.header]: Opening log for Oolite version 1.75 (x86-32 test release) under Linux at 2011-03-18 20:25:49 +0000.
2 processors detected.
Build options: spoken messages, mass/fuel pricing, JavaScript console support, OXP verifier, localization tools, debug GraphViz support, JavaScript profiling.

[display.mode.list.native]: X11 native resolution detected: 1440 x 900
[joystick.init]: Number of joysticks detected: 1
[dataCache.rebuild.pathsChanged]: Cache is stale (search paths have changed). Rebuilding from scratch.
--------
[rendering.opengl.version]: OpenGL renderer version: 1.4.0 ("1.4 Mesa 7.7.1"). Vendor: "Tungsten Graphics, Inc". Renderer: "Mesa DRI Intel(R) 945G GEM 20091221 2009Q4 x86/MMX/SSE2".
-------
[Random_Hits]: Created page 1 after 388 msec.
[Random_Hits]: Created page 2 after 896 msec.
[script.javaScript.timeLimit]: ***** ERROR: Script "Random_Hits" ran for 1.13591 seconds and has been terminated.

That means that two pages were created with an average time of 400 msec per page. Than on the last page it hits the time_limiter of one second that is inside Oolite. The third line is generated by Oolite itself.

Somehow this sounds as an Oolite bug to me, because the time logged after each page is the real time, retrieved from the system clock. (Based on the JS function Date.now()). But profiling shows that the JS time is less than a quarter from the total time. (at least on my computer) That should allow 4 seconds of overall time before the limiter hits.

That means, that
A) it is an Oolite bug and Oolite is using the total time instead of the JS part for the limiter, or
B) your computer has a considerable problem with JS and the JS time is the majority on your computer.

A seems unlikely because on spawning ships, the real time is also quite long and the limiter does not trigger on spawning code. That leaves B. Maybe one of the devs with linux knowledge has an idea what is happening here?.

Good that this problem surfaced. In Random hits I added detection of this problem, but other oxps with similar long code might just stop with only the log message.