Figuring out where operators spend time

I am still in the process of figuring out where my program spends time. The concatenate operator (#169) eliminated the most obvious source of wasted cycles, and now I am left with a CPU profile that does not have one or few main culprits, but instead a hundred or so operators that each spend more CPU time than I would intuitively expect them to (given the small amount of data they process in the particular test case I am looking at).

For each of these operators I can use the logging framework to compute the duration of each activation (obviously I can also aggregate them e.g., in a histogram, but since right now I am looking at few dozens of activations of each operator, I don't really have a need for that yet).

For example I have a Join operator that gets activated 57 times and spends up to a few hundred microseconds in each activation, to a total of 1.25ms. This seems to be on the expensive side, because the two relations being joined contain <=1 and <=4 records respectively. So I am looking for a way to zoom in even more to figure out where the operator is spending time exactly: (1) how many changes to each relation does it handle on each invocation, and is the amount of work it does proportional to the number of changes? (2) how much time does it spend executing user-supplied functions vs in the DD framework? (3) what are the framework overheads for the operator?

I suppose I can get an answer to (2) by instrumenting my functions, but I don't see an API to do (1) and I have no idea how to go about (3).

As usual, any guidance will be sincerely appreciated!

Start by reviewing the logging framework and the Join operator's activation path, then compare them with the profiling questions in the issue. Determine whether the existing API can expose relation changes, user-function time, and framework overhead; the work is done when a concrete profiling approach or API is defined and its expected measurements are documented.