audit syscalls made from the PortAudio callback

mixxxdj / mixxx

Mixxx is Free DJ software that gives you everything you need to perform live mixes.

http://mixxx.org

Other

4.51k stars 1.28k forks source link

audit syscalls made from the PortAudio callback #8719

Open mixxxbot opened 2 years ago

mixxxbot commented 2 years ago

Reported by: rryan Date: 2016-12-08T01:51:02Z Status: Confirmed Importance: Undecided Launchpad Issue: lp1648280 Tags: engine, performance

I've been examining the syscalls Mixxx makes from the PortAudio thread with dtrace to try and measure their cost. We should minimize the syscalls we do in a realtime context to avoid blocking the engine thread.

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T01:56:25Z

gettimeofday appears to take about 8 microseconds on average. The "ts" here is a walltime nanosecond counter (though I think the precision is microseconds, not nanos since the last 3 numbers are always zero).

Notably, I'm not broadcasting at all and EngineNetworkStream is still doing this work.

0 383 gettimeofday:return (tid 1488971) ts:1481161656405619000 gettimeofday libsystem_kernel.dylib__gettimeofday+0xa mixxxEngineNetworkStream::getWriteExpected()+0x17 mixxxSoundDeviceNetwork::writeProcess()+0xd4 mixxxSoundManager::writeProcess()+0xb9 mixxxSoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x751 mixxx(anonymous namespace)::paV19CallbackClkRef(void const, void, unsigned long, PaStreamCallbackTimeInfo const, unsigned long, void)+0x23 libportaudio.2.dylibAdaptingOutputOnlyProcess+0xe7 libportaudio.2.dylibPaUtil_EndBufferProcessing+0x1c4 libportaudio.2.dylibAudioIOProc+0x392 CoreAudioAUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5 CoreAudioAUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a CoreAudioAUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8 CoreAudioAUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2 CoreAudioHALC_ProxyIOContext::IOWorkLoop()+0x9e7 CoreAudioHALC_ProxyIOContext::IOThreadEntry(void*)+0x58 CoreAudioHALB_IOThread::Entry(void*)+0x4b libsystem_pthread.dylib_pthread_body+0x83 libsystem_pthread.dylib_pthread_body libsystem_pthread.dylib`thread_start+0xd

0 382 gettimeofday:entry (tid 1488971) ts:1481161656407042000 gettimeofday libsystem_kernel.dylib__gettimeofday+0xa mixxxEngineNetworkStream::getWriteExpected()+0x17 mixxxSoundDeviceNetwork::writeProcess()+0xd4 mixxxSoundManager::writeProcess()+0xb9 mixxxSoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x751 mixxx(anonymous namespace)::paV19CallbackClkRef(void const, void, unsigned long, PaStreamCallbackTimeInfo const, unsigned long, void)+0x23 libportaudio.2.dylibAdaptingOutputOnlyProcess+0xe7 libportaudio.2.dylibPaUtil_EndBufferProcessing+0x1c4 libportaudio.2.dylibAudioIOProc+0x392 CoreAudioAUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5 CoreAudioAUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a CoreAudioAUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8 CoreAudioAUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2 CoreAudioHALC_ProxyIOContext::IOWorkLoop()+0x9e7 CoreAudioHALC_ProxyIOContext::IOThreadEntry(void*)+0x58 CoreAudioHALB_IOThread::Entry(void*)+0x4b libsystem_pthread.dylib_pthread_body+0x83 libsystem_pthread.dylib_pthread_body libsystem_pthread.dylib`thread_start+0xd

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T01:58:10Z

EngineSideChain::wakeAll -- 14 microseconds (from one sample)

