ThreadDeath problem

Jump to navigation Jump to search
Revision as of 5 September 2017 at 02:35.
The highlighted comment was created in this revision.

ThreadDeath problem

I decided to put a bit more info about the ThreadDeath problem. The offending log entry would look like

Round 4 of 10
=========================
java.lang.ThreadDeath
	at java.lang.Thread.stop(Thread.java:853)
	at net.sf.robocode.host.security.RobotThreadManager.stop(RobotThreadManager.java:190)
	at net.sf.robocode.host.security.RobotThreadManager.stopSteps(RobotThreadManager.java:172)
	at net.sf.robocode.host.security.RobotThreadManager.forceStop(RobotThreadManager.java:143)
	at net.sf.robocode.host.proxies.HostingRobotProxy.forceStopThread(HostingRobotProxy.java:144)
	at net.sf.robocode.host.proxies.BasicRobotProxy.forceStopThread(BasicRobotProxy.java:44)
	at net.sf.robocode.battle.peer.RobotPeer.checkSkippedTurn(RobotPeer.java:649)
	at net.sf.robocode.battle.peer.RobotPeer.executeImpl(RobotPeer.java:492)
	at net.sf.robocode.host.proxies.BasicRobotProxy.executeImpl(BasicRobotProxy.java:384)
	at net.sf.robocode.host.proxies.BasicRobotProxy.execute(BasicRobotProxy.java:122)
	at robocode.AdvancedRobot.execute(AdvancedRobot.java:552)
	at eem.frame.gameInfo.gameInfo.run(gameInfo.java:95)
	at eem.frame.core.CoreBot.run(CoreBot.java:206)
	at net.sf.robocode.host.proxies.HostingRobotProxy.callUserCode(HostingRobotProxy.java:274)
	at net.sf.robocode.host.proxies.HostingRobotProxy.run(HostingRobotProxy.java:221)
	at net.sf.robocode.host.proxies.BasicRobotProxy.run(BasicRobotProxy.java:44)
	at java.lang.Thread.run(Thread.java:748)

Note that something was very wrong. My bot did not received even SYSTEM onDeath event as can be seen in the more complete log below. Though, my bot was counted as a looser for the first 3 rounds by the other bot. Also, my bot outputted some log during rounds 1 to 4, so the error happens somewhere during the round and steal control from the bot. Also note some time profiling at the end, many methods report max as a factor of 100 times more than an average time. I.e. some catastrophic event happend. One issue that the number of operation is different in every method execution, but I bet not by factor of 100.

=========================
Round 1 of 10
=========================
=========== Round #1=============
100007 best target penguin.Joker .611wr
SYSTEM: EvBotNG vtest skipped turn 19
Skipped turn 19 reported at 100020
SYSTEM: EvBotNG vtest skipped turn 32
Skipped turn 32 reported at 100033
100221: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = -0.6450138864756005 with real bullet
100314: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = -0.2827484567498845 with real bullet
100387: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = -0.20989274379107656 with real bullet
100431: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = 0.19347401753112997 with real bullet
=========================
Round 2 of 10
=========================
=========== Round #2=============
Probing new bullet energy 1.95
SYSTEM: EvBotNG vtest skipped turn 8
Skipped turn 8 reported at 200009
200055: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = 0.3557362360118722 with real bullet
200307: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = 0.08198800256947705 with real bullet
200335: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = 0.06521832333874987 with real bullet
penguin.Joker .611wr hit enemy: eem.EvBotNG vtest with gun: circularGun fired at dist: 566.5311086790286
200354: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = -0.10610623841145142 with real bullet
SYSTEM: EvBotNG vtest skipped turn 396
Skipped turn 396 reported at 200397
=========================
Round 3 of 10
=========================
java.lang.ThreadDeath
	at java.lang.Thread.stop(Thread.java:853)
	at net.sf.robocode.host.security.RobotThreadManager.stop(RobotThreadManager.java:190)
	at net.sf.robocode.host.security.RobotThreadManager.stopSteps(RobotThreadManager.java:172)
	at net.sf.robocode.host.security.RobotThreadManager.forceStop(RobotThreadManager.java:143)
	at net.sf.robocode.host.proxies.HostingRobotProxy.forceStopThread(HostingRobotProxy.java:144)
	at net.sf.robocode.host.proxies.BasicRobotProxy.forceStopThread(BasicRobotProxy.java:44)
	at net.sf.robocode.battle.peer.RobotPeer.checkSkippedTurn(RobotPeer.java:649)
	at net.sf.robocode.battle.peer.RobotPeer.executeImpl(RobotPeer.java:492)
	at net.sf.robocode.host.proxies.BasicRobotProxy.executeImpl(BasicRobotProxy.java:384)
	at net.sf.robocode.host.proxies.BasicRobotProxy.execute(BasicRobotProxy.java:122)
	at robocode.AdvancedRobot.execute(AdvancedRobot.java:552)
	at eem.frame.gameInfo.gameInfo.run(gameInfo.java:95)
	at eem.frame.core.CoreBot.run(CoreBot.java:206)
	at net.sf.robocode.host.proxies.HostingRobotProxy.callUserCode(HostingRobotProxy.java:274)
	at net.sf.robocode.host.proxies.HostingRobotProxy.run(HostingRobotProxy.java:221)
	at net.sf.robocode.host.proxies.BasicRobotProxy.run(BasicRobotProxy.java:44)
	at java.lang.Thread.run(Thread.java:748)
