This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: Function calls missing from profiler output
Type: behavior Stage: needs patch
Components: Library (Lib) Versions: Python 3.10, Python 3.9
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: georg.brandl, hagen, r.david.murray, terry.reedy
Priority: normal Keywords:

Created on 2011-09-09 22:37 by hagen, last changed 2022-04-11 14:57 by admin.

Messages (5)
msg143813 - (view) Author: Hagen Fürstenau (hagen) Date: 2011-09-09 22:37
I noticed that some function calls don't get reported by profile/cProfile. For example, 'len' works fine, but calls to 'range' or functions in 'itertools' don't show up. Is this a known limitation?

I remember that there was a bug in profiling C-functions with keyword arguments (issue5330, fixed), but I don't have the time right now to investigate whether this is related.
msg144137 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2011-09-16 16:46
Thanks for the report, which I verified on 3.2.2, Win7. When reporting a bug, please give a minimal example of code showing the bug, and the buggy output. I presume you mean something like the following (slightly edited):

>>> profile.run('for i in range(10): len({})')
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 :0(exec)
       10    0.000    0.000    0.000    0.000 :0(len)
        1    0.016    0.016    0.016    0.016 :0(setprofile)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.016    0.016 profile:0(for i in range(10): len({}))
        0    0.000             0.000          profile:0(profiler)

>>> profile.run('for i in range(10): range(1)')
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 :0(exec)
        1    0.000    0.000    0.000    0.000 :0(setprofile)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 profile:0(for i in range(10): range(1))
        0    0.000             0.000          profile:0(profiler)

The one call to range(10) and in the second case, the 10 calls to range(1) are missing while in the first case, the 10 calls to len(()) are reported. This looks like a bug to me. As far as I know, len and range are equal status builtin functions. The only Limitations reported in the doc are about timing accuracy.

A minimal test for this would be to look for ":0(range)" in the output, to match the way ":0(len)" does now.
msg144139 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-09-16 16:57
I wonder if it has something to do with range returning a special type?  range and len are very different things under the hood.
msg144140 - (view) Author: Hagen Fürstenau (hagen) Date: 2011-09-16 17:01
It happens for other C functions as well, e.g. itertools.permutations:

>>> profile.run('itertools.permutations(range(10), 3)')
         4 function calls in 0.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 :0(exec)
        1    0.000    0.000    0.000    0.000 :0(setprofile)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 profile:0(itertools.permutations(range(10), 3))
        0    0.000             0.000          profile:0(profiler)
msg144144 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2011-09-16 18:02
Range and most of the itertools functions are exposed at the Python level as iterator classes. (But since C does not have classes, they must be C-level functions!) The int 'class' is also not profiled.

I think this is wrong behavior. Int and range used to be non-class functions, which means the output of profile must have once included them (in 2.7 for range). Classes *are* functions in the wider sense, as used in the title of the 'Builtin functions'. User callables can also switch implementations. A closure might be replaced by a class; a class might be replaced by a factory function.

One could argue that this is such a long time bug (probably) that it should be handled as a feature request. The docs are a bit vague as to what is profiled, except that 26.3.1. Introduction to the profilers
does refer to 'C-level functions'.

However, the more important issue, at present, is keeping profile and cProfile, which wraps lsprof, in sync.
History
Date User Action Args
2022-04-11 14:57:21adminsetgithub: 57162
2020-11-01 00:40:24iritkatrielsetversions: + Python 3.9, Python 3.10, - Python 3.2, Python 3.3
2011-09-16 18:02:24terry.reedysetnosy: + georg.brandl
messages: + msg144144
2011-09-16 17:01:47hagensetmessages: + msg144140
2011-09-16 16:57:40r.david.murraysetnosy: + r.david.murray
messages: + msg144139
2011-09-16 16:46:48terry.reedysetversions: + Python 3.3
nosy: + terry.reedy

messages: + msg144137

stage: needs patch
2011-09-09 22:37:21hagencreate