Implausible performance counter data in traces

[stefandesouza]

I'm trying to trace an OpenMP application on Mare Nostrum 5 - GPP. I'm using the Extrae 4.3.3 environment module to trace it. While doing so, I noticed the traces that use more than 1 OpenMP thread show computational bursts on the first thread of impossibly high IPCs(1000-10000). As a result, the performance metrics I get for Instruction scalability, Frequency scalability and IPC scalability are incorrect as follows:

Overview of the Speedup, IPC and Frequency:
-------------------------------------------------
                        |       1[1] |       2[2]
-------------------------------------------------
Elapsed time (sec)      |      81.48 |      47.03
Efficiency              |       1.00 |       0.87
Speedup                 |       1.00 |       1.73
Average IPC             |       1.96 |      15.64
Average frequency (GHz) |       2.85 |     308.13
-------------------------------------------------


======== Output File: Other Metrics ========
Speedup, IPC, Frequency, I/O and Flushing written to /home/stefan/Downloads/basicanalysis-0.3.9/other_metrics.csv

Overview of the Efficiency metrics:
===========================================================
                       Trace mode |     OpenMP |     OpenMP
          Processes [Trace Order] |       1[1] |       2[2]
===========================================================
Global efficiency                 |     99.70% |     86.37%
-- Parallel efficiency            |     99.70% |     78.46%
   -- Load balance                |    100.00% |     89.41%
   -- Communication efficiency    |     99.70% |     87.76%
      -- Serialization efficiency |  Non-Avail |  Non-Avail
      -- Transfer efficiency      |  Non-Avail |  Non-Avail
-- Computation scalability        |    100.00% |    110.08%
   -- IPC scalability             |    100.00% |    799.07%
   -- Instruction scalability     |    100.00% |      0.13%
   -- Frequency scalability       |    100.00% |  10802.30%
===========================================================

The parallel efficiency numbers as well as overall Computational Scalability seem to be correct, but of course the Frequency and IPC values are implausible.
This doesn't seem to occur when tracing a separate use case of the same application that uses a different call tree.
I've tried tracing with a few test cases that all seem to produce correct results. I think the issue might have to do with the OpenMP implementation in the code, but I'm not sure what to look out for. Moreover the basic analysis script was run for the whole trace with no cutting or filtering. I'm hoping this behaviour may have been observed before and a fix exists.

My extrae.xml configuration is as follows:

<?xml version='1.0'?>

<trace enabled="yes"
 home="@sub_PREFIXDIR@"
 initial-mode="detail"
 type="paraver"
>

  <openmp enabled="yes" ompt="no">
    <locks enabled="no" />
    <taskloop enabled="no" />
    <counters enabled="yes" />
  </openmp>

  <pthread enabled="no">
    <locks enabled="no" />
    <counters enabled="yes" />
  </pthread>

  <counters enabled="yes">
    <cpu enabled="yes" starting-set-distribution="1">
      <set enabled="yes" domain="all" changeat-time="0">
        PAPI_TOT_INS,PAPI_TOT_CYC,PAPI_L2_DCM
      </set>
      <set enabled="yes" domain="all" changeat-time="0">
        PAPI_TOT_INS,PAPI_TOT_CYC,PAPI_VEC_SP,PAPI_SR_INS,PAPI_LD_INS,PAPI_FP_INS
        <sampling enabled="no" period="1000000000">PAPI_TOT_CYC</sampling>
      </set>
    </cpu>

    <network enabled="no" />

    <resource-usage enabled="no" />

    <memory-usage enabled="no" />
  </counters>

  <callers enabled="no">
    <mpi enabled="no">1-3</mpi>
    <sampling enabled="yes">1-5</sampling>
    <dynamic-memory enabled="no">1-3</dynamic-memory>
    <input-output enabled="yes">1-3</input-output>
    <syscall enabled="yes">1-3</syscall>
  </callers>
  <storage enabled="no">
    <trace-prefix enabled="yes">TRACE</trace-prefix>
    <size enabled="no">5</size>
    <temporal-directory enabled="yes">/scratch</temporal-directory>
    <final-directory enabled="yes">/gpfs/scratch/bsc41/bsc41273</final-directory>
  </storage>

  <buffer enabled="yes">
    <size enabled="yes">5000000</size>
    <circular enabled="no" />
  </buffer>

  <trace-control enabled="yes">
    <file enabled="no" frequency="5M">/gpfs/scratch/bsc41/bsc41273/control</file>
    <global-ops enabled="no"></global-ops>
  </trace-control>

  <others enabled="yes">
    <minimum-time enabled="no">10M</minimum-time>
    <finalize-on-signal enabled="yes" 
      SIGUSR1="no" SIGUSR2="no" SIGINT="yes"
      SIGQUIT="yes" SIGTERM="yes" SIGXCPU="yes"
      SIGFPE="yes" SIGSEGV="yes" SIGABRT="yes"
    />
    <flush-sampling-buffer-at-instrumentation-point enabled="yes" />
  </others>

  <sampling enabled="no" type="virtual" period="50m" variability="10m" />

  <dynamic-memory enabled="no" />

  <input-output enabled="yes" internals="no"/>

  <syscall enabled="no" />
  <merge enabled="yes" 
    synchronization="default"
    tree-fan-out="16"
    max-memory="512"
    joint-states="yes"
    keep-mpits="yes"
    translate-addresses="yes"
    sort-addresses="yes"
    translate-data-addresses="yes"
    overwrite="yes"
  />