0 756 psynch_cvbroad:entry (tid 1488971) ts:1481161657003383000 psynch_cvbroad libsystem_kernel.dylib__psynch_cvbroad+0xa QtCoreQWaitCondition::wakeAll()+0x3c mixxxEngineSideChain::writeSamples(float const*, int)+0x109 mixxxEngineMaster::process(int)+0xaca mixxxSoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x661 mixxx(anonymous namespace)::paV19CallbackClkRef(void const, void, unsigned long, PaStreamCallbackTimeInfo const, unsigned long, void)+0x23 libportaudio.2.dylibAdaptingOutputOnlyProcess+0xe7 libportaudio.2.dylibPaUtil_EndBufferProcessing+0x1c4 libportaudio.2.dylibAudioIOProc+0x392 CoreAudioAUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5 CoreAudioAUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a CoreAudioAUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8 CoreAudioAUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2 CoreAudioHALC_ProxyIOContext::IOWorkLoop()+0x9e7 CoreAudioHALC_ProxyIOContext::IOThreadEntry(void*)+0x58 CoreAudioHALB_IOThread::Entry(void*)+0x4b libsystem_pthread.dylib_pthread_body+0x83 libsystem_pthread.dylib_pthread_body libsystem_pthread.dylib`thread_start+0xd

0 757 psynch_cvbroad:return (tid 1488971) ts:1481161657003397000 psynch_cvbroad libsystem_kernel.dylib__psynch_cvbroad+0xa QtCoreQWaitCondition::wakeAll()+0x3c mixxxEngineSideChain::writeSamples(float const*, int)+0x109 mixxxEngineMaster::process(int)+0xaca mixxxSoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x661 mixxx(anonymous namespace)::paV19CallbackClkRef(void const, void, unsigned long, PaStreamCallbackTimeInfo const, unsigned long, void)+0x23 libportaudio.2.dylibAdaptingOutputOnlyProcess+0xe7 libportaudio.2.dylibPaUtil_EndBufferProcessing+0x1c4 libportaudio.2.dylibAudioIOProc+0x392 CoreAudioAUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5 CoreAudioAUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a CoreAudioAUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8 CoreAudioAUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2 CoreAudioHALC_ProxyIOContext::IOWorkLoop()+0x9e7 CoreAudioHALC_ProxyIOContext::IOThreadEntry(void*)+0x58 CoreAudioHALB_IOThread::Entry(void*)+0x4b libsystem_pthread.dylib_pthread_body+0x83 libsystem_pthread.dylib_pthread_body libsystem_pthread.dylib`thread_start+0xd

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T01:58:54Z

I need to update my dtrace scripts to measure the distributions of times rather than eyeballing it. For now, consider every timestamp I give to be a sample size of 1 :).

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T02:00:47Z

Setting controls for queued connections -- 12 microseconds

0 752 psynch_mutexwait:entry (tid 1488971) ts:1481161658531164000 psynch_mutexwait libsystem_kernel.dylib__psynch_mutexwait+0xa libsystem_pthread.dylib_pthread_mutex_lock_slow+0x12c CoreFoundationCFRunLoopWakeUp+0x4b QtGuiQEventDispatcherMac::wakeUp()+0x30 QtCoreQCoreApplication::postEvent(QObject*, QEvent*, int)+0x12f QtCoreQMetaObject::activate(QObject, QMetaObject const, int, void*)+0x55a mixxx`ControlDoublePrivate::valueChanged(double, QObject)+0x4a mixxxControlDoublePrivate::set(double, QObject*)+0x8e mixxxSoundDevicePortAudio::callbackProcessClkRef(unsigned int, float, float const, PaStreamCallbackTimeInfo const, unsigned long)+0x7a9 mixxx`(anonymous namespace)::paV19CallbackClkRef(void const, void, unsigned long, PaStreamCallbackTimeInfo const, unsigned long, void)+0x23 libportaudio.2.dylibAdaptingOutputOnlyProcess+0xe7 libportaudio.2.dylibPaUtil_EndBufferProcessing+0x1c4 libportaudio.2.dylibAudioIOProc+0x392 CoreAudioAUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5 CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement, unsigned int, AudioBufferList&)+0x9a CoreAudioAUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8 CoreAudioAUHAL::AUIOProc(unsigned int, AudioTimeStamp const, AudioBufferList const, AudioTimeStamp const, AudioBufferList, AudioTimeStamp const, void)+0x6f2 CoreAudioHALC_ProxyIOContext::IOWorkLoop()+0x9e7 CoreAudioHALC_ProxyIOContext::IOThreadEntry(void)+0x58 CoreAudio`HALB_IOThread::Entry(void)+0x4b libsystem_pthread.dylib_pthread_body+0x83 libsystem_pthread.dylib_pthread_body libsystem_pthread.dylib`thread_start+0xd

