Bug in nested profiling section outputs?

Using preCICE
,
1

I have been playing around with profiling in my application, and I ran into the following issue. Whenever I created nested profiling sections, the output looks like this:

N31:master_step
B31:594768
N32:run_my_step
B32:598006
E31:598006
E32:4035642
E31:4053910

This is wrong! As soon as the call to start the ‘run_my_step’ section is handled, it immediately writes the E31 line as well, which looks to be wrong. The actual end is called and written correctly later on. The precice-cli tool fails to merge these logs, complaining about improperly nested events. When I manually remove the first E31 line, it processes properly and the output looks okay.

Am I correct this is a bug? Has anyone else noticed this? This seems a very basic functionality and I haven’t seen any reports about it anywhere.

2

Hi @ErwinM,

I don’t know if this is already considered, but it is definitely good to have such feedback, especially since the profiling tools are rather new and so far mostly internally used.

I would suggest directly opening an issue: GitHub - precice/profiling: Python tools for processing preCICE profiling data

3

Hi,
I just had time to look into this.
Thanks for mentioning this! This is indeed a bug when nesting user defined profiling sections.

Technical reason is that vector destructs elements when increasing capacity from 1 to 2, which emits the E sections.
On godbolt

The fix is to change the type of _userEvents to std::deque.

I’ll open a PR and link it here.

4

I just merged the fix.

1 Like
5

This topic was automatically closed 3 days after the last reply. New replies are no longer allowed.