How to see cumulative time spent inside functions

[smason]

I've been using Scalene to improve some code and have successfully been able to improve overall performance by 2x. Specifically, Scalene pointed to one function being called a lot which I was able to refactor such that Numba was able to get more traction.

The issue is that now the function has disappeared from Scalene output as it's now native code. I was expecting that I'd see that time attributed to the calling Python code, but that doesn't seem to be the case.

Hence I'm wondering whether Scalene has a "cumulative mode" where sampling walks over stack frames and time gets added to callers.

[emeryberger]

Hi - first, great to hear you were able to use Scalene successfully. Second, Scalene definitely attributes time to the calling Python code, so perhaps Numba is doing something which is interfering with that attribution. A minimum working example would be great.

[smason]

Hi, sorry for delay, I've been trying to narrow it down and while doing this I realised I wasn't interpreting the CPU results correctly.

The code I was working on (~10k lines) was new to me and scalene quickly pointed me to the right place. I moved more of the code into numba which helped. I then spent a long time moving code around and trying to understand the resulting profiles.

The percentages reported didn't seem to be ending up where I was expecting, making me think some CPU time wasn't being accounted for correctly. While trying to understand what was going on I simplified the code to:

https://gist.github.com/smason/ec059af62ae207f3620519fb4bb003d0

The original code was fitting more complicated functions using iminuit and was using parallelization via multiprocessing due to the amount of data.

These experiments only showed me that accounting was being done correctly, and when looking at the original output I was just misinterpreting things.

I think it might help if the CPU numbers could be displayed in the table, along with some way of aggregating smaller lines together. For instance, in my real code there isn't any single place that dominates runtime but there are a few lines in functions that I'd want to group together (maybe with a context manager?) as they are getting reported individually and it's fiddly going through adding everything up (and they get scattered when sorting).

I think the current behavior of showing native and Python time in separate tooltips gets in the way; I needed lots of mouse moving to get the numbers so I can add them up. While writing this it occurred to me that it might also be worth displaying durations (i.e. in seconds) instead of percentages. Presumably this isn't something you record, but it seems somewhat easy to calculate by assuming samples are uniformly spaced.

It might also be worth printing the number of samples acquired somewhere along with how this will affect reported percentages, e.g. 100 samples could be off by ~10%, 1000 samples drops down to ~5%.