0 | 0:00 | DEBUG | Using configuration file PurpleWaveAIIDETournament.config.json
0 | 0:00 | DEBUG | Human: false
0 | 0:00 | DEBUG | Ladder: false
0 | 0:00 | DEBUG | Stream: false
0 | 0:00 | DEBUG | Tournament: true
0 | 0:00 | DEBUG | Round-robin: true
0 | 0:00 | DEBUG | Elimination: false
0 | 0:00 | DEBUG | Debugging: false
0 | 0:00 | DEBUG | Loading BWTA for Python 1.1 at (4)Python.scx
0 | 0:00 | DEBUG | Strategery.Selection.StrategySelectionRecommended@ad4df1 has finished recommended strategy phase in game 148 of 5; will fall back to Strategery.Selection.StrategySelectionDynamic$@a85723
0 | 0:00 | DEBUG | Game start time:  Sat Oct 17 20:02:41 NDT 2020
0 | 0:00 | DEBUG | OS:               Windows 7 6.1 x86
0 | 0:00 | DEBUG | JRE:              Oracle Corporation - 1.8.0_211
0 | 0:00 | DEBUG | CPUs available:   2
0 | 0:00 | DEBUG | System memory:    2147 MB
0 | 0:00 | DEBUG | JVM Max memory:   1037 MB
0 | 0:00 | DEBUG | JVM Total memory: 1037 MB
0 | 0:00 | DEBUG | JVM Free memory:  705 MB
0 | 0:00 | DEBUG | This copy of PurpleWave was packaged for distribution on Mon, Sep 28, 2020 12:17:44 AM
0 | 0:00 | DEBUG | This copy of PurpleWave came from Git revision 82d99bd1f57d158ab68478e9b35c42d521127e1b
0 | 0:00 | DEBUG | JBWAPI autocontinue: true
0 | 0:00 | DEBUG | JBWAPI debugConnection: false
0 | 0:00 | DEBUG | JBWAPI async: true
0 | 0:00 | DEBUG | JBWAPI async unsafe: true
0 | 0:00 | DEBUG | JBWAPI async frame buffer size: 10
0 | 0:00 | DEBUG | JBWAPI unlimited frame zero: true
0 | 0:00 | DEBUG | JBWAPI max frame duration: 30ms
0 | 0:00 | DEBUG | Strategy	PvZ2Gate910	PvZ10Gate	PvZMidgame5GateGoonReaver	PvZLateGameReaver	PvZ4GateGoon	PvZFFEEconomic	PvZMidgameBisu	PvZ2Gate1012	PvZLateGameTemplar	PvZMidgameNeoBisu	PvZMidgame5GateGoon	WorkersUnite	WorkersKill	PvEStormYes	PvEStormNo	WorkersSpread	PvZFFEConservative	PvZProxy2Gate
0 | 0:00 | DEBUG | #Games	33.0	31.0	113.0	113.0	108.0	35.0	2.0	44.0	35.0	1.0	32.0	0.0	0.0	0.0	0.0	0.0	5.0	6.0
0 | 0:00 | DEBUG | #Wtd	13.6	12.9	46.8	46.8	42.6	16.8	1.3	16.1	15.5	0.6	13.7	0.0	0.0	0.0	0.0	0.0	2.9	2.1
0 | 0:00 | DEBUG | #WtdWins	13.6	12.9	45.7	45.7	40.9	16.2	1.3	14.4	13.6	0.6	11.7	0.0	0.0	0.0	0.0	0.0	2.3	1.3
0 | 0:00 | DEBUG | WinPct	100%%	100%%	97%%	97%%	95%%	96%%	100%%	89%%	87%%	100%%	85%%	0%%	0%%	0%%	0%%	0%%	79%%	64%%
0 | 0:00 | DEBUG | WinEst	98%%	97%%	97%%	97%%	95%%	94%%	89%%	88%%	86%%	85%%	85%%	80%%	80%%	80%%	80%%	80%%	79%%	70%%
0 | 0:00 | DEBUG | Strategy interest
0 | 0:00 | DEBUG | 96%% PvZ2Gate910 + PvZ4GateGoon + PvZLateGameReaver + PvZMidgame5GateGoonReaver
0 | 0:00 | DEBUG | 94%% PvZ2Gate1012 + PvZ4GateGoon + PvZLateGameReaver + PvZMidgame5GateGoonReaver
0 | 0:00 | DEBUG | 91%% PvZ2Gate910 + PvZ4GateGoon + PvZLateGameTemplar + PvZMidgame5GateGoon
0 | 0:00 | DEBUG | 88%% PvZ2Gate1012 + PvZ4GateGoon + PvZLateGameTemplar + PvZMidgame5GateGoon
0 | 0:00 | DEBUG | Opponents is Steamhammer
0 | 0:00 | DEBUG | Rush distances is 5152.0, 5600.0, 5216.0, 5280.0
0 | 0:00 | DEBUG | Playbook is Strategery.TournamentPlaybook$@1461c51
0 | 0:00 | DEBUG | Policy is Strategery.Selection.StrategySelectionTournament$@1fa237d
0 | 0:00 | DEBUG | Enemy race is Zerg
0 | 0:00 | DEBUG | Strategy is PvZ2Gate910 PvZ4GateGoon PvZMidgame5GateGoonReaver PvZLateGameReaver
0 | 0:00 | DEBUG | Our bases is 0
0 | 0:00 | DEBUG | Enemy bases is 0
0 | 0:00 | DEBUG | Our Factories is 0
0 | 0:00 | DEBUG | Our Barracks is 0
0 | 0:00 | DEBUG | Our Gateways is 0
0 | 0:00 | DEBUG | Our Hatcheries is 0
0 | 0:00 | DEBUG | Enemy Factories is 0
0 | 0:00 | DEBUG | Enemy Barracks is 0
0 | 0:00 | DEBUG | Enemy Gateways is 0
0 | 0:00 | DEBUG | Enemy Hatcheries is 0
0 | 0:00 | DEBUG | Safe at home is true
0 | 0:00 | DEBUG | Safe to move out is true
0 | 0:00 | DEBUG | Should attack is false
0 | 0:00 | DEBUG | Status is PvZ2Gate910, 4-Gate Goons
0 | 0:00 | DEBUG | Performance danger is false
1 | 0:00 | DEBUG | Our bases changed from 0 to 1
197 | 0:08 | DEBUG | Task queue took @ 274ms, crossing the 55ms threshold. Task durations: 
TaskMicro: 3ms
TaskBattles: 0ms
TaskSquads: 1ms
TaskAccounting: 0ms
TaskManners: 0ms
TaskCamera: 0ms
TaskVisualizations: 0ms
484 | 0:20 | WARN  | TaskGridCreep crossed the 55ms threshold, taking 170ms for 178ms total this frame. 
484 | 0:20 | DEBUG | Task queue took @ 178ms, crossing the 55ms threshold. Task durations: 
TaskGridUnits: 1ms
TaskGridEnemyDetection: 0ms
TaskGridEnemyRangeAir: 0ms
TaskGridEnemyRangeGround: 0ms
TaskGridEnemyRangeAirGround: 0ms
TaskGridEnemyVulnerabilityGround: 0ms
TaskGridPsionicStorm: 0ms
TaskGridBuildable: 0ms
TaskGridBuildableTerrain: 0ms
TaskGridEnemyVision: 0ms
TaskGridFriendlyDetection: 0ms
TaskGridFriendlyVision: 0ms
TaskGridPsi2x2and3x2: 0ms
TaskGridPsi4x3: 0ms
TaskGridAltitudeBonus: 0ms
TaskGridBuildableTownHall: 0ms
TaskGridCreepInitial: 0ms
TaskGridCreep: 170ms
TaskGridMobilityBorder: 0ms
TaskGridWalkable: 0ms
TaskGridWalkableTerrain: 0ms
TaskGridUnwalkableUnits: 0ms
484 | 0:20 | WARN  | TaskGrids crossed the 55ms threshold, taking 172ms for 179ms total this frame. 
484 | 0:20 | DEBUG | Task queue took @ 179ms, crossing the 55ms threshold. Task durations: 
TaskMicro: 2ms
TaskBattles: 0ms
TaskSquads: 0ms
TaskPlanning: 4ms
TaskGrids: 172ms
TaskAccounting: 0ms
TaskManners: 0ms
TaskCamera: 0ms
TaskVisualizations: 0ms
1874 | 1:18 | DEBUG | Our Gateways changed from 0 to 1
2257 | 1:34 | DEBUG | Our Gateways changed from 1 to 2
2284 | 1:35 | WARN  | Microing Probe crossed the 55ms threshold by taking 843ms considering 
2284 | 1:35 | DEBUG | Task queue took @ 847ms, crossing the 55ms threshold. Task durations: 
TaskMicro: 846ms
TaskBattles: 1ms
TaskSquads: 0ms
TaskPlanning: 8ms
TaskGrids: 2ms
TaskFingerprinting: 2ms
TaskGeography: 1ms
TaskAccounting: 0ms
TaskGathering: 0ms
TaskArchitecture: 1ms
TaskManners: 0ms
TaskCamera: 0ms
TaskVisualizations: 0ms
2972 | 2:03 | DEBUG | Discovered novel enemy unit: Drone
2972 | 2:03 | DEBUG | Drone #21 40/40 [120, 54] [3859, 1728] projects to arrive in 98 frames at 2:07
2976 | 2:04 | WARN  | TaskGridEnemyRangeAir crossed the 55ms threshold, taking 1890ms for 1902ms total this frame. 
2976 | 2:04 | DEBUG | Task queue took @ 1902ms, crossing the 55ms threshold. Task durations: 
TaskGridUnits: 0ms
TaskGridEnemyDetection: 0ms
TaskGridEnemyRangeAir: 1890ms
2976 | 2:04 | WARN  | TaskGrids crossed the 55ms threshold, taking 1890ms for 1902ms total this frame. 
2976 | 2:04 | DEBUG | Task queue took @ 1903ms, crossing the 55ms threshold. Task durations: 
TaskPlanning: 9ms
TaskSquads: 1ms
TaskMicro: 26ms
TaskGrids: 1890ms
TaskVisualizations: 0ms
4020 | 2:47 | DEBUG | Discovered novel enemy unit: Overlord
4020 | 2:47 | DEBUG | Overlord #18 200/200 [97, 43] [3130, 1378] projects to arrive in 758 frames at 3:19
4136 | 2:52 | DEBUG | Enemy Hatcheries changed from 0 to 1
4136 | 2:52 | DEBUG | Discovered novel enemy unit: Hatchery
4136 | 2:52 | DEBUG | Hatchery #146 1151/1250 [77, 119] [2464, 3824] projects to complete in 158 frames at 2:58
4138 | 2:52 | DEBUG | Enemy bases changed from 0 to 1
4139 | 2:52 | DEBUG | Enemy bases changed from 1 to 2
4140 | 2:52 | DEBUG | Fingerprints is 12Hatch
4142 | 2:52 | DEBUG | Should attack changed from false to true
4378 | 3:02 | DEBUG | Enemy Hatcheries changed from 1 to 2
4378 | 3:02 | DEBUG | Fingerprints changed from 12Hatch to 9PoolGas 9Pool
4380 | 3:02 | DEBUG | Should attack changed from true to false
4380 | 3:02 | DEBUG | Status changed from PvZ2Gate910, 4-Gate Goons to PvZ2Gate910, Anti-AirASAP, 4-Gate Goons
4380 | 3:02 | DEBUG | Discovered novel enemy unit: Egg
4380 | 3:02 | DEBUG | Egg #166 200/200 [45, 120] [1468, 3854] projects to arrive in 86400 frames at 63:02
4380 | 3:02 | DEBUG | Discovered novel enemy unit: Lair
4380 | 3:02 | DEBUG | Lair #23 1250/1800 [44, 120] [1408, 3856] projects to complete in 507 frames at 3:23
4388 | 3:02 | DEBUG | Discovered novel enemy unit: Extractor
4388 | 3:02 | DEBUG | Extractor #13 750/750 [44, 115] [1408, 3680] is already complete
4394 | 3:03 | DEBUG | Discovered novel enemy unit: Spawning Pool
4394 | 3:03 | DEBUG | Spawning Pool #19 750/750 [43, 124] [1392, 3968] is already complete
4445 | 3:05 | DEBUG | Task queue took @ 66ms, crossing the 55ms threshold. Task durations: 
TaskMicro: 64ms
TaskSquads: 1ms
TaskPlanning: 9ms
TaskGrids: 4ms
TaskFingerprinting: 0ms
TaskGeography: 1ms
TaskAccounting: 0ms
TaskGathering: 0ms
TaskManners: 0ms
TaskCamera: 0ms
TaskVisualizations: 0ms
4497 | 3:07 | DEBUG | Discovered novel enemy unit: Larva
4497 | 3:07 | DEBUG | Larva #170 25/25 [45, 120] [1467, 3856] projects to arrive in 86400 frames at 63:07
4590 | 3:11 | DEBUG | Discovered novel enemy unit: Zergling
4590 | 3:11 | DEBUG | Zergling #162 35/35 [42, 119] [1351, 3816] projects to arrive in 944 frames at 3:50
5177 | 3:35 | DEBUG | Discovered novel enemy unit: Hydralisk Den
5177 | 3:35 | DEBUG | Hydralisk Den #148 85/850 [48, 121] [1552, 3872] projects to complete in -115 frames at 3:30
6739 | 4:40 | DEBUG | Our Gateways changed from 2 to 3
6905 | 4:47 | DEBUG | Should attack changed from false to true
6950 | 4:49 | DEBUG | Enemy upgrades is Metabolic Boost = 1
7494 | 5:12 | DEBUG | Discovered novel enemy unit: Sunken Colony
7494 | 5:12 | DEBUG | Sunken Colony #173 300/300 [72, 115] [2304, 3680] is already complete
7494 | 5:12 | DEBUG | Sunken Colony #4 300/300 [70, 115] [2240, 3680] is already complete
7621 | 5:17 | DEBUG | Our Gateways changed from 3 to 4
7723 | 5:21 | DEBUG | Discovered novel enemy unit: Creep Colony
7723 | 5:21 | DEBUG | Creep Colony #193 40/400 [72, 113] [2304, 3616] projects to complete in 242 frames at 5:31
8021 | 5:34 | DEBUG | Discovered novel enemy unit: Hydralisk
8021 | 5:34 | DEBUG | Hydralisk #179 80/80 [67, 116] [2172, 3736] projects to arrive in 1137 frames at 6:21
8646 | 6:00 | DEBUG | Our upgrades is Singularity Charge = 1
8746 | 6:04 | DEBUG | Discovered novel enemy unit: Lurker Egg
8746 | 6:04 | DEBUG | Lurker Egg #200 200/200 [73, 113] [2338, 3626] projects to arrive in 86400 frames at 66:04
8935 | 6:12 | DEBUG | Discovered novel enemy unit: Lurker
8935 | 6:12 | DEBUG | Lurker #179 79/125 [66, 112] [2132, 3614] projects to arrive in 703 frames at 6:41
12377 | 8:35 | DEBUG | Our bases changed from 1 to 2
12379 | 8:35 | WARN  | TaskPlanning crossed the 55ms threshold, taking 53ms for 58ms total this frame. 
12379 | 8:35 | DEBUG | Task queue took @ 59ms, crossing the 55ms threshold. Task durations: 
TaskMicro: 3ms
TaskPlanning: 53ms
TaskBattles: 4ms
TaskSquads: 1ms
TaskFingerprinting: 0ms
TaskGeography: 2ms
TaskAccounting: 0ms
TaskGathering: 0ms
TaskArchitecture: 1ms
TaskManners: 0ms
TaskCamera: 0ms
TaskVisualizations: 0ms
12379 | 8:35 | DEBUG | Status changed from PvZ2Gate910, Anti-AirASAP, 4-Gate Goons to PvZ5GateGoon
13276 | 9:13 | WARN  | Microing Observer crossed the 55ms threshold by taking 95ms considering 
13276 | 9:13 | DEBUG | Task queue took @ 104ms, crossing the 55ms threshold. Task durations: 
TaskMicro: 102ms
TaskBattles: 18ms
TaskVisualizations: 0ms
13780 | 9:34 | DEBUG | Enemy upgrades changed from Metabolic Boost = 1 to Pneumatized Carapace = 1, Metabolic Boost = 1
13950 | 9:41 | WARN  | TaskPlanning crossed the 55ms threshold, taking 52ms for 55ms total this frame. The task was overdue to run this frame.
13950 | 9:41 | DEBUG | Task queue took @ 55ms, crossing the 55ms threshold. Task durations: 
TaskPlanning: 52ms
TaskMicro: 18ms
TaskVisualizations: 0ms
13959 | 9:41 | DEBUG | Safe to move out changed from true to false
14092 | 9:47 | DEBUG | Our Gateways changed from 4 to 5
14108 | 9:47 | DEBUG | Safe to move out changed from false to true
14426 | 10:01 | DEBUG | Safe to move out changed from true to false
14628 | 10:09 | DEBUG | Safe at home changed from true to false
14630 | 10:09 | DEBUG | Enemy Hatcheries changed from 2 to 3
14631 | 10:09 | DEBUG | Enemy bases changed from 2 to 4
14790 | 10:16 | DEBUG | Safe at home changed from false to true
14852 | 10:18 | DEBUG | Enemy upgrades changed from Pneumatized Carapace = 1, Metabolic Boost = 1 to Pneumatized Carapace = 1, Muscular Augments = 1, Metabolic Boost = 1
14871 | 10:19 | DEBUG | Our upgrades changed from Singularity Charge = 1 to Singularity Charge = 1, Gravitic Boosters = 1
14966 | 10:23 | DEBUG | Safe at home changed from true to false
15065 | 10:27 | DEBUG | Safe at home changed from false to true
15212 | 10:33 | DEBUG | Safe to move out changed from false to true
16343 | 11:20 | DEBUG | Enemy Hatcheries changed from 3 to 4
16346 | 11:21 | DEBUG | Enemy bases changed from 4 to 5
16709 | 11:36 | DEBUG | Enemy upgrades changed from Pneumatized Carapace = 1, Muscular Augments = 1, Metabolic Boost = 1 to Pneumatized Carapace = 1, Muscular Augments = 1, Grooved Spines = 1, Metabolic Boost = 1
16855 | 11:42 | DEBUG | Safe at home changed from true to false
16855 | 11:42 | DEBUG | Safe to move out changed from true to false
17147 | 11:54 | DEBUG | Safe at home changed from false to true
17343 | 12:02 | DEBUG | Safe to move out changed from false to true
17416 | 12:05 | DEBUG | Safe at home changed from true to false
17416 | 12:05 | DEBUG | Safe to move out changed from true to false
17435 | 12:06 | DEBUG | Safe at home changed from false to true
17447 | 12:06 | DEBUG | Safe to move out changed from false to true
18377 | 12:45 | DEBUG | Enemy upgrades changed from Pneumatized Carapace = 1, Muscular Augments = 1, Grooved Spines = 1, Metabolic Boost = 1 to Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Grooved Spines = 1, Metabolic Boost = 1
18462 | 12:49 | DEBUG | Enemy upgrades changed from Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Grooved Spines = 1, Metabolic Boost = 1 to Zerg Carapace = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Grooved Spines = 1, Metabolic Boost = 1
18781 | 13:02 | DEBUG | Enemy Hatcheries changed from 4 to 3
18782 | 13:02 | DEBUG | Enemy bases changed from 5 to 4
19445 | 13:30 | DEBUG | Enemy Hatcheries changed from 3 to 4
19449 | 13:30 | DEBUG | Enemy bases changed from 4 to 5
19466 | 13:31 | DEBUG | Enemy upgrades changed from Zerg Carapace = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Grooved Spines = 1, Metabolic Boost = 1 to Zerg Carapace = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 1, Grooved Spines = 1, Metabolic Boost = 1
19472 | 13:31 | DEBUG | Our upgrades changed from Singularity Charge = 1, Gravitic Boosters = 1 to Singularity Charge = 1, Gravitic Drive = 1, Gravitic Boosters = 1
19592 | 13:36 | DEBUG | Enemy Hatcheries changed from 4 to 5
19598 | 13:36 | DEBUG | Enemy bases changed from 5 to 6
19620 | 13:37 | DEBUG | Status changed from PvZ5GateGoon to PvZLateGameReaver
19732 | 13:42 | DEBUG | Discovered novel enemy unit: Defiler
19732 | 13:42 | DEBUG | Defiler #410 80/80 [68, 114] [2202, 3652] projects to arrive in 752 frames at 14:13
20049 | 13:55 | DEBUG | Enemy bases changed from 6 to 5
20750 | 14:24 | DEBUG | Our bases changed from 2 to 3
21220 | 14:44 | DEBUG | Enemy Hatcheries changed from 5 to 6
21414 | 14:52 | DEBUG | Discovered novel enemy unit: Spire
21414 | 14:52 | DEBUG | Spire #294 600/600 [49, 116] [1568, 3712] is already complete
21490 | 14:55 | DEBUG | Enemy Hatcheries changed from 6 to 7
21736 | 15:05 | DEBUG | Our bases changed from 3 to 4
21791 | 15:07 | DEBUG | Discovered novel enemy unit: Scourge
21791 | 15:07 | DEBUG | Scourge #540 25/25 [67, 112] [2169, 3594] projects to arrive in 305 frames at 15:20
22471 | 15:36 | DEBUG | Our Gateways changed from 5 to 6
22943 | 15:55 | DEBUG | Discovered novel enemy unit: Mutalisk
22943 | 15:55 | DEBUG | Mutalisk #567 120/120 [30, 75] [974, 2424] projects to arrive in 418 frames at 16:13
22943 | 15:55 | DEBUG | Mutalisk #574 120/120 [73, 116] [2339, 3713] projects to arrive in 302 frames at 16:08
23174 | 16:05 | DEBUG | Safe to move out changed from true to false
23531 | 16:20 | DEBUG | Enemy upgrades changed from Zerg Carapace = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 1, Grooved Spines = 1, Metabolic Boost = 1 to Zerg Carapace = 2, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 1, Grooved Spines = 1, Metabolic Boost = 1
24009 | 16:40 | DEBUG | Our upgrades changed from Singularity Charge = 1, Gravitic Drive = 1, Gravitic Boosters = 1 to Singularity Charge = 1, Gravitic Drive = 1, Protoss Ground Weapons = 1, Gravitic Boosters = 1
24247 | 16:50 | DEBUG | Safe at home changed from true to false
25238 | 17:31 | DEBUG | Our bases changed from 4 to 3
25331 | 17:35 | DEBUG | Enemy upgrades changed from Zerg Carapace = 2, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 1, Grooved Spines = 1, Metabolic Boost = 1 to Zerg Carapace = 2, Metasynaptic Node = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 1, Grooved Spines = 1, Metabolic Boost = 1
25576 | 17:45 | WARN  | TaskPlanning crossed the 55ms threshold, taking 50ms for 55ms total this frame. The task was overdue to run this frame.
25576 | 17:45 | DEBUG | Task queue took @ 55ms, crossing the 55ms threshold. Task durations: 
TaskPlanning: 50ms
TaskMicro: 17ms
TaskVisualizations: 0ms
25782 | 17:54 | WARN  | TaskPlanning crossed the 55ms threshold, taking 55ms for 58ms total this frame. The task was overdue to run this frame.
25782 | 17:54 | DEBUG | Task queue took @ 59ms, crossing the 55ms threshold. Task durations: 
TaskPlanning: 55ms
TaskMicro: 16ms
TaskVisualizations: 0ms
25837 | 17:56 | DEBUG | Our bases changed from 3 to 2
25953 | 18:01 | DEBUG | Enemy upgrades changed from Zerg Carapace = 2, Metasynaptic Node = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 1, Grooved Spines = 1, Metabolic Boost = 1 to Zerg Carapace = 2, Metasynaptic Node = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 2, Grooved Spines = 1, Metabolic Boost = 1
26180 | 18:10 | DEBUG | Our Gateways changed from 6 to 5
26239 | 18:13 | DEBUG | Our Gateways changed from 5 to 4
26259 | 18:14 | DEBUG | Our bases changed from 2 to 1
26403 | 18:20 | DEBUG | Our Gateways changed from 4 to 3
26571 | 18:27 | DEBUG | Our Gateways changed from 3 to 2
27090 | 18:48 | DEBUG | Safe at home changed from false to true
27090 | 18:48 | DEBUG | Safe to move out changed from false to true
27091 | 18:48 | DEBUG | Our bases changed from 1 to 0
27137 | 18:50 | DEBUG | Enemy upgrades changed from Zerg Carapace = 2, Metasynaptic Node = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 2, Grooved Spines = 1, Metabolic Boost = 1 to Zerg Carapace = 2, Metasynaptic Node = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 2, Grooved Spines = 1, Metabolic Boost = 1, Anabolic Synthesis = 1
27141 | 18:50 | DEBUG | Discovered novel enemy unit: Ultralisk
27141 | 18:50 | DEBUG | Ultralisk #762 400/400 [61, 95] [1970, 3061] projects to arrive in 130 frames at 18:56
27179 | 18:52 | WARN  | TaskArchitecture crossed the 55ms threshold, taking 213ms for 222ms total this frame. 
27179 | 18:52 | DEBUG | Task queue took @ 223ms, crossing the 55ms threshold. Task durations: 
TaskMicro: 5ms
TaskSquads: 1ms
TaskBattles: 18ms
TaskArchitecture: 213ms
TaskVisualizations: 0ms
27202 | 18:53 | DEBUG | Discovered novel enemy unit: Queen
27202 | 18:53 | DEBUG | Queen #733 120/120 [106, 96] [3418, 3074] projects to arrive in 246 frames at 19:03
27272 | 18:56 | DEBUG | Our Gateways changed from 2 to 1
27326 | 18:58 | WARN  | TaskArchitecture crossed the 55ms threshold, taking 221ms for 222ms total this frame. The task was overdue to run this frame.
27326 | 18:58 | DEBUG | Task queue took @ 222ms, crossing the 55ms threshold. Task durations: 
TaskArchitecture: 221ms
TaskMicro: 3ms
TaskSquads: 5ms
TaskGrids: 5ms
TaskFingerprinting: 0ms
TaskGeography: 1ms
TaskAccounting: 0ms
TaskGathering: 0ms
TaskManners: 0ms
TaskCamera: 0ms
TaskVisualizations: 0ms
27375 | 19:00 | WARN  | TaskArchitecture crossed the 55ms threshold, taking 217ms for 218ms total this frame. The task was overdue to run this frame.
27375 | 19:00 | DEBUG | Task queue took @ 219ms, crossing the 55ms threshold. Task durations: 
TaskArchitecture: 217ms
TaskMicro: 2ms
TaskBattles: 1ms
TaskSquads: 5ms
TaskGrids: 4ms
TaskFingerprinting: 0ms
TaskGeography: 2ms
TaskAccounting: 0ms
TaskGathering: 0ms
TaskManners: 0ms
TaskCamera: 0ms
TaskVisualizations: 0ms
27418 | 19:02 | DEBUG | Enemy upgrades changed from Zerg Carapace = 2, Metasynaptic Node = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 2, Grooved Spines = 1, Metabolic Boost = 1, Anabolic Synthesis = 1 to Zerg Carapace = 2, Metasynaptic Node = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 2, Grooved Spines = 1, Metabolic Boost = 1, Zerg Flyer Carapace = 1, Anabolic Synthesis = 1
27474 | 19:04 | WARN  | TaskArchitecture crossed the 55ms threshold, taking 211ms for 213ms total this frame. The task was overdue to run this frame.
27474 | 19:04 | DEBUG | Task queue took @ 213ms, crossing the 55ms threshold. Task durations: 
TaskArchitecture: 211ms
TaskMicro: 3ms
TaskSquads: 5ms
TaskPlanning: 4ms
TaskGrids: 3ms
TaskFingerprinting: 0ms
TaskGeography: 1ms
TaskAccounting: 0ms
TaskGathering: 0ms
TaskManners: 0ms
TaskCamera: 0ms
TaskVisualizations: 0ms
27523 | 19:06 | WARN  | TaskArchitecture crossed the 55ms threshold, taking 206ms for 207ms total this frame. The task was overdue to run this frame.
27523 | 19:06 | DEBUG | Task queue took @ 207ms, crossing the 55ms threshold. Task durations: 
TaskArchitecture: 206ms
TaskMicro: 2ms
TaskSquads: 4ms
TaskPlanning: 4ms
TaskGrids: 4ms
TaskFingerprinting: 0ms
TaskGeography: 2ms
TaskVisualizations: 0ms
27621 | 19:10 | WARN  | TaskArchitecture crossed the 55ms threshold, taking 188ms for 189ms total this frame. The task was overdue to run this frame.
27621 | 19:10 | DEBUG | Task queue took @ 190ms, crossing the 55ms threshold. Task durations: 
TaskArchitecture: 188ms
TaskMicro: 3ms
TaskSquads: 0ms
TaskPlanning: 4ms
TaskGrids: 4ms
TaskFingerprinting: 0ms
TaskGeography: 2ms
TaskAccounting: 0ms
TaskGathering: 0ms
TaskManners: 0ms
TaskCamera: 0ms
TaskVisualizations: 0ms
27670 | 19:12 | WARN  | TaskArchitecture crossed the 55ms threshold, taking 201ms for 202ms total this frame. The task was overdue to run this frame.
27670 | 19:12 | DEBUG | Task queue took @ 202ms, crossing the 55ms threshold. Task durations: 
TaskArchitecture: 201ms
TaskMicro: 2ms
TaskPlanning: 4ms
TaskGrids: 4ms
TaskFingerprinting: 0ms
TaskGeography: 1ms
TaskAccounting: 0ms
TaskGathering: 0ms
TaskManners: 1ms
TaskCamera: 0ms
TaskVisualizations: 0ms
27768 | 19:17 | WARN  | TaskArchitecture crossed the 55ms threshold, taking 207ms for 208ms total this frame. The task was overdue to run this frame.
27768 | 19:17 | DEBUG | Task queue took @ 208ms, crossing the 55ms threshold. Task durations: 
TaskArchitecture: 207ms
TaskMicro: 2ms
TaskSquads: 5ms
TaskPlanning: 4ms
TaskGrids: 5ms
TaskFingerprinting: 0ms
TaskGeography: 1ms
TaskAccounting: 0ms
TaskGathering: 0ms
TaskManners: 0ms
TaskCamera: 0ms
TaskVisualizations: 0ms
27782 | 19:17 | DEBUG | Enemy upgrades changed from Zerg Carapace = 2, Metasynaptic Node = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 2, Grooved Spines = 1, Metabolic Boost = 1, Zerg Flyer Carapace = 1, Anabolic Synthesis = 1 to Zerg Carapace = 2, Metasynaptic Node = 1, Pneumatized Carapace = 1, Adrenal Glands = 1, Muscular Augments = 1, Zerg Melee Attacks = 2, Grooved Spines = 1, Metabolic Boost = 1, Chitinous Plating = 1, Zerg Flyer Carapace = 1, Anabolic Synthesis = 1
27818 | 19:19 | WARN  | TaskArchitecture crossed the 55ms threshold, taking 226ms for 228ms total this frame. The task was overdue to run this frame.
27818 | 19:19 | DEBUG | Task queue took @ 229ms, crossing the 55ms threshold. Task durations: 
TaskArchitecture: 226ms
TaskMicro: 2ms
TaskSquads: 5ms
TaskPlanning: 4ms
TaskGrids: 5ms
TaskFingerprinting: 0ms
TaskGeography: 1ms
TaskAccounting: 0ms
TaskGathering: 0ms
TaskManners: 0ms
TaskCamera: 0ms
TaskVisualizations: 0ms
27890 | 19:22 | DEBUG | Our Gateways changed from 1 to 0
27902 | 19:22 | DEBUG | Game ended in defeat
27902 | 19:22 | DEBUG | Cutoff: 	55ms
Task	Last run	 Run %	Seconds	Avg ms	Max (Recent)	Max (All time)	Extended	Disqualifying
Accounting          		 56%%	1	0	1	6	2	0
Architecture        	XXXXXXXXXX	 38%%	16	61	226	226	84	9
Battles             		 45%%	107	11	18	50	143	0
Camera              		 50%%	0	0	0	1	0	0
Fingerprinting      		 59%%	12	0	0	17	14	0
Gathering           		 49%%	10	0	0	18	227	0
Geography           		 49%%	19	1	3	26	365	0
Grids               		 43%%	40	5	6	1890	80	2
Manners             		 50%%	0	0	0	1	0	0
Micro               		 70%%	138	4	7	846	1658	3
Planning            		 31%%	76	4	10	55	927	4
Squads              		 62%%	25	4	12	23	88	0
Visualizations      		 100%%	0	0	0	2	47	0
27902 | 19:22 | DEBUG | Cutoff: 	55ms
Task	Last run	 Run %	Seconds	Avg ms	Max (Recent)	Max (All time)	Extended	Disqualifying
Accounting          		 56%%	1	0	1	6	2	0
Architecture        	XXXXXXXXXX	 38%%	16	61	226	226	84	9
Battles             		 45%%	107	11	18	50	143	0
Camera              		 50%%	0	0	0	1	0	0
Fingerprinting      		 59%%	12	0	0	17	14	0
Gathering           		 49%%	10	0	0	18	227	0
Geography           		 49%%	19	1	3	26	365	0
Grids               		 43%%	40	5	6	1890	80	2
Manners             		 50%%	0	0	0	1	0	0
Micro               		 70%%	138	4	7	846	1658	3
Planning            		 31%%	76	4	10	55	927	4
Squads              		 62%%	25	4	12	23	88	0
Visualizations      		 100%%	0	0	0	2	47	0
27902 | 19:22 | DEBUG | Game duration (fastest):    19m 22s
27902 | 19:22 | DEBUG | Game duration (wall clock): 11m 5s
27902 | 19:22 | DEBUG | 
Bot frames over 55ms: 20
Bot frames over 1000ms: 2
Bot frames over 10000ms: 1
27902 | 19:22 | DEBUG | The bot believes its performance, if running synchronously, would be good
27902 | 19:22 | DEBUG | Performance metrics:
Frame duration: After receiving 'frame ready' -> before sending 'frame done':
27,902 samples averaging 20.4 [5.4 - 1,449.4]
>= 5: 27902 samples averaging 20.4
>= 10: 27750 samples averaging 20.5
>= 15: 25208 samples averaging 21.2
>= 20: 16689 samples averaging 23
>= 25: 2317 samples averaging 30
>= 30: 640 samples averaging 38.3
>= 35: 197 samples averaging 52.6
>= 40: 80 samples averaging 74.9
>= 45: 11 samples averaging 277.3
>= 50: 4 samples averaging 683
>= 55: 4 samples averaging 683
>= 85: 4 samples averaging 683
Frame duration: After receiving 'frame ready' -> after sending 'frame done':
27,902 samples averaging 20.6 [5.4 - 1,451.3]
>= 5: 27902 samples averaging 20.6
>= 10: 27762 samples averaging 20.6
>= 15: 25289 samples averaging 21.3
>= 20: 16947 samples averaging 23.1
>= 25: 2458 samples averaging 30.1
>= 30: 674 samples averaging 38.6
>= 35: 221 samples averaging 51.8
>= 40: 102 samples averaging 68.9
>= 45: 34 samples averaging 122
>= 50: 6 samples averaging 473.7
>= 55: 4 samples averaging 685.1
>= 85: 4 samples averaging 685.1
Frame duration: After receiving 'frame ready' -> after sending 'frame done' (Using GetTickCount()):
27,902 samples averaging 20.5 [0 - 1,453]
>= 5: 27451 samples averaging 20.8
>= 10: 27451 samples averaging 20.8
>= 15: 27451 samples averaging 20.8
>= 20: 8744 samples averaging 31.9
>= 25: 8744 samples averaging 31.9
>= 30: 8744 samples averaging 31.9
>= 35: 184 samples averaging 60.9
>= 40: 184 samples averaging 60.9
>= 45: 184 samples averaging 60.9
>= 50: 5 samples averaging 562.6
>= 55: 5 samples averaging 562.6
>= 85: 4 samples averaging 687.5
Frame duration: After receiving 'frame ready' -> receiving next 'frame ready':
27,902 samples averaging 23.3 [7.2 - 1,451.4]
>= 5: 27902 samples averaging 23.3
>= 10: 27860 samples averaging 23.3
>= 15: 26981 samples averaging 23.6
>= 20: 21732 samples averaging 25
>= 25: 8248 samples averaging 28.5
>= 30: 1601 samples averaging 35.9
>= 35: 480 samples averaging 44.9
>= 40: 175 samples averaging 58.7
>= 45: 70 samples averaging 83.8
>= 50: 9 samples averaging 333.5
>= 55: 5 samples averaging 559.7
>= 85: 4 samples averaging 685.8
Frame duration: After receiving 'frame ready' -> receiving next 'frame ready' (Using GetTickCount()):
27,902 samples averaging 23.3 [0 - 1,453]
>= 5: 27772 samples averaging 23.4
>= 10: 27772 samples averaging 23.4
>= 15: 27772 samples averaging 23.4
>= 20: 13278 samples averaging 31.9
>= 25: 13278 samples averaging 31.9
>= 30: 13278 samples averaging 31.9
>= 35: 361 samples averaging 54
>= 40: 361 samples averaging 54
>= 45: 361 samples averaging 54
>= 50: 5 samples averaging 562.6
>= 55: 5 samples averaging 562.6
>= 85: 4 samples averaging 687.5
BWAPI duration: Before sending 'frame done' -> After receiving 'frame ready':
27,902 samples averaging 2.8 [0.1 - 20]
>= 1: 27901 samples averaging 2.8
>= 3: 8454 samples averaging 4
>= 5: 954 samples averaging 6.8
>= 10: 77 samples averaging 13.4
>= 15: 19 samples averaging 17
BWAPI duration: Before sending 'frame done' -> After sending 'frame done':
27,902 samples averaging 0.1 [0 - 8]
>= 1: 479 samples averaging 2.5
>= 3: 111 samples averaging 3.8
>= 5: 10 samples averaging 6.5
BWAPI duration: Before listening for 'frame ready' -> After receiving 'frame ready':
27,902 samples averaging 2.7 [0 - 19.9]
>= 1: 27486 samples averaging 2.7
>= 3: 7654 samples averaging 4
>= 5: 863 samples averaging 6.9
>= 10: 69 samples averaging 13.4
>= 15: 18 samples averaging 17.1
Copying frame to buffer:
27,902 samples averaging 1.9 [0.9 - 277.2]
>= 5: 211 samples averaging 11.1
>= 10: 84 samples averaging 17.5
>= 15: 31 samples averaging 26
>= 20: 7 samples averaging 58.2
>= 25: 1 samples averaging 277.2
>= 30: 1 samples averaging 277.2
Time holding frame until buffer frees capacity:
1 samples averaging 1,447.6 [1,447.6 - 1,447.6]
>= 0: 1 samples averaging 1,447.6
Frames already buffered when enqueuing a new frame:
27,903 samples averaging 0 [0 - 9]
>= 0: 27903 samples averaging 0
>= 1: 130 samples averaging 1.9
Frames behind real-time when handling events:
27,903 samples averaging 0 [0 - 8]
>= 0: 27903 samples averaging 0
>= 1: 44 samples averaging 2.7
Time flushing side effects:
27,903 samples averaging 0 [0 - 11.8]
>= 1: 5 samples averaging 8.6
>= 3: 4 samples averaging 10.3
>= 5: 4 samples averaging 10.3
Duration of bot event handlers:
27,901 samples averaging 20 [1.1 - 1,904]
>= 5: 27857 samples averaging 20
>= 10: 27676 samples averaging 20.1
>= 15: 24745 samples averaging 20.9
>= 20: 15245 samples averaging 22.7
>= 25: 1567 samples averaging 32.1
>= 30: 416 samples averaging 46.9
>= 35: 165 samples averaging 69.5
>= 40: 80 samples averaging 103.9
>= 45: 43 samples averaging 156.7
>= 50: 27 samples averaging 221.3
>= 55: 19 samples averaging 292.3
>= 85: 14 samples averaging 375
Time bot spent idle:
27,903 samples averaging 3.2 [0 - 28.4]
Time client spent waiting for bot:
27,902 samples averaging 18.3 [0 - 824.7]
>= 30: 367 samples averaging 36.9
Excess duration of client sleep:
30,090 samples averaging 0.1 [0 - 796]
>= 1: 482 samples averaging 6.7
>= 5: 189 samples averaging 13.8
>= 10: 75 samples averaging 24.6
>= 15: 8 samples averaging 129.4
>= 20: 2 samples averaging 472
>= 25: 2 samples averaging 472
>= 30: 2 samples averaging 472
>= 35: 2 samples averaging 472
>= 40: 2 samples averaging 472
>= 45: 2 samples averaging 472
>= 50: 2 samples averaging 472
>= 55: 2 samples averaging 472
>= 85: 2 samples averaging 472
Positive timer discrepancy compared to BWAPI:
15,149 samples averaging 4.8 [1 - 24]
>= 1: 15149 samples averaging 4.8
>= 2: 13694 samples averaging 5.2
>= 3: 12123 samples averaging 5.6
>= 4: 10410 samples averaging 6
>= 5: 7916 samples averaging 6.6
>= 10: 793 samples averaging 11.7
>= 15: 35 samples averaging 16.2
>= 20: 4 samples averaging 22.2
Negative timer discrepancy compared to BWAPI:
11,355 samples averaging 7.5 [1 - 23]
>= 1: 11355 samples averaging 7.5
>= 2: 10162 samples averaging 8.2
>= 3: 9270 samples averaging 8.8
>= 4: 8602 samples averaging 9.3
>= 5: 8028 samples averaging 9.7
>= 10: 4518 samples averaging 11.3
>= 15: 200 samples averaging 15.3
>= 20: 3 samples averaging 21.3
Number of events received from BWAPI:
27,902 samples averaging 1.5 [0 - 114]
>= 1: 27238 samples averaging 1.5
>= 2: 3981 samples averaging 4.5
>= 3: 3757 samples averaging 4.6
>= 4: 1641 samples averaging 6.8
>= 5: 946 samples averaging 8.8
>= 6: 532 samples averaging 11.8
>= 8: 260 samples averaging 17.2
>= 10: 169 samples averaging 21.8
>= 15: 92 samples averaging 30.3
>= 20: 57 samples averaging 38.9
Number of events received from BWAPI, multiplied by the receive-to-sent duration of that frame:
27,902 samples averaging 30.9 [0 - 3,167.3]
>= 5: 27238 samples averaging 31.7
>= 10: 27105 samples averaging 31.8
>= 15: 24825 samples averaging 33.5
>= 20: 17482 samples averaging 40.1
>= 25: 5755 samples averaging 77.3
>= 30: 4437 samples averaging 92.3
>= 35: 4095 samples averaging 97.3
>= 40: 3943 samples averaging 99.6
>= 45: 3754 samples averaging 102.4
>= 50: 3592 samples averaging 104.9
>= 55: 3429 samples averaging 107.4
>= 85: 1445 samples averaging 162
Number of events received from BWAPI, multiplied by the receive-to-sent duration of that frame (Using GetTickCount()):
27,902 samples averaging 30.9 [0 - 3,534]
>= 5: 26792 samples averaging 32.1
>= 10: 26792 samples averaging 32.1
>= 15: 26792 samples averaging 32.1
>= 20: 10808 samples averaging 56.5
>= 25: 10808 samples averaging 56.5
>= 30: 10808 samples averaging 56.5
>= 35: 3945 samples averaging 100.5
>= 40: 3945 samples averaging 100.5
>= 45: 3945 samples averaging 100.5
>= 50: 2540 samples averaging 130.2
>= 55: 2540 samples averaging 130.2
>= 85: 1797 samples averaging 156.1