Unexpected behavior with built-in iterators

[lozanodorian]

Probably a silly remark, but we couldn't explain this behavior with my team.

When we profile a loop with a built-in iterator, e.g.:

for _ in range(10 ** 7):
    pass

The result is:

Line #|      Hits|         Time| Time per hit|      %|Source code
------+----------+-------------+-------------+-------+-----------
     1|         0|            0|            0|  0.00%|for _ in range(10 ** 7):
     2|        20|            0|            0|  0.00%|    pass

i.e. that line 1 does not have any hit, while a pass has all the hits, which seems quite surprising. Do you know if this is normal?

[vpelletier]

I notice that no time is measured as spent on either line. This looks like pprofile is used in statistic mode and not in deterministic mode (pprofile --statistic).

The statistic mode works by spawning a thread besides what is being profiled. That thread periodically wakes up and captures the call stack of all other threads, and increments the hit counter of every cell in the call stack, so that hot-spots will accumulate more hits than the rest of the code. But the meaning of those hits is very different from the usual deterministic mode, where a hit is added every time a line is being executed (as far as sys.settrace can tell anyway).

Statistic mode makes more sense when profiling a large piece of code over a long time, as it allows reducing the profiling overhead (because the profiler has less work to do), at the expense of making the results a bit harder to read.