0 753 psynch_mutexwait:return (tid 1488971) ts:1481161658531176000 psynch_mutexwait libsystem_kernel.dylib__psynch_mutexwait+0xa libsystem_pthread.dylib_pthread_mutex_lock_slow+0x12c CoreFoundationCFRunLoopWakeUp+0x4b QtGuiQEventDispatcherMac::wakeUp()+0x30 QtCoreQCoreApplication::postEvent(QObject*, QEvent*, int)+0x12f QtCoreQMetaObject::activate(QObject, QMetaObject const, int, void*)+0x55a mixxx`ControlDoublePrivate::valueChanged(double, QObject)+0x4a mixxxControlDoublePrivate::set(double, QObject*)+0x8e mixxxSoundDevicePortAudio::callbackProcessClkRef(unsigned int, float, float const, PaStreamCallbackTimeInfo const, unsigned long)+0x7a9 mixxx`(anonymous namespace)::paV19CallbackClkRef(void const, void, unsigned long, PaStreamCallbackTimeInfo const, unsigned long, void)+0x23 libportaudio.2.dylibAdaptingOutputOnlyProcess+0xe7 libportaudio.2.dylibPaUtil_EndBufferProcessing+0x1c4 libportaudio.2.dylibAudioIOProc+0x392 CoreAudioAUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5 CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement, unsigned int, AudioBufferList&)+0x9a CoreAudioAUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8 CoreAudioAUHAL::AUIOProc(unsigned int, AudioTimeStamp const, AudioBufferList const, AudioTimeStamp const, AudioBufferList, AudioTimeStamp const, void)+0x6f2 CoreAudioHALC_ProxyIOContext::IOWorkLoop()+0x9e7 CoreAudioHALC_ProxyIOContext::IOThreadEntry(void)+0x58 CoreAudio`HALB_IOThread::Entry(void)+0x4b libsystem_pthread.dylib_pthread_body+0x83 libsystem_pthread.dylib_pthread_body libsystem_pthread.dylib`thread_start+0xd

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:14:13Z

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.

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:16:39Z

