Oolite Bulletins

Got the following error in the log. Not sure if the error is Explorers' Club related though. I'm running the 1.3.1 OXP Config version.

Hi Gimi,

Those are expected rare error messages. My understanding with the JS takeSnapShot function is that it 'locks' the JS engine until the screenshot has been saved to disc so if for some reason the disc write is too slow the JS engine will timeout the script. In designing the OXP I've isolated takeSnapShot in it's own worldScript so even if it does timeout it doesn't stop the rest of the OXP running and the error be safely ignored.

If you only see it very occasionally it shouldn't be a problem. If it starts showing up more frequently doing some disc maintenance on your hard-disk may help whether that's freeing up space, defragging or error checking/fixing the disk. When I was testing it on my old XP machine I was getting frequent timeouts until I ran Windows chkdsk which found and fixed a few errors and hey presto no more timeouts.

Having said all that I'm not quite sure why it's script "(nil)" that's been terminated, or where script "(nil)" comes from. It actually looks like the timeout has stopped another script entirely, but one that rather unhelpfully doesn't have a this.name defined, but that can't be right because the stacktrace is for the right script. I would normally expect it to be script "explorer_club_snapshot.js" that is terminated.

Makes sense Capt. Murphy. My hard drive does need a clean up, and the stuff I have running in the background probably doesn't help.

Capt. Murphy wrote:

My understanding with the JS takeSnapShot function is that it 'locks' the JS engine until the screenshot has been saved to disc so if for some reason the disc write is too slow the JS engine will timeout the script.

If that is the reason, than its an Oolite bug. For some long actions (like adding ships) the time is not measured and I think taking the snapshot itself should have been excluded also.

I still get the error reports, and had a CDT just now. It came just after the snapshot was saved. Log ends with: This was after 1 hour and 25 min continues play. The log is 3857 lines long, so I won't put it on here. If needed, I will put it on box.com for download. Stderr.txt is empty.

Eric Walch wrote:

Capt. Murphy wrote:

My understanding with the JS takeSnapShot function is that it 'locks' the JS engine until the screenshot has been saved to disc so if for some reason the disc write is too slow the JS engine will timeout the script.

If that is the reason, than its an Oolite bug. For some long actions (like adding ships) the time is not measured and I think taking the snapshot itself should have been excluded also.

I think Ahruman originally intended (still intends?) the function not to be available in deployment builds, so I guess that's why it wasn't optimised. It's in DEBUG flags in the source code.

Gimi, the last log entry indicates that both the scripts have done their stuff and finished running before your crash and before the Time Limiter kicks in. If you haven't changed anything in the scripts this line should indicate that the snapshot was successfully written in less than 1 second as the timer is supposed to kick in after 1 second if it hasn't. But the times in your log entries don't support that this is happening.... Edit - OK there appears to be a bug in the script as some testing indicated the timer isn't kicking in when it should....also came across another unrelated bug in the OXPconfig version which means the setting don't stick unless the nonOXPConfig version has been installed first...grrr


I'm bothered bugged by script "(nil)" which I've never seen before timing out after nearly 2 seconds. There's something weird going on here with the Time Limiter.

Are you taking snapshots on launch or arrival from witchspace?
Had the OXP released control of the ship before the crash happened? And when you say the crash was just after the snapshot was taken are we talking a fraction of a second or a few seconds?
Having you been using the OXP for a while and the timeouts have just started happening? If so are you using a Nightly build and if so which revision?
What kind of framerate are you running on? There is a frameCallback used here and this could be relevant.
Have you edited the script to change the values of this.explorerClub_snapshotDelay = 0.25; or this.explorerClub_releasePlayer = 1.25;
Can you upload the whole log - it might be useful.

Eric,

It appears that the delay whilst the snapshot is being saved prevents a one-shot Timer tied to a different worldScript from firing...is this to be expected? I thought I was being clever with this script - obviously not.....

When the main worldScript wants to take a snapshot it creates a frameCallback...
The callback function is this....(there is some extra logging compared to the version that Gimi has used).
The snapshot function itself is in the other worldScript.
The timer that's failing to fire is this.removeCallbackTimer even when the delay is only .1 second more than the delay for this.snapshotTimer, which should result in the timer ending the frameCallback before the takeSnapShot function has returned true even on my fast test machine (the snapshot takes about .3 seconds to save on my machine).

I've also tried this.snapshotTimer = new Timer(worldScripts["explorer_club_snapshot.js"],worldScripts["explorer_club_snapshot.js"].explorerClub_snapshot,this.explorerClub_snapshotDelay); as an alternative construction for the first timer as I noticed with the original construction log(this.name,"Test of this.name in explorer_club_snapshot.js"); was reporting back that this.name was "explorer_club.js", rather than "explorer_club_snapshot.js". But it doesn't make any difference to the timer failing to fire.

Some more extreme testing to get my machine to timeout (taking a dozen or so snapshots one after the other) indicates that the non-working timer isn't necessary anyway. I also get the script = "(nil)" in both 1.76 and trunk so my memory must be failing me if I didn't see this before. Still don't know why though?

I had assumed that a timeout would cause this.snapShot to fail to return true, and hence lock the player in an endless frameCallback in the other worldScript, but that doesn't seem to be the case. It seems a discrete function a single discrete command will always run it's course before the Time Limiter ends the script so isolating this.snapShot in it's own one-function worldScript is enough to prevent this happening.

Gimi, I am still interested your responses to the questions I posted above, particularly how quickly the crash occured.....but I don't think the crash is caused by Explorer_Club as such, as the log shows the script has run it's course.