</trace>

I've attached both full traces here:
traces.tar.gz

Thank you in advance for your help.

[gllort]

Hi Stef, does the OpenMP implementation use nested parallel regions (i.e., parallel regions inside other parallel regions)? Also, can you confirm which tracing library you're loading (libomptrace.so?) and which compiler was used to build the application?

[stefandesouza]

Hi Germán, the implementation doesn't seem to use any sort of OpenMP nested parallleism and only flat parallel DO loops. I load the 'libomptrace.so' library while tracing. It is a Fortran OpenMP only code but I don't believe there's a separate 'libomptracef.so' library. Lastly I'm building with gcc/12.3.0.

Here are the shared library dependencies:

[hlrs776062@glogin1 H2O]$ ldd qdd_gfortran 
        linux-vdso.so.1 (0x00007ffccaca4000)
        /opt/.snoopy/lib/libsnoopy.so (0x00007fa786f66000)
        libmkl_gf_lp64.so.2 => /gpfs/apps/MN5/GPP/ONEAPI/2023.2.0/mkl/2023.2.0/lib/intel64/libmkl_gf_lp64.so.2 (0x00007fa785d95000)
        libmkl_gnu_thread.so.2 => /gpfs/apps/MN5/GPP/ONEAPI/2023.2.0/mkl/2023.2.0/lib/intel64/libmkl_gnu_thread.so.2 (0x00007fa784069000)
        libgomp.so.1 => /apps/GPP/GCC/12.3.0/lib64/libgomp.so.1 (0x00007fa784021000)
        libmkl_core.so.2 => /gpfs/apps/MN5/GPP/ONEAPI/2023.2.0/mkl/2023.2.0/lib/intel64/libmkl_core.so.2 (0x00007fa77fca9000)
        libgfortran.so.5 => /apps/GPP/GCC/12.3.0/lib64/libgfortran.so.5 (0x00007fa77f9e6000)
        libm.so.6 => /lib64/libm.so.6 (0x00007fa77f8fd000)
        libmvec.so.1 => /lib64/libmvec.so.1 (0x00007fa77f8cf000)
        libgcc_s.so.1 => /apps/GPP/GCC/12.3.0/lib64/libgcc_s.so.1 (0x00007fa77f8af000)
        libquadmath.so.0 => /apps/GPP/GCC/12.3.0/lib64/libquadmath.so.0 (0x00007fa77f868000)
        libc.so.6 => /lib64/libc.so.6 (0x00007fa77f65f000)
        libdl.so.2 => /lib64/libdl.so.2 (0x00007fa77f65a000)
        libpthread.so.0 => /lib64/libpthread.so.0 (0x00007fa77f653000)
        /lib64/ld-linux-x86-64.so.2 (0x00007fa786f77000) 

The application does call some MKL FFT routines, and MKL is linked with MKLFLAGS += -lmkl_gnu_thread -lgomp, which I hope isn't a problem and wouldn't cause some sort of nested parallelism. The other input use case I trace with no issues also performs these calls so I wouldn't pin the problem there anyway.

[gllort]

It’s possible that the nested OpenMP still occurs because MKL is built with OpenMP support. When your application spawns parallel regions, MKL may create an additional layer of internal parallelism. Since you’re compiling with GCC, could you try using the alternative tracing library libnewomptrace.so and see if that resolves the issue?

[stefandesouza]

Hmm...using 'libnewomptrace.so' seems to partially solve the issue. I don't see huge IPC values, but a few ones of >10, which seem to still be incorrect. What looks problematic now is that the Average frequency seems to be increasing as I increase thread count, to a value of 5.20Ghz at 8 threads. It appears that some bursts on the first thread have really high cycle counts. Traces using 8 or more threads are too big to attach to github.

Overview of the Speedup, IPC and Frequency:
---------------------------------------------------------------------------
                        |       1[1] |       2[2] |       4[3] |       8[4]