Here's a syscall from Stat::track:

              libsystem_kernel.dylib`__psynch_cvbroad+0xa
              QtCore`QWaitCondition::wakeAll()+0x3c
              mixxx`StatsManager::maybeWriteReport(StatReport const&)+0x53
              mixxx`Stat::track(QString const&, Stat::StatType, int, double)+0xae
              mixxx`Timer::elapsed(bool)+0x55
              mixxx`ChannelMixer::mixChannelsRamping(EngineMaster::GainCalculator const&, QVarLengthArray<EngineMaster::ChannelInfo*, 64>*, QVarLengthArray<EngineMaster::GainCache, 64>*, float*, unsigned int)+0xc0
              mixxx`EngineMaster::process(int)+0x1e2
              mixxx`SoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x661
              mixxx`(anonymous namespace)::paV19CallbackClkRef(void const*, void*, unsigned long, PaStreamCallbackTimeInfo const*, unsigned long, void*)+0x23
              libportaudio.2.dylib`AdaptingOutputOnlyProcess+0xe7
              libportaudio.2.dylib`PaUtil_EndBufferProcessing+0x1c4
              libportaudio.2.dylib`AudioIOProc+0x392
              CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5
              CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a
              CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8
              CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2
              CoreAudio`HALC_ProxyIOContext::IOWorkLoop()+0x9e7
              CoreAudio`HALC_ProxyIOContext::IOThreadEntry(void*)+0x58
              CoreAudio`HALB_IOThread::Entry(void*)+0x4b
              libsystem_pthread.dylib`_pthread_body+0x83
  syscall duration ns
           value  ------------- Distribution ------------- count
            4096 |                                         0
            8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
           16384 |                                         0

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:17:40Z

              libsystem_kernel.dylib`madvise+0xa
              librubberband.dylib`RubberBand::RingBuffer<float>::~RingBuffer()+0xf
              librubberband.dylib`RubberBand::RubberBandStretcher::Impl::ChannelData::~ChannelData()+0x62
              librubberband.dylib`RubberBand::RubberBandStretcher::Impl::~Impl()+0x162
              librubberband.dylib`RubberBand::RubberBandStretcher::~RubberBandStretcher()+0x17
              mixxx`EngineBufferScaleRubberBand::initRubberBand()+0x57
              mixxx`EngineBuffer::process(float*, int)+0xac
              mixxx`EngineDeck::process(float*, int)+0x123
              mixxx`EngineMaster::processChannels(int)+0x654
              mixxx`EngineMaster::process(int)+0x135
              mixxx`SoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x661
              mixxx`(anonymous namespace)::paV19CallbackClkRef(void const*, void*, unsigned long, PaStreamCallbackTimeInfo const*, unsigned long, void*)+0x23
              libportaudio.2.dylib`AdaptingOutputOnlyProcess+0xe7
              libportaudio.2.dylib`PaUtil_EndBufferProcessing+0x1c4
              libportaudio.2.dylib`AudioIOProc+0x392
              CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5
              CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a
              CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8
              CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2
              CoreAudio`HALC_ProxyIOContext::IOWorkLoop()+0x9e7
  syscall duration ns
           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |@@@@@@@@@@@@@@@@@@@@                     1
            8192 |@@@@@@@@@@@@@@@@@@@@                     1
           16384 |                                         0

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:20:06Z

