Thread history
Viewing a history listing
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.
Hi mate.
That is an awesome fix you provided there. I tested all kind of stuff related to skipped turns and it works like a charm.
Things I tested so far:
no more hidden skipped turns (very nice)
no more wrong onScannedEvents(..) (I'm most excited :) well done)
right turn number for skipped turn events (nice to have :) )
disable bots if they skip more than 30 turns - just to check if it still works (and it does :))
also gone is the 'skipped turn message but no actually skipped turn' issue (just a minor issue but thanks for fixing this too)
it also looks like the influence of other bots is gone too. If I compare 'all nano' vs 'all general' melee battles,
I got no difference in average skipped turns anymore
I have a quite large code base for skipped turns and I could detect something that looks suspicious. The output is from different battles - all full (10) melee.
This is the output if everything works fine ([x] skip xA - xB is the output within onStatus(), xA - lastStatusTime, xB - currentStatusTime):
SYSTEM: Numbat 2.1* skipped turn 6 [7] skip 5 - 7 SYSTEM: Bonus for killing cs.Grudge 1.0: 17 SYSTEM: Numbat 2.1* skipped turn 156 [157] skip 155 - 157 SYSTEM: Numbat 2.1* skipped turn 404 [405] skip 403 - 405 SYSTEM: Numbat 2.1* skipped turn 728 SYSTEM: Numbat 2.1* skipped turn 729 [730] skip 727 - 730 SYSTEM: Bonus for killing simonton.nano.MeleeSeed 1.8: 4 SYSTEM: Bonus for killing kawigi.nano.Lib 1.0: 3 SYSTEM: wompi.Numbat 2.1* wins the round.
This is the output for some other battles and it looks like the system sends an StatusEvent even if the bot is dead.
Round 8 of 35
=========================
SYSTEM: Bonus for killing radnor.DoctorBob 1.42: 7
[1004] skip 973 - 1004 <------- last status event on 973 and current status event on 1004
no skip events and I'm not having skipped 31 turns (average is 6 per battle)
see following outputs for equally behavior on onDeath
I can't say if I died on 974 and the system just delayed the message,
or if something other happens
[1004] DEAD <-------- output from onDeath()
SYSTEM: wompi.Numbat 2.1* has died
Round 9 of 35
=========================
[244] skip 241 - 244
[0244] DEAD
SYSTEM: wompi.Numbat 2.1* has died
Round 25 of 35
=========================
SYSTEM: Bonus for killing cs.Grudge 1.0: 5
SYSTEM: Bonus for killing radnor.DoctorBob 1.42: 2
[661] skip 649 - 661
[0661] DEAD
SYSTEM: wompi.Numbat 2.1* has died
There is another one, but that should be discussed by the community, I guess. If a bot skips 30 turns within the victory turns he gets the 'no action message':
SYSTEM: wompi.BugBot* (2) wins the round. SYSTEM: BugBot* (2) skipped turn 36 .... SYSTEM: BugBot* (2) skipped turn 83 <-------- way more than 30 turns SYSTEM: BugBot* (2) has not performed any actions in a reasonable amount of time. SYSTEM: No score will be generated.
So the bot gets disabled and (probably - not tested right now)) no score, even if he has won the game at this point. I don't know if this should be handled somehow or if it is a legal response to bots - would be great to get some opinions about this issue.
Anyway, great work and you can be sure all your work on the RoboCode engine is very much appreciated by all community members, I guess.
Take Care
Big thanks Fnl for sorting this out! And also to Wompi for testing it! I saw this yesterday and was wondering if I even remembered how the heck to test this, and was sad Wompi wasn't around, but I guess he is. :-)
You guys rock!
Great work! I'm curious, did this just affect the printing, getTime() and skipped turn notifications, or was Robocode actually doing the skipped turns inconsistently before?
@Skilgannon - Sorry I don't get the question. Is the question related to the two new issues or to the former issues? And who is it you asking :) me or Fnl? It is probably because I'm not a native english speaker but I can not realize what is meant, sorry for that.
@Voidious - thanks, I'm reading the wiki every day but have almost no time/clear mind over the week.
It was directed more at Fnl, but perhaps you can answer. I was wondering if the actual internals of Robocode were also behaving incorrectly, or if it only looked like it from the robot perspective.
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.
