Skipped Turns ... what to know about?

Jump to navigation Jump to search
Revision as of 11 June 2012 at 17:42.
The highlighted comment was created in this revision.

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

    Wompi11:08, 11 June 2012

    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().

      Voidious15:44, 11 June 2012
       

      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.

        Voidious15:48, 11 June 2012
         

        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...

          Rednaxela15:55, 11 June 2012
           

          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.

            Voidious17:08, 11 June 2012
             

            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 :(

              Wompi17:13, 11 June 2012
               

              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.

                Voidious17:29, 11 June 2012
                 

                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()).

                  Wompi17:45, 11 June 2012
                   

                  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...

                    Voidious18:39, 11 June 2012
                     

                    Hmm this is the stripped output of the skipped turn:

                    [261] 148000 [261][261] 70000
                    SYSTEM: TassieDevil* (1) skipped turn 262
                    [262] 9240000 [262][262] 9105000
                    [263] 143000 [263][263] 69000
                    
                    round=0 turn=261
                    energy=202.08677255822562
                    x=776.13582252718
                    y=581.8541150752402
                    bodyHeading=2.973757997491294
                    gunHeading=3.678005429962749 
                    radarHeading=3.8565206558480885
                    gunHeat=0.3999999999999998
                    velocity=-8.0
                    
                    round=0 turn=262
                    energy=202.08677255822562
                    x=774.7994399340073
                    y=589.7417054274748
                    bodyHeading=2.973757997491294
                    gunHeading=3.664416366700783
                    radarHeading=3.057533429188674
                    gunHeat=0.2999999999999998
                    velocity=-8.0 
                    
                    round=0 turn=263
                    energy=202.08677255822562
                    x=773.4630573408346
                    y=597.6292957797094
                    bodyHeading=2.973757997491294
                    gunHeading=3.6510126360667408
                    radarHeading=3.82952786195208
                    gunHeat=0.19999999999999982
                    velocity=-8.0
                    
                      Wompi18:42, 11 June 2012