---------------------------------------------------------------------------
Elapsed time (sec)      |      90.31 |      52.77 |      35.33 |      29.96
Efficiency              |       1.00 |       0.86 |       0.64 |       0.38
Speedup                 |       1.00 |       1.71 |       2.56 |       3.01
Average IPC             |       2.77 |       2.41 |       1.92 |       1.31
Average frequency (GHz) |       2.87 |       3.31 |       4.03 |       5.20
---------------------------------------------------------------------------


======== Output File: Other Metrics ========
Speedup, IPC, Frequency, I/O and Flushing written to /home/stefan/Downloads/basicanalysis-0.3.9/other_metrics.csv

Overview of the Efficiency metrics:
=====================================================================================
                       Trace mode |     OpenMP |     OpenMP |     OpenMP |     OpenMP
          Processes [Trace Order] |       1[1] |       2[2] |       4[3] |       8[4]
=====================================================================================
Global efficiency                 |     94.02% |     80.46% |     60.08% |     35.43%
-- Parallel efficiency            |     94.02% |     81.02% |     63.91% |     45.37%
   -- Load balance                |    100.00% |     87.37% |     72.03% |     57.66%
   -- Communication efficiency    |     94.02% |     92.73% |     88.73% |     78.68%
      -- Serialization efficiency |  Non-Avail |  Non-Avail |  Non-Avail |  Non-Avail
      -- Transfer efficiency      |  Non-Avail |  Non-Avail |  Non-Avail |  Non-Avail
-- Computation scalability        |    100.00% |     99.31% |     94.01% |     78.09%
   -- IPC scalability             |    100.00% |     87.16% |     69.52% |     47.24%
   -- Instruction scalability     |    100.00% |     98.83% |     96.46% |     91.40%
   -- Frequency scalability       |    100.00% |    115.28% |    140.20% |    180.85%
=====================================================================================

Edit: Just tried linking MKL with the serial library and tracing with both 'libnewomptrace.so' and 'libomptrace.so' -> same issue as original post.

[gllort]

Could you share the application binary, the input data, and the execution script in a tar file through the temporal folder on MareNostrum 5 so we can reproduce the issue and investigate it?

[stefandesouza]

Thank you for being willing to take a further look. I hope it's alright for me to directly attach the testcase here.

testcase.tar.gz

[valentin-seitz]

I get the same weird frequencies on a hybrid OpenMP+MPI trace (28000(3500x8) processes, 112 tasks per node, 74.9GB, Detailed+MPI+OpenMP mode) as well on the basic analysis (0.3.9) available in Marenostrum 5.

The application is the "most boring" when it comes to hybrid parallelism and just does parallels without nested parallelism.

I ran like: modelfactors.py -d -tmd prv -ms 100000000000000 <mtrace>.prv and got the following output:

==DEBUG== Running in debug mode.
==DEBUG== Using /gpfs/apps/MN5/GPP/BSCTOOLS/basicanalysis/0.3.9/utils.py 0.3.9
==DEBUG== Using /apps/GPP/PYTHON/3.12.1/INTEL/bin/python3 3.12.1
==DEBUG== Using SciPy 1.13.0
==DEBUG== Using NumPy 1.26.0
==DEBUG== Using /apps/GPP/BSCTOOLS/dimemas/5.5.0/bin/Dimemas
==DEBUG== Using /apps/GPP/BSCTOOLS/wxparaver/latest/bin/paramedir

...

Overview of the Efficiency, Speedup, IPC and Frequency:
-------------------------------------------
                        |  28000(3500x8)[1]
-------------------------------------------
Elapsed time (sec)      |             58.88
Average IPC             |              4.41
Average frequency (GHz) |          40377.60
-------------------------------------------

Turns out for me, the most likely culprit is a very low granularity which leads to very very high bogus PAPI values emitted into the trace.

Control scale here is useful IPC and the statistic is time. We can see some bursts having a very high useful IPC value of up to 25000000. This of course raises the average value when computed with paramedir in the mode: Average Value.

This also applies for the Frequency:

Which for me results in a few bursts raising my average frequency to 8Ghzs for the few objects i selected.

@stefandesouza Maybe you can check if the same is happening to your trace?

[stefandesouza]

I see something similar. Here's a histogram of useful IPC correlated with burst duration for a trace with 112 threads. Most of the really high bogus values in the range of 1000-5000 seem to be from bursts between 300-1000µs. So quite granular, but not really in the region where I'd expect problems like this. Anyway, they seem to be primarily concentrated on the first thread and don't seem to occur in larger bursts of >3ms.

[valentin-seitz]

Anyway, they seem to be primarily concentrated on the first thread and don't seem to occur in larger bursts of >3ms.