=========== Round #3=============
Probing new bullet energy 1.95
300093: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = 0.37068349323008726 with real bullet
SYSTEM: EvBotNG vtest skipped turn 156
Skipped turn 156 reported at 300157
SYSTEM: EvBotNG vtest skipped turn 191
Skipped turn 191 reported at 300192
300301: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = -0.2802401527715257 with real bullet
300493: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = 0.1975865759018777 with real bullet
SYSTEM: EvBotNG vtest skipped turn 559
Skipped turn 559 reported at 300560
=========================
Round 4 of 10
=========================
java.lang.ThreadDeath
	at java.lang.Thread.stop(Thread.java:853)
	at net.sf.robocode.host.security.RobotThreadManager.stop(RobotThreadManager.java:190)
	at net.sf.robocode.host.security.RobotThreadManager.stopSteps(RobotThreadManager.java:172)
	at net.sf.robocode.host.security.RobotThreadManager.forceStop(RobotThreadManager.java:143)
	at net.sf.robocode.host.proxies.HostingRobotProxy.forceStopThread(HostingRobotProxy.java:144)
	at net.sf.robocode.host.proxies.BasicRobotProxy.forceStopThread(BasicRobotProxy.java:44)
	at net.sf.robocode.battle.peer.RobotPeer.checkSkippedTurn(RobotPeer.java:649)
	at net.sf.robocode.battle.peer.RobotPeer.executeImpl(RobotPeer.java:492)
	at net.sf.robocode.host.proxies.BasicRobotProxy.executeImpl(BasicRobotProxy.java:384)
	at net.sf.robocode.host.proxies.BasicRobotProxy.execute(BasicRobotProxy.java:122)
	at robocode.AdvancedRobot.execute(AdvancedRobot.java:552)
	at eem.frame.gameInfo.gameInfo.run(gameInfo.java:95)
	at eem.frame.core.CoreBot.run(CoreBot.java:206)
	at net.sf.robocode.host.proxies.HostingRobotProxy.callUserCode(HostingRobotProxy.java:274)
	at net.sf.robocode.host.proxies.HostingRobotProxy.run(HostingRobotProxy.java:221)
	at net.sf.robocode.host.proxies.BasicRobotProxy.run(BasicRobotProxy.java:44)
	at java.lang.Thread.run(Thread.java:748)
=========== Round #4=============
Probing new bullet energy 1.95
400161: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = 0.6168884721887381 with real bullet
400292: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = 0.09859694511664721 with real bullet
400317: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = -0.47485553157064525 with real bullet
400345: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = 0.2798221445512617 with real bullet
400476: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = 0.2817195309815388 with real bullet
400492: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = 0.34782608695652234 with real bullet
=========================
Round 5 of 10
=========================
=========== Round #5=============
Probing new bullet energy 1.95
SYSTEM: Bonus for killing penguin.Joker .611wr: 11
SYSTEM: eem.EvBotNG vtest wins the round.
Hit by bullet: [5, 4, 3, 6, 0, 0, 0, 0, 0, 0]
Wall hits stats: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
Skipped turns stats: [2, 2, 3, 0, 0, 0, 0, 0, 0, 0]
Hit rate stats:   16/158  =   10.13%
Bullet hit bullet stats::   10/158  =    6.33%
Rounds ratio of win/lose = 1/2
Finishing places stats: [1, 2]
myWinLosePlace = 0
My score in this round = 113.4 enemy score = 0.0
My total score = 176.89999999999998 enemy score = 246.76000000000022
Round APS stats: [25.01444251877526, 0.0, 0.0, 14.727325750947783, 100.0, 0.0, 0.0, 0.0, 0.0, 0.0]
Accumulated APS = 41.76%
--- bot penguin.Joker .611wr stats:
hit rate for the following bot(s) out of 172 shots
 eem.EvBotNG vtest:   18/172  =   10.47%
  My virtual gun hit rate stats stats
                 enemy name              circularGun                headOnGun              realHitsGun               unknownGun
          eem.EvBotNG vtest        1/172  =    0.58%        0/172  =    0.00%       18/172  =   10.47%       17/172  =    9.88%
