Don't count time spent in Python towards the player

[simonlindholm]

We're seeing a lot of time spent in Python (inefficient IO?) rather than in the player in our profiles. When I add a debug print in the python time measuring code to also count Python processor self time, I get measurements like the following:

...
[mars:red] Turn time: 24.86
[mars:red] times 89.0 51.9
[mars:blue] times 5.0 2.8
[mars:blue] Turn time: 1.265
[earth:red] times 3.4 2.4
[earth:red] Turn time: 0.948
[earth:blue] times 2.3 1.6
[earth:blue] Turn time: 0.777
[mars:red] Turn time: 23.979
[mars:red] times 74.2 46.9
[mars:blue] times 3.6 2.5
[mars:blue] Turn time: 1.821
[earth:red] times 4.9 2.0
[earth:red] Turn time: 1.242
[earth:blue] Turn time: 0.649
[earth:blue] times 3.3 2.8
[mars:red] Turn time: 14.271
[mars:red] times 47.3 31.5
EOF

where "Turn time" is the value we measure from clock() in our C++ code, the first value of "times" is what the Python code currently measures, and the second value of "times" is the difference in time.process_time() for the same block of code that Python measures (lines sometimes appear in the wrong order due to buffering). It's clear that most time is spent in Python, and that the first value minus the second is a much better approximation of the time used by the bot than the current one. I get similar values outside of docker, there typically with less time spent in Python I think (but it might also just have been different maps).

This will hopefully address timeouts due to large numbers of units in upcoming tournaments. Optimizing the Python code (I'm sort of suspecting the line-buffered IO??) is left as future work. :)

[joshuagruenstein]

Correct me if I'm wrong, but as data = self.get_next_message() is blocking, wouldn't this change just totally not count time spent by the player? If that is the case, part of the spirit of this PR could still be achieved by moving start_time to after sending the message to the player, not before.

[simonlindholm]

No, it doesn't -- self time doesn't count time spent in the kernel, waiting. It would count time spent in other threads, so if there are such this might be a bad idea. Moving start_time might help and is worth measuring, but I think get_next_message() might be just a much (or even more) of a problem.

[simonlindholm]

Yeah, if I introduce a mid_time_python, end_time_python - mid_time_python is typically like 100x greater than mid_time_python - start_time_python :)

Gotta be the line buffering that's the problem.

[joshuagruenstein]

Cool, looks good. Just merged this. We'll look over #149 a lil more and do some testing before merging it.