Ouch, malloc. That's about as long as my average callback duration.

              libsystem_kernel.dylib`madvise+0xa
              libsystem_malloc.dylib`malloc_zone_malloc+0x47
              libsystem_malloc.dylib`malloc+0x2a
              libc++.1.dylib`operator new(unsigned long)+0x1e
              QtCore`QMetaObject::activate(QObject*, QMetaObject const*, int, void**)+0x4d1
              mixxx`ControlDoublePrivate::valueChanged(double, QObject*)+0x4a
              mixxx`ControlDoublePrivate::set(double, QObject*)+0x8e
              mixxx`EngineVuMeter::process(float*, int)+0x1e7
              mixxx`EngineMaster::process(int)+0xaeb
              mixxx`SoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x661
              mixxx`(anonymous namespace)::paV19CallbackClkRef(void const*, void*, unsigned long, PaStreamCallbackTimeInfo const*, unsigned long, void*)+0x23
              libportaudio.2.dylib`AdaptingOutputOnlyProcess+0xe7
              libportaudio.2.dylib`PaUtil_EndBufferProcessing+0x1c4
              libportaudio.2.dylib`AudioIOProc+0x392
              CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5
              CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a
              CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8
              CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2
              CoreAudio`HALC_ProxyIOContext::IOWorkLoop()+0x9e7
              CoreAudio`HALC_ProxyIOContext::IOThreadEntry(void*)+0x58
  syscall duration ns
           value  ------------- Distribution ------------- count
           32768 |                                         0
           65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
          131072 |                                         0

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:20:36Z

              libsystem_kernel.dylib`__psynch_mutexdrop+0xa
              CoreFoundation`CFRunLoopWakeUp+0xf0
              QtGui`QEventDispatcherMac::wakeUp()+0x30
              QtCore`QCoreApplication::postEvent(QObject*, QEvent*, int)+0x12f
              QtCore`QMetaObject::activate(QObject*, QMetaObject const*, int, void**)+0x55a
              mixxx`ControlDoublePrivate::valueChanged(double, QObject*)+0x4a
              mixxx`ControlDoublePrivate::set(double, QObject*)+0x8e
              mixxx`EngineBuffer::updateIndicators(double, int)+0x110
              mixxx`EngineMaster::processChannels(int)+0x6b3
              mixxx`EngineMaster::process(int)+0x135
              mixxx`SoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x661
              mixxx`(anonymous namespace)::paV19CallbackClkRef(void const*, void*, unsigned long, PaStreamCallbackTimeInfo const*, unsigned long, void*)+0x23
              libportaudio.2.dylib`AdaptingOutputOnlyProcess+0xe7
              libportaudio.2.dylib`PaUtil_EndBufferProcessing+0x1c4
              libportaudio.2.dylib`AudioIOProc+0x392
              CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5
              CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a
              CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8
              CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2
              CoreAudio`HALC_ProxyIOContext::IOWorkLoop()+0x9e7
  syscall duration ns
           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     16
            8192 |@@@@                                     2
           16384 |                                         0

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:20:56Z

              libsystem_kernel.dylib`__psynch_mutexdrop+0xa
              QtCore`QWaitCondition::wakeAll()+0x55
              mixxx`EngineSideChain::writeSamples(float const*, int)+0x109
              mixxx`EngineMaster::process(int)+0xaca
              mixxx`SoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x661
              mixxx`(anonymous namespace)::paV19CallbackClkRef(void const*, void*, unsigned long, PaStreamCallbackTimeInfo const*, unsigned long, void*)+0x23
              libportaudio.2.dylib`AdaptingOutputOnlyProcess+0xe7
              libportaudio.2.dylib`PaUtil_EndBufferProcessing+0x1c4
              libportaudio.2.dylib`AudioIOProc+0x392
              CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5
              CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a
              CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8
              CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2
              CoreAudio`HALC_ProxyIOContext::IOWorkLoop()+0x9e7
              CoreAudio`HALC_ProxyIOContext::IOThreadEntry(void*)+0x58
              CoreAudio`HALB_IOThread::Entry(void*)+0x4b
              libsystem_pthread.dylib`_pthread_body+0x83
              libsystem_pthread.dylib`_pthread_body
              libsystem_pthread.dylib`thread_start+0xd
  syscall duration ns
           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |@@@@@@@@@@@@@                            4
            8192 |@@@@@@@@@@@@@@@@@@@@@@@                  7
           16384 |@@@                                      1
           32768 |                                         0

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:21:28Z

              libsystem_kernel.dylib`madvise+0xa
              mixxx`QHash<int, CachingReaderChunkForOwner*>::remove(int const&)+0x152
              mixxx`CachingReader::freeChunk(CachingReaderChunkForOwner*)+0x75
              mixxx`CachingReader::allocateChunkExpireLRU(long)+0x33
              mixxx`CachingReader::hintAndMaybeWake(QVarLengthArray<Hint, 512> const&)+0x33b
              mixxx`EngineBuffer::hintReader(double)+0x1a0
              mixxx`EngineBuffer::process(float*, int)+0xa88
              mixxx`EngineDeck::process(float*, int)+0x123
              mixxx`EngineMaster::processChannels(int)+0x654
              mixxx`EngineMaster::process(int)+0x135
              mixxx`SoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x661
              mixxx`(anonymous namespace)::paV19CallbackClkRef(void const*, void*, unsigned long, PaStreamCallbackTimeInfo const*, unsigned long, void*)+0x23
              libportaudio.2.dylib`AdaptingOutputOnlyProcess+0xe7
              libportaudio.2.dylib`PaUtil_EndBufferProcessing+0x1c4
              libportaudio.2.dylib`AudioIOProc+0x392
              CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5
              CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a
              CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8
              CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2
              CoreAudio`HALC_ProxyIOContext::IOWorkLoop()+0x9e7
  syscall duration ns
           value  ------------- Distribution ------------- count
            4096 |                                         0
            8192 |@@@@@@@@@@@@@@@                          3
           16384 |@@@@@@@@@@@@@@@@@@@@@@@@@                5
           32768 |                                         0

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:22:38Z

              libsystem_kernel.dylib`__psynch_cvbroad+0xa
              QtCore`QWaitCondition::wakeAll()+0x3c
              mixxx`EngineSideChain::writeSamples(float const*, int)+0x109
              mixxx`EngineMaster::process(int)+0xaca
              mixxx`SoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x661
              mixxx`(anonymous namespace)::paV19CallbackClkRef(void const*, void*, unsigned long, PaStreamCallbackTimeInfo const*, unsigned long, void*)+0x23
              libportaudio.2.dylib`AdaptingOutputOnlyProcess+0xe7
              libportaudio.2.dylib`PaUtil_EndBufferProcessing+0x1c4
              libportaudio.2.dylib`AudioIOProc+0x392
              CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5
              CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a
              CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8
              CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2
              CoreAudio`HALC_ProxyIOContext::IOWorkLoop()+0x9e7
              CoreAudio`HALC_ProxyIOContext::IOThreadEntry(void*)+0x58
              CoreAudio`HALB_IOThread::Entry(void*)+0x4b
              libsystem_pthread.dylib`_pthread_body+0x83
              libsystem_pthread.dylib`_pthread_body
              libsystem_pthread.dylib`thread_start+0xd
  syscall duration ns
           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |                                         1
            8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@             58
           16384 |@@@@@@@@@@@                              23
           32768 |                                         0

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:22:59Z

              libsystem_kernel.dylib`__psynch_mutexdrop+0xa
              CoreFoundation`CFRunLoopWakeUp+0xf0
              QtGui`QEventDispatcherMac::wakeUp()+0x30
              QtCore`QCoreApplication::postEvent(QObject*, QEvent*, int)+0x12f
              QtCore`QMetaObject::activate(QObject*, QMetaObject const*, int, void**)+0x55a
              mixxx`ControlDoublePrivate::valueChanged(double, QObject*)+0x4a
              mixxx`ControlDoublePrivate::set(double, QObject*)+0x8e
              mixxx`SoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x7a9
              mixxx`(anonymous namespace)::paV19CallbackClkRef(void const*, void*, unsigned long, PaStreamCallbackTimeInfo const*, unsigned long, void*)+0x23
              libportaudio.2.dylib`AdaptingOutputOnlyProcess+0xe7
              libportaudio.2.dylib`PaUtil_EndBufferProcessing+0x1c4
              libportaudio.2.dylib`AudioIOProc+0x392
              CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5
              CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a
              CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8
              CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2
              CoreAudio`HALC_ProxyIOContext::IOWorkLoop()+0x9e7
              CoreAudio`HALC_ProxyIOContext::IOThreadEntry(void*)+0x58
              CoreAudio`HALB_IOThread::Entry(void*)+0x4b
              libsystem_pthread.dylib`_pthread_body+0x83
  syscall duration ns
           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              118
            8192 |@@@@@@@@@@@@                             51
           16384 |@@                                       7
           32768 |                                         1
           65536 |                                         0

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:24:22Z

              libsystem_kernel.dylib`__psynch_mutexwait+0xa
              libsystem_pthread.dylib`_pthread_mutex_lock_slow+0x12c
              CoreFoundation`CFRunLoopWakeUp+0x4b
              QtGui`QEventDispatcherMac::wakeUp()+0x30
              QtCore`QCoreApplication::postEvent(QObject*, QEvent*, int)+0x12f
              QtCore`QMetaObject::activate(QObject*, QMetaObject const*, int, void**)+0x55a
              mixxx`ControlDoublePrivate::valueChanged(double, QObject*)+0x4a
              mixxx`ControlDoublePrivate::set(double, QObject*)+0x8e
              mixxx`EngineVuMeter::process(float*, int)+0x1e7
              mixxx`EngineMaster::process(int)+0xaeb
              mixxx`SoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x661
              mixxx`(anonymous namespace)::paV19CallbackClkRef(void const*, void*, unsigned long, PaStreamCallbackTimeInfo const*, unsigned long, void*)+0x23
              libportaudio.2.dylib`AdaptingOutputOnlyProcess+0xe7
              libportaudio.2.dylib`PaUtil_EndBufferProcessing+0x1c4
              libportaudio.2.dylib`AudioIOProc+0x392
              CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5
              CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a
              CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8
              CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2
              CoreAudio`HALC_ProxyIOContext::IOWorkLoop()+0x9e7
  syscall duration ns
           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |@@                                       30
            8192 |@@@@@@@@                                 111
           16384 |@@@@@@@@@@@@@@@@@@@@@@@@                 342
           32768 |@@@@@@                                   78
           65536 |                                         3
          131072 |                                         0

              libsystem_kernel.dylib`__psynch_mutexwait+0xa
              libsystem_pthread.dylib`_pthread_mutex_lock_slow+0x12c
              CoreFoundation`CFRunLoopWakeUp+0x4b
              QtGui`QEventDispatcherMac::wakeUp()+0x30
              QtCore`QCoreApplication::postEvent(QObject*, QEvent*, int)+0x12f
              QtCore`QMetaObject::activate(QObject*, QMetaObject const*, int, void**)+0x55a
              mixxx`ControlDoublePrivate::valueChanged(double, QObject*)+0x4a
              mixxx`ControlDoublePrivate::set(double, QObject*)+0x8e
              mixxx`EngineBuffer::updateIndicators(double, int)+0xc0
              mixxx`EngineMaster::processChannels(int)+0x6b3
              mixxx`EngineMaster::process(int)+0x135
              mixxx`SoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x661
              mixxx`(anonymous namespace)::paV19CallbackClkRef(void const*, void*, unsigned long, PaStreamCallbackTimeInfo const*, unsigned long, void*)+0x23
              libportaudio.2.dylib`AdaptingOutputOnlyProcess+0xe7
              libportaudio.2.dylib`PaUtil_EndBufferProcessing+0x1c4
              libportaudio.2.dylib`AudioIOProc+0x392
              CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5
              CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a
              CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8
              CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2
  syscall duration ns
           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |@                                        18
            8192 |@@@@@@@@@                                106
           16384 |@@@@@@@@@@@@@@@@@@@@@@@                  282
           32768 |@@@@@                                    64
           65536 |@                                        11
          131072 |                                         0

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:25:14Z

              libsystem_kernel.dylib`__gettimeofday+0xa
              mixxx`EngineNetworkStream::getWriteExpected()+0x17
              mixxx`SoundDeviceNetwork::writeProcess()+0xd4
              mixxx`SoundManager::writeProcess()+0xb9
              mixxx`SoundDevicePortAudio::callbackProcessClkRef(unsigned int, float*, float const*, PaStreamCallbackTimeInfo const*, unsigned long)+0x751
              mixxx`(anonymous namespace)::paV19CallbackClkRef(void const*, void*, unsigned long, PaStreamCallbackTimeInfo const*, unsigned long, void*)+0x23
              libportaudio.2.dylib`AdaptingOutputOnlyProcess+0xe7
              libportaudio.2.dylib`PaUtil_EndBufferProcessing+0x1c4
              libportaudio.2.dylib`AudioIOProc+0x392
              CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int)+0x2c5
              CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&)+0x9a
              CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&)+0x1f8
              CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*)+0x6f2
              CoreAudio`HALC_ProxyIOContext::IOWorkLoop()+0x9e7
              CoreAudio`HALC_ProxyIOContext::IOThreadEntry(void*)+0x58
              CoreAudio`HALB_IOThread::Entry(void*)+0x4b
              libsystem_pthread.dylib`_pthread_body+0x83
              libsystem_pthread.dylib`_pthread_body
              libsystem_pthread.dylib`thread_start+0xd
  syscall duration ns
           value  ------------- Distribution ------------- count
            2048 |                                         0
            4096 |@@@@@@@@@@@@@@@@@@@@@@@                  160
            8192 |@@@@@@@@@@@@@@@@                         112
           16384 |                                         1
           32768 |                                         0

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:52:34Z

I didn't see anything in here that was particularly surprising -- these were all things we knew we were doing, but having ballpark numbers is nice.

Some initial thoughts:

We may see some tail latency improvements from using tcmalloc given the cases where we ended up in malloc seemed quite expensive (up to 65us).
ControlObject::set can cost 16us locking mutexes alone. Queued connections allocate memory too (which can also block). We really need to get COs out of the engine.
SideChain writing costs ~8-16us just signaling the sidechain thread.
Why is SoundDeviceNetwork open when no shoutcast stream is enabled? Do we need to be calling gettimeofday from the engine thread?

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-08T03:53:39Z

Here's my 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;
}

syscall:::entry
/execname == "mixxx" && tid == self->callback_tid/
{
  self->syscall_ts = timestamp;
}

syscall:::return
/execname == "mixxx" && tid == self->callback_tid && self->syscall_ts/
{
  @[ustack(), "syscall duration ns"] = quantize(timestamp - self->syscall_ts);
  self->syscall_ts = 0;
}

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2016-12-08T11:00:25Z

We may see some tail latency improvements from using tcmalloc given the cases where we ended up in malloc seemed quite expensive (up to 65us).

Does it mean we need to override the new() operator for some classes? How does it work together with precompiled qt libraries?

ControlObject::set can cost 16us locking mutexes alone. Queued connections allocate memory too (which can also block). We really need to get COs out of the engine.

Yes! I have already thought about it what will be a good approach, that is performant, but not requires a change in our business logic.

On Idea was to implement a new CO Proxy type that has value buffer for pending changes from the engine and a chain pointer that allows to chain all touched COs.

During the callback set() writes the value buffer and puts the CO on top of the linked list. After the engine call, a new threads works though the fifo list and updates the underlying CO accordingly.

Unfortunately I am not sure if this really improves the performance, because the work is still there and the fifo should be empty before we can continue with the next engine call.

If we assume that we protect these threads from each other by a single mutex, we use actually more CPU, but we benefit from multi core cpus.

Maybe we find a way to make the chain of Engine COs lock free

Why is SoundDeviceNetwork open when no shoutcast stream is enabled?

There is no strong reason for it. It requires some work to enable it on demand though.

Do we need to be calling gettimeofday from the engine thread?

Yes, that is the main reason for having SoundDeviceNetwork, it runs at the network synced gettimeofday clock.

By the way, there is a Pending PR, that allows to run the whole engine at this clock to remove sync artifacts from the broadcast stream: https://github.com/mixxxdj/mixxx/pull/894

mixxxbot commented 2 years ago

Commented by: rryan Date: 2016-12-09T18:01:16Z

Taking the max of on-cpu vs on+off-cpu callback duration shows something of an upper bound (ok, sloppy math) for the amount of time the callback can sleep.

callback on-cpu duration max ns 2447591 callback duration max ns 4713387

Here is a histogram of the number of times that the callback thread blocks per callback (I put a dtrace probe on sched:::off-cpu and incremented a counter between HALC_IO:::IOProc_Begin and HALC_IO:::IOProc_End to get this metric.

This is playing 2 tracks at system reported latency of 13.5828ms for about 30 seconds.

  offcpu count
           value  ------------- Distribution ------------- count
              -1 |                                         0
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 15659
               1 |                                         11
               2 |                                         7
               4 |                                         1
               8 |                                         0

Note that these power-of-2 histograms dtrace produces account an event to the smallest power of 2 that is less than or equal to the true number. So the true maximum here is somewhere between 4 and 7.