We cannot explain the time step profile

[inducer]

Data gathered by @matthiasdiener

271,000 elements

7,500 elements

• Why is the invoker taking so long?
• Invoker time seems to be dependent on problem size. It should not be.
• Given that BoundPyOpenCLExecutor waits, what is behind the long wait in post_step?
• In the large-scale case, why does the last invoker take twice the time of the others?

Added April 29, 2025:

• t_step and t_2step disagree. Why?
• Large meshes have been observed to take more host time than small ones. Why?

cc @MTCam

[matthiasdiener]

Here is the full loopy invoker code for the 1-rank rhs of smoke_test_shock1d: https://gist.github.com/matthiasdiener/b50910994b638097c37c9162f2005982

Some highlights (lowlights?):

• ~24000 lines of Python code
• 2600 allocations for global temporaries

inducer/arraycontext#309 does not seem to have affected performance or the profile.

[inducer]

Possibly relevant:

• Replace _lpy_even_div with // in unchecked mode inducer/loopy#796
• Redundant checks for not-supplied offset parameters in invoker inducer/loopy#929
• Make a way to turn off possibly-expensive wait_for/event wrangling inducer/loopy#930
• Only allocate global temporaries for their live ranges in invoker inducer/loopy#931

[inducer]

Is the profiled run using _alias_global_temporaries? If so, I'm surprised that there are so many allocations still floating around.

[matthiasdiener]

Is the profiled run using _alias_global_temporaries? If so, I'm surprised that there are so many allocations still floating around.

Yes, it is using _alias_global_temporaries.

Another data point - running with -O does not seem to meaningfully improve the time step time.

[matthiasdiener]

A line-based profile of the whole invoker code is located here: https://gist.github.com/matthiasdiener/ddc4e3c88382854cc65e8d720b5d3f57

Something that stands out is this code in _lpy_host_unfiltered_rhs_part_0:

for _tv in _global_temporaries:
    if _tv is not None: _tv.release()

[inducer]

I think the profile link above is the same as the original source link? (I.e. I don't see a profile there.)

As for the tv.release() line, it makes sense that it sticks out, it should be the only one that's repeated a lot of times.

[matthiasdiener]

Oops, the correct link is https://gist.github.com/matthiasdiener/ddc4e3c88382854cc65e8d720b5d3f57 (also corrected above).

[inducer]

As for the tv.release() line, it makes sense that it sticks out, it should be the only one that's repeated a lot of times.

Each individual release should be relatively cheap: all it should be doing is return some memory to a memory pool. IIUC, this is vaguely consistent with the profile at first:

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   303       113      25370.0    224.5      4.1          if _tv is not None: _tv.release()

If I'm reading the profile right, it's 224ns per release, compared to ~200ns per trip of a for loop.

But then later on, the timings head way north:

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   346       243   29345771.0 120764.5     19.4          if _tv is not None: _tv.release()

I don't understand why.

[inducer]

Have we made progress on this?