If the frequent timeouts are a new thing and you've been using the OXP for a while I'd definitely recommend trying some hard-disc maintenance to see if it makes a difference. This OXP also acts as a warning system for dodgy hard-discs.....

I'll get the other little bug in the OXPconfig version fixed, and get rid of the defunct timer as-well.

Capt. Murphy wrote:

Gimi, the last log entry indicates that both the scripts have done their stuff and finished running before your crash and before the Time Limiter kicks in. If you haven't changed anything in the scripts this line should indicate that the snapshot was successfully written in less than 1 second as the timer is supposed to kick in after 1 second if it hasn't. But the times in your log entries don't support that this is happening.... Edit - OK there appears to be a bug in the script as some testing indicated the timer isn't kicking in when it should....also came across another unrelated bug in the OXPconfig version which means the setting don't stick unless the nonOXPConfig version has been installed first...grrr

The screen-shot was taken successfully. I launched from the station, the screen changed to show the planet, screen changed back for a millisecond, and then CDT.

Capt. Murphy wrote:

Are you taking snapshots on launch or arrival from witchspace?
Had the OXP released control of the ship before the crash happened? And when you say the crash was just after the snapshot was taken are we talking a fraction of a second or a few seconds?

Snapshots are taken upon launch from the station. I have not modified the OXP or changed any settings in OXP Config. I didn't have time to register whether I had regained control of the ship. The CDT was just a fraction of a second after the screen shot was taken.

Capt. Murphy wrote:

Having you been using the OXP for a while and the timeouts have just started happening? If so are you using a Nightly build and if so which revision?
What kind of framerate are you running on? There is a frameCallback used here and this could be relevant.
Have you edited the script to change the values of this.explorerClub_snapshotDelay = 0.25; or this.explorerClub_releasePlayer = 1.25;
Can you upload the whole log - it might be useful.

I have had it in there for a while, but I haven't noticed the errors until recently. Not sure if they were there before last upgrade to 1.3.1. I was using Oolite trunk 1.77 Rev 4790. My framrate is generaly good. Between 70 and 99 FPS, but can drop towards 40 when things get very busy. Never seen it below 40. No scripts have been changed.

You can find the whole log here

Hope this helps.

Thanks Gimi,

I'll see if I can reproduce a crash with trunk, although given you are not getting them everytime I'm not hopeful. Could you let me know if you get any more in the meantime.

One thing I should have mentioned is that screen resolution has a big impact on the time taken to save a snapshot and hence likelihood of javascript timeout. My Win7 machine is saving a snapshot at my fullscreen of 1366 x 768 in about .3 seconds, but it's a lot quicker from a smaller window. Your resolution has double the number of pixels so is likely to take significantly longer.

Another factor to consider is any realtime file monitoring utilities e.g antivirus that are set to monitor all disc writes? I use MSE and have excluded all directories related to Oolite from it's real time protection. Virus scanning the snapshot on save was adding about 10-20% to the save time at full screen resolutions.

Let me know if disc maintenance helps with the frequency. You can also quickly test how long a snapshot takes on your system by using the debug console. With Oolite open (probably doesn't matter if you are docked or not) type :time takeSnapShot() into console and it will report back how long the save process took. You can compare values to see if anything you do improves the performance.

Version 1.3.2 is available for download - a couple of minor bugfixes only - see first post for readme and download link.

Version 1.3.2 and 1.3.2oxpC: 5/03/12

Fixed minor bug in oxpC version that caused settings not to be saved in some circumstances.
Changed timing of record visit on witch space exit from this.shipWillExitWitchSpace to this.shipExitedWitchSpace - for compatibility with as yet unreleased long range jump OXPs.
Fixed mechanism of failsafe which prevents freeze should a JS timeout occur.

Gimi - if you are using still playing with nightly/trunk builds Eric has excluded the takeSnapShot() function from the time limiter as of revision 4794 - so you should be timeout free. I've tried hard to get Explorers' Club to crash Oolite and not been able to do so.

Capt. Murphy wrote:

Gimi - if you are using still playing with nightly/trunk builds Eric has excluded the takeSnapShot() function from the time limiter as of revision 4794 - so you should be timeout free. I've tried hard to get Explorers' Club to crash Oolite and not been able to do so.

I have been away for winter break with the family, so haven't played in a while. I'm not at all convinced that it was Explorers' Club that caused the crash, but will continue to use it with trunk so we can see if anything pops up.

Anyone know if there is a way to make Windows 7 log memory usage per process. As this crash happened after playing continuously for several hours, It would be interesting to see how much memory Oolite was using at the time of the crash.

Gimi wrote:

Anyone know if there is a way to make Windows 7 log memory usage per process. As this crash happened after playing continuously for several hours, It would be interesting to see how much memory Oolite was using at the time of the crash.

I use resmon.exe to monitor it manually when testing stuff, but to automatically log memory use I think perfmon.exe can be set up to log results for a particular process, although I've not got round to trying it yet.

See http://stackoverflow.com/questions/6933 ... er-process

Version 1.3.3 of the standalone and oxpConfig versions is available for download.

Version 1.3.3 and 1.3.3oxpC: 30/06/12

Fixed timer clean up mechanism to avoid unrooted timer errors when flicking rapidly to and from the long range chart.

I have updated to 1.3.3 running 1.76.1 and noticed from that in 1.3.2_2012-03-05 on the F7 screen it told you whether you have visited the system or not. But 1.3.3 does not! Is there any chance of this feature returning as I really liked it?