Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve DAC timing plausibility and add a CPU timer fallback #881

Merged
merged 6 commits into from
May 23, 2016

Conversation

daschuer
Copy link
Member

Here it is.
It works surprisingly well with the pulse ALSA device. Even if we have a 47 ms cycle for a 43 ms buffer and two callbacks without a gap if the buffer is consumed.

if (!m_invalidTimeInfoWarned) {
qWarning() << "SoundDevicePortAudio: Audio API provides invalid time stamps,"
<< "waveform syncing disabled."
<< "waveform by CPU Timer"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe clearer if you said "syncing waveform with a CPU timer"

@daschuer
Copy link
Member Author

fixed

@daschuer
Copy link
Member Author

daschuer commented Feb 2, 2016

Can we merge this now?

@rryan
Copy link
Member

rryan commented Feb 6, 2016

CoreAudio provides reliable timestamps but triggers the warning on startup:

Debug [Main]: Opened PortAudio stream successfully... starting
Debug [Main]: PortAudio: Started stream successfully
Debug [Main]:    Actual sample rate:  96000 Hz, latency: 48.2396 ms
Debug [Main]: Compressor attack per frame:  0.0001875 decay per frame:  1.875e-05
Debug [Main]: SoundDeviceNetwork::open() "Network stream"
Debug [Main]: framesPerBuffer: 8192
Debug [Main]: Requested sample rate:  96000 Hz, latency: 85.3333 ms
Debug [Main]: Using "Built-in Output" as output sound device clock reference
Debug [Main]: 2 output sound devices opened
Debug [Main]: 0 input  sound devices opened
Debug [Main]: Displaying mixxx
Debug [Main]: Running Mixxx
Debug [Main]: ControllerManager::getControllerList
Debug []: timeSinceLastCbSecs 513643 callbackEntrytoDacSecs 0.105467 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0853333 diff 513643
Warning []: SoundDevicePortAudio: Audio API provides invalid time stamps, syncing waveforms with a CPU Timer DacTime: 513643 EntrytoDac: 0

Here's a sample of timings while running normally. Printline is inserted in SoundDevicePortAudio::updateCallbackEntryToDacTime.cpp line 1001.

Debug [Engine]: timeSinceLastCbSecs 0.0928863 callbackEntrytoDacSecs 0.168164 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0702531 diff 0.105464
Debug [Engine]: timeSinceLastCbSecs 0.0930512 callbackEntrytoDacSecs 0.160472 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0627001 diff 0.105489
Debug [Engine]: timeSinceLastCbSecs 0.0927867 callbackEntrytoDacSecs 0.152995 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0549823 diff 0.105466
Debug [Engine]: timeSinceLastCbSecs 0.0929719 callbackEntrytoDacSecs 0.145373 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0475289 diff 0.105483
Debug [Engine]: timeSinceLastCbSecs 0.0926972 callbackEntrytoDacSecs 0.137986 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0398903 diff 0.105459
Debug [Engine]: timeSinceLastCbSecs 0.0928862 callbackEntrytoDacSecs 0.130437 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0325264 diff 0.105464
Debug [Engine]: timeSinceLastCbSecs 0.0930727 callbackEntrytoDacSecs 0.122722 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0249735 diff 0.105488
Debug [Engine]: timeSinceLastCbSecs 0.0926653 callbackEntrytoDacSecs 0.115362 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0172341 diff 0.105459
Debug [Engine]: timeSinceLastCbSecs 0.0929323 callbackEntrytoDacSecs 0.107757 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00990209 diff 0.105454
Debug [Engine]: timeSinceLastCbSecs 0.000275094 callbackEntrytoDacSecs 0.19309 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00230312 diff 0.105729
Debug [Engine]: timeSinceLastCbSecs 0.0927759 callbackEntrytoDacSecs 0.185424 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0873614 diff 0.105505
Debug [Engine]: timeSinceLastCbSecs 0.092875 callbackEntrytoDacSecs 0.177878 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0799188 diff 0.105501
Debug [Engine]: timeSinceLastCbSecs 0.0927894 callbackEntrytoDacSecs 0.170396 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0723771 diff 0.105475
Debug [Engine]: timeSinceLastCbSecs 0.0929543 callbackEntrytoDacSecs 0.162791 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.064921 diff 0.105491
Debug [Engine]: timeSinceLastCbSecs 0.0928539 callbackEntrytoDacSecs 0.155249 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0573 diff 0.105469
Debug [Engine]: timeSinceLastCbSecs 0.0928256 callbackEntrytoDacSecs 0.147775 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0497795 diff 0.105487
Debug [Engine]: timeSinceLastCbSecs 0.0929479 callbackEntrytoDacSecs 0.140168 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0422872 diff 0.105496
Debug [Engine]: timeSinceLastCbSecs 0.0927388 callbackEntrytoDacSecs 0.132733 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0346726 diff 0.105466
Debug [Engine]: timeSinceLastCbSecs 0.09301 callbackEntrytoDacSecs 0.125055 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0272672 diff 0.105465
Debug [Engine]: timeSinceLastCbSecs 0.0928434 callbackEntrytoDacSecs 0.117546 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0195905 diff 0.105466
Debug [Engine]: timeSinceLastCbSecs 0.0927583 callbackEntrytoDacSecs 0.110109 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0120805 diff 0.105453
Debug [Engine]: timeSinceLastCbSecs 0.000302447 callbackEntrytoDacSecs 0.195442 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00465549 diff 0.105756
Debug [Engine]: timeSinceLastCbSecs 0.0927212 callbackEntrytoDacSecs 0.187783 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0896864 diff 0.105484
Debug [Engine]: timeSinceLastCbSecs 0.0928187 callbackEntrytoDacSecs 0.180286 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0822985 diff 0.105473
Debug [Engine]: timeSinceLastCbSecs 0.0928315 callbackEntrytoDacSecs 0.172794 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0748131 diff 0.105479
Debug [Engine]: timeSinceLastCbSecs 0.0928669 callbackEntrytoDacSecs 0.165256 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.067315 diff 0.105474
Debug [Engine]: timeSinceLastCbSecs 0.0929436 callbackEntrytoDacSecs 0.157649 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0597814 diff 0.105478
Debug [Engine]: timeSinceLastCbSecs 0.0928992 callbackEntrytoDacSecs 0.150086 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0521711 diff 0.10548
Debug [Engine]: timeSinceLastCbSecs 0.092889 callbackEntrytoDacSecs 0.142535 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0446053 diff 0.105486
Debug [Engine]: timeSinceLastCbSecs 0.09294 callbackEntrytoDacSecs 0.134922 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0370496 diff 0.105479
Debug [Engine]: timeSinceLastCbSecs 0.0928232 callbackEntrytoDacSecs 0.127427 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0294429 diff 0.105474
Debug [Engine]: timeSinceLastCbSecs 0.092839 callbackEntrytoDacSecs 0.119917 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.021953 diff 0.105469
Debug [Engine]: timeSinceLastCbSecs 0.0930335 callbackEntrytoDacSecs 0.112224 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0144474 diff 0.105477
Debug [Engine]: timeSinceLastCbSecs 0.000763549 callbackEntrytoDacSecs 0.197557 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00674717 diff 0.10624
Debug [Engine]: timeSinceLastCbSecs 0.0920333 callbackEntrytoDacSecs 0.190108 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.091317 diff 0.105491
Debug [Engine]: timeSinceLastCbSecs 0.0927934 callbackEntrytoDacSecs 0.182636 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.084617 diff 0.10548
Debug [Engine]: timeSinceLastCbSecs 0.0930068 callbackEntrytoDacSecs 0.174983 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0771569 diff 0.1055
Debug [Engine]: timeSinceLastCbSecs 0.0928755 callbackEntrytoDacSecs 0.167433 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0694834 diff 0.105491
Debug [Engine]: timeSinceLastCbSecs 0.0927691 callbackEntrytoDacSecs 0.159985 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0619412 diff 0.105479
Debug [Engine]: timeSinceLastCbSecs 0.0929314 callbackEntrytoDacSecs 0.152374 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0545055 diff 0.105467
Debug [Engine]: timeSinceLastCbSecs 0.0928134 callbackEntrytoDacSecs 0.144918 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0469074 diff 0.10549
Debug [Engine]: timeSinceLastCbSecs 0.0928689 callbackEntrytoDacSecs 0.137368 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0394274 diff 0.105476
Debug [Engine]: timeSinceLastCbSecs 0.0928564 callbackEntrytoDacSecs 0.129837 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0318918 diff 0.105468
Debug [Engine]: timeSinceLastCbSecs 0.0928514 callbackEntrytoDacSecs 0.122319 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0243687 diff 0.105469
Debug [Engine]: timeSinceLastCbSecs 0.0930093 callbackEntrytoDacSecs 0.114648 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0168506 diff 0.105474
Debug [Engine]: timeSinceLastCbSecs 0.0928119 callbackEntrytoDacSecs 0.107163 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00917468 diff 0.105467
Debug [Engine]: timeSinceLastCbSecs 0.000313431 callbackEntrytoDacSecs 0.192496 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00169607 diff 0.10578
Debug [Engine]: timeSinceLastCbSecs 0.0926989 callbackEntrytoDacSecs 0.18485 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.086716 diff 0.105499
Debug [Engine]: timeSinceLastCbSecs 0.09298 callbackEntrytoDacSecs 0.17724 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0793504 diff 0.105537
Debug [Engine]: timeSinceLastCbSecs 0.092604 callbackEntrytoDacSecs 0.169908 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0717038 diff 0.105475
Debug [Engine]: timeSinceLastCbSecs 0.0928609 callbackEntrytoDacSecs 0.162382 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0644331 diff 0.105477
Debug [Engine]: timeSinceLastCbSecs 0.0930527 callbackEntrytoDacSecs 0.154692 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0569055 diff 0.105506
Debug [Engine]: timeSinceLastCbSecs 0.0927398 callbackEntrytoDacSecs 0.147257 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0491861 diff 0.105477
Debug [Engine]: timeSinceLastCbSecs 0.0929604 callbackEntrytoDacSecs 0.139636 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0417797 diff 0.105483
Debug [Engine]: timeSinceLastCbSecs 0.0927911 callbackEntrytoDacSecs 0.132166 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0341527 diff 0.105471
Debug [Engine]: timeSinceLastCbSecs 0.0928534 callbackEntrytoDacSecs 0.124649 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0266949 diff 0.105475
Debug [Engine]: timeSinceLastCbSecs 0.0928936 callbackEntrytoDacSecs 0.117082 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0191748 diff 0.105467
Debug [Engine]: timeSinceLastCbSecs 0.0928847 callbackEntrytoDacSecs 0.109535 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0116146 diff 0.105472
Debug [Engine]: timeSinceLastCbSecs 0.000222971 callbackEntrytoDacSecs 0.194868 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00406319 diff 0.105695
Debug [Engine]: timeSinceLastCbSecs 0.0926738 callbackEntrytoDacSecs 0.187323 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0891736 diff 0.10549
Debug [Engine]: timeSinceLastCbSecs 0.0928629 callbackEntrytoDacSecs 0.179786 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0818331 diff 0.105482
Debug [Engine]: timeSinceLastCbSecs 0.0928946 callbackEntrytoDacSecs 0.172219 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0743035 diff 0.105477
Debug [Engine]: timeSinceLastCbSecs 0.0928485 callbackEntrytoDacSecs 0.164709 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0667422 diff 0.105482
Debug [Engine]: timeSinceLastCbSecs 0.092913 callbackEntrytoDacSecs 0.157123 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.059227 diff 0.105476
Debug [Engine]: timeSinceLastCbSecs 0.092885 callbackEntrytoDacSecs 0.149577 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0516473 diff 0.105482
Debug [Engine]: timeSinceLastCbSecs 0.0928619 callbackEntrytoDacSecs 0.14204 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0440957 diff 0.105473
Debug [Engine]: timeSinceLastCbSecs 0.092889 callbackEntrytoDacSecs 0.134487 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0365671 diff 0.105475
Debug [Engine]: timeSinceLastCbSecs 0.0928734 callbackEntrytoDacSecs 0.12694 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0290114 diff 0.105468
Debug [Engine]: timeSinceLastCbSecs 0.0928967 callbackEntrytoDacSecs 0.119383 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0214714 diff 0.105475
Debug [Engine]: timeSinceLastCbSecs 0.0928607 callbackEntrytoDacSecs 0.111857 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.013908 diff 0.105476
Debug [Engine]: timeSinceLastCbSecs 0.000209346 callbackEntrytoDacSecs 0.19719 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00638065 diff 0.105685
Debug [Engine]: timeSinceLastCbSecs 0.0926785 callbackEntrytoDacSecs 0.189645 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0915046 diff 0.105485
Debug [Engine]: timeSinceLastCbSecs 0.0928771 callbackEntrytoDacSecs 0.182106 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0841595 diff 0.105491
Debug [Engine]: timeSinceLastCbSecs 0.0928907 callbackEntrytoDacSecs 0.174542 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0766157 diff 0.105483
Debug [Engine]: timeSinceLastCbSecs 0.0929396 callbackEntrytoDacSecs 0.166946 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0690584 diff 0.105494
Debug [Engine]: timeSinceLastCbSecs 0.092937 callbackEntrytoDacSecs 0.159337 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0614521 diff 0.105488
Debug [Engine]: timeSinceLastCbSecs 0.092775 callbackEntrytoDacSecs 0.151896 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0538484 diff 0.105489
Debug [Engine]: timeSinceLastCbSecs 0.0930305 callbackEntrytoDacSecs 0.144202 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0464067 diff 0.105492
Debug [Engine]: timeSinceLastCbSecs 0.0929344 callbackEntrytoDacSecs 0.13663 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0387095 diff 0.105521
Debug [Engine]: timeSinceLastCbSecs 0.0927054 callbackEntrytoDacSecs 0.129211 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0311084 diff 0.105475
Debug [Engine]: timeSinceLastCbSecs 0.0928176 callbackEntrytoDacSecs 0.121731 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0237364 diff 0.105479
Debug [Engine]: timeSinceLastCbSecs 0.0930415 callbackEntrytoDacSecs 0.114022 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0162521 diff 0.105478
Debug [Engine]: timeSinceLastCbSecs 0.0928478 callbackEntrytoDacSecs 0.106505 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00854387 diff 0.105475
Debug [Engine]: timeSinceLastCbSecs 0.000312673 callbackEntrytoDacSecs 0.191838 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00102936 diff 0.105788
Debug [Engine]: timeSinceLastCbSecs 0.0924647 callbackEntrytoDacSecs 0.184409 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.08605 diff 0.10549
Debug [Engine]: timeSinceLastCbSecs 0.0930565 callbackEntrytoDacSecs 0.176716 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0789186 diff 0.10552
Debug [Engine]: timeSinceLastCbSecs 0.0927541 callbackEntrytoDacSecs 0.169271 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0711955 diff 0.105497
Debug [Engine]: timeSinceLastCbSecs 0.0929932 callbackEntrytoDacSecs 0.161624 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0637748 diff 0.105509
Debug [Engine]: timeSinceLastCbSecs 0.092744 callbackEntrytoDacSecs 0.154192 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0561149 diff 0.105487
Debug [Engine]: timeSinceLastCbSecs 0.0928997 callbackEntrytoDacSecs 0.146617 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0487042 diff 0.105479
Debug [Engine]: timeSinceLastCbSecs 0.0927949 callbackEntrytoDacSecs 0.139158 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0411378 diff 0.105482
Debug [Engine]: timeSinceLastCbSecs 0.0929879 callbackEntrytoDacSecs 0.131499 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0336763 diff 0.105477
Debug [Engine]: timeSinceLastCbSecs 0.0929094 callbackEntrytoDacSecs 0.123928 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0260217 diff 0.105482
Debug [Engine]: timeSinceLastCbSecs 0.0928642 callbackEntrytoDacSecs 0.116387 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0184456 diff 0.105472
Debug [Engine]: timeSinceLastCbSecs 0.0928491 callbackEntrytoDacSecs 0.108874 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0109147 diff 0.105475
Debug [Engine]: timeSinceLastCbSecs 0.000324866 callbackEntrytoDacSecs 0.194208 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00339901 diff 0.1058
Debug [Engine]: timeSinceLastCbSecs 0.0926146 callbackEntrytoDacSecs 0.186617 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0884075 diff 0.105491
Debug [Engine]: timeSinceLastCbSecs 0.0927786 callbackEntrytoDacSecs 0.179172 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0811262 diff 0.105491
Debug [Engine]: timeSinceLastCbSecs 0.0928563 callbackEntrytoDacSecs 0.171643 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0736809 diff 0.105485
Debug [Engine]: timeSinceLastCbSecs 0.092981 callbackEntrytoDacSecs 0.163998 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0661579 diff 0.105488
Debug [Engine]: timeSinceLastCbSecs 0.0928995 callbackEntrytoDacSecs 0.156438 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0585102 diff 0.105494
Debug [Engine]: timeSinceLastCbSecs 0.0928224 callbackEntrytoDacSecs 0.148938 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.050944 diff 0.105483
Debug [Engine]: timeSinceLastCbSecs 0.0928478 callbackEntrytoDacSecs 0.141427 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.043455 diff 0.105487
Debug [Engine]: timeSinceLastCbSecs 0.0929368 callbackEntrytoDacSecs 0.133817 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0359405 diff 0.10548
Debug [Engine]: timeSinceLastCbSecs 0.0929092 callbackEntrytoDacSecs 0.126246 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.028337 diff 0.105485
Debug [Engine]: timeSinceLastCbSecs 0.0928798 callbackEntrytoDacSecs 0.118692 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0207612 diff 0.105477
Debug [Engine]: timeSinceLastCbSecs 0.0928352 callbackEntrytoDacSecs 0.111193 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0132147 diff 0.10548
Debug [Engine]: timeSinceLastCbSecs 0.000384827 callbackEntrytoDacSecs 0.196526 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00571284 diff 0.105865
Debug [Engine]: timeSinceLastCbSecs 0.0925175 callbackEntrytoDacSecs 0.18897 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0906613 diff 0.105493
Debug [Engine]: timeSinceLastCbSecs 0.0928348 callbackEntrytoDacSecs 0.181502 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0834772 diff 0.105527
Debug [Engine]: timeSinceLastCbSecs 0.0929628 callbackEntrytoDacSecs 0.173865 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0759757 diff 0.105519
Debug [Engine]: timeSinceLastCbSecs 0.092871 callbackEntrytoDacSecs 0.166304 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0683462 diff 0.105496
Debug [Engine]: timeSinceLastCbSecs 0.0928788 callbackEntrytoDacSecs 0.158749 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0608085 diff 0.105486
Debug [Engine]: timeSinceLastCbSecs 0.092918 callbackEntrytoDacSecs 0.151178 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.053263 diff 0.1055
Debug [Engine]: timeSinceLastCbSecs 0.0927081 callbackEntrytoDacSecs 0.143792 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0456784 diff 0.105488
Debug [Engine]: timeSinceLastCbSecs 0.0930789 callbackEntrytoDacSecs 0.136054 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0383036 diff 0.105496
Debug [Engine]: timeSinceLastCbSecs 0.0927254 callbackEntrytoDacSecs 0.128648 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0305581 diff 0.105482
Debug [Engine]: timeSinceLastCbSecs 0.0928405 callbackEntrytoDacSecs 0.121136 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.023166 diff 0.105477
Debug [Engine]: timeSinceLastCbSecs 0.0929586 callbackEntrytoDacSecs 0.113513 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0156588 diff 0.10548
Debug [Engine]: timeSinceLastCbSecs 0.0928305 callbackEntrytoDacSecs 0.106008 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00803352 diff 0.105472
Debug [Engine]: timeSinceLastCbSecs 0.000284273 callbackEntrytoDacSecs 0.191342 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.000536388 diff 0.105756
Debug [Engine]: timeSinceLastCbSecs 0.0927077 callbackEntrytoDacSecs 0.183713 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0855854 diff 0.105502
Debug [Engine]: timeSinceLastCbSecs 0.0928728 callbackEntrytoDacSecs 0.176201 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0782111 diff 0.105529
Debug [Engine]: timeSinceLastCbSecs 0.0929231 callbackEntrytoDacSecs 0.168592 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0706716 diff 0.10551
Debug [Engine]: timeSinceLastCbSecs 0.0928231 callbackEntrytoDacSecs 0.161083 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0630819 diff 0.105491
Debug [Engine]: timeSinceLastCbSecs 0.0929226 callbackEntrytoDacSecs 0.153504 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0555921 diff 0.105501
Debug [Engine]: timeSinceLastCbSecs 0.0927361 callbackEntrytoDacSecs 0.146078 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0480028 diff 0.105477
Debug [Engine]: timeSinceLastCbSecs 0.0929322 callbackEntrytoDacSecs 0.138489 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0406001 diff 0.105488
Debug [Engine]: timeSinceLastCbSecs 0.0930649 callbackEntrytoDacSecs 0.130872 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0330013 diff 0.105603
Debug [Engine]: timeSinceLastCbSecs 0.0926913 callbackEntrytoDacSecs 0.123402 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0252697 diff 0.10549
Debug [Engine]: timeSinceLastCbSecs 0.092802 callbackEntrytoDacSecs 0.115926 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0179117 diff 0.105483
Debug [Engine]: timeSinceLastCbSecs 0.0928685 callbackEntrytoDacSecs 0.108384 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.010443 diff 0.105476
Debug [Engine]: timeSinceLastCbSecs 0.000265254 callbackEntrytoDacSecs 0.193718 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0029079 diff 0.105742
Debug [Engine]: timeSinceLastCbSecs 0.0928145 callbackEntrytoDacSecs 0.186025 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.087976 diff 0.10553
Debug [Engine]: timeSinceLastCbSecs 0.0927209 callbackEntrytoDacSecs 0.178602 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0804948 diff 0.105495
Debug [Engine]: timeSinceLastCbSecs 0.0929601 callbackEntrytoDacSecs 0.170995 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0731073 diff 0.105514
Debug [Engine]: timeSinceLastCbSecs 0.0929151 callbackEntrytoDacSecs 0.163391 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0654806 diff 0.105492
Debug [Engine]: timeSinceLastCbSecs 0.092875 callbackEntrytoDacSecs 0.155855 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0578988 diff 0.105497
Debug [Engine]: timeSinceLastCbSecs 0.0928536 callbackEntrytoDacSecs 0.148322 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0503572 diff 0.105485
Debug [Engine]: timeSinceLastCbSecs 0.0927933 callbackEntrytoDacSecs 0.140867 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.042837 diff 0.105489
Debug [Engine]: timeSinceLastCbSecs 0.093019 callbackEntrytoDacSecs 0.133202 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.035377 diff 0.10551
Debug [Engine]: timeSinceLastCbSecs 0.0928443 callbackEntrytoDacSecs 0.125669 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0276914 diff 0.105488
Debug [Engine]: timeSinceLastCbSecs 0.0928731 callbackEntrytoDacSecs 0.118136 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0201804 diff 0.105495
Debug [Engine]: timeSinceLastCbSecs 0.0928824 callbackEntrytoDacSecs 0.110574 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0126407 diff 0.105482

@daschuer
Copy link
Member Author

daschuer commented Feb 8, 2016

Yes the Data is OK. I will tweak the checks a bit.

Debug [Engine]: timeSinceLastCbSecs 0.0928119 callbackEntrytoDacSecs 0.107163 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00917468 diff 0.105467
Debug [Engine]: timeSinceLastCbSecs 0.000313431 callbackEntrytoDacSecs 0.192496 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00169607 diff 0.10578
Debug [Engine]: timeSinceLastCbSecs 0.0926989 callbackEntrytoDacSecs 0.18485 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.086716 diff 0.105499

This sequence looks not that nice. It seams that your sound API insists to use a 0.0928119 cycle even though you have requested a 0.0853333. To catch up it does two in a row to catch up.
This will most likely leads to buffer overruns if you use an usb Mic with independent crystal since it may have not two buffers that can be consumed in a row.

@daschuer
Copy link
Member Author

daschuer commented Feb 8, 2016

Please try again. It should work without any warning in your case.

@rryan
Copy link
Member

rryan commented Feb 10, 2016

Hm, still seems to produce the error:

Debug [Main]: Opened PortAudio stream successfully... starting
Debug [Main]: PortAudio: Started stream successfully
Debug [Main]:    Actual sample rate:  96000 Hz, latency: 48.2396 ms
Debug [Main]: Compressor attack per frame:  0.0001875 decay per frame:  1.875e-05
Debug [Main]: SoundDeviceNetwork::open() "Network stream"
Debug [Main]: framesPerBuffer: 8192
Debug [Main]: Requested sample rate:  96000 Hz, latency: 85.3333 ms
Debug [Main]: Using "Built-in Output" as output sound device clock reference
Debug [Main]: 2 output sound devices opened
Debug [Main]: 0 input  sound devices opened
Debug [Main]: Displaying mixxx
Debug [Main]: Running Mixxx
Debug [Main]: ControllerManager::getControllerList
Debug [LibraryScanner 1]: LibraryHashDAO::initialize LibraryScanner(0x7fbd8ea63260, name = "LibraryScanner 1") "LIBRARY_SCANNER"
Debug [LibraryScanner 1]: CueDAO::initialize LibraryScanner(0x7fbd8ea63260, name = "LibraryScanner 1") "LIBRARY_SCANNER"
Debug [LibraryScanner 1]: TrackDAO::initialize LibraryScanner(0x7fbd8ea63260, name = "LibraryScanner 1") "LIBRARY_SCANNER"
Debug [LibraryScanner 1]: DirectoryDAO::initialize LibraryScanner(0x7fbd8ea63260, name = "LibraryScanner 1") "LIBRARY_SCANNER"
Debug [LibraryScanner 1]: LibraryScanner event loop starting.
Debug []: timeSinceLastCbSecs 0.206169 callbackEntrytoDacSecs 0.105454 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0853333 diff 0.140957
Debug []: SSE: Denormals to zero mode already enabled
Debug []: SSE: Flush to zero mode already enabled
Debug []: Denormals to zero mode is working
Debug [Engine]: timeSinceLastCbSecs 0.0171489 callbackEntrytoDacSecs 0.190788 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0 diff 0.122603
Warning [Engine]: SoundDevicePortAudio: Audio API provides invalid time stamps, syncing waveforms with a CPU Timer DacTime: 679847 EntrytoDac: 0.190788 TimeSinceLastCb: 0.0171489 diff: 0.122603
Debug [Engine]: timeSinceLastCbSecs 0.0756951 callbackEntrytoDacSecs 0.183276 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0681844 diff 0.105454
Debug [Engine]: timeSinceLastCbSecs 0.0930377 callbackEntrytoDacSecs 0.175581 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0778227 diff 0.105463
Debug [Engine]: timeSinceLastCbSecs 0.0927329 callbackEntrytoDacSecs 0.16817 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0701183 diff 0.105451
Debug [Engine]: timeSinceLastCbSecs 0.0929707 callbackEntrytoDacSecs 0.160541 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0627187 diff 0.10546
Debug [Engine]: timeSinceLastCbSecs 0.0928089 callbackEntrytoDacSecs 0.153062 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0550814 diff 0.105456
Debug [Engine]: timeSinceLastCbSecs 0.092887 callbackEntrytoDacSecs 0.145512 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0476058 diff 0.10546
Debug [Engine]: timeSinceLastCbSecs 0.0928427 callbackEntrytoDacSecs 0.137988 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0400521 diff 0.105446
Debug [Engine]: timeSinceLastCbSecs 0.0928646 callbackEntrytoDacSecs 0.130459 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0325428 diff 0.105448
Debug [Engine]: timeSinceLastCbSecs 0.0928942 callbackEntrytoDacSecs 0.122892 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0250115 diff 0.105442
Debug [Engine]: timeSinceLastCbSecs 0.0928911 callbackEntrytoDacSecs 0.115338 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0174507 diff 0.105446
Debug [Engine]: timeSinceLastCbSecs 0.0929545 callbackEntrytoDacSecs 0.107709 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0098929 diff 0.105437
Debug [Engine]: timeSinceLastCbSecs 0.000188748 callbackEntrytoDacSecs 0.193042 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00227171 diff 0.105626
Debug [Engine]: timeSinceLastCbSecs 0.0926442 callbackEntrytoDacSecs 0.185568 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0874163 diff 0.105462
Debug [Engine]: timeSinceLastCbSecs 0.0929106 callbackEntrytoDacSecs 0.177983 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0801054 diff 0.105455
Debug [Engine]: timeSinceLastCbSecs 0.092994 callbackEntrytoDacSecs 0.170325 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0725281 diff 0.105458
Debug [Engine]: timeSinceLastCbSecs 0.0927038 callbackEntrytoDacSecs 0.162955 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0648674 diff 0.105458
Debug [Engine]: timeSinceLastCbSecs 0.0928669 callbackEntrytoDacSecs 0.155413 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0574969 diff 0.10545
Debug [Engine]: timeSinceLastCbSecs 0.0929212 callbackEntrytoDacSecs 0.147829 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0499634 diff 0.105454
Debug [Engine]: timeSinceLastCbSecs 0.0928427 callbackEntrytoDacSecs 0.140311 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0423756 diff 0.105445
Debug [Engine]: timeSinceLastCbSecs 0.0928908 callbackEntrytoDacSecs 0.132761 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0348662 diff 0.105452
Debug [Engine]: timeSinceLastCbSecs 0.0928591 callbackEntrytoDacSecs 0.125226 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0273087 diff 0.105443
Debug [Engine]: timeSinceLastCbSecs 0.092932 callbackEntrytoDacSecs 0.117631 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.019783 diff 0.105446
Debug [Engine]: timeSinceLastCbSecs 0.0929262 callbackEntrytoDacSecs 0.11003 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0121843 diff 0.105439
Debug [Engine]: timeSinceLastCbSecs 0.000243193 callbackEntrytoDacSecs 0.195364 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0045915 diff 0.105682
Debug [Engine]: timeSinceLastCbSecs 0.0926055 callbackEntrytoDacSecs 0.187878 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0896816 diff 0.105468
Debug [Engine]: timeSinceLastCbSecs 0.0928612 callbackEntrytoDacSecs 0.180341 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0824095 diff 0.10546
Debug [Engine]: timeSinceLastCbSecs 0.0928796 callbackEntrytoDacSecs 0.172798 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0748817 diff 0.105463
Debug [Engine]: timeSinceLastCbSecs 0.0928438 callbackEntrytoDacSecs 0.16528 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0673354 diff 0.105455
Debug [Engine]: timeSinceLastCbSecs 0.0929218 callbackEntrytoDacSecs 0.157722 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0598249 diff 0.105485
Debug [Engine]: timeSinceLastCbSecs 0.0928297 callbackEntrytoDacSecs 0.150199 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0522365 diff 0.105459
Debug [Engine]: timeSinceLastCbSecs 0.0928984 callbackEntrytoDacSecs 0.142631 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0447401 diff 0.105456
Debug [Engine]: timeSinceLastCbSecs 0.0928703 callbackEntrytoDacSecs 0.135096 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.037175 diff 0.105458
Debug [Engine]: timeSinceLastCbSecs 0.0929833 callbackEntrytoDacSecs 0.12744 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0296381 diff 0.105451
Debug [Engine]: timeSinceLastCbSecs 0.0927803 callbackEntrytoDacSecs 0.119994 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0219881 diff 0.105453
Debug [Engine]: timeSinceLastCbSecs 0.0930191 callbackEntrytoDacSecs 0.112303 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0145412 diff 0.105447
Debug [Engine]: timeSinceLastCbSecs 0.000292142 callbackEntrytoDacSecs 0.197636 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.00685537 diff 0.10574
Debug [Engine]: timeSinceLastCbSecs 0.092573 callbackEntrytoDacSecs 0.190131 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0918966 diff 0.105474
Debug [Engine]: timeSinceLastCbSecs 0.0928977 callbackEntrytoDacSecs 0.182563 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0846569 diff 0.105471
Debug [Engine]: timeSinceLastCbSecs 0.0927694 callbackEntrytoDacSecs 0.175123 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0770925 diff 0.105467
Debug [Engine]: timeSinceLastCbSecs 0.0928533 callbackEntrytoDacSecs 0.167595 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0696564 diff 0.105458
Debug [Engine]: timeSinceLastCbSecs 0.0929253 callbackEntrytoDacSecs 0.160002 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0621364 diff 0.105457
Debug [Engine]: timeSinceLastCbSecs 0.093001 callbackEntrytoDacSecs 0.152345 bufferSizeSec 0.0853333 m_lastCallbackEntrytoDacSecs 0.0545444 diff 0.105469

@daschuer
Copy link
Member Author

If we compare the data form the first callback with the data of the second one, we have

DAC                                         |----------------|----------------| 0.0853333
SLC1  |--|                                                                      0.0171489 
SLC2     |--------------|                                                       0.0756951
SLC2                    |------------------|                                    0.0930377
CED1     |-------------------------------------|                                0.190788
CED2                    |-------------------------------------|                 0.183276
CED3                                       |----------------------------------| 0.175581
Error2:                                     |--|                                0.0171502 20%
Error3:                                                                       | 0,0000094 0.01% 

So we facing two issues:

  • The first callback comes too early SLC1 from m_clkRefTimer is much shorter than expected
  • The second callback comes with an error of 20 %, interestingly this is the same time we measure in SLC1. It looks like the timing is based on the open() moment an the callback is just delayed.

So there is a chance to special case Mac here. But we are talking about only two callbacks after setting up the hardware, so I will just skip calculation.

@daschuer
Copy link
Member Author

Ok, This should work now.

@daschuer daschuer mentioned this pull request Feb 29, 2016
@rryan
Copy link
Member

rryan commented Apr 14, 2016

Thanks -- I'll re-test soon.

@rryan
Copy link
Member

rryan commented Apr 16, 2016

Still triggers right away upon startup:

Debug [Main]: SoundManager::setupDevices()
Debug [Controller]: ControllerManager: Setting up devices
Debug [Main]: SoundDevicePortAudio::open() "1, Built-in Output"
Debug [Controller]: Scanning PortMIDI devices:
Debug [Main]: framesPerBuffer: 1024
Debug [Controller]: Scanning HID devices:
Debug [Main]: Requested sample rate:  96000 Hz, latency: 10.6667 ms
Debug [Main]: Output channels: 2 | Input channels: 0
Debug [Main]: Opening stream with id 1
Debug [Controller]: Found "Apple Inc." "Apple Internal Keyboard / Trackpad" "r549" S/N "" "Usage Page 1 Usage 6"
Debug [Controller]: Found "Apple Inc." "Apple Internal Keyboard / Trackpad" "r549" S/N "" "Usage Page 1 Usage 2"
Debug [Controller]: Found "Apple Inc." "Apple Internal Keyboard / Trackpad" "r549" S/N "" "Usage Page 1 Usage 2"
Debug [Controller]: Found "Apple Inc." "Apple Internal Keyboard / Trackpad" "r549" S/N "" "Usage Page 65280 Usage 1"
Debug [Controller]: ControllerManager::getControllerList
Debug [Controller]: Controller polling stopped.
Debug [Main]: Opened PortAudio stream successfully... starting
Debug [Main]: PortAudio: Started stream successfully
Debug [Main]:    Actual sample rate:  96000 Hz, latency: 16.2396 ms
Debug [Main]: Compressor attack per frame:  0.0001875 decay per frame:  1.875e-05
Debug [Main]: SoundDeviceNetwork::open() "Network stream"
Debug [Main]: framesPerBuffer: 1024
Debug [Main]: Requested sample rate:  96000 Hz, latency: 10.6667 ms
Debug [Main]: Using "Built-in Output" as output sound device clock reference
Debug [Main]: 2 output sound devices opened
Debug [Main]: 0 input  sound devices opened
Debug [Main]: Displaying mixxx
Debug [Main]: Running Mixxx
Debug [Main]: ControllerManager::getControllerList
Debug []: timeSinceLastCbSecs 1.38344e+06 callbackEntrytoDacSecs 0.0358016 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0106667 diff 1.38344e+06
Debug []: SSE: Denormals to zero mode already enabled
Debug []: SSE: Flush to zero mode already enabled
Debug []: Denormals to zero mode is working
Debug [Engine]: timeSinceLastCbSecs 0.0189008 callbackEntrytoDacSecs 0.0213333 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0358016 diff 0.0189008
Debug [Engine]: timeSinceLastCbSecs 6.314e-05 callbackEntrytoDacSecs 0.0213333 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0213333 diff 0.0251981
Warning [Engine]: SoundDevicePortAudio: Audio API provides invalid time stamps, syncing waveforms with a CPU Timer DacTime: 1.38344e+06 EntrytoDac: 0.0445354 TimeSinceLastCb: 0.00429483 diff: 0.0168302
Debug [Engine]: timeSinceLastCbSecs 0.00429483 callbackEntrytoDacSecs 0.0213333 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0213333 diff 0.0168302
Debug [Engine]: timeSinceLastCbSecs 0.000350563 callbackEntrytoDacSecs 0.0213333 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0213333 diff 0.0235526
Debug [Engine]: timeSinceLastCbSecs 0.0228391 callbackEntrytoDacSecs 0.042677 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0213333 diff 0.0335161
Debug [Engine]: timeSinceLastCbSecs 0.000300195 callbackEntrytoDacSecs 0.0533437 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.042677 diff 0.000300195
Debug [Engine]: timeSinceLastCbSecs 0.0228545 callbackEntrytoDacSecs 0.0408525 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0533437 diff -0.000303373
Debug [Engine]: timeSinceLastCbSecs 0.000105046 callbackEntrytoDacSecs 0.0515191 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0408525 diff 0.000105046
Debug [Engine]: timeSinceLastCbSecs 0.0232518 callbackEntrytoDacSecs 0.0388371 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0515191 diff -9.68626e-05
Debug [Engine]: timeSinceLastCbSecs 0.00049637 callbackEntrytoDacSecs 0.0495038 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0388371 diff 0.00049637
Debug [Engine]: timeSinceLastCbSecs 0.0225944 callbackEntrytoDacSecs 0.0370739 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0495038 diff -0.000502181
Debug [Engine]: timeSinceLastCbSecs 0.000117252 callbackEntrytoDacSecs 0.0477406 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0370739 diff 0.000117252
Debug [Engine]: timeSinceLastCbSecs 0.000107314 callbackEntrytoDacSecs 0.0584072 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0477406 diff 0.000107314
Debug [Engine]: timeSinceLastCbSecs 0.0230448 callbackEntrytoDacSecs 0.045807 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0584072 diff -0.000222115
Debug [Engine]: timeSinceLastCbSecs 0.000118436 callbackEntrytoDacSecs 0.0564737 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.045807 diff 0.000118436
Debug [Engine]: timeSinceLastCbSecs 0.0233065 callbackEntrytoDacSecs 0.0437418 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0564737 diff -9.20359e-05
Debug [Engine]: timeSinceLastCbSecs 0.00035703 callbackEntrytoDacSecs 0.0544084 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0437418 diff 0.00035703
Debug [Engine]: timeSinceLastCbSecs 0.0226132 callbackEntrytoDacSecs 0.0420802 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0544084 diff -0.000381626
Debug [Engine]: timeSinceLastCbSecs 0.000117731 callbackEntrytoDacSecs 0.0527469 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0420802 diff 0.000117731
Debug [Engine]: timeSinceLastCbSecs 0.0231228 callbackEntrytoDacSecs 0.0401651 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0527469 diff -0.000125659
Debug [Engine]: timeSinceLastCbSecs 0.000150309 callbackEntrytoDacSecs 0.0508318 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0401651 diff 0.000150309
Debug [Engine]: timeSinceLastCbSecs 0.0230508 callbackEntrytoDacSecs 0.0382962 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0508318 diff -0.000151401
Debug [Engine]: timeSinceLastCbSecs 0.000122865 callbackEntrytoDacSecs 0.0489629 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0382962 diff 0.000122865
Debug [Engine]: timeSinceLastCbSecs 0.0230853 callbackEntrytoDacSecs 0.0364223 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0489629 diff -0.000121942
Debug [Engine]: timeSinceLastCbSecs 0.000104867 callbackEntrytoDacSecs 0.047089 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0364223 diff 0.000104867
Debug [Engine]: timeSinceLastCbSecs 5.3402e-05 callbackEntrytoDacSecs 0.0577557 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.047089 diff 5.34019e-05
Debug [Engine]: timeSinceLastCbSecs 0.0230802 callbackEntrytoDacSecs 0.0451862 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0577557 diff -0.000155929
Debug [Engine]: timeSinceLastCbSecs 0.000120034 callbackEntrytoDacSecs 0.0558529 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0451862 diff 0.000120034
Debug [Engine]: timeSinceLastCbSecs 0.0230872 callbackEntrytoDacSecs 0.0433138 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0558529 diff -0.000118505
Debug [Engine]: timeSinceLastCbSecs 0.000116901 callbackEntrytoDacSecs 0.0539804 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0433138 diff 0.000116901
Debug [Engine]: timeSinceLastCbSecs 0.0231375 callbackEntrytoDacSecs 0.0413939 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0539804 diff -0.000115683
Debug [Engine]: timeSinceLastCbSecs 0.000173782 callbackEntrytoDacSecs 0.0520606 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0413939 diff 0.000173782
Debug [Engine]: timeSinceLastCbSecs 0.0230793 callbackEntrytoDacSecs 0.0394759 bufferSizeSec 0.0106667 m_lastCallbackEntrytoDacSecs 0.0520606 diff -0.000172066

@rryan
Copy link
Member

rryan commented Apr 16, 2016

I enabled very verbose debugging in portaudio. Here's a normal run where the plausibility check passes:

Debug [Main]: Loading SoundSource plugins "/Users/rjryan/Code/mixxx/osx64_build/plugins"
Debug [Main]: SoundSource providers for file extension "aif"
Debug [Main]:   1 : "libsndfile"
Debug [Main]: SoundSource providers for file extension "aiff"
Debug [Main]:   1 : "libsndfile"
Debug [Main]: SoundSource providers for file extension "flac"
Debug [Main]:   2 : "Xiph.org libFLAC"
Debug [Main]:   1 : "libsndfile"
Debug [Main]: SoundSource providers for file extension "it"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: SoundSource providers for file extension "m4a"
Debug [Main]:   2 : "Apple Core Audio"
Debug [Main]: SoundSource providers for file extension "med"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: SoundSource providers for file extension "mod"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: SoundSource providers for file extension "mp2"
Debug [Main]:   2 : "Apple Core Audio"
Debug [Main]: SoundSource providers for file extension "mp3"
Debug [Main]:   2 : "Apple Core Audio"
Debug [Main]: SoundSource providers for file extension "ogg"
Debug [Main]:   2 : "Xiph.org OggVorbis"
Debug [Main]: SoundSource providers for file extension "okt"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: SoundSource providers for file extension "opus"
Debug [Main]:   2 : "Xiph.org libopusfile"
Debug [Main]: SoundSource providers for file extension "s3m"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: SoundSource providers for file extension "stm"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: SoundSource providers for file extension "wav"
Debug [Main]:   1 : "libsndfile"
Debug [Main]: SoundSource providers for file extension "xm"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: qt_mac_get_scalefactor 2
Debug [Main]: "Mixxx" "2.1.0-alpha-pre" "(git clockref r5618; built on: Apr 16 2016 @ 00:29:01; flags: asan=0 autodjcrates=1 battery=0 buildtime=1 bulk=0 color=0 coreaudio=1 faad=1 ffmpeg=0 hid=1 hss1394=0 ipod=0 localecompare=0 macappstore=0 mad=0 mediafoundation=0 modplug=1 opengles=0 optimize=native opus=1 perftools=0 perftools_profiler=0 profiling=0 qdebug=1 qt_sqlite_plugin=1 shoutcast=1 test=1 vamp=1 verbose=0 vinylcontrol=1 wv=1)" is starting...
Debug [Main]: Library versions:
Debug [Main]: Qt: 4.8.7
Debug [Main]: libshout: 2.3.1
Debug [Main]: PortAudio: 1246464 PortAudio V19.5.0-devel, revision unknown
Debug [Main]: RubberBand: 1.8.1
Debug [Main]: SoundTouch: 1.9.2
Debug [Main]: TagLib: 1.9.1
Debug [Main]: ChromaPrint: 1.2.0
Debug [Main]: Vorbis: Xiph.Org libVorbis 1.3.5
Debug [Main]: FLAC: 1.3.1
Debug [Main]: QDesktopServices::storageLocation(HomeLocation): "/Users/rjryan"
Debug [Main]: QDesktopServices::storageLocation(DataLocation): "/Users/rjryan/Library/Application Support/Mixxx"
Debug [Main]: QCoreApplication::applicationDirPath() "/Users/rjryan/Code/mixxx"
Debug [Main]: Loading resources from  "/Users/rjryan/Code/mixxx/res/"
Warning [Main]: Configuration file is at version "2.0.0" instead of the current 2.1.0-alpha-pre
Debug [Main]: Loading resources from  "/Users/rjryan/Code/mixxx/res/"
Warning [Main]: QFileInfo::absolutePath: Constructed with empty filename
Debug [Main]: Loading resources from  "/Users/rjryan/Code/mixxx/res/"
Debug [Main]: Loading translations for locale "en_US" from translations folder "/Users/rjryan/Code/mixxx/res/translations/" : fail
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Samplers]" , "show_samplers" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Microphone]" , "show_microphone" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[VinylControl]" , "show_vinylcontrol" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[PreviewDeck]" , "show_previewdeck" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[EffectRack1]" , "show" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Library]" , "show_coverart" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Master]" , "maximize_library" )
Debug [Main]: Loading resources from  "/Users/rjryan/Code/mixxx/res/"
Debug [Main]: Compressor attack per frame:  0.000408163 decay per frame:  4.08163e-05
before paHostApiInitializers[0].
||PaMacCore (vv)|| PaMacCore_Initialize(): hostApiIndex=0
||PaMacCore (vv)|| gatherDeviceInfo()
||PaMacCore (v )|| Found 2 device(s).
Device 0    : 43
Device 1    : 50
||PaMacCore (v )|| Default in : 43
||PaMacCore (v )|| Default out: 50
||PaMacCore (vv)|| InitializeDeviceInfo(): macCoreDeviceId=43
||PaMacCore (vv)|| GetChannelInfo()
||PaMacCore (vv)|| GetChannelInfo()
||PaMacCore (vv)|| InitializeDeviceInfo(): macCoreDeviceId=50
||PaMacCore (vv)|| GetChannelInfo()
||PaMacCore (vv)|| GetChannelInfo()
after paHostApiInitializers[0].
Debug [Main]: WARNING: AudioInput already registered!
Debug [Main]: WARNING: AudioInput already registered!
Debug [Main]: WARNING: AudioInput already registered!
Debug [Main]: WARNING: AudioInput already registered!
Debug [Main]: Available QtSQL drivers: ("QSQLITE", "QPSQL7", "QPSQL")
Debug [Main]: DB status: "/Users/rjryan/Library/Application Support/Mixxx/mixxxdb.sqlite" = true
Debug [Main]: SchemaManager::upgradeToSchemaVersion already at version 26
Debug [Main]: TrackDAO::initialize QThread(0x7fbba8c6f7c0, name = "Main") "qt_sql_default_connection"
Debug [Main]: CrateDAO::initialize()
Debug [Main]: CueDAO::initialize QThread(0x7fbba8c6f7c0, name = "Main") "qt_sql_default_connection"
Debug [Main]: DirectoryDAO::initialize QThread(0x7fbba8c6f7c0, name = "Main") "qt_sql_default_connection"
Debug [Main]: LibraryHashDAO::initialize QThread(0x7fbba8c6f7c0, name = "Main") "qt_sql_default_connection"
Debug [Main]: Starting LibraryScanner thread.
Debug [LibraryScanner 1]: LibraryHashDAO::initialize LibraryScanner(0x7fbbaeb23b48, name = "LibraryScanner 1") "LIBRARY_SCANNER"
Debug [LibraryScanner 1]: CueDAO::initialize LibraryScanner(0x7fbbaeb23b48, name = "LibraryScanner 1") "LIBRARY_SCANNER"
Debug [LibraryScanner 1]: TrackDAO::initialize LibraryScanner(0x7fbbaeb23b48, name = "LibraryScanner 1") "LIBRARY_SCANNER"
Debug [LibraryScanner 1]: DirectoryDAO::initialize LibraryScanner(0x7fbbaeb23b48, name = "LibraryScanner 1") "LIBRARY_SCANNER"
Debug [LibraryScanner 1]: LibraryScanner event loop starting.
Debug [Main]: Appending Quick Link:  "Music" --- "/Users/rjryan/Music/"
Debug [Main]: Appending Quick Link:  "Downloads" --- "/Users/rjryan/Downloads/"
Debug [Main]: Appending Quick Link:  "DownloadsOld" --- "/Users/rjryan/Downloads/DownloadsOld/"
Debug [Main]: Committing transaction on "qt_sql_default_connection" result: true
Debug [Main]: Traktor Library Location=[ "/Users/rjryan/collection.nml" ]
Debug [Main]: Checking for access to user's library directories:
Debug [Main]: Checking for access to "/Users/rjryan/Drive/Music" : true
Debug [Main]: Checking for access to "/Users/rjryan/Movies" : true
Debug [Main]: AnalyzerWaveform::AnalyzerWaveform()
Debug [Main]: Setting VAMP_PATH to:  "/Users/rjryan/Code/mixxx/osx64_build/vamp-plugins"
Debug [Main]: Creating ControllerManager
Debug [Main]: Extension ".bulk.xml" total 1 presets
Debug [Main]: Extension ".hid.xml" total 15 presets
Debug [Main]: Extension ".midi.xml" total 96 presets
Debug [Main]: Setting VAMP_PATH to:  "/Users/rjryan/Code/mixxx/osx64_build/vamp-plugins:/Users/rjryan/Code/mixxx/osx64_build/vamp-plugins"
Debug [Main]: VampPluginLoader::listPlugins() returned 4 plugins
Debug [Main]: Plugin output displayname: "mixxxbpmdetection:0" "SoundTouch BPM Detector (Legacy)"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:0" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:1" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:2" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:3" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-keydetector:0" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-keydetector:1" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-keydetector:2" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-keydetector:3" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-tempotracker:0" "Tempo and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-tempotracker:1" "Tempo and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-tempotracker:2" "Tempo and Beat Tracker"
Debug [Main]: Setting VAMP_PATH to:  "/Users/rjryan/Code/mixxx/osx64_build/vamp-plugins:/Users/rjryan/Code/mixxx/osx64_build/vamp-plugins:/Users/rjryan/Code/mixxx/osx64_build/vamp-plugins"
Debug [Main]: VampPluginLoader::listPlugins() returned 4 plugins
Debug [Main]: Plugin output displayname: "mixxxbpmdetection:0" "SoundTouch BPM Detector (Legacy)"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:0" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:1" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:2" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:3" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-keydetector:0" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-keydetector:1" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-keydetector:2" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-keydetector:3" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-tempotracker:0" "Tempo and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-tempotracker:1" "Tempo and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-tempotracker:2" "Tempo and Beat Tracker"
Debug [Main]: DlgPrefKey::loadSettings
Debug [Main]: Key plugin ID: "qm-keydetector:2"
Debug [Main]: ControllerManager::getControllerList
Debug [Main]: Set root GL Context widget valid: QGLWidget(0x7fbbae8f31c0) true
Debug [Main]: Created root GL Context valid: 0x7fbbae8f31f0 true
Debug [Main]: Root GL Context format:
Debug [Main]: Double Buffering: true
Debug [Main]: Swap interval: 1
Debug [Main]: Depth buffer: true
Debug [Main]: Direct rendering: true
Debug [Main]: Has overlay: false
Debug [Main]: RGBA: true
Debug [Main]: Sample buffers: false
Debug [Main]: Samples: -1
Debug [Main]: Stencil buffers: true
Debug [Main]: Stereo: false
Debug [Main]: LegacySkinParser loading skin: "/Users/rjryan/Code/mixxx/res/skins/TestKitchen"
Debug [Main]: Skin is a >=1.12.0 style skin.
Warning [Main]: src/skin/legacyskinparser.cpp:570 SKIN ERROR at /Users/rjryan/Code/mixxx/res/skins/TestKitchen/skin.xml:20 <QuickWidget>: Invalid node name in skin: "QuickWidget"
Debug [Main]: MixxxLibraryFeature::activate()
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Samplers]" , "show_samplers" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Microphone]" , "show_microphone" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[VinylControl]" , "show_vinylcontrol" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[PreviewDeck]" , "show_previewdeck" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[EffectRack1]" , "show" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Library]" , "show_coverart" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Master]" , "maximize_library" )
Debug [Controller]: ControllerManager: Setting up devices
Debug [Main]: SoundManager::setupDevices()
Debug [Controller]: Scanning PortMIDI devices:
Debug [LibraryScanner 1]: LibraryScanner::slotStartScan
Debug [Controller]: Scanning HID devices:
Debug [Main]: SoundDevicePortAudio::open() "1, Built-in Output"
Debug [Main]: framesPerBuffer: 64
Debug [Main]: Requested sample rate:  44100 Hz, latency: 1.45125 ms
Debug [Main]: Output channels: 2 | Input channels: 0
Debug [Main]: Opening stream with id 1
||PaMacCore (vv)|| OpenStream(): in chan=-1, in fmt=-1, out chan=2, out fmt=1 SR=44100, FPB=64
||PaMacCore (v )|| Opening Stream.
||PaMacCore (v )|| After querying hardware, setting block size to 64.
||PaMacCore (vv)|| OpenAndSetupOneAudioUnit(): in chan=-1, in fmt=-1, out chan=2, out fmt=1, requestedFramesPerBuffer=64
Debug [LibraryScanner 1]: Recursively scanning library.
2016-04-16 00:44:39.881 mixxx[88769:12210066] 00:44:39.881 WARNING:  140: This application, or a library it uses, is using the deprecated Carbon Component Manager for hosting Audio Units. Support for this will be removed in a future release. Also, this makes the host incompatible with version 3 audio units. Please transition to the API's in AudioComponent.h.
||PaMacCore (v )|| Opened device 50 for output.
||PaMacCore (vv)|| OpenAndSetupOneAudioUnit(): in chan=-1, in fmt=-1, out chan=-1, out fmt=-1, requestedFramesPerBuffer=64
Debug [Controller]: Found "Apple Inc." "Apple Internal Keyboard / Trackpad" "r549" S/N "" "Usage Page 1 Usage 2"
Debug [Controller]: Found "Apple Inc." "Apple Internal Keyboard / Trackpad" "r549" S/N "" "Usage Page 65280 Usage 1"
Debug [Controller]: Found "Apple Inc." "Apple Internal Keyboard / Trackpad" "r549" S/N "" "Usage Page 1 Usage 6"
Debug [Controller]: Found "Apple Inc." "Apple Internal Keyboard / Trackpad" "r549" S/N "" "Usage Page 1 Usage 2"
Debug [Controller]: ControllerManager::getControllerList
Debug [Controller]: Searching for controller preset "Apple_Internal_Keyboard___Trackpad_.hid.xml" in paths: "/Users/rjryan/Library/Application Support/Mixxx/controllers/,/Users/rjryan/Code/mixxx/res/controllers/"
Debug [Controller]: Loading controller preset from "/Users/rjryan/Library/Application Support/Mixxx/controllers/Apple_Internal_Keyboard___Trackpad_.hid.xml"
Debug [Main]: Opened PortAudio stream successfully... starting
||PaMacCore (vv)|| IsStreamStopped()
||PaMacCore (vv)|| StartStream()
||PaMacCore (v )|| Starting stream.
Debug [Controller]: Searching for controller preset "Apple_Internal_Keyboard___Trackpad_--2.hid.xml" in paths: "/Users/rjryan/Library/Application Support/Mixxx/controllers/,/Users/rjryan/Code/mixxx/res/controllers/"
Debug [Main]: PortAudio: Started stream successfully
Debug [Main]:    Actual sample rate:  44100 Hz, latency: 13.5828 ms
Debug [Main]: SoundDeviceNetwork::open() "Network stream"
Debug [Controller]: Loading controller preset from "/Users/rjryan/Library/Application Support/Mixxx/controllers/Apple_Internal_Keyboard___Trackpad_--2.hid.xml"
Debug [Main]: framesPerBuffer: 64
Debug [Main]: Requested sample rate:  44100 Hz, latency: 1.45125 ms
Debug [Main]: Using "Built-in Output" as output sound device clock reference
Debug [Main]: 2 output sound devices opened
Debug [Main]: 0 input  sound devices opened
Debug [Controller]: Searching for controller preset "Apple_Internal_Keyboard___Trackpad_--3.hid.xml" in paths: "/Users/rjryan/Library/Application Support/Mixxx/controllers/,/Users/rjryan/Code/mixxx/res/controllers/"
Debug [Controller]: Loading controller preset from "/Users/rjryan/Library/Application Support/Mixxx/controllers/Apple_Internal_Keyboard___Trackpad_--3.hid.xml"
Debug [Main]: Displaying mixxx
Debug [Main]: Running Mixxx
Debug [Main]: ControllerManager::getControllerList
Debug [Controller]: Searching for controller preset "Apple_Internal_Keyboard___Trackpad_--4.hid.xml" in paths: "/Users/rjryan/Library/Application Support/Mixxx/controllers/,/Users/rjryan/Code/mixxx/res/controllers/"
Debug [Controller]: Loading controller preset from "/Users/rjryan/Library/Application Support/Mixxx/controllers/Apple_Internal_Keyboard___Trackpad_--4.hid.xml"
Debug [Controller]: Controller polling stopped.
Debug [LibraryScanner 1]: LibraryScanner::slotFinishHashedScan
Debug [LibraryScanner 1]: LibraryScanner::slotFinishUnhashedScan
Debug [LibraryScanner 1]: Recursive scanning finished cleanly.
Debug [LibraryScanner 1]: Committing transaction on "LIBRARY_SCANNER" result: true
Debug [LibraryScanner 1]: Marking tracks in changed directories as verified
Debug [LibraryScanner 1]: Marking unchanged directories and tracks as verified
Debug [LibraryScanner 1]: Checking remaining unverified tracks.
Debug [LibraryScanner 1]: Marking unverified tracks as deleted.
Debug [LibraryScanner 1]: Marking unverified directories as deleted.
Debug [LibraryScanner 1]: Detecting moved files.
Debug [LibraryScanner 1]: Committing transaction on "LIBRARY_SCANNER" result: true
Debug [LibraryScanner 1]: Detecting cover art for unscanned files.
Debug [LibraryScanner 1]: Scan finished cleanly
Debug [LibraryScanner 1]: Scan took: 16456057 ns. 14 unchanged directories. 0 changed/added directories. 0 tracks verified from changed/added directories. 0 new tracks.
Debug [Main]: BaseTrackCache(0x7fbbaea45b20) updateIndexWithQuery took 2 ms
Debug [Main]: LibraryTableModel(0x7fbbae77fc30) select() took 4 ms 281
||PaMacCore (vv)|| AudioIOProc()
Debug []: timeSinceLastCbSecs 1.38829e+06 callbackEntrytoDacSecs 0.013509 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.00145125 diff 1.38829e+06
Debug []: SSE: Denormals to zero mode already enabled
Debug []: SSE: Flush to zero mode already enabled
Debug []: Denormals to zero mode is working
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00140868 callbackEntrytoDacSecs 0.013538 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013509 diff -1.36413e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00156359 callbackEntrytoDacSecs 0.0134267 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013538 diff 1.10082e-06
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0014545 callbackEntrytoDacSecs 0.0134235 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134267 diff 3.28285e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146521 callbackEntrytoDacSecs 0.0134095 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134235 diff -5.61314e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143655 callbackEntrytoDacSecs 0.0134242 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134095 diff 4.89305e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145196 callbackEntrytoDacSecs 0.0134235 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134242 diff -2.82923e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0014224 callbackEntrytoDacSecs 0.013453 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134235 diff 6.47889e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146689 callbackEntrytoDacSecs 0.0134368 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013453 diff -5.37307e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146186 callbackEntrytoDacSecs 0.0134261 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134368 diff -9.6814e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145875 callbackEntrytoDacSecs 0.0134186 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134261 diff 1.77263e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00141868 callbackEntrytoDacSecs 0.0134512 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134186 diff 2.08382e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00149518 callbackEntrytoDacSecs 0.0134073 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134512 diff 6.37054e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146992 callbackEntrytoDacSecs 0.0133886 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134073 diff -8.71931e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.001423 callbackEntrytoDacSecs 0.0134168 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0133886 diff -3.51183e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146046 callbackEntrytoDacSecs 0.0134076 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134168 diff 1.77912e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143927 callbackEntrytoDacSecs 0.0134199 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134076 diff 3.629e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143248 callbackEntrytoDacSecs 0.0134385 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134199 diff -1.72242e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143631 callbackEntrytoDacSecs 0.0134532 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134385 diff -2.17024e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00147978 callbackEntrytoDacSecs 0.0134247 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134532 diff 2.88025e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00147158 callbackEntrytoDacSecs 0.0134045 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134247 diff 1.00947e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0014591 callbackEntrytoDacSecs 0.013397 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134045 diff 3.26626e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00139599 callbackEntrytoDacSecs 0.0134522 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013397 diff -2.02176e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00137028 callbackEntrytoDacSecs 0.0135329 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134522 diff -2.98195e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143087 callbackEntrytoDacSecs 0.0135521 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135329 diff -1.14114e-06
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144904 callbackEntrytoDacSecs 0.0135544 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135521 diff 1.25962e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144797 callbackEntrytoDacSecs 0.0135575 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135544 diff -2.38371e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144634 callbackEntrytoDacSecs 0.0135623 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135575 diff -9.29531e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144789 callbackEntrytoDacSecs 0.0135656 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135623 diff -3.82602e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146981 callbackEntrytoDacSecs 0.013547 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135656 diff -1.8009e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00142498 callbackEntrytoDacSecs 0.0135733 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013547 diff 5.07776e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0048263 callbackEntrytoDacSecs 0.0135544 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135733 diff 0.00335613
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144913 callbackEntrytoDacSecs 0.0135567 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135544 diff 1.47139e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00149173 callbackEntrytoDacSecs 0.0135159 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135567 diff -2.77361e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00140471 callbackEntrytoDacSecs 0.0135624 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135159 diff -2.88894e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00147754 callbackEntrytoDacSecs 0.0135364 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135624 diff 2.33635e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00140532 callbackEntrytoDacSecs 0.0135821 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135364 diff -2.22155e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00147908 callbackEntrytoDacSecs 0.0135543 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135821 diff 9.37618e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146181 callbackEntrytoDacSecs 0.0135439 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135543 diff 1.34926e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144582 callbackEntrytoDacSecs 0.0135492 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135439 diff -1.05096e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145693 callbackEntrytoDacSecs 0.0135434 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135492 diff -1.28359e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00149324 callbackEntrytoDacSecs 0.0135017 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135434 diff 3.00851e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00148968 callbackEntrytoDacSecs 0.0134636 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135017 diff 2.8882e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0013733 callbackEntrytoDacSecs 0.013541 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134636 diff -5.88047e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00149239 callbackEntrytoDacSecs 0.0135001 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013541 diff 2.88713e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145173 callbackEntrytoDacSecs 0.0134997 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135001 diff 1.33081e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145724 callbackEntrytoDacSecs 0.0134935 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134997 diff -2.10213e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00152146 callbackEntrytoDacSecs 0.0134247 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134935 diff 1.34489e-06
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146874 callbackEntrytoDacSecs 0.0134069 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134247 diff -2.6446e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143448 callbackEntrytoDacSecs 0.0134241 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134069 diff 3.58994e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00142098 callbackEntrytoDacSecs 0.0134542 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134241 diff -1.57178e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00148103 callbackEntrytoDacSecs 0.0134244 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134542 diff 3.1708e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146037 callbackEntrytoDacSecs 0.0134153 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134244 diff -9.09014e-10
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00131538 callbackEntrytoDacSecs 0.0135499 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134153 diff -1.24825e-06
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.001455 callbackEntrytoDacSecs 0.0135464 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135499 diff 1.99881e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145053 callbackEntrytoDacSecs 0.0135473 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135464 diff 1.84779e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143967 callbackEntrytoDacSecs 0.0135583 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135473 diff -5.38226e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145067 callbackEntrytoDacSecs 0.0135589 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135583 diff -1.12229e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144805 callbackEntrytoDacSecs 0.0135621 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135589 diff 9.93923e-09
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0014481 callbackEntrytoDacSecs 0.0135651 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135621 diff -1.24257e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00524222 callbackEntrytoDacSecs 0.0134931 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135651 diff 0.00371893
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143115 callbackEntrytoDacSecs 0.0135131 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134931 diff -4.60233e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145077 callbackEntrytoDacSecs 0.0135138 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135131 diff 2.30831e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00141261 callbackEntrytoDacSecs 0.0135523 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135138 diff -1.79227e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145914 callbackEntrytoDacSecs 0.0135445 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135523 diff 1.34959e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144086 callbackEntrytoDacSecs 0.0135551 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135445 diff 2.23748e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146386 callbackEntrytoDacSecs 0.0135426 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135551 diff 9.27368e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00150439 callbackEntrytoDacSecs 0.0134891 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135426 diff -3.21272e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00137388 callbackEntrytoDacSecs 0.0135664 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0134891 diff -1.34023e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145077 callbackEntrytoDacSecs 0.0135669 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135664 diff 2.48592e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145519 callbackEntrytoDacSecs 0.0135629 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135669 diff -3.90084e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0014431 callbackEntrytoDacSecs 0.0135711 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135629 diff 1.8644e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144975 callbackEntrytoDacSecs 0.0135724 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135711 diff -1.71031e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0014466 callbackEntrytoDacSecs 0.013577 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135724 diff -5.31647e-09
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00148634 callbackEntrytoDacSecs 0.0135421 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013577 diff 2.00807e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144055 callbackEntrytoDacSecs 0.0135529 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135421 diff 9.29318e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0167808 callbackEntrytoDacSecs 0.0135523 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135529 diff 0.0153289
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144721 callbackEntrytoDacSecs 0.013556 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135523 diff -2.89222e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0014528 callbackEntrytoDacSecs 0.0135544 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013556 diff -4.71509e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144961 callbackEntrytoDacSecs 0.013556 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135544 diff -4.02272e-09
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145007 callbackEntrytoDacSecs 0.0135572 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013556 diff 9.66773e-09
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0014697 callbackEntrytoDacSecs 0.0135389 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135572 diff 8.90846e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0279234 callbackEntrytoDacSecs 0.0135523 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135389 diff 0.0264856
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143975 callbackEntrytoDacSecs 0.0135635 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135523 diff -2.64251e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0014551 callbackEntrytoDacSecs 0.0135597 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135635 diff 4.5958e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.001446 callbackEntrytoDacSecs 0.0135648 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135597 diff -1.6035e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145993 callbackEntrytoDacSecs 0.0135561 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135648 diff -4.49177e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0177577 callbackEntrytoDacSecs 0.0135766 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135561 diff 0.0163271
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143965 callbackEntrytoDacSecs 0.0135875 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135766 diff -6.68286e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146672 callbackEntrytoDacSecs 0.0135721 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135875 diff 3.29032e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146045 callbackEntrytoDacSecs 0.013563 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135721 diff 6.0766e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144825 callbackEntrytoDacSecs 0.013566 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013563 diff 1.59913e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145778 callbackEntrytoDacSecs 0.0135597 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013566 diff 2.19796e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145123 callbackEntrytoDacSecs 0.0135611 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135597 diff 1.43393e-06
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0150472 callbackEntrytoDacSecs 0.0135694 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135611 diff 0.0136043
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00147196 callbackEntrytoDacSecs 0.0135485 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135694 diff -1.96166e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0014246 callbackEntrytoDacSecs 0.013575 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135485 diff -1.48313e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146218 callbackEntrytoDacSecs 0.0135642 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013575 diff 1.48982e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143891 callbackEntrytoDacSecs 0.0135765 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135642 diff -5.61581e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144476 callbackEntrytoDacSecs 0.0135828 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135765 diff -1.77154e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144623 callbackEntrytoDacSecs 0.0135877 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135828 diff -1.36146e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0144714 callbackEntrytoDacSecs 0.0135384 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135877 diff 0.0129709
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00159691 callbackEntrytoDacSecs 0.0133926 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135384 diff -1.91033e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00128878 callbackEntrytoDacSecs 0.013555 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0133926 diff -3.01149e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145187 callbackEntrytoDacSecs 0.0135544 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.013555 diff -8.13658e-09
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145105 callbackEntrytoDacSecs 0.0135546 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135544 diff 6.0784e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144974 callbackEntrytoDacSecs 0.0135561 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135546 diff -9.50896e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0150463 callbackEntrytoDacSecs 0.0135669 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135561 diff 0.0136059
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143894 callbackEntrytoDacSecs 0.0135789 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135669 diff -3.36342e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146706 callbackEntrytoDacSecs 0.0135631 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135789 diff 1.76723e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145443 callbackEntrytoDacSecs 0.0135601 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135631 diff 1.66116e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144034 callbackEntrytoDacSecs 0.0135708 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135601 diff -1.69413e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00146371 callbackEntrytoDacSecs 0.0135585 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135708 diff 1.61117e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143189 callbackEntrytoDacSecs 0.0135778 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135585 diff -9.94147e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0213763 callbackEntrytoDacSecs 0.0135168 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135778 diff 0.0198642
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00141599 callbackEntrytoDacSecs 0.0135517 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135168 diff -4.16224e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00142125 callbackEntrytoDacSecs 0.0135816 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135517 diff -6.48968e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00147661 callbackEntrytoDacSecs 0.0135563 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135816 diff 7.77549e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145168 callbackEntrytoDacSecs 0.0135559 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135563 diff 1.07544e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144246 callbackEntrytoDacSecs 0.0135648 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135559 diff 6.38227e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.01815 callbackEntrytoDacSecs 0.0135556 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135648 diff 0.0166896
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00148195 callbackEntrytoDacSecs 0.0135259 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135556 diff 9.628e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00143587 callbackEntrytoDacSecs 0.0135403 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135259 diff -9.77056e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144557 callbackEntrytoDacSecs 0.0135459 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135403 diff -3.84311e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00141926 callbackEntrytoDacSecs 0.0135778 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135459 diff -1.1791e-07
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00144843 callbackEntrytoDacSecs 0.0135805 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135778 diff -9.4238e-08
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0152702 callbackEntrytoDacSecs 0.0135488 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135805 diff 0.0137872
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00145156 callbackEntrytoDacSecs 0.0135482 bufferSizeSec 0.00145125 m_lastCallbackEntrytoDacSecs 0.0135488 diff -2.2621e-07
||PaMacCore (vv)|| AudioIOProc()

