Count is incremented extra for timers that overlap calls to MicroProfileFlip

[EricRehmeyer]

Hello, I either found an issue where timers report numbers incorrectly, or I'm misunderstanding something. TL;DR - S.Frame[nTimerIndex].nCount seems wrong for timers that overlap a call to MicroProfileFlip()

--

I have a background thread doing work like this:

{
MicroProfileEnter(token);
StuffThatTakesOneSecond();
MicroProfileLeave();
}

The main thread is calling MicroProfileFlip(nullptr) at 60 FPS.

The main thread is also polling for activity on my token's name via a custom function like MicroProfileGetTime which also returns S.Frame[nTimerIndex].nCount so I know how often the code is called.

The problem I run into is that it looks like the StuffThatTakesOneSecond shows up 61 times in the log, for an average of 16.3 ms per call, while the truth is that it is only called one time, taking 1 second.

This appears to be due to line 3250 S.Frame[nTimerIndex].nCount += 1; https://github.com/jonasmr/microprofile/blob/master/microprofile.cpp#L3250 Every still-going timer's nCount is incremented when a flip happens, which is throwing off my numbers.

If I comment out that line, then I get the expected results when I poll for data - I get something like time=0.016f, count=0 for sixty frames in a row, then time=something, count=1. My total collected data tells me StuffThatTakesOneSecond ran for a second, and was called once.

This (maybe) bug also has the side-effect of skewing how often code seems to be run, based on how long that instrumented code takes. I found some code with an average time of 9 ms getting called 16,000 times. After optimization it took 2 ms, but was only called 8,000 times. The calling behavior never changed, and the truth was that the code was only running about 7,200 times both before and after the optimization.

--

Question 1 - Does this seem like a bug in MicroProfile, or does it seem like I'm misunderstanding something? Question 2 - If this is a bug, is line 3255 also unnecessary? pFrameGroupThread[nGroup].nCount += 1; https://github.com/jonasmr/microprofile/blob/master/microprofile.cpp#L3255 I couldn't figure out the right way to verify whether the HTML view is affected by this, but it seems like if one line should be removed, the other should be too.

Thanks in advance -Eric

[jonasmr]

Hi

I think the logic is it shows up as once in that frame because it was inside the entirety of that frame. Its a very valid point that the actual call counts is then off. Ideally we could have both.

I have to investigate if there is any fallout from changing this.