profiling: don't carry kwargs around

[matthiasdiener]

Fixes #177.
Approx. 10% -2% overhead vs. profiling with master branch.

[inducer]

LGTM, thanks for working on this. As to your comment regarding 10% overhead, what is the baseline? Does this represent an increase in overhead? If so, where's that coming from? I don't see any change that I would spontaneously blame for a cost increase.

[matthiasdiener]

LGTM, thanks for working on this. As to your comment regarding 10% overhead, what is the baseline? Does this represent an increase in overhead? If so, where's that coming from? I don't see any change that I would spontaneously blame for a cost increase.

The baseline is profiling without this PR, ie, 10% additional overhead compared to the normal profiling overhead. I believe this is due to calling _cache_kernel_stats() (which transforms kwargs into args_tuple) on every kernel call. I have not found a way around that (or to cache the args_tuple).

[matthiasdiener]

LGTM, thanks for working on this. As to your comment regarding 10% overhead, what is the baseline? Does this represent an increase in overhead? If so, where's that coming from? I don't see any change that I would spontaneously blame for a cost increase.

The baseline is profiling without this PR, ie, 10% additional overhead compared to the normal profiling overhead. I believe this is due to calling _cache_kernel_stats() (which transforms kwargs into args_tuple) on every kernel call. I have not found a way around that (or to cache the args_tuple).

As a side question: part of the overhead appears to come from the fact that hash(program) is quite slow - about 0.3 ms, two orders of magnitude slower than hash(program.name). Is this expected?

[inducer]

As a side question: part of the overhead appears to come from the fact that hash(program) is quite slow - about 0.3 ms, two orders of magnitude slower than hash(program.name). Is this expected?

It's expected that it is slow the first time it happens. (A hash of the whole program needs to be computed, after all. Every expression, every variable definition, the whole thing.) It should however not stay slow. But I think we can make it fast the second and following times: inducer/loopy#185

[matthiasdiener]

As a side question: part of the overhead appears to come from the fact that hash(program) is quite slow - about 0.3 ms, two orders of magnitude slower than hash(program.name). Is this expected?

It's expected that it is slow the first time it happens. (A hash of the whole program needs to be computed, after all. Every expression, every variable definition, the whole thing.) It should however not stay slow. But I think we can make it fast the second and following times: inducer/loopy#185

Nice, thanks! ;-)

[inducer]

inducer/loopy#185 is merged. Could you try again and report overhead?

[matthiasdiener]

I ran these a few times but still can not believe my lying eyes:

(Lassen/pocl/GPU; Vortex2D/450 elements/100 time steps)

Wall time in seconds	Loopy without inducer/loopy#185	Loopy with inducer/loopy#185
No profiling	57.0s	50.9s
Old profiling (current master)	85.9s	55.7s
New profiling (with #179)	95.6s	54.4s

[inducer]

Huh, nice. I'm glad we dug into the overhead a bit more. This looks good to merge then, especially given that it seems to have negative overhead now. :P