@rryan
Copy link
Member

rryan commented Apr 16, 2016

And here's a run where it fails:

Debug [Main]: Loading SoundSource plugins "/Users/rjryan/Code/mixxx/osx64_build/plugins"
Debug [Main]: SoundSource providers for file extension "aif"
Debug [Main]:   1 : "libsndfile"
Debug [Main]: SoundSource providers for file extension "aiff"
Debug [Main]:   1 : "libsndfile"
Debug [Main]: SoundSource providers for file extension "flac"
Debug [Main]:   2 : "Xiph.org libFLAC"
Debug [Main]:   1 : "libsndfile"
Debug [Main]: SoundSource providers for file extension "it"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: SoundSource providers for file extension "m4a"
Debug [Main]:   2 : "Apple Core Audio"
Debug [Main]: SoundSource providers for file extension "med"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: SoundSource providers for file extension "mod"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: SoundSource providers for file extension "mp2"
Debug [Main]:   2 : "Apple Core Audio"
Debug [Main]: SoundSource providers for file extension "mp3"
Debug [Main]:   2 : "Apple Core Audio"
Debug [Main]: SoundSource providers for file extension "ogg"
Debug [Main]:   2 : "Xiph.org OggVorbis"
Debug [Main]: SoundSource providers for file extension "okt"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: SoundSource providers for file extension "opus"
Debug [Main]:   2 : "Xiph.org libopusfile"
Debug [Main]: SoundSource providers for file extension "s3m"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: SoundSource providers for file extension "stm"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: SoundSource providers for file extension "wav"
Debug [Main]:   1 : "libsndfile"
Debug [Main]: SoundSource providers for file extension "xm"
Debug [Main]:   2 : "MODPlug"
Debug [Main]: qt_mac_get_scalefactor 2
Debug [Main]: "Mixxx" "2.1.0-alpha-pre" "(git clockref r5618; built on: Apr 16 2016 @ 00:29:01; flags: asan=0 autodjcrates=1 battery=0 buildtime=1 bulk=0 color=0 coreaudio=1 faad=1 ffmpeg=0 hid=1 hss1394=0 ipod=0 localecompare=0 macappstore=0 mad=0 mediafoundation=0 modplug=1 opengles=0 optimize=native opus=1 perftools=0 perftools_profiler=0 profiling=0 qdebug=1 qt_sqlite_plugin=1 shoutcast=1 test=1 vamp=1 verbose=0 vinylcontrol=1 wv=1)" is starting...
Debug [Main]: Library versions:
Debug [Main]: Qt: 4.8.7
Debug [Main]: libshout: 2.3.1
Debug [Main]: PortAudio: 1246464 PortAudio V19.5.0-devel, revision unknown
Debug [Main]: RubberBand: 1.8.1
Debug [Main]: SoundTouch: 1.9.2
Debug [Main]: TagLib: 1.9.1
Debug [Main]: ChromaPrint: 1.2.0
Debug [Main]: Vorbis: Xiph.Org libVorbis 1.3.5
Debug [Main]: FLAC: 1.3.1
Debug [Main]: QDesktopServices::storageLocation(HomeLocation): "/Users/rjryan"
Debug [Main]: QDesktopServices::storageLocation(DataLocation): "/Users/rjryan/Library/Application Support/Mixxx"
Debug [Main]: QCoreApplication::applicationDirPath() "/Users/rjryan/Code/mixxx"
Debug [Main]: Loading resources from  "/Users/rjryan/Code/mixxx/res/"
Warning [Main]: Configuration file is at version "2.0.0" instead of the current 2.1.0-alpha-pre
Debug [Main]: Loading resources from  "/Users/rjryan/Code/mixxx/res/"
Warning [Main]: QFileInfo::absolutePath: Constructed with empty filename
Debug [Main]: Loading resources from  "/Users/rjryan/Code/mixxx/res/"
Debug [Main]: Loading translations for locale "en_US" from translations folder "/Users/rjryan/Code/mixxx/res/translations/" : fail
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Samplers]" , "show_samplers" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Microphone]" , "show_microphone" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[VinylControl]" , "show_vinylcontrol" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[PreviewDeck]" , "show_previewdeck" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[EffectRack1]" , "show" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Library]" , "show_coverart" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Master]" , "maximize_library" )
Debug [Main]: Loading resources from  "/Users/rjryan/Code/mixxx/res/"
Debug [Main]: Compressor attack per frame:  0.000408163 decay per frame:  4.08163e-05
before paHostApiInitializers[0].
||PaMacCore (vv)|| PaMacCore_Initialize(): hostApiIndex=0
||PaMacCore (vv)|| gatherDeviceInfo()
||PaMacCore (v )|| Found 2 device(s).
Device 0    : 43
Device 1    : 50
||PaMacCore (v )|| Default in : 43
||PaMacCore (v )|| Default out: 50
||PaMacCore (vv)|| InitializeDeviceInfo(): macCoreDeviceId=43
||PaMacCore (vv)|| GetChannelInfo()
||PaMacCore (vv)|| GetChannelInfo()
||PaMacCore (vv)|| InitializeDeviceInfo(): macCoreDeviceId=50
||PaMacCore (vv)|| GetChannelInfo()
||PaMacCore (vv)|| GetChannelInfo()
after paHostApiInitializers[0].
Debug [Main]: WARNING: AudioInput already registered!
Debug [Main]: WARNING: AudioInput already registered!
Debug [Main]: WARNING: AudioInput already registered!
Debug [Main]: WARNING: AudioInput already registered!
Debug [Main]: Available QtSQL drivers: ("QSQLITE", "QPSQL7", "QPSQL")
Debug [Main]: DB status: "/Users/rjryan/Library/Application Support/Mixxx/mixxxdb.sqlite" = true
Debug [Main]: SchemaManager::upgradeToSchemaVersion already at version 26
Debug [Main]: TrackDAO::initialize QThread(0x7ff2ca46f7c0, name = "Main") "qt_sql_default_connection"
Debug [Main]: CrateDAO::initialize()
Debug [Main]: CueDAO::initialize QThread(0x7ff2ca46f7c0, name = "Main") "qt_sql_default_connection"
Debug [Main]: DirectoryDAO::initialize QThread(0x7ff2ca46f7c0, name = "Main") "qt_sql_default_connection"
Debug [Main]: LibraryHashDAO::initialize QThread(0x7ff2ca46f7c0, name = "Main") "qt_sql_default_connection"
Debug [Main]: Starting LibraryScanner thread.
Debug [LibraryScanner 1]: LibraryHashDAO::initialize LibraryScanner(0x7ff2cfffbe98, name = "LibraryScanner 1") "LIBRARY_SCANNER"
Debug [LibraryScanner 1]: CueDAO::initialize LibraryScanner(0x7ff2cfffbe98, name = "LibraryScanner 1") "LIBRARY_SCANNER"
Debug [LibraryScanner 1]: TrackDAO::initialize LibraryScanner(0x7ff2cfffbe98, name = "LibraryScanner 1") "LIBRARY_SCANNER"
Debug [LibraryScanner 1]: DirectoryDAO::initialize LibraryScanner(0x7ff2cfffbe98, name = "LibraryScanner 1") "LIBRARY_SCANNER"
Debug [LibraryScanner 1]: LibraryScanner event loop starting.
Debug [Main]: Appending Quick Link:  "Music" --- "/Users/rjryan/Music/"
Debug [Main]: Appending Quick Link:  "Downloads" --- "/Users/rjryan/Downloads/"
Debug [Main]: Appending Quick Link:  "DownloadsOld" --- "/Users/rjryan/Downloads/DownloadsOld/"
Debug [Main]: Committing transaction on "qt_sql_default_connection" result: true
Debug [Main]: Traktor Library Location=[ "/Users/rjryan/collection.nml" ]
Debug [Main]: Checking for access to user's library directories:
Debug [Main]: Checking for access to "/Users/rjryan/Drive/Music" : true
Debug [Main]: Checking for access to "/Users/rjryan/Movies" : true
Debug [Main]: AnalyzerWaveform::AnalyzerWaveform()
Debug [Main]: Setting VAMP_PATH to:  "/Users/rjryan/Code/mixxx/osx64_build/vamp-plugins"
Debug [Main]: Creating ControllerManager
Debug [Main]: Extension ".bulk.xml" total 1 presets
Debug [Main]: Extension ".hid.xml" total 15 presets
Debug [Main]: Extension ".midi.xml" total 96 presets
Debug [Main]: Setting VAMP_PATH to:  "/Users/rjryan/Code/mixxx/osx64_build/vamp-plugins:/Users/rjryan/Code/mixxx/osx64_build/vamp-plugins"
Debug [Main]: VampPluginLoader::listPlugins() returned 4 plugins
Debug [Main]: Plugin output displayname: "mixxxbpmdetection:0" "SoundTouch BPM Detector (Legacy)"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:0" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:1" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:2" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:3" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-keydetector:0" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-keydetector:1" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-keydetector:2" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-keydetector:3" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-tempotracker:0" "Tempo and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-tempotracker:1" "Tempo and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-tempotracker:2" "Tempo and Beat Tracker"
Debug [Main]: Setting VAMP_PATH to:  "/Users/rjryan/Code/mixxx/osx64_build/vamp-plugins:/Users/rjryan/Code/mixxx/osx64_build/vamp-plugins:/Users/rjryan/Code/mixxx/osx64_build/vamp-plugins"
Debug [Main]: VampPluginLoader::listPlugins() returned 4 plugins
Debug [Main]: Plugin output displayname: "mixxxbpmdetection:0" "SoundTouch BPM Detector (Legacy)"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:0" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:1" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:2" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-barbeattracker:3" "Bar and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-keydetector:0" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-keydetector:1" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-keydetector:2" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-keydetector:3" "Key Detector"
Debug [Main]: Plugin output displayname: "qm-tempotracker:0" "Tempo and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-tempotracker:1" "Tempo and Beat Tracker"
Debug [Main]: Plugin output displayname: "qm-tempotracker:2" "Tempo and Beat Tracker"
Debug [Main]: DlgPrefKey::loadSettings
Debug [Main]: Key plugin ID: "qm-keydetector:2"
Debug [Main]: ControllerManager::getControllerList
Debug [Main]: Set root GL Context widget valid: QGLWidget(0x7ff2ca591890) true
Debug [Main]: Created root GL Context valid: 0x7ff2cfeabaf0 true
Debug [Main]: Root GL Context format:
Debug [Main]: Double Buffering: true
Debug [Main]: Swap interval: 1
Debug [Main]: Depth buffer: true
Debug [Main]: Direct rendering: true
Debug [Main]: Has overlay: false
Debug [Main]: RGBA: true
Debug [Main]: Sample buffers: false
Debug [Main]: Samples: -1
Debug [Main]: Stencil buffers: true
Debug [Main]: Stereo: false
Debug [Main]: LegacySkinParser loading skin: "/Users/rjryan/Code/mixxx/res/skins/TestKitchen"
Debug [Main]: Skin is a >=1.12.0 style skin.
Warning [Main]: src/skin/legacyskinparser.cpp:570 SKIN ERROR at /Users/rjryan/Code/mixxx/res/skins/TestKitchen/skin.xml:20 <QuickWidget>: Invalid node name in skin: "QuickWidget"
Debug [Main]: MixxxLibraryFeature::activate()
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Samplers]" , "show_samplers" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Microphone]" , "show_microphone" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[VinylControl]" , "show_vinylcontrol" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[PreviewDeck]" , "show_previewdeck" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[EffectRack1]" , "show" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Library]" , "show_coverart" )
Warning [Main]: ControlDoublePrivate::getControl returning NULL for ( "[Master]" , "maximize_library" )
Debug [Controller]: ControllerManager: Setting up devices
Debug [Main]: SoundManager::setupDevices()
Debug [Controller]: Scanning PortMIDI devices:
Debug [Controller]: Scanning HID devices:
Debug [Main]: SoundDevicePortAudio::open() "1, Built-in Output"
Debug [Main]: framesPerBuffer: 128
Debug [Main]: Requested sample rate:  96000 Hz, latency: 1.33333 ms
Debug [Main]: Output channels: 2 | Input channels: 0
Debug [Main]: Opening stream with id 1
||PaMacCore (vv)|| OpenStream(): in chan=-1, in fmt=-1, out chan=2, out fmt=1 SR=96000, FPB=128
||PaMacCore (v )|| Opening Stream.
||PaMacCore (v )|| After querying hardware, setting block size to 128.
||PaMacCore (vv)|| OpenAndSetupOneAudioUnit(): in chan=-1, in fmt=-1, out chan=2, out fmt=1, requestedFramesPerBuffer=128
Debug [Controller]: Found "Apple Inc." "Apple Internal Keyboard / Trackpad" "r549" S/N "" "Usage Page 1 Usage 6"
Debug [Controller]: Found "Apple Inc." "Apple Internal Keyboard / Trackpad" "r549" S/N "" "Usage Page 1 Usage 2"
Debug [Controller]: Found "Apple Inc." "Apple Internal Keyboard / Trackpad" "r549" S/N "" "Usage Page 65280 Usage 1"
Debug [Controller]: Found "Apple Inc." "Apple Internal Keyboard / Trackpad" "r549" S/N "" "Usage Page 1 Usage 2"
Debug [Controller]: ControllerManager::getControllerList
Debug [Controller]: Searching for controller preset "Apple_Internal_Keyboard___Trackpad_.hid.xml" in paths: "/Users/rjryan/Library/Application Support/Mixxx/controllers/,/Users/rjryan/Code/mixxx/res/controllers/"
2016-04-16 00:48:30.184 mixxx[88895:12211856] 00:48:30.184 WARNING:  140: This application, or a library it uses, is using the deprecated Carbon Component Manager for hosting Audio Units. Support for this will be removed in a future release. Also, this makes the host incompatible with version 3 audio units. Please transition to the API's in AudioComponent.h.
Debug [Controller]: Loading controller preset from "/Users/rjryan/Library/Application Support/Mixxx/controllers/Apple_Internal_Keyboard___Trackpad_.hid.xml"
Debug [Controller]: Searching for controller preset "Apple_Internal_Keyboard___Trackpad_--2.hid.xml" in paths: "/Users/rjryan/Library/Application Support/Mixxx/controllers/,/Users/rjryan/Code/mixxx/res/controllers/"
Debug [Controller]: Loading controller preset from "/Users/rjryan/Library/Application Support/Mixxx/controllers/Apple_Internal_Keyboard___Trackpad_--2.hid.xml"
Debug [Controller]: Searching for controller preset "Apple_Internal_Keyboard___Trackpad_--3.hid.xml" in paths: "/Users/rjryan/Library/Application Support/Mixxx/controllers/,/Users/rjryan/Code/mixxx/res/controllers/"
Debug [Controller]: Loading controller preset from "/Users/rjryan/Library/Application Support/Mixxx/controllers/Apple_Internal_Keyboard___Trackpad_--3.hid.xml"
Debug [Controller]: Searching for controller preset "Apple_Internal_Keyboard___Trackpad_--4.hid.xml" in paths: "/Users/rjryan/Library/Application Support/Mixxx/controllers/,/Users/rjryan/Code/mixxx/res/controllers/"
Debug [Controller]: Loading controller preset from "/Users/rjryan/Library/Application Support/Mixxx/controllers/Apple_Internal_Keyboard___Trackpad_--4.hid.xml"
Debug [Controller]: Controller polling stopped.
||PaMacCore (v )|| Opened device 50 for output.
||PaMacCore (vv)|| OpenAndSetupOneAudioUnit(): in chan=-1, in fmt=-1, out chan=-1, out fmt=-1, requestedFramesPerBuffer=128
Debug [Main]: Opened PortAudio stream successfully... starting
||PaMacCore (vv)|| IsStreamStopped()
||PaMacCore (vv)|| StartStream()
||PaMacCore (v )|| Starting stream.
Debug [Main]: PortAudio: Started stream successfully
Debug [Main]:    Actual sample rate:  96000 Hz, latency: 6.90625 ms
Debug [Main]: Compressor attack per frame:  0.0001875 decay per frame:  1.875e-05
Debug [Main]: SoundDeviceNetwork::open() "Network stream"
Debug [Main]: framesPerBuffer: 128
Debug [Main]: Requested sample rate:  96000 Hz, latency: 1.33333 ms
Debug [Main]: Using "Built-in Output" as output sound device clock reference
Debug [Main]: 2 output sound devices opened
Debug [Main]: 0 input  sound devices opened
Debug [Main]: Displaying mixxx
Debug [Main]: Running Mixxx
Debug [Main]: ControllerManager::getControllerList
||PaMacCore (vv)|| AudioIOProc()
Debug []: timeSinceLastCbSecs 1.38852e+06 callbackEntrytoDacSecs 0.0155224 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00133333 diff 1.38852e+06
Debug []: SSE: Denormals to zero mode already enabled
Debug []: SSE: Flush to zero mode already enabled
Debug []: Denormals to zero mode is working
Debug [Engine]: timeSinceLastCbSecs 0.00016823 callbackEntrytoDacSecs 0.00266667 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0155224 diff 0.00016823
Debug [Engine]: timeSinceLastCbSecs 2.4798e-05 callbackEntrytoDacSecs 0.00266667 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00266667 diff 0.0142139
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00270113 callbackEntrytoDacSecs 0.016616 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00266667 diff 0.0153171
Debug [Engine]: timeSinceLastCbSecs 5.1569e-05 callbackEntrytoDacSecs 0.0179493 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.016616 diff 5.1569e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00665453 callbackEntrytoDacSecs 0.0125734 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0179493 diff -5.47138e-05
Debug [Engine]: timeSinceLastCbSecs 6.6721e-05 callbackEntrytoDacSecs 0.0139067 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0125734 diff 6.6721e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00469975 callbackEntrytoDacSecs 0.0161042 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0139067 diff 0.0055639
Debug [Engine]: timeSinceLastCbSecs 0.000106743 callbackEntrytoDacSecs 0.0174376 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0161042 diff 0.000106743
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00279693 callbackEntrytoDacSecs 0.0158627 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0174376 diff -0.000111223
Debug [Engine]: timeSinceLastCbSecs 7.1892e-05 callbackEntrytoDacSecs 0.0171961 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0158627 diff 7.1892e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00279017 callbackEntrytoDacSecs 0.0156633 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0171961 diff -7.59761e-05
Debug [Engine]: timeSinceLastCbSecs 5.3091e-05 callbackEntrytoDacSecs 0.0169966 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0156633 diff 5.3091e-05
Debug [Engine]: timeSinceLastCbSecs 3.1521e-05 callbackEntrytoDacSecs 0.0183299 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0169966 diff 3.1521e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00279164 callbackEntrytoDacSecs 0.0167936 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0183299 diff -7.80181e-05
Debug [Engine]: timeSinceLastCbSecs 3.2937e-05 callbackEntrytoDacSecs 0.0181269 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0167936 diff 3.2937e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00288929 callbackEntrytoDacSecs 0.0165343 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0181269 diff -3.67181e-05
Debug [Engine]: timeSinceLastCbSecs 4.8494e-05 callbackEntrytoDacSecs 0.0178676 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0165343 diff 4.8494e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.0028704 callbackEntrytoDacSecs 0.016279 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0178676 diff -5.1572e-05
Debug [Engine]: timeSinceLastCbSecs 8.8008e-05 callbackEntrytoDacSecs 0.0176123 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.016279 diff 8.8008e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00284078 callbackEntrytoDacSecs 0.016023 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0176123 diff -8.17983e-05
Debug [Engine]: timeSinceLastCbSecs 5.158e-05 callbackEntrytoDacSecs 0.0173564 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.016023 diff 5.158e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00280748 callbackEntrytoDacSecs 0.0158266 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0173564 diff -5.5605e-05
Debug [Engine]: timeSinceLastCbSecs 3.9494e-05 callbackEntrytoDacSecs 0.01716 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0158266 diff 3.9494e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00286517 callbackEntrytoDacSecs 0.0155848 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.01716 diff -4.32891e-05
Debug [Engine]: timeSinceLastCbSecs 4.8148e-05 callbackEntrytoDacSecs 0.0169182 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0155848 diff 4.8148e-05
Debug [Engine]: timeSinceLastCbSecs 2.9011e-05 callbackEntrytoDacSecs 0.0182515 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0169182 diff 2.9011e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00281773 callbackEntrytoDacSecs 0.0166971 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0182515 diff -7.00323e-05
Debug [Engine]: timeSinceLastCbSecs 9.2667e-05 callbackEntrytoDacSecs 0.0180304 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0166971 diff 9.2667e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00281562 callbackEntrytoDacSecs 0.0164514 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0180304 diff -9.67557e-05
Debug [Engine]: timeSinceLastCbSecs 4.9623e-05 callbackEntrytoDacSecs 0.0177847 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0164514 diff 4.9623e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00296907 callbackEntrytoDacSecs 0.016113 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0177847 diff -3.59395e-05
Warning [Engine]: SoundDevicePortAudio: Audio API provides invalid time stamps, syncing waveforms with a CPU Timer DacTime: 1.38852e+06 EntrytoDac: 0.0174464 TimeSinceLastCb: 0.000318455 diff: 0.000318455
Debug [Engine]: timeSinceLastCbSecs 0.000318455 callbackEntrytoDacSecs 0.00266667 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.016113 diff 0.000318455
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00248064 callbackEntrytoDacSecs 0.00151936 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00266667 diff 0.0144515
Debug [Engine]: timeSinceLastCbSecs 9.7726e-05 callbackEntrytoDacSecs 0.00266667 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00151936 diff 0.0145493
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00278005 callbackEntrytoDacSecs 0.0157549 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00266667 diff 0.0145349
Debug [Engine]: timeSinceLastCbSecs 0.00646836 callbackEntrytoDacSecs 0.0170882 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0157549 diff 0.00646836
Debug [Engine]: timeSinceLastCbSecs 4.6252e-05 callbackEntrytoDacSecs 0.0184215 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0170882 diff 4.6252e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00305457 callbackEntrytoDacSecs 0.016814 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0184215 diff 0.000113718
Debug [Engine]: timeSinceLastCbSecs 4.4678e-05 callbackEntrytoDacSecs 0.0181474 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.016814 diff 4.4678e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00283684 callbackEntrytoDacSecs 0.0165954 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0181474 diff -4.84309e-05
Debug [Engine]: timeSinceLastCbSecs 6.6105e-05 callbackEntrytoDacSecs 0.0179288 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0165954 diff 6.6105e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00285995 callbackEntrytoDacSecs 0.0163329 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0179288 diff -6.92348e-05
Debug [Engine]: timeSinceLastCbSecs 7.8484e-05 callbackEntrytoDacSecs 0.0176662 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0163329 diff 7.8484e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00279512 callbackEntrytoDacSecs 0.0161326 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0176662 diff -7.18236e-05
Debug [Engine]: timeSinceLastCbSecs 7.9606e-05 callbackEntrytoDacSecs 0.017466 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0161326 diff 7.9606e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00282394 callbackEntrytoDacSecs 0.0158916 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.017466 diff -8.37347e-05
Debug [Engine]: timeSinceLastCbSecs 6.1568e-05 callbackEntrytoDacSecs 0.0172249 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0158916 diff 6.1568e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00284566 callbackEntrytoDacSecs 0.0156467 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0172249 diff -6.59163e-05
Debug [Engine]: timeSinceLastCbSecs 5.2305e-05 callbackEntrytoDacSecs 0.01698 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0156467 diff 5.2305e-05
Debug [Engine]: timeSinceLastCbSecs 2.2427e-05 callbackEntrytoDacSecs 0.0183134 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.01698 diff 2.2427e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00282889 callbackEntrytoDacSecs 0.0167498 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0183134 diff -6.80252e-05
Debug [Engine]: timeSinceLastCbSecs 5.0268e-05 callbackEntrytoDacSecs 0.0180831 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0167498 diff 5.0268e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00284125 callbackEntrytoDacSecs 0.0165213 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0180831 diff -5.38862e-05
Debug [Engine]: timeSinceLastCbSecs 5.427e-05 callbackEntrytoDacSecs 0.0178547 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0165213 diff 5.427e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00284112 callbackEntrytoDacSecs 0.0162991 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0178547 diff -4.7782e-05
Debug [Engine]: timeSinceLastCbSecs 5.0111e-05 callbackEntrytoDacSecs 0.0176324 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0162991 diff 5.0111e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00287432 callbackEntrytoDacSecs 0.0160378 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0176324 diff -5.36461e-05
Debug [Engine]: timeSinceLastCbSecs 0.00208927 callbackEntrytoDacSecs 0.00266667 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0160378 diff 0.00208927
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.000857711 callbackEntrytoDacSecs 0.00266667 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00266667 diff 0.0126112
Debug [Engine]: timeSinceLastCbSecs 3.78e-05 callbackEntrytoDacSecs 0.00266667 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00266667 diff 0.0131247
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: timeSinceLastCbSecs 0.00282731 callbackEntrytoDacSecs 0.0155619 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00266667 diff 0.0143892
Debug [Engine]: timeSinceLastCbSecs 0.000113526 callbackEntrytoDacSecs 0.0168952 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0155619 diff 0.000113526
Debug [Engine]: timeSinceLastCbSecs 2.2179e-05 callbackEntrytoDacSecs 0.0182285 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0168952 diff 2.2179e-05

