#748

On-CPU and Off-CPU time mismatch

Openpidtuneropened 1y ago

First of all, thank you for this amazing tool. I tried to find an existing issue matching this but could not find it.

Describe the bug

I have a C++ application that waits most of the time in a std::condition_variable, and every 15 seconds performs a short task:

std::mutex mMutex;
std::condition_variable mCV;
// ...
std::unique_lock<std::mutex> lockGuard(mMutex);
mCV.wait_for(lockGuard, std::chrono::milliseconds(15000), endCondition);
// ...
// some short task

I created a 10.5 seconds perf record as explained in the README:

perf record \
    -e cycles \                             # on-CPU profiling
    -e sched:sched_switch --switch-events \ # off-CPU profiling
    --sample-cpu \                          # track on which core code is executed
    -m 8M \                                 # reduce chance of event loss
    --aio -z \                              # reduce disk-I/O overhead and data size
    --call-graph dwarf \                    # we definitely want backtraces
    <your application>

Then loaded in latest continuous pre-release (although the same shows in earlier versions):

As it can be observed, the Time Line the cycles show where the "short task" activity happens, but the "on/off CPU time" ratio (76.3% / 23.7%) seems incorrect, as most of the time is spend waiting in the mCV.wait_for call.

Furthermore, in the Top Down pane, the off CPU column for the std::condition_variable::wait_for<?> symbol call shows 0%. I would expect this call to have the highest off-CPU percentage.

Is this a bug or am I interpreting the presented data incorrectly? Thank you for your help!

Version Info (please complete the following information):

Activity

2
milianw9mo ago

please attach a MWE to simplfy reproduction on my end. then I can have a look.

regarding the on vs off-cpu timing data. have you looked at the raw data with perf script --show-switch-events and checked the time delta we get from that compared to your expectations?

visually speaking I agree that it seems bogus to have more on-CPU time than off-CPU time.

milianw9mo ago

please attach a MWE to simplfy reproduction on my end. then I can have a look.

regarding the on vs off-cpu timing data. have you looked at the raw data with perf script --show-switch-events and checked the time delta we get from that compared to your expectations?

visually speaking I agree that it seems bogus to have more on-CPU time than off-CPU time.