For me its a very similar thing. What you see in my histograms above are basically 4 MPI processes with the 8 threads each. And those bogus values only seem to appear in the primary threads of each team.

Maybe to add: I ran the same exact executable also with DLB-TALP with ompt events and get reasonable average frequencies reported by it. TALP just accumulate the PAPI_TOT_INST and PAPI_TOT_CYC values in 64 bit integers and reads them at every ompt/MPI event. So granularity in PAPI is most likely not the culprit.

After talking with a colleague we suspect some internal representation overflow in either the merger or paraver to be the problem. It would make sense as the primary thread normally has a lot more instructions executed, so the overflow would happen there with a higher probability.

I will at some point take a closer look at the two possibilities and let you know when i find something interesting! ;)

[stefandesouza]

Cool! I'll try and see if I get reasonable results with TALP in the meantime:)

Edit: It seems that TALP has no support for pure OpenMP codes
Directly linking the LLVM runtime seems to give me correct counter values.

[gllort]

I was able to reproduce the issue and can confirm what you mentioned. During very small bursts, the frequency spikes to impossible values, especially on the main thread.

Regarding the overflow suspicion, I’ve noticed a type mismatch in a few places. While the delta between the previous counter measurement and the current one is calculated in the merger using "unsigned long long" types, the raw counter values stored in the files are represented as "long long". Although both are 64-bit integers, "long long" has a smaller positive range due to the sign bit. Could this be the source of the problem?

[valentin-seitz]

@gllort
After a bit more investigation, my example actually turned out to have some nested OpenMP parallelism.
But the runtime defaults should not do anything stupid and just execute it by using a serial team.
You can see the serial team activity quite clearly in here:

If i do a histogram of this timeline tho i get very weird results, as i would expect the non-initial threads to have zero timings, but they don't. Could be draw mode, but i don't expect any events in there anyway?

Here the exported CSV from the histogram:

	void arch::parallel_reduce_driver 	
THREAD 1.1.1	372193.36	
THREAD 1.1.2	9.05	
THREAD 1.1.3	9.01	
THREAD 1.1.4	9.22	
THREAD 1.1.5	9.09	
THREAD 1.1.6	8.88	
THREAD 1.1.7	9.07	
THREAD 1.1.8	9.41	
THREAD 1.2.1	269584.64	
THREAD 1.2.2	7.85	
THREAD 1.2.3	7.96	
THREAD 1.2.4	8.14	
THREAD 1.2.5	7.85	
THREAD 1.2.6	7.79	
THREAD 1.2.7	7.97	
THREAD 1.2.8	8.25	
THREAD 1.1139.1	299695.38	
THREAD 1.1139.2	7.94	
THREAD 1.1139.3	7.97	
THREAD 1.1139.4	8.10	
THREAD 1.1139.5	7.81	
THREAD 1.1139.6	7.84	
THREAD 1.1139.7	7.93	
THREAD 1.1139.8	8.21	
THREAD 1.3500.1	340075.33	
THREAD 1.3500.2	7.77	
THREAD 1.3500.3	7.86	
THREAD 1.3500.4	8.04	
THREAD 1.3500.5	7.77	
THREAD 1.3500.6	7.82	
THREAD 1.3500.7	7.98	
THREAD 1.3500.8	8.14	

Num. Cells	32.00	
Total	1281779.41	
Average	40055.61	
Maximum	372193.36	
Minimum	7.77	
StDev	106848.30	
Avg/Max	0.11	

Any idea if this is a paraver bug or an extrae problem?
If you have an idea let me know so i can open a bug report in the corresponding repository :)

---

Additionally, i could identify that especially in these regions we have unreasonable hardware counter values:

The red and pink values correspond to possible nested parallelism executions.
Looking at the counter value in the primary thread we can read a value of useful instructions to be: value 5,237,200,299,755 in a Duration: 103.86 us. That seems a bit too effiencient ;)

I don't know exactly who is to blame here, but maybe these insights help you debugging the situation :)

[gllort]

@valentin-seitz, regarding the histogram for values in the non-initial threads: does the Minimum shown in the Control window include the value 0? If so, that might explain why those threads are accumulating values, the zero may be counted inside the histogram range.

On the other topic: the strange counter values are a classic symptom of nested parallelism. Which tracing library are you using? If there is any chance of nesting, you should definitely use libnewomptrace.so (or the other variants that include "new" in the name). The older libraries do not support nested parallelism.

Without proper support, threads in nested levels write their trace data into the buffers of first-level threads that happen to have the same thread ID in their own level. This causes incorrect counter values, because the merger ends up mixing data from different threads when computing differences. The newer libraries avoid this issue.

Have you tried using the new libraries?