@rryan
Copy link
Member

rryan commented Apr 16, 2016

I think the take-home point is that PortAudio delivers multiple callbacks to Mixxx per OS callback in some situations and so making assumptions about 1 callback == 1 DAC period isn't going to work.

@rryan
Copy link
Member

rryan commented Apr 16, 2016

Added some logging of the stream times and it looks like currentTime is the same across multiple callbacks from the same CoreAudio callback -- so maybe we can use currentTime to identify a new OS callback? Does this also hold on Linux when user buffer < host buffer?

||PaMacCore (v )|| Opened device 50 for output.
||PaMacCore (vv)|| OpenAndSetupOneAudioUnit(): in chan=-1, in fmt=-1, out chan=-1, out fmt=-1, requestedFramesPerBuffer=128
Debug [Main]: Opened PortAudio stream successfully... starting
||PaMacCore (vv)|| IsStreamStopped()
||PaMacCore (vv)|| StartStream()
||PaMacCore (v )|| Starting stream.
Debug [Main]: PortAudio: Started stream successfully
Debug [Main]:    Actual sample rate:  96000 Hz, latency: 6.90625 ms
Debug [Main]: Compressor attack per frame:  0.0001875 decay per frame:  1.875e-05
Debug [Main]: SoundDeviceNetwork::open() "Network stream"
Debug [Main]: framesPerBuffer: 128
Debug [Main]: Requested sample rate:  96000 Hz, latency: 1.33333 ms
Debug [Main]: Using "Built-in Output" as output sound device clock reference
Debug [Main]: 2 output sound devices opened
Debug [Main]: 0 input  sound devices opened
Debug [Main]: Displaying mixxx
Debug [Main]: Running Mixxx
Debug [Main]: ControllerManager::getControllerList
||PaMacCore (vv)|| AudioIOProc()
Debug []: updateCallbackEntryToDacTime currentTime 1389393725219163 outputBufferDacTime 1389393740665915 inputBufferAdcTime 0
Debug []: timeSinceLastCbSecs 1.38939e+06 callbackEntrytoDacSecs 0.0154468 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00133333 diff 1.38939e+06
Debug []: SSE: Denormals to zero mode already enabled
Debug []: SSE: Flush to zero mode already enabled
Debug []: Denormals to zero mode is working
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393725219163 outputBufferDacTime 1389393741999248 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.000383311 callbackEntrytoDacSecs 0.00266667 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0154468 diff 0.000383311
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393725219163 outputBufferDacTime 1389393743332581 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 6.8607e-05 callbackEntrytoDacSecs 0.00266667 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00266667 diff 0.014182
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393728060204 outputBufferDacTime 1389393744662160 inputBufferAdcTime 0
Warning [Engine]: SoundDevicePortAudio: Audio API provides invalid time stamps, syncing waveforms with a CPU Timer DacTime: 1.38939e+06 EntrytoDac: 0.016602 TimeSinceLastCb: 0.00230845 diff: 0.0149104
Debug [Engine]: timeSinceLastCbSecs 0.00230845 callbackEntrytoDacSecs 0.00169155 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00266667 diff 0.0149104
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393728060204 outputBufferDacTime 1389393745995493 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 7.5054e-05 callbackEntrytoDacSecs 0.00266667 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00169155 diff 0.0149855
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393730932834 outputBufferDacTime 1389393747325071 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.0027892 callbackEntrytoDacSecs 0.0163922 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00266667 diff 0.0151814
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393730932834 outputBufferDacTime 1389393748658404 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 5.7764e-05 callbackEntrytoDacSecs 0.0177256 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0163922 diff 5.7764e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393733837522 outputBufferDacTime 1389393749998398 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.00285099 callbackEntrytoDacSecs 0.0161609 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0177256 diff -4.70392e-05
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393733837522 outputBufferDacTime 1389393751331731 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 5.5037e-05 callbackEntrytoDacSecs 0.0174942 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0161609 diff 5.5037e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393736752189 outputBufferDacTime 1389393752661310 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.00285869 callbackEntrytoDacSecs 0.0159091 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0174942 diff -5.973e-05
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393736752189 outputBufferDacTime 1389393753994643 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 4.9525e-05 callbackEntrytoDacSecs 0.0172425 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0159091 diff 4.9525e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393739640846 outputBufferDacTime 1389393755324220 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.00284292 callbackEntrytoDacSecs 0.0156834 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0172425 diff -4.94904e-05
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393739640846 outputBufferDacTime 1389393756657553 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 5.7254e-05 callbackEntrytoDacSecs 0.0170167 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0156834 diff 5.7254e-05
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393739640846 outputBufferDacTime 1389393757990887 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 3.0151e-05 callbackEntrytoDacSecs 0.01835 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0170167 diff 3.0151e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393742566222 outputBufferDacTime 1389393759330881 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.00283397 callbackEntrytoDacSecs 0.0167647 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.01835 diff -8.47451e-05
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393742566222 outputBufferDacTime 1389393760664214 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 5.7425e-05 callbackEntrytoDacSecs 0.018098 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0167647 diff 5.7425e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393745471224 outputBufferDacTime 1389393761993792 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.00285188 callbackEntrytoDacSecs 0.0165226 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.018098 diff -5.6879e-05
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393745471224 outputBufferDacTime 1389393763327126 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 5.3584e-05 callbackEntrytoDacSecs 0.0178559 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0165226 diff 5.3584e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393748373134 outputBufferDacTime 1389393764656703 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.00284892 callbackEntrytoDacSecs 0.0162836 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0178559 diff -5.67479e-05
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393748373134 outputBufferDacTime 1389393765990036 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.00658753 callbackEntrytoDacSecs 0.0176169 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0162836 diff 0.00658753
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393758164350 outputBufferDacTime 1389393774132751 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.00345522 callbackEntrytoDacSecs 0.0159684 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0176169 diff 0.000473386
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393758164350 outputBufferDacTime 1389393775466085 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.000155063 callbackEntrytoDacSecs 0.00266667 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0159684 diff 0.000155063
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393761069904 outputBufferDacTime 1389393776795663 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.00252479 callbackEntrytoDacSecs 0.00147521 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00266667 diff 0.0142505
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393761069904 outputBufferDacTime 1389393778128996 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.000116089 callbackEntrytoDacSecs 0.00266667 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00147521 diff 0.0143666
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393763899168 outputBufferDacTime 1389393779458574 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.0027021 callbackEntrytoDacSecs 0.0155594 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.00266667 diff 0.0142615
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393763899168 outputBufferDacTime 1389393780791907 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 6.9455e-05 callbackEntrytoDacSecs 0.0168927 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0155594 diff 6.9455e-05
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393763899168 outputBufferDacTime 1389393782125240 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 5.2899e-05 callbackEntrytoDacSecs 0.0182261 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0168927 diff 5.2899e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393766769892 outputBufferDacTime 1389393783465234 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.00273463 callbackEntrytoDacSecs 0.0166953 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0182261 diff -0.000129429
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393766769892 outputBufferDacTime 1389393784798568 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 5.1843e-05 callbackEntrytoDacSecs 0.0180287 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0166953 diff 5.1843e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393769670987 outputBufferDacTime 1389393786128146 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.00284611 callbackEntrytoDacSecs 0.0164572 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0180287 diff -5.87438e-05
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393769670987 outputBufferDacTime 1389393787461480 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 5.3124e-05 callbackEntrytoDacSecs 0.0177905 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0164572 diff 5.3124e-05
||PaMacCore (vv)|| AudioIOProc()
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393772650842 outputBufferDacTime 1389393788801473 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 0.00293855 callbackEntrytoDacSecs 0.0161506 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0177905 diff -3.46495e-05
Debug [Engine]: updateCallbackEntryToDacTime currentTime 1389393772650842 outputBufferDacTime 1389393790134807 inputBufferAdcTime 0
Debug [Engine]: timeSinceLastCbSecs 6.6338e-05 callbackEntrytoDacSecs 0.017484 bufferSizeSec 0.00133333 m_lastCallbackEntrytoDacSecs 0.0161506 diff 6.6338e-05

