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 :1() 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 :1() 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.
