Python cProfile results: two numbers for ncalls

Question

I just recently began profiling a server application that I've been working on, trying to find out where some excess processor time is being spent and looking for ways to make things smoother.

Overall, I think I've got a good hang of using cProfile and pstats, but I don't understand how some of functions list two numbers in the ncalls column.

For example, in the below results, why are there two numbers listed for all the copy.deepcopy stuff?

         2892482 function calls (2476782 primitive calls) in 5.952 seconds     Ordered by: cumulative time     ncalls  tottime  percall  cumtime  percall filename:lineno(function)        27    0.015    0.001    5.229    0.194 /usr/local/lib/python2.7/twisted/internet/base.py:762(runUntilCurrent)         7    0.000    0.000    3.109    0.444 /usr/local/lib/python2.7/twisted/internet/task.py:201(__call__)         7    0.000    0.000    3.109    0.444 /usr/local/lib/python2.7/twisted/internet/defer.py:113(maybeDeferred)         5    0.000    0.000    2.885    0.577 defs/1sec.def:3690(onesec)         5    2.100    0.420    2.885    0.577 defs/1sec.def:87(loop)      1523    0.579    0.000    2.105    0.001 defs/cactions.def:2(cActions) 384463/1724    0.474    0.000    1.039    0.001 /usr/local/lib/python2.7/copy.py:145(deepcopy) 33208/1804    0.147    0.000    1.018    0.001 /usr/local/lib/python2.7/copy.py:226(_deepcopy_list) 17328/15780    0.105    0.000    0.959    0.000 /usr/local/lib/python2.7/copy.py:253(_deepcopy_dict) 

Answer 1

The smaller number is the number of 'primitive' or non-recursive calls. The larger number is the total number of invocations, including recursive calls. Since deepcopy is implemented recursively, it means that you called deepcopy directly 1724 times, but that it ended up calling itself ~383k times to copy sub-objects.