Skipped Turns ... what to know about?

Hi mates. I'm quite new to the 'skipped turn' behavior and would appreciate a little heads up.

I just put this on my robot:

public void onStatus(..)
{
    start = System.nanoTime();
}

public run()
{
     .....
     while(true)
     {
           .....
           System.out.format("[%d] %d \n",getTime(),System.nanoTime() - start);
           excecute();
     }
}

This is what i get and i'm not sure how to interpret it:

[203] 7260000 
[204] 4098000 
SYSTEM: TassieDevil* (1) skipped turn 205
SYSTEM: TassieDevil* (1) skipped turn 206
[205] 7443000 
SYSTEM: TassieDevil* (1) skipped turn 207
[206] 8137000 
SYSTEM: TassieDevil* (1) skipped turn 208
[207] 8656000 
[208] 7771000 
[209] 4019000 
SYSTEM: TassieDevil* (1) skipped turn 210
SYSTEM: TassieDevil* (1) skipped turn 211
[210] 7488000 

To me it looks like that the turn counter is not incremented on skipped turns and the next turn after the skipped gets the time++. Normally this would have no influence on my bot, but i send some stats to another team bot who needs to know when the stats are gathered. I don't believe that it works like this and i'm very sure i missing out some here. My thought was that if i skip a turn it shouldn't reach the printout line. Is there a way to get the time i can spend until i get a skipped turn?

thanks in advance and take care

I think I understand what's going on here. When you go over your time limit for a turn, you skip the next one or more turns. But this probably means that none of the events are fired or anything else when you call execute(), and the while loop still runs.

If you think about what code is actually executing from your bot, there's the main while loop, and whenever you call execute, Robocode processes the setXXX stuff you've called and fires all your events. There's no way really for Robocode to make your main while loop skip ahead a couple of iterations. But presumably, no events are being fired for that tick, and any "actions" you take in the while loop are not happening when you call execute().

Hmm, actually, you're right, I'm still confused. Maybe if you also print the time from onScannedRobot we could see more clearly what's going on? Eg, maybe after turn 209, it decides you skip 2 turns and prints about them, but the while loop still happens for those turns, but execute() does nothing for the next 2 calls to it.

Actually... I was pretty sure this lag in "getTime()" wasn't the case in the past. I suspect this may be a Robocode bug that explains the unusual observations you were reporting elsewhere Voidious...

So is this what we think should happen here?

• You call execute() on turn t. You've taken <math>turnTime * 3.5</math> during your events processing and run loop for time t, so you need to skip 3 turns.
• Your turn t processes normally, execute() hangs while Robocode processes 3 more turns, events are fired to your bot for turn t+4, and control returns to the run loop with time t+4.

Alternatively, and this would explain the above output:

• Instead of execute() hanging while Robocode processes 3 more turns, your calls to execute() just do nothing for 3 turns, but your main loop still runs.

That would be unfortunate, since you might do significant processing in run() with no effect, and several iterations of run() might count against your next turn's time allotment, causing you to skip more turns.

I played around a little and now i am even more confused :). I changed my whole code and now it runs all mostly under 1 ms. But still 'skipped turns' from time to time but with awkward times.

The output is:

System.out.format("[%d] %d [%d][%d] %d\n", getTime(),System.nanoTime() - start,onScanEventTime,onScanBotTime,onScanTimeDiff);

[94] 233000 [94][94] 113000
[95] 159000 [95][95] 41000
[96] 19648000 [96][96] 19506000    <---- no skip at 19 ms 
[97] 230000 [97][97] 84000
[98] 367000 [98][98] 232000

[145] 911000 [145][145] 152000
[146] 183000 [0][0] 0                                   < --- no scan
[147] 283000 [147][147] 129000
SYSTEM: TassieDevil* (1) skipped turn 148
[148] 9762000 [148][148] 9543000       < ---- skip at 9 ms
[149] 149000 [0][0] 0
[150] 141000 [0][0] 0
[151] 200000 [0][0] 0
[152] 148000 [0][0] 0
[153] 148000 [0][0] 0
[154] 257000 [154][154] 105000
[155] 199000 [155][155] 97000

As you can see the times are always the same for onScannedRobot(...) and run(). My first thought about the run() .. while loop was like yours. The loop runs to execute every turn and print out the time spend but without the setXXX(...) stuff doing. My guess about this was then i can see at least the time that brought me the skipping turn. But as you can see the spend time for the skipped turns are still under 15ms (i guess this is the most time you can spend right?) .

The other side is, i do really nothing special that could cause the system to skip turns, just a couple of minor loops and every turn it is almost the same stuff (just minor differences). Does the garbage collector need every than an now a little more time to remove dead objects? Because i make every new scan a new MessageObject for communication with the team mate.

And there you can see the skipped turn gets his scan event like every turn.

[64] 1224000 [64][64] 1074000
[65] 165000 [65][65] 46000
SYSTEM: TassieDevil* (2) skipped turn 66
[66] 207000 [66][66] 106000                          < --- reached the end of onScannedRobot(..) and set the vars
[67] 229000 [67][67] 45000

I'm still sure i missed something important but still can't see it :(

The last output of yours is the most direct evidence of a bug, imo - you "skipped a turn" but onScannedRobot was supposedly processed for that tick, the tick before, and the tick after. Either you didn't really skip that turn, or getTime() was wrong. As another data point, here's the info on a sort of similar bug I was hitting: User_talk:Voidious#weird_bug_I.27m_hitting_891.

If you enable replay recording, after the battle you can save the battle, and it outputs an XML file with all the data from that battle (like every tick, it's huge). Maybe you can also print out some info here to cross-check against the replay file?

Besides that, I think it's time to report a bug about this, and/or start digging through the code myself to figure out what's going on. =)

Btw, under the menus, you can "recalculate CPU constant" and it will tell you how much time each bot is allowed per turn on your system. Not sure how you're calculating elapsed time, but maybe it's not the same chunk of time being examined as Robocode.

Well, the turn time on my system is 5.6 ms. So most of the output is right. But the 19ms should skip 3 turns and the last output shouldn't skip the turn. I will give the XML record a try maybe i can find something there. As for the elapsed time, its just like the above code shows - start time at onStatus(..) and difference before the last step (excecute()).

I didn't even know onStatus existed. That runs before all other events on every tick? I could definitely clean up a couple things by using that...