@daschuer
Copy link
Member Author

daschuer commented May 8, 2016

The target of all this measuring is to sync the Waveform samples with the audio samples.
For this we match the DAC time with Mixxx Performace timer, this does only work if the measuring of "currentTime" was done just before we measure our own time. In the ideal case, the thread is not interrupted between the DAC measuring and our own measuring, and there are always the same amount of CPU instructions in between.

If there is a second thread or buffer or something in Portaudio involved, we cannot trust the currentTime. It represends the moment when Portaudio processed the callback but not the moment when Mixxx processes its callback. This seams to be the case in the CoreAudio wrapper.

We can also not rely to the fact that a change in currentTime indecates an immediately Mixxx callback, since there are 3 or 4 Mixxx callback for a Coraudio callback.

So it is in the first instance correct to switch back to the the CPU timer. The CPU timer suffers the error produced by the two independent crystals, but this should be minor compared to the jitter introduced by the Portaudio callback implementation.

I assume your waveforms are much smoother with this PR compared to master.
It this true? ... than we should merge this.


If we aiming for a low latency vinyl setup, this extra buffer inside port audio is not desired.
It would be better if Mixxx runs directly on the Coraudio Callback using the same buffer size.

The jack implementation of PA suffers the same issue, and will be solved one mixxx is a native jack client. Maybe we should become a native Coraudio client as well.

