Profiling MotionBuilder Python Code, Including its C Modules
This is another post in my short quest to profile per-frame functions in Motion Builder. This script below uses hotshot, the built in python profiler, to profile not only a function I write, but built in MBuilder c++ modules (FBPlayerControl().StepForward()).
8 9 10 | #wrap motionbuilder c module functions you want to profile in python functions def stepForward(): lPlayerControl.StepForward() |
Above is a snippet of the script below. We are wrapping the StepForward() MBuilder call in a function called stepForward(). Hotshot can profile any python function, so we trick it by wrapping a function around the c module.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 | from pyfbsdk import * import hotshot import hotshot.stats import sys lPlayerControl = FBPlayerControl() #wrap motionbuilder c module functions you want to profile in python functions def stepForward(): lPlayerControl.StepForward() #this is our function that we want to profile def myFn(): FStart = int(lPlayerControl.ZoomWindowStart.GetFrame(True)) FStop = int(lPlayerControl.ZoomWindowStop.GetFrame(True)) FBPlayerControl().GotoStart() for frame in range(FStart,FStop): stepForward() #here we set up the hotshot profiler to create a profile file (binary) #by running our function (myFn) prof = hotshot.Profile("c:\\myFn.prof") prof.runcall(myFn) prof.close() #now we load the profile stats stats = hotshot.stats.load("c:\\myFn.prof") stats.strip_dirs() stats.sort_stats('time', 'calls') #and finally, we print the profile stats to the disk in a file 'myFn.log' saveout = sys.stdout fsock = open('c:\\myFn.log', 'w') sys.stdout = fsock stats.print_stats(20) sys.stdout = saveout fsock.close() |
This is what the file we generated (myFn.log) looks like:
1305 function calls in 15411.020 CPU seconds
Ordered by: internal time, call count
ncalls tottime percall cumtime percall filename:lineno(function)
1304 15398.358 11.809 15398.358 11.809 speedtest.py:9(stepForward)
1 12.662 12.662 15411.020 15411.020 speedtest.py:13(myFn)
0 0.000 0.000 profile:0(profiler) |
As you can see, FBPlayerControl().StepForward() is very resource intensive, and should rarely be used when crunching a lot of keyframe data. I hope this helps anyone in finding resource bottlenecks in large scripts, here’s an example of output from a larger script where I am trying to see how long scene.evaluate() and stepforward() are taking, and get rid of them by querying the keyframe data the way KxL showed before:
58745 function calls in 26273.622 CPU seconds
Ordered by: internal time, call count
ncalls tottime percall cumtime percall filename:lineno(function)
1304 14243.406 10.923 14243.406 10.923 stabtest.py:57(stepForward)
5217 8448.493 1.619 8448.493 1.619 stabtest.py:52(evalScene)
5216 1347.949 0.258 1347.949 0.258 stabtest.py:99(keyTransRot)
5223 1028.827 0.197 1028.827 0.197 stabtest.py:23(getPosition)
1 672.045 672.045 26273.394 26273.394 stabtest.py:62(stab)
1305 268.026 0.205 3963.387 3.037 stabtest.py:67(faceOrient)
5226 53.200 0.010 68.283 0.013 stabtest.py:16(vec3)
5220 40.443 0.008 40.443 0.008 euclid.py:485(__abs__)
2610 31.510 0.012 36.667 0.014 euclid.py:384(__sub__)
5220 30.552 0.006 70.996 0.014 euclid.py:497(normalize)
13058 30.549 0.002 30.549 0.002 euclid.py:285(__init__)
2610 27.759 0.011 32.958 0.013 euclid.py:519(cross)
3918 22.071 0.006 796.673 0.203 stabtest.py:34(avgPos)
1306 16.727 0.013 19.413 0.015 euclid.py:439(__div__)
1306 11.738 0.009 14.161 0.011 euclid.py:354(__add__)
1 0.228 0.228 26273.622 26273.622 stabtest.py:152(stabCall)
4 0.100 0.025 0.100 0.025 stabtest.py:20(fbv)
0 0.000 0.000 profile:0(profiler) |
As you can see above, most of the time is spent on scene evaluation and stepforward.