screeps / driver

ISC License
26 stars 36 forks source link

Time sometimes goes backwards for a moment #54

Open nevercast opened 7 months ago

nevercast commented 7 months ago

My hypothesis is that this read is not atomic, the high bits are read, then the timer rolls over to a new high bit, the low bits have gone from max to min value when they roll over, and now the low bits are read.

Before the call to getUsed the timer may have been

0xFAFF

Now it's

0xFB00

The JavaScript code reads

0xFA00

(Numbers not to scale)

https://github.com/screeps/driver/blob/e691bd3ee843cb12ac4bedc68397b2b92709f622/lib/runtime/runtime.js#L26

I believe if cpuTime is copied to a local value first, and then destructed [0], [1]. Time will no longer go backwards and getUsed will never be negative

Cheers.

wtfrank commented 4 months ago

This rollover seems to be equivalent to 1300CPU

Following are the results of pairs of calls to getCpuTme() on MMO today (14th May 2024) that occurred not long after each other.

1st call 2nd call delta
-1200.0631857999251 100.26343420002377 1300.326619999949
-1226.9246276998892 73.41425370005891 1300.3388813999481
-1242.352072100155 57.95801579998806 1300.3100879001431
70.28952509999363 -1229.4321969000011 -1299.7217219999948
58.899245199994766 -1240.8014530000073 -1299.700698200002

This is a rare event as my bot makes many calls to getCpuTime() in the course of a day, and this condition occurs less than 100 times a day. When it occurs, the difference between the result of the two calls is consistently very close to 1300 CPU.

wtfrank commented 4 months ago

Most likely fixed in later versions of isolated-vm by this patch (which uses a single bigint instead of a pair of u32s) https://github.com/laverdet/isolated-vm/commit/6fa0e771f6136d09d39d83c781f88669ffb7b3b8