homepage

A C function or method call without keyword arguments gets reported by
the profiler as expected (in the line with "{method 'sort' of 'list'
object}"):
>>> cProfile.run("[].sort()")
 4 function calls in 0.000 CPU seconds
 Ordered by: standard name
 ncalls tottime percall cumtime percall filename:lineno(function)
 1 0.000 0.000 0.000 0.000 <string>:1(<module>)
 1 0.000 0.000 0.000 0.000 {built-in method exec}
 1 0.000 0.000 0.000 0.000 {method 'disable' of
'_lsprof.Profiler' objects}
 1 0.000 0.000 0.000 0.000 {method 'sort' of 'list'
objects}
However, once a keyword argument is given, the relevant line is missing:
>>> cProfile.run("[].sort(reverse=True)")
 3 function calls in 0.000 CPU seconds
 Ordered by: standard name
 ncalls tottime percall cumtime percall filename:lineno(function)
 1 0.000 0.000 0.000 0.000 <string>:1(<module>)
 1 0.000 0.000 0.000 0.000 {built-in method exec}
 1 0.000 0.000 0.000 0.000 {method 'disable' of
'_lsprof.Profiler' objects}
This happens with profile and cProfile in 2.6 and 3.0.

I found the reason for this problem: C function calls with keyword
arguments follow a different path than those without keywords in the
function "call_function" of ceval.c. They end up being handled by
"do_call", but there the call is not wrapped by C_TRACE, so a profiler
function registered through sys.setprofile() doesn't see such calls.
The same problem occurs in "ext_do_call", which gets called in the
handling of the opcodes CALL_FUNCTION_VAR and CALL_FUNCTION_KW, causing
omission of a function call like
>>> [].sort(**{'reverse':True})
from the profiler report.
The attached patch solves the problem, but I don't know if it's the best
solution. Handling calls with keyword arguments at the beginning of
"call_function" seems to have bigger performance drawbacks though.

Updated patch, with test.

Committed in r73064, r73065, r73066, r73067. Thanks!