Skipped Turns ... what to know about?
The highlighted comment was created in this revision.
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...
Hmm this is the stripped output of the skipped turn:
Finally i got a skipped turn (288) and it works like we thought it must work. The whole turn got no events and even the loop got no turn, so no print out. On the other hand i think i found your bug. If you look at the table below you can see that the robot is advanced in his skipped turn and the next turn has the 15.98 distance difference. this should be 8 or less because of the skipped turn.
To me it looks right now there are three bugs
- skipped robots advance just like in a normal turn but they get no events
- skipped robots get events and advance just normal (so it is just a message with no consequences)
- robots get no skipped events at all even if they are way out of time
[285] 121000 0 [285][285] 49000 [270.78095:748.65046] - [1.41372] // ([x:y] - [heading]) [286] 130000 0 [286][286] 54000 [262.87944:747.39899] - [1.41372] SYSTEM: TassieDevil* (1) skipped turn 287 [287] 16716000 16 [287][287] 16582000 [254.97794:746.14751] - [1.41372] [289] 131000 0 [289][289] 55000 [239.28147:743.09643] - [1.34390]
| turn | 286 | 287 | 288 | 289 |
| energy | 160.07883925169597 | 160.07883925169597 | 160.07883925169597 | 157.07883925169597 |
| x | 262.8794433297025 | 254.9779366049414 | 247.07642988018029 | 239.28146936189842 |
| y | 747.3989879466453 | 746.1475122263234 | 744.8960365060016 | 743.0964280712507 |
| bodyHeading | 1.4137166941154065 | 1.4137166941154067 | 1.4137166941154067 | 1.3439035240356334 |
| gunHeading | 1.1884119094971828 | 1.161216370645719 | 1.161216370645719 | 1.135682848864048 |
| radarHeading | 1.7448331266273467 | 0.9322394243784347 | 0.5360878333247008 | 1.295952474940478 |
| gunHeat | .09999999999999981 | 0.0 | 0.0 | 1.5 |
| veocity | -8.0 | -8.0 | -8.0 | -8.0 |
| getX() | 262.87944 | 254.97794 | skipped | 239.28147 |
| getY() | 747.39899 | 746.14751 | skipped | 743.09643 |
| getHeadingRadians() | 1.41372 | [1.41372 | skipped | 1.34390 |
| delta dist | ... | 8.0 | should be skipped | 15.98 |
Sorry i just edited my former post .. to save space.
Yep onStatus(..) is always the first event and holds every state of your robot.
The bug I hit was using the distance between locations from two ticks that had a getTime() difference of 1, so it shouldn't be an issue about moving during skipped turns. Anwyay, bots definitely should still move during skipped turns (or that could really break some physics), they just shouldn't be able to change their heading/velocity/distance remaining.
Thanks for doing all this debugging!
Ah good point. So the table shows almost how it should work. No bodyHeading and gunHeading change but still a radarHeading change. I will make some deeper tests, maybe i find something that brings some light on this.
Cool! So you think the original bug you hit was just "skipped turn message but didn't really skip turn"?
Also, if you called setTurnRight or setGunTurnRight and the command hasn't finished turning, I think those headings would still change on a skipped turn, as they would if you issued no new setXXX commands.
I think i got your bug figured out. Right now i'm to overtired to give you the numbers but i will do this tomorrow.
Basically what it does is the system skips some turns without a skip turn event, it just misses the turns out (happens very frequently). So it looks like this:
- 1 normal turn
- 2 lost turn without any data and no skip event
- 3 normal turn, you try to calculate the enemys x y but you get the wrong bearing from the system, your own values are ok
- 4 normal turn with delta time = 1, you calculate the enemys x y with the right values but if you calculate the distance to the last (wrong) x,y you get some distance that is way out of line
You can check this very easy if you just put the follow in onStatus(...)
if ((getTime() - lastTime) > 1)
{
System.out.format("blabla...\n");
}
lastTime = getTime();blabla should print out without a skipped turn event or console message.
Buahh 3:00am ... i have to sleep :) take care
Well this is what i got so far:
- robots get skipped turn events but actually never skip the turn (happens only by one turn skips)
- robots skip turns but get no skipped turn events
- after a skipped turn(s) the robot gets the wrong enemy bearing/distance and can not calculate the right x,y position of the enemy
- it also happens that the robot gets 2 scan events in a 1vs1 match with time differences out of order
- minor - the skipped turn message shows the turn number of the last turn and not the actual skipped turn number
- faster client speed causes more skipped turn
To make it replicable i wrote a little BugBot_1.0 which can be downloaded and checked by yourself. The source is included along with some examples for the output of the above issue points. Just put two BugBots against each other and play with the client speed. You can also record the match (1 round is enough) and see what the XML files says about the issues (this is not really necessary the console output shows it quite good).
The bot generate all kind of the above points and can be used to find the robocode bug behind this. If you don't get some of the above output just increase the speed of the client and it should be happen. You can also increase the amount of skipped turns by raising the run variables.
Well i hope this helps a little and hopefully the code is sound.
take care
Wow, awesome! We should definitely file a bug report to Robocode for some of these - I'm sure BugBot will be really helpful in finding these bugs and testing the fixes. I'll check him out this evening too. Cheers!
Thank you for the nice debugging Wompi! I was not aware of these issues. I especially like all the steps and details needed for seeing these issues. It's like a scientific approach. :-) This one will take me some time to fully understand, and I need to examine all the details and the BugBot_1.0 in detail. I also need to be sure that the BugBot is not really containing bugs. ;-) After that I will need to find the root of each issue and fix these. I don't expect this to be an easy task, so bear over with me if it takes some time to do. I will have my first priority to fix. :-)
Ah i missed your response. Yep take your time. I guess it is only fair to do some debug work because you probably have other things do do as well :).
Btw. thanks for taking care of the Robocode engine.
Take Care
This issue took a looong time to fix properly, i.e. without braking other stuff in Robocode and still fix all the observed issues. Sorry for that.
I have made an 1.8.1 Alpha 2 version of Robocode you can try out here: http://robocode.sourceforge.net/files/robocode-1.8.1.0-Alpha-2-setup.jar
Please check this version out and see if all issues regarding skipped turns have been solved properly. :-)
--Fnl 22:59, 22 February 2013 (UTC)
Sure thing, I will give it a try right away and give you a response as fast as I get some results. Thank you Fnl.
Hmm... I'm not sure we can do much with that unless you also print out getX(), getY(), and/or getHeadingRadians() from your while loop and/or onScannedRobot, so we can see what matches up and what doesn't. I'll also try reproduce this later when I have some time.
