Win32 event loop appearing to be the program bottleneck

Question

I am making a game in Python with Pyglet. I have just finished the display part, and getting issues with speed. Like a good person, I profiled, and got the following: (uninteresting bits excluded; currently it just redraws the screen when I push an arrow key with random magenta and white)

    15085326 function calls (15085306 primitive calls) in 32.166 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   32.168   32.168 <string>:1(<module>)

   120139    0.499    0.000    0.686    0.000 allocation.py:132(alloc)
   120121    0.563    0.000    0.844    0.000 allocation.py:268(dealloc)

       99    0.743    0.008   20.531    0.207 engine.py:58(Update)

   237600    0.796    0.000   11.995    0.000 sprite.py:349(_set_texture)
   120121    0.677    0.000    9.062    0.000 sprite.py:365(_create_vertex_list)
   357721    1.487    0.000    3.478    0.000 sprite.py:377(_update_position)

   420767    0.786    0.000    2.054    0.000 vertexbuffer.py:421(get_region)
   715442    0.859    0.000    1.280    0.000 vertexbuffer.py:467(invalidate)


        1    9.674    9.674   32.168   32.168 win32.py:46(run)
      180    0.007    0.000    1.771    0.010 win32.py:83(_timer_func)


   237600    0.416    0.000   17.069    0.000 window.py:60(SetTile)
   237600    0.646    0.000    2.174    0.000 window.py:72(GetTileTexture)

Everything which took < 0.5 seconds for total time has been removed, pretty much. Mostly stuff that couldn't be a problem.

This is the result of me hitting the keyboard for half a minute. For the most part, I could get 2 or 3 changes of screen per second.. I would personally like as fast as I could hit the keyboard. Heck, my aim is a good 50-60fps.

The win32 run being 10 seconds not spent in subfunctions is what worries me. It could be idle time (even though there is a pyglet idle), but wouldn't that be spent drawing?

The part I thought was slow was actually fast; the window SetTile part. To deal with the tiles, I have a 2D list of sprites that represent them on screen and simply alter the images. I don't think that's an issue.

The other potential problem I saw was my Update - I have to iterate across ~2400 tiles each time it is called. However, it doesn't seem all that bad. Only 0.7 seconds for 90 keypresses.

I start to wonder if this is a sign that Python is too slow for my needs. Then again, it shouldn't be. It's not too much of a computationally heavy thing I'm doing.

tl;dr Is the win32 event loop in Python my bottleneck, and what does that mean? If not, where may I have lost speed?

Code available if needed. I assume it's Pywin32 used by pyglet.

Answer 1

REVISED Answer: I deleted the columns that are worthless information, such as self time, call count, and per-call time. Then I arranged them in descending order by cumtime, and discarded the small ones.

cumtime  filename:lineno(function)
 32.168  <string>:1(<module>)
 32.168  win32.py:46(run)
 20.531  engine.py:58(Update)
 17.069  window.py:60(SetTile)
 11.995  sprite.py:349(_set_texture)
  9.062  sprite.py:365(_create_vertex_list)

Cumtime means the total amount of time that particular routine was on the call stack. So naturally some high-level routines were on the stack for all 32 seconds. Others were on the stack a smaller fraction of the time. For example, _set_texture was active about 1/3 the time, while _create_vertex_list was also active about 1/3 of the time. That suggests vertices are being created a lot, rather than being re-used, so maybe you could save about 30% of time by not recreating them.

But that's just a guess. There is no need to guess.

What you need to know is the fraction of time statements (not just functions) in your code were active on the stack. You need to know that because if there is a performance problem, it is such a line of code.

Here's how the problem can be found if you have one.

The profiler seems based on gprof, and here are some comments about that.