Profiling huge python script setups in BGE

What do you do when you have several thousand lines of code and around a hundred script files, and you want to know what is causing your game to run slowly?

In my case, it was quite easy. Instead of having lots of:

Always (every frame)->Python 

logic setups, I have lots of:

Always (first frame)->Python 

setups whereby on the first frame, it registers itself to a scheduler. The scheduler then provides a single point from which 99% of the games code is run.

The scheduler can be as simple as:


events = list()
def register(function, args=None):
    if args is None:
        args = list()
    events.append((function, args))

def run():
    for event in events:
        event[0](event[1])

or can be as complicated as you like (mine is ~150 lines, and supports registering functions to be run at arbitrary intervals etc. etc.)

If this is the way things are done, then profiling your entire game is as simple as using the cProfile module, and changing the scedhuler to include a profile object, and to run the functions inside the cProfile profiler, and then displaying them somehow.


import cProfile

events = list()
profiler = cProfile.Profile()

def register(function, args=None):
    if args is None:
        args = list()
    events.append((function, args))

def run_profiled():
    profiler.runcall(run)  # <-- This

def print_stats():
    profiler.print_stats(1)

def run():
    for event in events:
        event[0](event[1])

Note that the profiler is quite slow, so performance may not be as good while profiling.

Upon calling print_stats, you will get a result like:




         7331805 function calls in 13.289 seconds


   Ordered by: internal time


   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    19768    5.084    0.000    6.096    0.000 meshfx.py:54(update)
        2    3.413    1.706    3.413    1.706 {built-in method GameLogic.LibLoad}
  3716384    0.674    0.000    0.674    0.000 {method 'setXYZ' of 'KX_VertexProxy' objects}
    72179    0.438    0.000    0.438    0.000 {method 'rayCast' of 'KX_GameObject' objects}
     2478    0.244    0.000    0.275    0.000 camera.py:29(update)
     9884    0.234    0.000    0.430    0.000 engine.py:29(_update)
     5882    0.231    0.000    0.408    0.000 projectiles.py:46(ai)
    70832    0.208    0.000   13.030    0.000 scheduler.py:77(__call__)
   538160    0.183    0.000    0.183    0.000 {built-in method builtins.min}
    61878    0.176    0.000    0.254    0.000 tools.py:7(get_polar)
   512853    0.150    0.000    0.150    0.000 {built-in method builtins.max}
     3481    0.141    0.000   13.288    0.004 scheduler.py:24(update_noprofile)
    31800    0.116    0.000    0.313    0.000 medium.py:39(combine_vecs)
   113930    0.098    0.000    0.117    0.000 scheduler.py:101(time_until_next_run)
     9884    0.089    0.000    1.809    0.000 ai.py:65(_update)
     7950    0.080    0.000    1.532    0.000 medium.py:120(update)

Which tells you how long each function took to run.

I do a similar thing but I set a dictionary of base level functions:

loop_methods = {"base_update": self.base_update,
                "main_state_machine": self.main_state_machine}

And call them from a dedicated profiler function:

self.manager.profile("base_update")

The profiler then times the function and stores that info in a base level dictionary which can be printed. It’s probably not as efficient as cProfile, but it’s more flexible since I can include other info, for example number of particles, in the dictionary.

It’s interesting to see how other people structure their projects when they are written almost 100% in python as there’s no standardized way of doing it. Recently I’ve changed my own method by moving the game loop out of the base level and in to a “level” object which contains all the game objects and behavior for the current game area/level/scene. This allows me to store global game data at the base level, and quickly reload/destroy the level object without restarting the game (saving time on Blender specific overheads). Before I was using globalDict to store this stuff but it’s not advised to store custom python objects there so I was very limited to what global data I could use (it has to be converted before saving to hard drive, but it’s better than being restricted in what kind of data structures you can use for global data). I can also put things like the player_input handler and audio handler in the base level so they continue to work when the level is changed (good if you’ve got some background music playing).

“level” object which contains all the game objects and behavior for the current game area/level/scene. This allows me to store global game data at the base level, and quickly reload/destroy the level object without restarting the game

Yup, I just started doing this as well. In fact, my current project loads all assets before you open the menu (5-6 seconds) so that the time to get into a level is just the time to load the level geometry (around a second). Likewise I can switch the level without having to reload all the other assets! Took a while to figure out how to chase down all the objects that have been spawned and don’t necessarily have logic associated with them.

It’s interesting to see how other people structure their projects when they are written almost 100% in python as there’s no standardized way of doing it.

One of these days I’d like to get a whole bunch of the experienced BGE devs to share their tips on this in a proper discussion. I’m sure other people have come up with ingenious solutions to problems I have…