Repository navigation
profile and cProfile do not report C functions called with keyword arguments #49580
Description
| BPO | 5330 |
|---|---|
| Nosy | @pitrou |
| Files |
Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.
Show more details
GitHub fields:
assignee = None
closed_at = <Date 2009-05-30.21:44:39.160>
created_at = <Date 2009-02-20.13:10:18.661>
labels = ['type-bug', 'library']
title = 'profile and cProfile do not report C functions called with keyword arguments'
updated_at = <Date 2009-05-30.21:44:39.158>
user = 'https://bugs.python.org/hagen'bugs.python.org fields:
activity = <Date 2009-05-30.21:44:39.158>
actor = 'pitrou'
assignee = 'nbastin'
closed = True
closed_date = <Date 2009-05-30.21:44:39.160>
closer = 'pitrou'
components = ['Library (Lib)']
creation = <Date 2009-02-20.13:10:18.661>
creator = 'hagen'
dependencies = []
files = ['13146', '14122']
hgrepos = []
issue_num = 5330
keywords = ['patch']
message_count = 4.0
messages = ['82530', '82566', '88580', '88583']
nosy_count = 3.0
nosy_names = ['nbastin', 'pitrou', 'hagen']
pr_nums = []
priority = 'critical'
resolution = 'fixed'
stage = 'patch review'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue5330'
versions = ['Python 2.6', 'Python 3.0', 'Python 3.1', 'Python 2.7']
Activity
hagen commentedon Feb 20, 2009
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 secondsOrdered 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 secondsOrdered 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.
hagen commentedon Feb 21, 2009
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
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.
pitrou commentedon May 30, 2009
Updated patch, with test.
pitrou commentedon May 30, 2009
Committed in r73064, r73065, r73066, r73067. Thanks!