@rryan
Copy link
Member

rryan commented May 8, 2016

I don't think we want to move away from using PortAudio -- I also don't
think we should have a native Jack client. We should instead work with
PortAudio to fix our issues.

On Sun, May 8, 2016, 2:24 PM Daniel Schürmann notifications@github.com
wrote:

The target of all this measuring is to sync the Waveform samples with the
audio samples.
For this we match the DAC time with Mixxx Performace timer, this does only
work if the measuring of "currentTime" was done just before we measure our
own time. In the ideal case, we the thread is not interrupted between the
DAC measuring and our own measuring, and there are always the same amount
of CPU instructions.

If there is a second thread or buffer or something in Portaudio involved,
we cannot trust the currentTime. It represends the moment when Portaudio
processed the callback but not the moment when Mixxx processes its
callback. This seams to be the case in the CoreAudio wrapper.

We can also not rely to the fact that a change in currentTime indecates an
immediately Mixxx callback, since there are 3 or 4 Mixxx callback for a
Coraudio callback.

So it is in the first instance correct to switch back to the the CPU
timer. The CPU timer suffers the error produced by the two independent
crystals, but this should be minor compared to the jitter introduced by the
Portaudio callback implementation.

I assume your waveforms are much smoother with this PR compared to master.

It this true? Than we should merge that.