--- bot eem.EvBotNG vtest stats:
wrong path prediction count: 7 <------------------------------ improve me!
Hit me count by the following bot(s)
 penguin.Joker .611wr:   18/172  =   10.47%
  Enemies virtual gun stats
    circularGun of bot penguin.Joker .611wr hit me   12/172  =    6.98%
    headOnGun of bot penguin.Joker .611wr hit me   13/172  =    7.56%
    realHitsGun of bot penguin.Joker .611wr hit me    1/172  =    0.58%
hit rate for the following bot(s) out of 158 shots
 penguin.Joker .611wr:   16/158  =   10.13%
  My virtual gun hit rate stats stats
                 enemy name              circularGun         circularAccelGun                headOnGun                  kdtGF50                 kdtGF100                 kdtGF200                 kdtGF400                 kdtGF800                kdtGF1600           guessFactorGun                randomGun            assistedGFGun   decayingGuessFactorGun   flipLastGuessFactorGun
       penguin.Joker .611wr       11/147  =    7.48%       13/147  =    8.84%       17/147  =   11.56%       23/147  =   15.65%       14/147  =    9.52%       12/147  =    8.16%       19/147  =   12.93%       14/147  =    9.52%       18/147  =   12.24%       11/147  =    7.48%       17/147  =   11.56%       13/147  =    8.84%        7/147  =    4.76%       17/147  =   11.56%
bot penguin.Joker .611wr intercepted my bullet   10/172  =    5.81%
Profiler stats---------------------------
  getOverlap was executed 22026 execution times: min 67 nS, average 118 nS, max 58 uS
  getJoin was executed 5 execution times: min 2 uS, average 2 uS, max 3 uS
  choseNewPath was executed 2529 execution times: min 95 uS, average 321 uS, max 14 mS
  rankAimAtAllSolutions was executed 2358 execution times: min 243 nS, average 4 uS, max 2 mS
  waveWithBullets.getDanger was executed 312940 execution times: min 74 nS, average 331 nS, max 2 mS
  calculateDanger was executed 10899 execution times: min 801 nS, average 43 uS, max 13 mS
  waveWithBullets.getWaveDanger was executed 26899 execution times: min 450 nS, average 2 uS, max 2 mS
  gunManagerManage was executed 2529 execution times: min 3 uS, average 586 uS, max 12 mS
---------------------------
500353: penguin.Joker .611wr hit eem.EvBotNG vtest at GF = -0.31909710498646854 with real bullet
=========================
    Beaming (talk)02:41, 5 September 2017

    Would you try modifing the source of robocode to make it ouput the result of checkSkippedTurn? I think the bug may be whether the skipped turns are counted incorrectly or some skipped turns are not logged to console.

      Xor (talk)03:21, 5 September 2017

      Skipped turns are logged (and SkippedTurnEvents happens) only when the Robocode regains control over the execution of the thread. Since there is an unhandled exception being thrown right during the skipped turn checking, it makes sense that the skipped turns are not logged. I'm pretty sure you are skipping too many turns, Thread.stop() is being called as it is supposed to be (by looking at Robocode source), the exception is being thrown (because Thread.stop() is deprecated) and for some reason it's not being handled.

      So, the error message is pretty much "you have skipped too many turns, I tried to stop your thread but for this I called a deprecated function which throws an error". The bot punishment for skipping too many turns is correct. The correct questions are: this should really happen? not the error, but the "too many skipped turns" thing. Does it happen when locking to 1000 FPS? If it was a "fair" turn skipping, it should happen while locked to 1000 FPS as well? If yes, why it's behaving differently when on full speed? Can others reproduce the same issue? (pick Roborio vs Neuromancer, for example, and go full speed). Why it's more likely to happen when a slow bot is against a fast bot? And so on.

      Does you guys have any other interesting observations on that?

        Rsalesc (talk)03:35, 5 September 2017