classification
Title: profile and cProfile do not report C functions called with keyword arguments
Type: behavior Stage: patch review
Components: Library (Lib) Versions: Python 3.0, Python 3.1, Python 2.7, Python 2.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: nbastin Nosy List: hagen, nbastin, pitrou
Priority: critical Keywords: patch

Created on 2009-02-20 13:10 by hagen, last changed 2009-05-30 21:44 by pitrou. This issue is now closed.

Files
File name Uploaded Description Edit
ceval.patch hagen, 2009-02-21 13:45
issue5330.patch pitrou, 2009-05-30 21:00
Messages (4)
msg82530 - (view) Author: Hagen F├╝rstenau (hagen) Date: 2009-02-20 13:10
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.
msg82566 - (view) Author: Hagen F├╝rstenau (hagen) Date: 2009-02-21 13:45
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.
msg88580 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2009-05-30 21:00
Updated patch, with test.
msg88583 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2009-05-30 21:44
Committed in r73064, r73065, r73066, r73067. Thanks!
History
Date User Action Args
2009-05-30 21:44:39pitrousetstatus: open -> closed
resolution: fixed
messages: + msg88583
2009-05-30 21:00:10pitrousetfiles: + issue5330.patch
nosy: + pitrou
messages: + msg88580

2009-04-15 10:28:17pitrousetstage: patch review
versions: + Python 3.1, Python 2.7
2009-04-05 17:36:02georg.brandlsetassignee: nbastin

nosy: + nbastin
2009-04-05 17:35:57georg.brandllinkissue1229680 superseder
2009-04-05 15:30:24georg.brandlsetpriority: critical
2009-02-21 13:45:50hagensetfiles: + ceval.patch
keywords: + patch
messages: + msg82566
2009-02-20 13:10:18hagencreate