If we aiming for a low latency vinyl setup, this extra buffer inside port
audio is not desired.
It would be better if Mixxx runs directly on the Coraudio Callback using
the same buffer size.

The jack implementation of PA suffers the same issue, and will be solved
one mixxx is a native jack client. Maybe we should become a native Coraudio
client as well.


You are receiving this because you commented.
Reply to this email directly or view it on GitHub
#881 (comment)

@daschuer
Copy link
Member Author

daschuer commented May 9, 2016

In the Jack case, the issue is IMHO pretty clear. The way Jack works, is completely different compared to the way Portaudio works. Portaudio does not allow to expose streams without connect them to a device. It also does not allow to set up stream connections from any other third party application, nor change the latency. Portaudio has a concept of devices. Jack has a concept of Mono ports.

Since Jack is already a wrapper around a Soudn API with a simple API, it does not make sense to wrap it again and turn Portaudio into Jack, to expose the jack features.
Portaudio aims to provide a unified API for any sound system. Adding Jack only features will break their concept.


I have just digged thought the pa_mac_core.c. I did not understand everything, but it looks like the "quite advanced" CoreAudio API is stripped a lot to behave like other APIs. It looks like CoreAudio has its own buffer and latency management. It delivers nice object orientated buffers, independent for input and output devices. PA does then a lot of things and buffering. It finally removes all these features and build a single callback with a fixed buffer size and input and output in one call. By this, the exact timing and the low latency nature seems to be lost.

