Comment 5 for bug 1648280

To verify the dtrace timings make sense I recorded some playing a single MP3 with --developer and compared them with this dtrace script:

HALC_IO*:::IOProc_Begin
/execname == "mixxx"/
{
  self->callback_tid = tid;
  self->callback_enter_ts = timestamp;
  self->callback_enter_vts = vtimestamp;
}

HALC_IO*:::IOProc_End
/execname == "mixxx" && self->callback_enter_ts/
{
  @[ustack(), "callback duration ns"] = quantize(timestamp - self->callback_enter_ts);
  @[ustack(), "callback on-cpu duration ns"] = quantize(vtimestamp - self->callback_enter_vts);
  self->callback_enter_ts = 0;
  self->callback_enter_vts = 0;
}

Debug [Main]: Stat("SoundDevicePortAudio::callbackProcessClkRef 1, Built-in Output_duration","count=47361,average=67407.8ns,min=16148ns,max=2.09314e+06ns,variance=1.57389e+09ns^2,stddev=39672.3ns")

I used Mixxx's experiment mode to measure 30 seconds of playing, not including Mixxx startup or shutdown (since that tends to trigger outliers).

  callback on-cpu duration ns
           value ------------- Distribution ------------- count
            8192 | 0
           16384 | 164
           32768 |@@@@@@@@@@@@@ 10218
           65536 |@@@@@@@@@@@@@@@@@@@@@ 16484
          131072 |@@@@@ 3755
          262144 | 71
          524288 | 0
         1048576 | 1
         2097152 | 0

  callback duration ns
           value ------------- Distribution ------------- count
            8192 | 0
           16384 | 43
           32768 |@@@@@@@@@ 6981
           65536 |@@@@@@@@@@@@@@@@@@ 13896
          131072 |@@@@@@@@@@@@ 9293
          262144 |@ 475
          524288 | 3
         1048576 | 1
         2097152 | 1
         4194304 | 0

The min and maxes line up pretty well, so I think I can trust these measurements. I think the difference in max values from the on-cpu vs. on-cpu+off-cpu duration indicates the thread is spending up to a millisecond blocked.