- Timestamp:
- 11/11/16 02:53:52 (7 years ago)
- Files:
Legend:
- Unmodified
- Added
- Removed
- Modified
- Copied
- Moved
trunk/libffado/src/libstreaming/StreamProcessorManager.cpp
r2524 r2651 199 199 debugError("(%p) sem_[timed]wait error (result=%d errno=EINVAL)\n", 200 200 this, result); 201 debugError("(%p) timeout_nsec=%" PRId64" ts.sec=%"PRId64" ts.nsec=%"PRId64"\n",201 debugError("(%p) timeout_nsec=%" PRId64 " ts.sec=%" PRId64 " ts.nsec=%" PRId64 "\n", 202 202 this, m_activity_wait_timeout_nsec, 203 203 (int64_t)ts.tv_sec, (int64_t)ts.tv_nsec); … … 206 206 debugError("(%p) sem_[timed]wait error (result=%d errno=%d)\n", 207 207 this, result, errno); 208 debugError("(%p) timeout_nsec=%" PRId64" ts.sec=%"PRId64" ts.nsec=%"PRId64"\n",208 debugError("(%p) timeout_nsec=%" PRId64 " ts.sec=%" PRId64 " ts.nsec=%" PRId64 "\n", 209 209 this, m_activity_wait_timeout_nsec, 210 210 (int64_t)ts.tv_sec, (int64_t)ts.tv_nsec); … … 636 636 #if DEBUG_EXTREME_ENABLE 637 637 int64_t now = Util::SystemTimeSource::getCurrentTime(); 638 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, "CTR pred: %" PRId64", syncdelay: %"PRId64", diff: %"PRId64"\n", ticks_at_period, ticks_at_period_margin, ticks_at_period_margin-ticks_at_period );639 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, "PREWAIT pred: %" PRId64", now: %"PRId64", wait: %"PRId64"\n", pred_system_time_at_xfer, now, pred_system_time_at_xfer-now );638 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, "CTR pred: %" PRId64 ", syncdelay: %" PRId64 ", diff: %" PRId64 "\n", ticks_at_period, ticks_at_period_margin, ticks_at_period_margin-ticks_at_period ); 639 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, "PREWAIT pred: %" PRId64 ", now: %" PRId64 ", wait: %" PRId64 "\n", pred_system_time_at_xfer, now, pred_system_time_at_xfer-now ); 640 640 #endif 641 641 … … 645 645 #if DEBUG_EXTREME_ENABLE 646 646 now = Util::SystemTimeSource::getCurrentTime(); 647 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, "POSTWAIT pred: %" PRId64", now: %"PRId64", excess: %"PRId64"\n", pred_system_time_at_xfer, now, now-pred_system_time_at_xfer );647 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, "POSTWAIT pred: %" PRId64 ", now: %" PRId64 ", excess: %" PRId64 "\n", pred_system_time_at_xfer, now, now-pred_system_time_at_xfer ); 648 648 #endif 649 649 } … … 666 666 // figure out where we are now 667 667 uint64_t time_of_first_sample = m_SyncSource->getTimeAtPeriod(); 668 debugOutput( DEBUG_LEVEL_VERBOSE, " sync at TS=%011" PRIu64" (%03us %04uc %04ut)...\n",668 debugOutput( DEBUG_LEVEL_VERBOSE, " sync at TS=%011" PRIu64 " (%03us %04uc %04ut)...\n", 669 669 time_of_first_sample, 670 670 (unsigned int)TICKS_TO_SECS(time_of_first_sample), … … 683 683 time_of_first_sample = addTicks(time_of_first_sample, 684 684 time_for_startup_ticks); 685 debugOutput( DEBUG_LEVEL_VERBOSE, " add %d frames (%011" PRIu64" ticks)...\n",685 debugOutput( DEBUG_LEVEL_VERBOSE, " add %d frames (%011" PRIu64 " ticks)...\n", 686 686 time_for_startup_frames, time_for_startup_ticks); 687 687 688 debugOutput( DEBUG_LEVEL_VERBOSE, " => first sample at TS=%011" PRIu64" (%03us %04uc %04ut)...\n",688 debugOutput( DEBUG_LEVEL_VERBOSE, " => first sample at TS=%011" PRIu64 " (%03us %04uc %04ut)...\n", 689 689 time_of_first_sample, 690 690 (unsigned int)TICKS_TO_SECS(time_of_first_sample), … … 699 699 uint64_t time_to_start_recv = substractTicks(time_of_first_sample, 700 700 prestart_cycles_for_recv * TICKS_PER_CYCLE); 701 debugOutput( DEBUG_LEVEL_VERBOSE, " => xmit starts at TS=%011" PRIu64" (%03us %04uc %04ut)...\n",701 debugOutput( DEBUG_LEVEL_VERBOSE, " => xmit starts at TS=%011" PRIu64 " (%03us %04uc %04ut)...\n", 702 702 time_to_start_xmit, 703 703 (unsigned int)TICKS_TO_SECS(time_to_start_xmit), 704 704 (unsigned int)TICKS_TO_CYCLES(time_to_start_xmit), 705 705 (unsigned int)TICKS_TO_OFFSET(time_to_start_xmit)); 706 debugOutput( DEBUG_LEVEL_VERBOSE, " => recv starts at TS=%011" PRIu64" (%03us %04uc %04ut)...\n",706 debugOutput( DEBUG_LEVEL_VERBOSE, " => recv starts at TS=%011" PRIu64 " (%03us %04uc %04ut)...\n", 707 707 time_to_start_recv, 708 708 (unsigned int)TICKS_TO_SECS(time_to_start_recv), … … 756 756 signed int fc; 757 757 (*it)->getBufferHeadTimestamp ( &ts, &fc ); 758 debugOutput( DEBUG_LEVEL_VERBOSE, " transmit buffer tail %010" PRId64" => head TS %010"PRIu64", fc=%d...\n",758 debugOutput( DEBUG_LEVEL_VERBOSE, " transmit buffer tail %010" PRId64 " => head TS %010" PRIu64 ", fc=%d...\n", 759 759 time_of_first_sample, (uint64_t)ts, fc); 760 760 } … … 786 786 } 787 787 if(!m_SyncSource->scheduleStartRunning(time_to_start_sync)) { 788 debugError("m_SyncSource->scheduleStartRunning(%11" PRIu64") failed\n", time_to_start_sync);788 debugError("m_SyncSource->scheduleStartRunning(%11" PRIu64 ") failed\n", time_to_start_sync); 789 789 return false; 790 790 } … … 796 796 if(*it != m_SyncSource) { 797 797 if(!(*it)->scheduleStartRunning(time_to_start_recv)) { 798 debugError("%p->scheduleStartRunning(%11" PRIu64") failed\n", *it, time_to_start_recv);798 debugError("%p->scheduleStartRunning(%11" PRIu64 ") failed\n", *it, time_to_start_recv); 799 799 return false; 800 800 } … … 806 806 if(*it != m_SyncSource) { 807 807 if(!(*it)->scheduleStartRunning(time_to_start_xmit)) { 808 debugError("%p->scheduleStartRunning(%11" PRIu64") failed\n", *it, time_to_start_xmit);808 debugError("%p->scheduleStartRunning(%11" PRIu64 ") failed\n", *it, time_to_start_xmit); 809 809 return false; 810 810 } … … 839 839 #endif 840 840 841 debugOutput( DEBUG_LEVEL_VERBOSE, " initial time of transfer %010" PRId64", rate %f...\n",841 debugOutput( DEBUG_LEVEL_VERBOSE, " initial time of transfer %010" PRId64 ", rate %f...\n", 842 842 m_time_of_transfer, rate); 843 843 … … 858 858 859 859 int64_t transmit_tail_timestamp = addTicks(m_time_of_transfer, delay_in_ticks); 860 debugOutput( DEBUG_LEVEL_VERBOSE, " preset transmit tail TS %010" PRId64", rate %f...\n",860 debugOutput( DEBUG_LEVEL_VERBOSE, " preset transmit tail TS %010" PRId64 ", rate %f...\n", 861 861 transmit_tail_timestamp, rate); 862 862 … … 869 869 signed int fc; 870 870 (*it)->getBufferHeadTimestamp ( &ts, &fc ); 871 debugOutput( DEBUG_LEVEL_VERBOSE, " => transmit head TS %010" PRId64", fc=%d...\n",871 debugOutput( DEBUG_LEVEL_VERBOSE, " => transmit head TS %010" PRId64 ", fc=%d...\n", 872 872 (uint64_t)ts, fc); 873 873 } … … 926 926 StreamProcessor *s = m_ReceiveProcessors.at(i); 927 927 diff = diffTicks(m_SyncSource->getTimeAtPeriod(), s->getTimeAtPeriod()); 928 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, " offset between SyncSP %p and SP %p is %" PRId64" ticks...\n",928 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, " offset between SyncSP %p and SP %p is %" PRId64 " ticks...\n", 929 929 m_SyncSource, s, diff); 930 930 if ( nb_sync_runs == periods_per_align_try ) { … … 948 948 diff_between_streams[i] /= periods_per_align_try; 949 949 diff_between_streams_frames[i] = (int)roundf(diff_between_streams[i] / s->getTicksPerFrame()); 950 debugOutput( DEBUG_LEVEL_VERBOSE, " avg offset between SyncSP %p and SP %p is %" PRId64" ticks, %d frames...\n",950 debugOutput( DEBUG_LEVEL_VERBOSE, " avg offset between SyncSP %p and SP %p is %" PRId64 " ticks, %d frames...\n", 951 951 m_SyncSource, s, diff_between_streams[i], diff_between_streams_frames[i]); 952 952 … … 1230 1230 #if DEBUG_EXTREME_ENABLE 1231 1231 int64_t now = Util::SystemTimeSource::getCurrentTime(); 1232 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, "CTR pred: %" PRId64", syncdelay: %"PRId64", diff: %"PRId64"\n", ticks_at_period, ticks_at_period_margin, ticks_at_period_margin-ticks_at_period );1233 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, "PREWAIT pred: %" PRId64", now: %"PRId64", wait: %"PRId64"\n", pred_system_time_at_xfer, now, pred_system_time_at_xfer-now );1232 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, "CTR pred: %" PRId64 ", syncdelay: %" PRId64 ", diff: %" PRId64 "\n", ticks_at_period, ticks_at_period_margin, ticks_at_period_margin-ticks_at_period ); 1233 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, "PREWAIT pred: %" PRId64 ", now: %" PRId64 ", wait: %" PRId64 "\n", pred_system_time_at_xfer, now, pred_system_time_at_xfer-now ); 1234 1234 #endif 1235 1235 … … 1239 1239 #if DEBUG_EXTREME_ENABLE 1240 1240 now = Util::SystemTimeSource::getCurrentTime(); 1241 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, "POSTWAIT pred: %" PRId64", now: %"PRId64", excess: %"PRId64"\n", pred_system_time_at_xfer, now, now-pred_system_time_at_xfer );1241 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, "POSTWAIT pred: %" PRId64 ", now: %" PRId64 ", excess: %" PRId64 "\n", pred_system_time_at_xfer, now, now-pred_system_time_at_xfer ); 1242 1242 #endif 1243 1243 … … 1369 1369 // so 50 ticks = 10%, which is a rather large jitter value. 1370 1370 if(diff-ticks_per_period > m_max_diff_ticks || diff-ticks_per_period < -m_max_diff_ticks) { 1371 debugOutput(DEBUG_LEVEL_VERBOSE, "rather large TSP difference TS=%011" PRIu64" => TS=%011"PRIu64" (%d, nom %d)\n",1371 debugOutput(DEBUG_LEVEL_VERBOSE, "rather large TSP difference TS=%011" PRIu64 " => TS=%011" PRIu64 " (%d, nom %d)\n", 1372 1372 m_time_of_transfer2, m_time_of_transfer, diff, ticks_per_period); 1373 1373 } … … 1376 1376 1377 1377 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, 1378 "transfer period %d at %" PRIu64" ticks...\n",1378 "transfer period %d at %" PRIu64 " ticks...\n", 1379 1379 m_nbperiods, m_time_of_transfer); 1380 1380 … … 1392 1392 } 1393 1393 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, 1394 "XF at %011" PRIu64" ticks, RBF=%d, XBF=%d, SUM=%d...\n",1394 "XF at %011" PRIu64 " ticks, RBF=%d, XBF=%d, SUM=%d...\n", 1395 1395 m_time_of_transfer, rcv_bf, xmt_bf, rcv_bf+xmt_bf); 1396 1396 #endif … … 1467 1467 if(m_SyncSource == NULL) return false; 1468 1468 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, 1469 "transfer(%d) at TS=%011" PRIu64" (%03us %04uc %04ut)...\n",1469 "transfer(%d) at TS=%011" PRIu64 " (%03us %04uc %04ut)...\n", 1470 1470 t, m_time_of_transfer, 1471 1471 (unsigned int)TICKS_TO_SECS(m_time_of_transfer), … … 1481 1481 ++it ) { 1482 1482 if(!(*it)->getFrames(m_period, m_time_of_transfer)) { 1483 debugWarning("could not getFrames(%u, %11" PRIu64") from stream processor (%p)\n",1483 debugWarning("could not getFrames(%u, %11" PRIu64 ") from stream processor (%p)\n", 1484 1484 m_period, m_time_of_transfer,*it); 1485 1485 retval &= false; // buffer underrun … … 1504 1504 1505 1505 if(!(*it)->putFrames(m_period, transmit_timestamp)) { 1506 debugWarning("could not putFrames(%u,%" PRIu64") to stream processor (%p)\n",1506 debugWarning("could not putFrames(%u,%" PRIu64 ") to stream processor (%p)\n", 1507 1507 m_period, transmit_timestamp, *it); 1508 1508 retval &= false; // buffer underrun … … 1545 1545 if(m_SyncSource == NULL) return false; 1546 1546 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, 1547 "transferSilence(%d) at TS=%011" PRIu64" (%03us %04uc %04ut)...\n",1547 "transferSilence(%d) at TS=%011" PRIu64 " (%03us %04uc %04ut)...\n", 1548 1548 t, m_time_of_transfer, 1549 1549 (unsigned int)TICKS_TO_SECS(m_time_of_transfer), … … 1559 1559 ++it ) { 1560 1560 if(!(*it)->dropFrames(m_period, m_time_of_transfer)) { 1561 debugWarning("could not dropFrames(%u, %11" PRIu64") from stream processor (%p)\n",1561 debugWarning("could not dropFrames(%u, %11" PRIu64 ") from stream processor (%p)\n", 1562 1562 m_period, m_time_of_transfer,*it); 1563 1563 retval &= false; // buffer underrun … … 1582 1582 1583 1583 if(!(*it)->putSilenceFrames(m_period, transmit_timestamp)) { 1584 debugWarning("could not putSilenceFrames(%u,%" PRIu64") to stream processor (%p)\n",1584 debugWarning("could not putSilenceFrames(%u,%" PRIu64 ") to stream processor (%p)\n", 1585 1585 m_period, transmit_timestamp, *it); 1586 1586 retval &= false; // buffer underrun