For the original issue here seems to be that PA tries to query a fresh current Time for every callback, but the time is not advanced by CoreAudio. It might not expect such an unusual use of their API ;-)

Do you had time to compare the waveform behavior?

@rryan
Copy link
Member

rryan commented May 9, 2016

This sounds like a bug in Mixxx -- we're using a host buffer size that's smaller than the CoreAudio buffer so we are getting multiple callbacks to fill one CoreAudio buffer or something like this.

Anecdotally, CoreAudio is Mixxx's best supported and best performing API. I don't think there's any problem with the way we use PortAudio for CoreAudio support. On a Mac, Mixxx "just works" with no problems.

The problem I am describing is that we are assuming every callback from PortAudio means that X milliseconds have passed by -- and what I'm saying is that is an incorrect assumption that we should not rely on.

@daschuer
Copy link
Member Author

daschuer commented May 9, 2016

This sounds like a bug in Mixxx -- we're using a host buffer size that's smaller than the CoreAudio buffer so we are getting multiple callbacks to fill one CoreAudio buffer or something like this.

Probably yes, but since it works quite good and is still "Mixxx's best supported and best performing API" this cannot be a big issue. Maybe we can treat it like a feature: you have requested a 1.33 ms buffer and you get it :-)

The problem I am describing is that we are assuming every callback from PortAudio means that X milliseconds have passed by -- and what I'm saying is that is an incorrect assumption that we should not rely on.

We do not rely on it. Thats why we need a reliable jitter measurement. The code in this PR correctly detects that the timing is not reliable and uses the CPU timer instead. So your test case proves that the code works. Without the patch, Mixxx just uses the "wrong" Timing values which leads to a jerking waveform. Not sure if this is that notable, because we have an other issue with the V-Sync
and the error here is only ~3 ms in the 1.33 ms buffer case.

By the way, the original PA author is aware that the timing is not reliable:
https://github.com/EddieRingle/portaudio/blob/master/src/hostapi/coreaudio/notes.txt#L95

@rryan
Copy link
Member

rryan commented May 23, 2016

Ok -- sounds like this is working-as-intended for OS X -- pending an improvement to PortAudio or our usage of PortAudio.

@rryan
Copy link
Member

rryan commented May 23, 2016

Thanks for the changes!

@rryan rryan merged commit c44a7cc into mixxxdj:master May 23, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants