Performance tools

[matthiasdiener]

Overview of the current status of performance measurement tools used with mirgecom.

What we have

(Internal) 1. OpenCL kernel profiling via the builtin profiling

• Works well generally, very detailed (time, flops, memory accesses etc.), low overhead
• Does not match the kernel profile by nvprof
  • ~20% higher number of called kernels vs. nvprof
  • Possibly caused by empty kernels that get counted as OpenCL events but don't actually get executed

(Internal) 2. Performance logging via PR #96

• Only little additional performance info (currently: time step time, visualization time, logging time)
• Should add in the future: I/O time, communication time, initialization time, ...

(External) 3. Python profiling

• Currently using pyinstrument
  • $ pip install pyinstrument, then replace python with pyinstrument on command line: $ pyinstrument -m mpi4py examples/wave-eager-mpi.py
  • Easy to use, low overhead
  • Cons:
    • Not very flexible, only top-down view
    • Issues with sampling (see below)

(External) 4. Low-level profiling (VTune, perf, nvprof, ...)

• VTune/perf seem to be not too useful for the moment (see e.g. this perf output)
• nvprof works well and might be valuable for in-depth profiling of kernels in the future

What we don't have

The issues below make it difficult to get a comprehensive profile at the moment.

Issue 1: Matching OpenCL kernels to the Python code

• The current execution isn't fully eager; kernels are enqueued by Python but are executed asynchronously when the OpenCL runtime feels like it
• This makes it difficult to see which Python code caused which particular kernel execution, among other things
• Potential workaround: make it possible to run in "super-eager" (or fully synchronous) mode
  • When enqueuing a kernel, wait for its OpenCL event to finish
  • Easy to implement for Loopy kernels, (maybe) more difficult for the pyopencl array kernels
• Resolution: Ignore for now, as this is unlikely to change the performance characterization in a substantial way. Would be nice to have the possibility to run fully synchronous in the future.

Issue 2: Missing short(?) Python functions from profiling

• Pyinstrument missed rather obvious performance issues such as profiling: don't carry kwargs around #179; short (but frequent) Python code seems to miss from the profile, even when disabling all filtering
• A theory is that this is caused by Pyinstrument's sampling (1ms)
  • Could try to tinker with its sampling interval (there seems to be no API for it)
  • Pyinstrument might not be the best tool for our purpose, we could try (e.g.) cProfile
• Resolution: Use cProfile for now.

Issue 3: Low-level (non-kernel) performance

• As mentioned above, profiling on a level below Python (but above he kernels) isn't very useful at the moment, e.g. it is hard to find out what the OpenCL runtime is doing (apart from spending lots of time in pthreads), or to cross check the Python profiling results
• Resolution: Ignore for now.

Issue 4: Mismatch between OpenCL kernel profile and nvprof

• Pointed out above.
• Resolution: Ignore for now, as this is unlikely to change the performance characterization in a substantial way. Need to find the source of the mismatch.

Thoughts?

[inducer]

Did you try https://vmprof.readthedocs.io/en/latest/?

[inducer]

(I really didn't mean for this to be an "answer", but I can't figure out how to make it a "comment"...)

[matthiasdiener]

Hmm, it appears like a comment to me

[matthiasdiener]

vmprof doesn't work on ppc64le:

$ pip install vmprof
Collecting vmprof
  Downloading vmprof-0.4.15.tar.gz (289 kB)
     |████████████████████████████████| 289 kB 13.7 MB/s
    ERROR: Command errored out with exit status 1:
     command: /g/g91/diener3/Work/emirge/miniforge3/envs/dgfem/bin/python3.8 -c 'import sys, setuptools, tokenize; sys.argv[0] = '"'"'/tmp/pip-install-smcs_00o/vmprof_662369a44cd748889c169597a619de41/setup.py'"'"'; __file__='"'"'/tmp/pip-install-smcs_00o/vmprof_662369a44cd748889c169597a619de41/setup.py'"'"';f=getattr(tokenize, '"'"'open'"'"', open)(__file__);code=f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, __file__, '"'"'exec'"'"'))' egg_info --egg-base /tmp/pip-pip-egg-info-eobtcrzt
         cwd: /tmp/pip-install-smcs_00o/vmprof_662369a44cd748889c169597a619de41/
    Complete output (5 lines):
    Traceback (most recent call last):
      File "<string>", line 1, in <module>
      File "/tmp/pip-install-smcs_00o/vmprof_662369a44cd748889c169597a619de41/setup.py", line 65, in <module>
        raise NotImplementedError("unknown platform.machine(): %s" %
    NotImplementedError: unknown platform.machine(): ppc64le
    ----------------------------------------
ERROR: Command errored out with exit status 1: python setup.py egg_info Check the logs for full command output.

[inducer]

Did you ask on their issue tracker?

[MTCam]

(Internal) 2. Performance logging via PR #96

• Only little additional performance info (currently: time step time, visualization time, logging time)
• Should add in the future: I/O time, communication time, initialization time, ...

It would be very useful to be able to pick apart the operator performance. Currently it looks like all one blob "stepping" - from which it is sort of hard to extract useful info. Would like to see performance characteristics of (some of which you already mentioned):

• Flux routine
• EOS-specific calls
• Boundary processing
  • Internal boundaries
  • Partition boundaries

Actually we are currently facing a "performance situation" where having the boundary timings would be great, and would have been great to help us catch something earlier.

[MTCam]

Thanks, good point. Surely there will still be a way to ferret out the performance of the constituent pieces? Or is there not, and we shouldn't care?

I guess on second thought that lazy can re-arrange the "pieces" into rather unrecognizable constructs that do not have 1-1 correspondence to the Python-based constructs. So hrm... I am curious about how we do performance "debugging" in that paradigm.

[inducer]

Yes, that's exactly the thing. In the presence of fusion and other transforms, there's not necessarily a 1-to-1 correspondence that would let you attribute run time to bits of code. That doesn't mean nothing can be done. We can knock out bits of the operator and see how the runtime changes, at least.

[inducer]

But in-line measurement of different part does indeed become quite tricky. That said, "metadata can save us(tm)", potentially. We could conceivably add instrumentation that tells us a timing for all flops tagged a certain way.

[MTCam]

I have been employing the first strategy you mentioned for timing down inside the inviscid operator, and was feeling sort of bad about it. After reading your note, I feel less bad now.

What you say about using metadata to identify source constructs (or similar) for bits of the transformed codes sounds like a feasible solution. I'm having trouble envisioning the case where your proposed metadata strategy would not work to get us what we need. You said flops specifically, but is data movement fair game too?

[inducer]

Sure. Flops were just an example.