Changeset 866
- Timestamp:
- 01/20/08 03:59:17 (15 years ago)
- Files:
-
- trunk/libffado/config.h.in (modified) (1 diff)
- trunk/libffado/src/debugmodule/debugmodule.h (modified) (2 diffs)
- trunk/libffado/src/libieee1394/cycletimer.h (modified) (4 diffs)
- trunk/libffado/src/libieee1394/CycleTimerHelper.cpp (modified) (4 diffs)
- trunk/libffado/src/libieee1394/IsoHandler.cpp (modified) (14 diffs)
- trunk/libffado/src/libieee1394/IsoHandler.h (modified) (2 diffs)
- trunk/libffado/src/libieee1394/IsoHandlerManager.cpp (modified) (3 diffs)
- trunk/libffado/src/libstreaming/amdtp/AmdtpReceiveStreamProcessor.cpp (modified) (2 diffs)
- trunk/libffado/src/libstreaming/amdtp/AmdtpTransmitStreamProcessor.cpp (modified) (13 diffs)
- trunk/libffado/src/libstreaming/generic/StreamProcessor.cpp (modified) (18 diffs)
- trunk/libffado/src/libstreaming/StreamProcessorManager.cpp (modified) (6 diffs)
- trunk/libffado/src/libutil/TimestampedBuffer.cpp (modified) (11 diffs)
- trunk/libffado/src/libutil/TimestampedBuffer.h (modified) (1 diff)
- trunk/libffado/tests/test-ffado.cpp (modified) (2 diffs)
Legend:
- Unmodified
- Added
- Removed
- Modified
- Copied
- Moved
trunk/libffado/config.h.in
r863 r866 40 40 #define SHAREDIR "$SHAREDIR" 41 41 42 #define DEBUG_IMPLEMENT_BACKLOG 0 42 #define DEBUG_IMPLEMENT_BACKLOG 0 43 44 // make this zero to disable the most extreme 45 // debug logging in the critical sections 46 #define DEBUG_EXTREME_ENABLE 0 43 47 44 48 #define IEEE1394SERVICE_USE_CYCLETIMER_DLL 1 trunk/libffado/src/debugmodule/debugmodule.h
r864 r866 185 185 format, \ 186 186 ##args ) 187 #define DEBUG_NORMAL( x ) x; 188 189 #if DEBUG_EXTREME_ENABLE 190 #define debugOutputExtreme( level, format, args... ) \ 191 m_debugModule.print( level, \ 192 __FILE__, \ 193 __FUNCTION__, \ 194 __LINE__, \ 195 format, \ 196 ##args ) 197 #define debugOutputShortExtreme( level, format, args... ) \ 198 m_debugModule.printShort( level, \ 199 format, \ 200 ##args ) 201 #define DEBUG_EXTREME( x ) x; 202 #else 203 #define debugOutputExtreme( level, format, args... ) 204 #define debugOutputShortExtreme( level, format, args... ) 205 #define DEBUG_EXTREME( x ) 206 #endif 187 207 188 208 #else … … 190 210 #define debugOutput( level, format, args... ) 191 211 #define debugOutputShort( level, format, args... ) 212 #define DEBUG_NORMAL( x ) 213 214 #define debugOutputExtreme( level, format, args... ) 215 #define debugOutputShortExtreme( level, format, args... ) 216 #define DEBUG_EXTREME( x ) 192 217 193 218 #endif trunk/libffado/src/libieee1394/cycletimer.h
r864 r866 305 305 uint64_t timestamp; 306 306 307 debugOutput (DEBUG_LEVEL_VERY_VERBOSE,"SYT=%04llX CY=%u CTR=%08llX\n",308 syt_timestamp, rcv_cycle, ctr_now);307 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "SYT=%04llX CY=%u CTR=%08llX\n", 308 syt_timestamp, rcv_cycle, ctr_now); 309 309 310 310 // reconstruct the full cycle … … 345 345 timestamp = new_cycles * TICKS_PER_CYCLE; 346 346 } else { 347 debugOutput (DEBUG_LEVEL_VERY_VERBOSE,348 "Detected wraparound: %d + %d = %d\n",349 rcv_cycle,delta_cycles,new_cycles);347 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 348 "Detected wraparound: %d + %d = %d\n", 349 rcv_cycle, delta_cycles, new_cycles); 350 350 351 351 new_cycles-=8000; // wrap around … … 391 391 uint64_t timestamp; 392 392 393 debugOutput (DEBUG_LEVEL_VERY_VERBOSE,"SYT=%08llX CY=%04X CTR=%08llX\n",394 syt_timestamp,xmt_cycle,ctr_now);393 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "SYT=%08llX CY=%04X CTR=%08llX\n", 394 syt_timestamp, xmt_cycle, ctr_now); 395 395 396 396 // reconstruct the full cycle … … 431 431 timestamp = new_cycles * TICKS_PER_CYCLE; 432 432 } else { 433 debugOutput (DEBUG_LEVEL_VERY_VERBOSE,434 "Detected wraparound: %d + %d = %d\n",435 xmt_cycle,delta_cycles,new_cycles);433 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 434 "Detected wraparound: %d + %d = %d\n", 435 xmt_cycle, delta_cycles, new_cycles); 436 436 437 437 new_cycles-=8000; // wrap around trunk/libffado/src/libieee1394/CycleTimerHelper.cpp
r864 r866 165 165 CycleTimerHelper::Execute() 166 166 { 167 debugOutput ( DEBUG_LEVEL_VERY_VERBOSE, "Execute %p...\n", this);167 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, "Execute %p...\n", this); 168 168 if (!m_first_run) { 169 169 // wait for the next update period … … 182 182 return false; 183 183 } 184 debugOutput ( DEBUG_LEVEL_VERY_VERBOSE, " read : CTR: %11lu, local: %17llu\n",185 cycle_timer, local_time);184 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, " read : CTR: %11lu, local: %17llu\n", 185 cycle_timer, local_time); 186 186 187 187 if (m_first_run) { … … 226 226 m_next_time_usecs = local_time + m_usecs_per_update; 227 227 228 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, " usecs: current: %f next: %f usecs_late=%f\n", 229 m_current_time_usecs, m_next_time_usecs, usecs_late); 230 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, " ticks: current: %f next: %f diff=%f\n", 231 m_current_time_ticks, m_next_time_ticks, diff_ticks); 232 233 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, " state: local: %11llu, dll_e2: %f, rate: %f\n", 234 local_time, m_dll_e2, getRate()); 235 } 236 237 // FIXME: priority inversion! 228 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, " usecs: current: %f next: %f usecs_late=%f\n", 229 m_current_time_usecs, m_next_time_usecs, usecs_late); 230 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, " ticks: current: %f next: %f diff=%f\n", 231 m_current_time_ticks, m_next_time_ticks, diff_ticks); 232 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, " state: local: %11llu, dll_e2: %f, rate: %f\n", 233 local_time, m_dll_e2, getRate()); 234 } 235 236 // FIXME: priority inversion possible, run this at higher prio than client threads 238 237 ENTER_CRITICAL_SECTION; 239 238 m_current_vars.ticks = (uint64_t)(m_current_time_ticks);// + m_average_offset_ticks); … … 270 269 if (y_step_in_ticks_int > 0) { 271 270 retval = addTicks(offset_in_ticks_int, y_step_in_ticks_int); 272 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, "y_step_in_ticks_int > 0: %lld, time_diff: %f, rate: %f, retval: %lu\n",273 271 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "y_step_in_ticks_int > 0: %lld, time_diff: %f, rate: %f, retval: %lu\n", 272 y_step_in_ticks_int, time_diff, my_vars.rate, retval); 274 273 } else { 275 274 retval = substractTicks(offset_in_ticks_int, -y_step_in_ticks_int); 276 275 277 276 // this can happen if the update thread was woken up earlier than it should have been 278 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, "y_step_in_ticks_int <= 0: %lld, time_diff: %f, rate: %f, retval: %lu\n",279 277 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "y_step_in_ticks_int <= 0: %lld, time_diff: %f, rate: %f, retval: %lu\n", 278 y_step_in_ticks_int, time_diff, my_vars.rate, retval); 280 279 } 281 280 trunk/libffado/src/libieee1394/IsoHandler.cpp
r864 r866 83 83 , m_max_packet_size( 1024 ) 84 84 , m_irq_interval( -1 ) 85 , m_packetcount( 0 )86 , m_dropped( 0 )87 85 , m_Client( 0 ) 88 86 , m_poll_timeout( 100 ) … … 104 102 , m_max_packet_size( max_packet_size ) 105 103 , m_irq_interval( irq ) 106 , m_packetcount( 0 )107 , m_dropped( 0 )108 104 , m_Client( 0 ) 109 105 , m_poll_timeout( 100 ) … … 126 122 , m_max_packet_size( max_packet_size ) 127 123 , m_irq_interval( irq ) 128 , m_packetcount( 0 )129 , m_dropped( 0 )130 124 , m_Client( 0 ) 131 125 , m_poll_timeout( 100 ) … … 174 168 IsoHandler::waitForClient() 175 169 { 176 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, "waiting...\n");170 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "waiting...\n"); 177 171 if(m_Client) { 178 172 bool result; … … 182 176 result = m_Client->waitForConsumePacket(); 183 177 } 184 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, " returns %d\n", result);178 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, " returns %d\n", result); 185 179 return result; 186 180 } else { 187 debugOutput (DEBUG_LEVEL_VERBOSE, " no client\n");181 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, " no client\n"); 188 182 } 189 183 return false; … … 193 187 IsoHandler::tryWaitForClient() 194 188 { 195 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, "waiting...\n");189 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "waiting...\n"); 196 190 if(m_Client) { 197 191 bool result; … … 201 195 result = m_Client->canConsumePacket(); 202 196 } 203 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, " returns %d\n", result);197 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, " returns %d\n", result); 204 198 return result; 205 199 } else { 206 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, " no client\n");200 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, " no client\n"); 207 201 } 208 202 return false; … … 212 206 IsoHandler::Execute() 213 207 { 214 debugOutput ( DEBUG_LEVEL_VERY_VERBOSE, "%p: Execute thread...\n", this);208 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, "%p: Execute thread...\n", this); 215 209 216 210 // bypass if not running … … 224 218 // wait for the availability of frames in the client 225 219 // (blocking for transmit handlers) 226 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, "(%p, %s) Waiting for Client activity...\n", this, getTypeString());220 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "(%p, %s) Waiting for Client activity...\n", this, getTypeString()); 227 221 if (waitForClient()) { 228 222 #if ISOHANDLER_USE_POLL … … 277 271 bool 278 272 IsoHandler::iterate() { 279 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, "(%p, %s) Iterating ISO handler...\n",273 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "(%p, %s) Iterating ISO handler...\n", 280 274 this, getTypeString()); 281 275 if(m_State == E_Running) { … … 288 282 return false; 289 283 } 290 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, "(%p, %s) done interating ISO handler...\n",291 this, getTypeString());284 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "(%p, %s) done interating ISO handler...\n", 285 this, getTypeString()); 292 286 return true; 293 287 } else { … … 427 421 m_speed, m_prebuffers); 428 422 } 429 debugOutputShort( DEBUG_LEVEL_NORMAL, " Packet count................: %10d (%5d dropped)\n",430 this->getPacketCount(), this->getDroppedCount());431 423 } 432 424 … … 478 470 unsigned int cycle, unsigned int dropped) { 479 471 480 /* debugOutput( DEBUG_LEVEL_VERY_VERBOSE, 481 "received packet: length=%d, channel=%d, cycle=%d\n", 482 length, channel, cycle );*/ 483 m_packetcount++; 484 m_dropped += dropped; 485 472 debugOutputExtreme(DEBUG_LEVEL_ULTRA_VERBOSE, 473 "received packet: length=%d, channel=%d, cycle=%d\n", 474 length, channel, cycle); 486 475 if(m_Client) { 487 476 return m_Client->putPacket(data, length, channel, tag, sy, cycle, dropped); … … 497 486 int cycle, unsigned int dropped) { 498 487 499 /* debugOutput( DEBUG_LEVEL_ULTRA_VERBOSE, 500 "sending packet: length=%d, cycle=%d\n", 501 *length, cycle );*/ 502 m_packetcount++; 503 m_dropped += dropped; 504 488 debugOutputExtreme(DEBUG_LEVEL_ULTRA_VERBOSE, 489 "sending packet: length=%d, cycle=%d\n", 490 *length, cycle); 505 491 if(m_Client) { 506 492 return m_Client->getPacket(data, length, tag, sy, cycle, dropped, m_max_packet_size); trunk/libffado/src/libieee1394/IsoHandler.h
r864 r866 113 113 int getPacketLatency() { return m_irq_interval;}; 114 114 115 int getPacketCount() {return m_packetcount;};116 void resetPacketCount() {m_packetcount=0;};117 118 int getDroppedCount() {return m_dropped;};119 void resetDroppedCount() {m_dropped=0;};120 121 115 unsigned int getPreBuffers() {return m_prebuffers;}; 122 116 void setPreBuffers(unsigned int n) {m_prebuffers=n;}; … … 141 135 int m_irq_interval; 142 136 143 int m_packetcount;144 int m_dropped;145 137 Streaming::StreamProcessor *m_Client; 146 138 trunk/libffado/src/libieee1394/IsoHandlerManager.cpp
r864 r866 154 154 155 155 // Use a shadow map of the fd's such that the poll call is not in a critical section 156 uint64_t poll_enter = m_service.getCurrentTimeAsUsecs();156 DEBUG_EXTREME( uint64_t poll_enter = m_service.getCurrentTimeAsUsecs() ); 157 157 err = poll (m_poll_fds_shadow, m_poll_nfds_shadow, m_poll_timeout); 158 uint64_t poll_exit = m_service.getCurrentTimeAsUsecs();158 DEBUG_EXTREME( uint64_t poll_exit = m_service.getCurrentTimeAsUsecs() ); 159 159 160 160 if (err == -1) { … … 168 168 int nb_rcv = 0; 169 169 int nb_xmit = 0; 170 uint64_t iter_enter = m_service.getCurrentTimeAsUsecs();170 DEBUG_EXTREME( uint64_t iter_enter = m_service.getCurrentTimeAsUsecs() ); 171 171 for (i = 0; i < m_poll_nfds_shadow; i++) { 172 172 if(m_poll_fds_shadow[i].revents) { 173 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, "received events: %08X for (%p)\n",174 m_poll_fds_shadow[i].revents, m_IsoHandler_map_shadow[i]);173 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "received events: %08X for (%p)\n", 174 m_poll_fds_shadow[i].revents, m_IsoHandler_map_shadow[i]); 175 175 } 176 176 if (m_poll_fds_shadow[i].revents & POLLERR) { … … 195 195 } 196 196 } 197 uint64_t iter_exit = m_service.getCurrentTimeAsUsecs();198 199 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, " poll took %6lldus, iterate took %6lldus, iterated (R: %2d, X: %2d) handlers\n",200 poll_exit-poll_enter, iter_exit-iter_enter,201 nb_rcv, nb_xmit);197 DEBUG_EXTREME( uint64_t iter_exit = m_service.getCurrentTimeAsUsecs() ); 198 199 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, " poll took %6lldus, iterate took %6lldus, iterated (R: %2d, X: %2d) handlers\n", 200 poll_exit-poll_enter, iter_exit-iter_enter, 201 nb_rcv, nb_xmit); 202 202 203 203 return true; trunk/libffado/src/libstreaming/amdtp/AmdtpReceiveStreamProcessor.cpp
r864 r866 161 161 #ifdef DEBUG 162 162 if(isRunning()) { 163 debugOutput(DEBUG_LEVEL_VERY_VERBOSE,"STMP: %lluticks | syt_interval=%d, tpf=%f\n", 164 m_last_timestamp, m_syt_interval, getTicksPerFrame()); 163 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 164 "STMP: %lluticks | syt_interval=%d, tpf=%f\n", 165 m_last_timestamp, m_syt_interval, getTicksPerFrame()); 165 166 } 166 167 #endif … … 182 183 unsigned int nevents, unsigned int offset) 183 184 { 184 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "(%p)->processReadBlock(%u, %u)\n",this,nevents,offset); 185 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, 186 "(%p)->processReadBlock(%u, %u)\n", 187 this,nevents,offset); 185 188 186 189 bool no_problem=true; trunk/libffado/src/libstreaming/amdtp/AmdtpTransmitStreamProcessor.cpp
r864 r866 84 84 int cycles_until_transmit; 85 85 86 debugOutput ( DEBUG_LEVEL_ULTRA_VERBOSE, "Try for cycle %d\n", cycle ); 86 debugOutputExtreme( DEBUG_LEVEL_ULTRA_VERBOSE, 87 "Try for cycle %d\n", cycle ); 87 88 // check whether the packet buffer has packets for us to send. 88 89 // the base timestamp is the one of the next sample in the buffer … … 117 118 118 119 if (dropped) { 119 debugOutput 120 "Gen HDR: CY=%04u, TC=%04u, CUT=%04d, TST=%011llu (%04u), TSP=%011llu (%04u)\n",121 cycle,122 transmit_at_cycle, cycles_until_transmit,123 transmit_at_time, ( unsigned int ) TICKS_TO_CYCLES ( transmit_at_time),124 presentation_time, ( unsigned int ) TICKS_TO_CYCLES ( presentation_time) );120 debugOutput( DEBUG_LEVEL_VERBOSE, 121 "Gen HDR: CY=%04u, TC=%04u, CUT=%04d, TST=%011llu (%04u), TSP=%011llu (%04u)\n", 122 cycle, 123 transmit_at_cycle, cycles_until_transmit, 124 transmit_at_time, (unsigned int)TICKS_TO_CYCLES(transmit_at_time), 125 presentation_time, (unsigned int)TICKS_TO_CYCLES(presentation_time) ); 125 126 } 126 127 // two different options: … … 138 139 if ( cycles_until_presentation <= AMDTP_MIN_CYCLES_BEFORE_PRESENTATION ) 139 140 { 140 debugOutput ( DEBUG_LEVEL_VERBOSE,141 "Insufficient frames (P): N=%02d, CY=%04u, TC=%04u, CUT=%04d\n",142 fc, cycle, transmit_at_cycle, cycles_until_transmit );141 debugOutput( DEBUG_LEVEL_NORMAL, 142 "Insufficient frames (P): N=%02d, CY=%04u, TC=%04u, CUT=%04d\n", 143 fc, cycle, transmit_at_cycle, cycles_until_transmit ); 143 144 // we are too late 144 145 return eCRV_XRun; … … 148 149 unsigned int now_cycle = ( unsigned int ) ( TICKS_TO_CYCLES ( m_1394service.getCycleTimerTicks() ) ); 149 150 150 debugOutput ( DEBUG_LEVEL_VERBOSE, 151 "Insufficient frames (NP): N=%02d, CY=%04u, TC=%04u, CUT=%04d, NOW=%04d\n", 152 fc, cycle, transmit_at_cycle, cycles_until_transmit, now_cycle ); 153 debugWarning("Insufficient frames (NP): N=%02d, CY=%04u, TC=%04u, CUT=%04d, NOW=%04d\n", 154 fc, cycle, transmit_at_cycle, cycles_until_transmit, now_cycle ); 151 debugOutputExtreme(DEBUG_LEVEL_VERBOSE, 152 "Insufficient frames (NP): N=%02d, CY=%04u, TC=%04u, CUT=%04d, NOW=%04d\n", 153 fc, cycle, transmit_at_cycle, cycles_until_transmit, now_cycle ); 155 154 156 155 // there is still time left to send the packet … … 195 194 { 196 195 // we are too late 197 debugOutput(DEBUG_LEVEL_ VERBOSE,196 debugOutput(DEBUG_LEVEL_NORMAL, 198 197 "Too late: CY=%04u, TC=%04u, CUT=%04d, TSP=%011llu (%04u)\n", 199 198 cycle, … … 224 223 else 225 224 { 226 debugOutput (DEBUG_LEVEL_VERY_VERBOSE,227 "Too early: CY=%04u, TC=%04u, CUT=%04d, TST=%011llu (%04u), TSP=%011llu (%04u)\n",228 cycle,229 transmit_at_cycle, cycles_until_transmit,230 transmit_at_time, ( unsigned int ) TICKS_TO_CYCLES ( transmit_at_time),231 presentation_time, ( unsigned int ) TICKS_TO_CYCLES ( presentation_time ));225 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 226 "Too early: CY=%04u, TC=%04u, CUT=%04d, TST=%011llu (%04u), TSP=%011llu (%04u)\n", 227 cycle, 228 transmit_at_cycle, cycles_until_transmit, 229 transmit_at_time, (unsigned int)TICKS_TO_CYCLES(transmit_at_time), 230 presentation_time, (unsigned int)TICKS_TO_CYCLES(presentation_time)); 232 231 #ifdef DEBUG 233 232 if ( cycles_until_transmit > AMDTP_MAX_CYCLES_TO_TRANSMIT_EARLY + 1 ) 234 233 { 235 debugOutput (DEBUG_LEVEL_VERY_VERBOSE,236 "Way too early: CY=%04u, TC=%04u, CUT=%04d, TST=%011llu (%04u), TSP=%011llu (%04u)\n",237 cycle,238 transmit_at_cycle, cycles_until_transmit,239 transmit_at_time, ( unsigned int ) TICKS_TO_CYCLES ( transmit_at_time),240 presentation_time, ( unsigned int ) TICKS_TO_CYCLES ( presentation_time ));234 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 235 "Way too early: CY=%04u, TC=%04u, CUT=%04d, TST=%011llu (%04u), TSP=%011llu (%04u)\n", 236 cycle, 237 transmit_at_cycle, cycles_until_transmit, 238 transmit_at_time, (unsigned int)TICKS_TO_CYCLES(transmit_at_time), 239 presentation_time, (unsigned int)TICKS_TO_CYCLES(presentation_time)); 241 240 } 242 241 #endif … … 256 255 if ( m_data_buffer->readFrames ( m_syt_interval, ( char * ) ( data + 8 ) ) ) 257 256 { 258 debugOutput ( DEBUG_LEVEL_ULTRA_VERBOSE, "XMIT DATA (cy %04d): TSP=%011llu (%04u)\n", 259 cycle, m_last_timestamp, ( unsigned int ) TICKS_TO_CYCLES ( m_last_timestamp ) ); 257 debugOutputExtreme(DEBUG_LEVEL_ULTRA_VERBOSE, 258 "XMIT DATA (cy %04d): TSP=%011llu (%04u)\n", 259 cycle, m_last_timestamp, (unsigned int)TICKS_TO_CYCLES(m_last_timestamp)); 260 260 return eCRV_OK; 261 261 } … … 271 271 { 272 272 struct iec61883_packet *packet = ( struct iec61883_packet * ) data; 273 debugOutput ( DEBUG_LEVEL_ULTRA_VERBOSE, "XMIT SILENT (cy %04d): CY=%04u, TSP=%011llu (%04u)\n", 274 cycle, m_last_timestamp, ( unsigned int ) TICKS_TO_CYCLES ( m_last_timestamp ) ); 273 debugOutputExtreme(DEBUG_LEVEL_ULTRA_VERBOSE, 274 "XMIT SILENT (cy %04d): CY=%04u, TSP=%011llu (%04u)\n", 275 cycle, m_last_timestamp, (unsigned int)TICKS_TO_CYCLES(m_last_timestamp)); 275 276 276 277 packet->sid = m_local_node_id; … … 308 309 { 309 310 struct iec61883_packet *packet = ( struct iec61883_packet * ) data; 310 debugOutput ( DEBUG_LEVEL_ULTRA_VERBOSE, "XMIT EMPTY (cy %04d): CY=%04u, TSP=%011llu (%04u)\n", 311 cycle, m_last_timestamp, ( unsigned int ) TICKS_TO_CYCLES ( m_last_timestamp ) ); 311 debugOutputExtreme(DEBUG_LEVEL_ULTRA_VERBOSE, 312 "XMIT EMPTY (cy %04d): CY=%04u, TSP=%011llu (%04u)\n", 313 cycle, m_last_timestamp, (unsigned int)TICKS_TO_CYCLES(m_last_timestamp) ); 312 314 packet->sid = m_local_node_id; 313 315 … … 1034 1036 { 1035 1037 AmdtpPortInfo *pinfo=dynamic_cast<AmdtpPortInfo *>(*it); 1036 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "idx %u: looking at port %s at position %u\n", 1037 idx, (*it)->getName().c_str(), pinfo->getPosition()); 1038 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, 1039 "idx %u: looking at port %s at position %u\n", 1040 idx, (*it)->getName().c_str(), pinfo->getPosition()); 1038 1041 if(pinfo->getPosition() == idx) { 1039 1042 struct _MBLA_port_cache p; … … 1049 1052 1050 1053 m_audio_ports.push_back(p); 1051 debugOutput(DEBUG_LEVEL_VERBOSE, "Cached port %s at position %u\n", 1052 p.port->getName().c_str(), idx); 1054 debugOutput(DEBUG_LEVEL_VERBOSE, 1055 "Cached port %s at position %u\n", 1056 p.port->getName().c_str(), idx); 1053 1057 goto next_index; 1054 1058 } … … 1065 1069 { 1066 1070 AmdtpPortInfo *pinfo=dynamic_cast<AmdtpPortInfo *>(*it); 1067 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "idx %u: looking at port %s at position %u, location %u\n", 1068 idx, (*it)->getName().c_str(), pinfo->getPosition(), pinfo->getLocation()); 1071 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, 1072 "idx %u: looking at port %s at position %u, location %u\n", 1073 idx, (*it)->getName().c_str(), pinfo->getPosition(), pinfo->getLocation()); 1069 1074 if ((*it)->getPortType() == Port::E_Midi) { 1070 1075 struct _MIDI_port_cache p; … … 1082 1087 1083 1088 m_midi_ports.push_back(p); 1084 debugOutput(DEBUG_LEVEL_VERBOSE, "Cached port %s at position %u, location %u\n", 1085 p.port->getName().c_str(), p.position, p.location); 1089 debugOutput(DEBUG_LEVEL_VERBOSE, 1090 "Cached port %s at position %u, location %u\n", 1091 p.port->getName().c_str(), p.position, p.location); 1086 1092 } 1087 1093 } trunk/libffado/src/libstreaming/generic/StreamProcessor.cpp
r864 r866 388 388 389 389 if (result == eCRV_OK) { 390 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "RECV: CY=%04u TS=%011llu\n", 391 cycle, m_last_timestamp); 390 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 391 "RECV: CY=%04u TS=%011llu\n", 392 cycle, m_last_timestamp); 392 393 // update some accounting 393 394 m_last_good_cycle = cycle; … … 502 503 } 503 504 if (dropped_cycles > 0) { 504 debugWarning("(%p) dropped %d packets on cycle %u (last_cycle=%u, dropped=%d)\n", this, dropped_cycles, cycle, m_last_cycle, dropped); 505 debugWarning("(%p) dropped %d packets on cycle %u (last_cycle=%u, dropped=%d)\n", 506 this, dropped_cycles, cycle, m_last_cycle, dropped); 505 507 m_dropped += dropped_cycles; 506 508 // HACK: this should not be necessary, since the header generation functions should trigger the xrun. … … 595 597 enum eChildReturnValue result = generateSilentPacketHeader(data, length, tag, sy, cycle, dropped_cycles, max_length); 596 598 if (result == eCRV_Packet) { 597 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "XMIT SILENT: CY=%04u TS=%011llu\n", 598 cycle, m_last_timestamp); 599 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 600 "XMIT SILENT: CY=%04u TS=%011llu\n", 601 cycle, m_last_timestamp); 599 602 // update some accounting 600 603 m_last_good_cycle = cycle; … … 646 649 enum eChildReturnValue result = generatePacketHeader(data, length, tag, sy, cycle, dropped_cycles, max_length); 647 650 if (result == eCRV_Packet || result == eCRV_Defer) { 648 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "XMIT: CY=%04u TS=%011llu\n", 649 cycle, m_last_timestamp); 651 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 652 "XMIT: CY=%04u TS=%011llu\n", 653 cycle, m_last_timestamp); 650 654 // update some accounting 651 655 m_last_good_cycle = cycle; … … 743 747 } 744 748 745 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "XMIT EMPTY: CY=%04u\n", cycle); 749 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 750 "XMIT EMPTY: CY=%04u\n", 751 cycle); 746 752 generateEmptyPacketHeader(data, length, tag, sy, cycle, dropped_cycles, max_length); 747 753 generateEmptyPacketData(data, length, tag, sy, cycle, dropped_cycles, max_length); … … 759 765 bool StreamProcessor::getFrames(unsigned int nbframes, int64_t ts) { 760 766 bool result; 761 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "%p.getFrames(%d, %11llu)", nbframes, ts); 767 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, 768 "%p.getFrames(%d, %11llu)", 769 nbframes, ts); 762 770 assert( getType() == ePT_Receive ); 763 771 if(isDryRunning()) result = getFramesDry(nbframes, ts); … … 788 796 lag_ticks = diffTicks(ts, ts_expected); 789 797 lag_frames = (((float)lag_ticks) / srate); 790 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "stream (%p): drifts %6d ticks = %10.5f frames (rate=%10.5f), %lld, %llu, %d\n", 791 this, lag_ticks, lag_frames, srate, ts, ts_expected, fc); 798 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 799 "stream (%p): drifts %6d ticks = %10.5f frames (rate=%10.5f), %lld, %llu, %d\n", 800 this, lag_ticks, lag_frames, srate, ts, ts_expected, fc); 792 801 if (lag_frames >= 1.0) { 793 802 // the stream lags … … 809 818 bool StreamProcessor::getFramesDry(unsigned int nbframes, int64_t ts) 810 819 { 811 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "stream (%p): dry run %d frames (@ ts=%lld)\n", 812 this, nbframes, ts); 820 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 821 "stream (%p): dry run %d frames (@ ts=%lld)\n", 822 this, nbframes, ts); 813 823 // dry run on this side means that we put silence in all enabled ports 814 824 // since there is do data put into the ringbuffer in the dry-running state … … 829 839 { 830 840 bool result; 831 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "%p.putFrames(%d, %11llu)", nbframes, ts); 841 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 842 "%p.putFrames(%d, %11llu)", 843 nbframes, ts); 832 844 assert( getType() == ePT_Transmit ); 833 845 if(isDryRunning()) result = putFramesDry(nbframes, ts); … … 840 852 StreamProcessor::putFramesWet(unsigned int nbframes, int64_t ts) 841 853 { 842 debugOutput(DEBUG_LEVEL_ULTRA_VERBOSE, "StreamProcessor::putFramesWet(%d, %llu)\n", nbframes, ts); 854 debugOutputExtreme(DEBUG_LEVEL_ULTRA_VERBOSE, 855 "StreamProcessor::putFramesWet(%d, %llu)\n", 856 nbframes, ts); 843 857 // transfer the data 844 858 m_data_buffer->blockProcessWriteFrames(nbframes, ts); 845 debugOutput(DEBUG_LEVEL_ULTRA_VERBOSE, " New timestamp: %llu\n", ts); 859 debugOutputExtreme(DEBUG_LEVEL_ULTRA_VERBOSE, 860 " New timestamp: %llu\n", ts); 846 861 return true; // FIXME: what about failure? 847 862 } … … 850 865 StreamProcessor::putFramesDry(unsigned int nbframes, int64_t ts) 851 866 { 852 debugOutput(DEBUG_LEVEL_ULTRA_VERBOSE, "StreamProcessor::putFramesDry(%d, %llu)\n", nbframes, ts); 867 debugOutputExtreme(DEBUG_LEVEL_ULTRA_VERBOSE, 868 "StreamProcessor::putFramesDry(%d, %llu)\n", 869 nbframes, ts); 853 870 // do nothing 854 871 return true; … … 858 875 StreamProcessor::putSilenceFrames(unsigned int nbframes, int64_t ts) 859 876 { 860 debugOutput(DEBUG_LEVEL_ULTRA_VERBOSE, "StreamProcessor::putSilenceFrames(%d, %llu)\n", nbframes, ts); 877 debugOutputExtreme(DEBUG_LEVEL_ULTRA_VERBOSE, 878 "StreamProcessor::putSilenceFrames(%d, %llu)\n", 879 nbframes, ts); 861 880 862 881 size_t bytes_per_frame = getEventSize() * getEventsPerFrame(); … … 1640 1659 bool StreamProcessor::waitForProduce(unsigned int nframes) 1641 1660 { 1642 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "(%p, %s) wait ...\n", this, getTypeString()); 1661 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 1662 "(%p, %s) wait ...\n", 1663 this, getTypeString()); 1643 1664 struct timespec ts; 1644 1665 int result; … … 1662 1683 if (result == -1) { 1663 1684 if (errno == ETIMEDOUT) { 1664 debugOutput(DEBUG_LEVEL_VERBOSE, "(%p, %s) pthread_cond_timedwait() timed out\n", this, getTypeString()); 1685 debugOutput(DEBUG_LEVEL_VERBOSE, 1686 "(%p, %s) pthread_cond_timedwait() timed out\n", 1687 this, getTypeString()); 1665 1688 pthread_mutex_unlock(&m_activity_cond_lock); 1666 1689 return false; 1667 1690 } else { 1668 debugError("(%p, %s) pthread_cond_timedwait error\n", this, getTypeString()); 1691 debugError("(%p, %s) pthread_cond_timedwait error\n", 1692 this, getTypeString()); 1669 1693 pthread_mutex_unlock(&m_activity_cond_lock); 1670 1694 return false; … … 1686 1710 bool StreamProcessor::waitForConsume(unsigned int nframes) 1687 1711 { 1688 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "(%p, %s) wait ...\n", this, getTypeString()); 1712 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 1713 "(%p, %s) wait ...\n", 1714 this, getTypeString()); 1689 1715 struct timespec ts; 1690 1716 int result; … … 1718 1744 } 1719 1745 pthread_mutex_unlock(&m_activity_cond_lock); 1720 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "(%p, %s) leave ...\n", this, getTypeString()); 1746 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 1747 "(%p, %s) leave ...\n", 1748 this, getTypeString()); 1721 1749 return true; 1722 1750 } … … 1737 1765 unsigned int bufferspace = m_data_buffer->getBufferSpace(); 1738 1766 if(bufferspace >= nframes) { 1739 // debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "enough space (%u)...\n", bufferspace);1740 1767 return true; 1741 1768 } else return false; … … 1768 1795 unsigned int bufferfill = m_data_buffer->getBufferFill(); 1769 1796 if(bufferfill >= nframes) { 1770 // debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "enough items (%u)...\n", bufferfill);1771 1797 return true; 1772 1798 } else return false; trunk/libffado/src/libstreaming/StreamProcessorManager.cpp
r864 r866 711 711 712 712 while(period_not_ready) { 713 debugOutput( DEBUG_LEVEL_VERBOSE, "waiting for period (%d frames in buffer)...\n", m_SyncSource->getBufferFill()); 713 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 714 "waiting for period (%d frames in buffer)...\n", 715 m_SyncSource->getBufferFill()); 714 716 bool result; 715 717 if(m_SyncSource->getType() == StreamProcessor::ePT_Receive) { … … 770 772 // and the receive processors should have done their transfer. 771 773 m_time_of_transfer = m_SyncSource->getTimeAtPeriod(); 772 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "transfer at %llu ticks...\n", 773 m_time_of_transfer); 774 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, 775 "transfer at %llu ticks...\n", 776 m_time_of_transfer); 774 777 775 778 // this is to notify the client of the delay that we introduced by waiting 776 779 m_delayed_usecs = - m_SyncSource->getTimeUntilNextPeriodSignalUsecs(); 777 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "delayed for %d usecs...\n", m_delayed_usecs); 780 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, 781 "delayed for %d usecs...\n", 782 m_delayed_usecs); 778 783 779 784 #ifdef DEBUG … … 789 794 xmt_bf = (*it)->getBufferFill(); 790 795 } 791 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "XF at %011llu ticks, RBF=%d, XBF=%d, SUM=%d...\n", 792 m_time_of_transfer, rcv_bf, xmt_bf, rcv_bf+xmt_bf); 796 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, 797 "XF at %011llu ticks, RBF=%d, XBF=%d, SUM=%d...\n", 798 m_time_of_transfer, rcv_bf, xmt_bf, rcv_bf+xmt_bf); 793 799 794 800 // check if xruns occurred on the Iso side. … … 832 838 */ 833 839 bool StreamProcessorManager::transfer() { 834 debugOutput ( DEBUG_LEVEL_VERY_VERBOSE, "Transferring period...\n");840 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, "Transferring period...\n"); 835 841 bool retval=true; 836 842 retval &= transfer(StreamProcessor::ePT_Receive); … … 849 855 bool StreamProcessorManager::transfer(enum StreamProcessor::eProcessorType t) { 850 856 if(m_SyncSource == NULL) return false; 851 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "transfer(%d) at TS=%011llu (%03us %04uc %04ut)...\n", 857 debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, 858 "transfer(%d) at TS=%011llu (%03us %04uc %04ut)...\n", 852 859 t, m_time_of_transfer, 853 860 (unsigned int)TICKS_TO_SECS(m_time_of_transfer), … … 920 927 bool StreamProcessorManager::transferSilence(enum StreamProcessor::eProcessorType t) { 921 928 if(m_SyncSource == NULL) return false; 922 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "transferSilence(%d) at TS=%011llu (%03us %04uc %04ut)...\n", 929 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, 930 "transferSilence(%d) at TS=%011llu (%03us %04uc %04ut)...\n", 923 931 t, m_time_of_transfer, 924 932 (unsigned int)TICKS_TO_SECS(m_time_of_transfer), trunk/libffado/src/libutil/TimestampedBuffer.cpp
r864 r866 156 156 float TimestampedBuffer::calculateRate() { 157 157 ffado_timestamp_t diff; 158 158 159 159 diff=m_buffer_next_tail_timestamp - m_buffer_tail_timestamp; 160 161 debugOutput(DEBUG_LEVEL_VERY_VERBOSE,"getRate: %f/%f=%f\n", 162 (float)(diff), 163 (float)m_update_period, 164 ((float)(diff))/((float) m_update_period)); 165 160 161 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 162 "getRate: %f/%f=%f\n", 163 (float)(diff), 164 (float)m_update_period, 165 ((float)(diff))/((float) m_update_period)); 166 166 167 // the maximal difference we can allow (64secs) 167 168 const ffado_timestamp_t max=m_wrap_at/((ffado_timestamp_t)2); … … 176 177 if (rate<0.0) debugError("rate < 0! (%f)\n",rate); 177 178 if (fabsf(m_nominal_rate - rate)>(m_nominal_rate*0.1)) { 178 debugWarning("(%p) rate (%10.5f) more that 10%% off nominal (rate=%10.5f, diff="TIMESTAMP_FORMAT_SPEC", update_period=%d)\n", 179 debugWarning("(%p) rate (%10.5f) more that 10%% off nominal " 180 "(rate=%10.5f, diff="TIMESTAMP_FORMAT_SPEC", update_period=%d)\n", 179 181 this, rate,m_nominal_rate,diff, m_update_period); 180 182 … … 532 534 */ 533 535 bool TimestampedBuffer::blockProcessWriteFrames(unsigned int nbframes, ffado_timestamp_t ts) { 534 535 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "Transferring period...\n"); 536 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 537 "(%p) Writing %u frames for ts "TIMESTAMP_FORMAT_SPEC"\n", 538 this, nbframes, ts); 536 539 int xrun; 537 540 unsigned int offset = 0; … … 642 645 bool TimestampedBuffer::blockProcessReadFrames(unsigned int nbframes) { 643 646 644 debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "Reading %u from buffer (%p)...\n", nbframes, this); 647 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 648 "(%p) Reading %u frames\n", 649 this, nbframes); 645 650 646 651 int xrun; … … 773 778 EXIT_CRITICAL_SECTION; 774 779 775 debugOutput (DEBUG_LEVEL_VERY_VERBOSE, "for (%p) to "776 TIMESTAMP_FORMAT_SPEC" => "TIMESTAMP_FORMAT_SPEC", NTS="777 778 this, new_timestamp, ts, m_buffer_next_tail_timestamp, m_dll_e2, getRate());780 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 781 "for (%p) to "TIMESTAMP_FORMAT_SPEC" => "TIMESTAMP_FORMAT_SPEC", " 782 "NTS="TIMESTAMP_FORMAT_SPEC", DLL2=%f, RATE=%f\n", 783 this, new_timestamp, ts, m_buffer_next_tail_timestamp, m_dll_e2, getRate()); 779 784 780 785 } … … 820 825 EXIT_CRITICAL_SECTION; 821 826 822 debugOutput(DEBUG_LEVEL_VERBOSE, "for (%p) to "TIMESTAMP_FORMAT_SPEC" => " 823 TIMESTAMP_FORMAT_SPEC", NTS="TIMESTAMP_FORMAT_SPEC", DLL2=%f, RATE=%f\n", 824 this, new_timestamp, ts, m_buffer_next_tail_timestamp, m_dll_e2, getRate()); 825 826 } 827 828 /** 829 * @brief Synchronize the buffer head to a specified timestamp 830 * 831 * Try to synchronize the buffer head to a specific timestamp. This 832 * can mean adding or removing samples to/from the buffer such that 833 * the buffer head aligns with the specified timestamp. The alignment 834 * is within ts +/- Tsample/2 835 * 836 * @param target the timestamp to align to 837 * @return true if alignment succeeded, false if not 838 */ 839 bool 840 TimestampedBuffer::syncBufferHeadToTimestamp(ffado_timestamp_t target) 841 { 842 uint64_t ts_head; 843 uint64_t ts_target=(uint64_t)target; 844 signed int fc; 845 int32_t lag_ticks; 846 float lag_frames; 847 848 ffado_timestamp_t ts_head_tmp; 849 getBufferHeadTimestamp(&ts_head_tmp, &fc); 850 ts_head=(uint64_t)ts_head_tmp; 851 // if target > ts_head then the wanted buffer head timestamp 852 // is later than the actual. This means that we (might) have to drop 853 // some frames. 854 lag_ticks=diffTicks(ts_target, ts_head); 855 float rate=getRate(); 856 857 assert(rate!=0.0); 858 859 lag_frames=(((float)lag_ticks)/rate); 860 861 debugOutput( DEBUG_LEVEL_VERBOSE, "(%p): HEAD=%llu, TS=%llu, diff=%ld = %10.5f frames (rate=%10.5f)\n", 862 this, ts_head, ts_target, lag_ticks, lag_frames, rate); 863 864 if (lag_frames>=1.0) { 865 // the buffer head is too early 866 // ditch frames until the buffer head is on time 867 char dummy[getBytesPerFrame()]; // one frame of garbage 868 int frames_to_ditch=(int)roundf(lag_frames); 869 debugOutput( DEBUG_LEVEL_VERBOSE, "(%p): ditching %d frames (@ ts=%lld)\n",this,frames_to_ditch,ts_target); 870 871 while (frames_to_ditch--) { 872 readFrames(1, dummy); 873 } 874 875 } else if (lag_frames<=-1.0) { 876 // the buffer head is too late 877 // add some padding frames 878 int frames_to_add=(int)roundf(lag_frames); 879 debugOutput( DEBUG_LEVEL_VERBOSE, "(%p): adding %d frames (@ ts=%lld)\n",this,-frames_to_add,ts_target); 880 881 while (frames_to_add++) { 882 writeDummyFrame(); 883 } 884 } 885 getBufferHeadTimestamp(&ts_head_tmp, &fc); 886 ts_head=(uint64_t)ts_head_tmp; 887 debugOutput( DEBUG_LEVEL_VERBOSE, "(%p): new HEAD=%llu, fc=%d, target=%llu, new diff=%lld\n", 888 this, ts_head, fc, ts_target, diffTicks(ts_target, ts_head)); 889 // FIXME: of course this doesn't always succeed 890 return true; 891 } 892 893 /** 894 * @brief Synchronize the buffer tail to a specified timestamp 895 * 896 * Try to synchronize the buffer tail to a specific timestamp. This 897 * can mean adding or removing samples to/from the buffer such that 898 * the buffer tail aligns with the specified timestamp. The alignment 899 * is within ts +/- Tsample/2 900 * 901 * @param target the timestamp to align to 902 * @return true if alignment succeeded, false if not 903 */ 904 bool 905 TimestampedBuffer::syncBufferTailToTimestamp(ffado_timestamp_t target) 906 { 907 uint64_t ts_tail; 908 uint64_t ts_target=(uint64_t)target; 909 signed int fc; 910 int32_t lag_ticks; 911 float lag_frames; 912 913 debugWarning("Untested\n"); 914 915 ffado_timestamp_t ts_tail_tmp; 916 getBufferTailTimestamp(&ts_tail_tmp, &fc); 917 ts_tail=(uint64_t)ts_tail_tmp; 918 // if target < ts_tail then the wanted buffer head timestamp 919 // is later than the actual. This means that we (might) have to drop 920 // some frames. 921 lag_ticks=diffTicks(ts_tail, ts_target); 922 float rate=getRate(); 923 924 assert(rate!=0.0); 925 926 lag_frames=(((float)lag_ticks)/rate); 927 928 debugOutput( DEBUG_LEVEL_VERBOSE, "(%p): HEAD=%llu, TS=%llu, diff=%ld = %10.5f frames (rate=%10.5f)\n", 929 this, ts_tail, ts_target, lag_ticks, lag_frames, rate); 930 931 if (lag_frames>=1.0) { 932 // the buffer head is too early 933 // ditch frames until the buffer head is on time 934 char dummy[getBytesPerFrame()]; // one frame of garbage 935 int frames_to_ditch=(int)roundf(lag_frames); 936 debugOutput( DEBUG_LEVEL_VERBOSE, "(%p): ditching %d frames (@ ts=%lld)\n",this,frames_to_ditch,ts_target); 937 938 while (frames_to_ditch--) { 939 readFrames(1, dummy); 940 } 941 942 } else if (lag_frames<=-1.0) { 943 // the buffer head is too late 944 // add some padding frames 945 int frames_to_add=(int)roundf(lag_frames); 946 debugOutput( DEBUG_LEVEL_VERBOSE, "(%p): adding %d frames (@ ts=%lld)\n",this,-frames_to_add,ts_target); 947 948 while (frames_to_add++) { 949 writeDummyFrame(); 950 } 951 } 952 getBufferHeadTimestamp(&ts_tail_tmp, &fc); 953 ts_tail=(uint64_t)ts_tail_tmp; 954 debugOutput( DEBUG_LEVEL_VERBOSE, "(%p): new HEAD=%llu, fc=%d, target=%llu, new diff=%lld\n", 955 this, ts_tail, fc, ts_target, diffTicks(ts_target, ts_tail)); 956 // FIXME: of course this doesn't always succeed 957 return true; 958 } 959 960 /** 961 * @brief correct lag 962 * 963 * Try to synchronize the buffer tail to a specific timestamp. This 964 * can mean adding or removing samples to/from the buffer such that 965 * the buffer tail aligns with the specified timestamp. The alignment 966 * is within ts +/- Tsample/2 967 * 968 * @param target the timestamp to align to 969 * @return true if alignment succeeded, false if not 970 */ 971 bool 972 TimestampedBuffer::syncCorrectLag(int64_t lag_ticks) 973 { 974 float lag_frames; 975 float rate=getRate(); 976 assert(rate!=0.0); 977 978 lag_frames=(((float)lag_ticks)/rate); 979 if (lag_frames >= 1.0) { 980 // the buffer head is too late 981 // add some padding frames 982 int frames_to_add=(int)roundf(lag_frames); 983 debugOutput( DEBUG_LEVEL_VERBOSE, "(%p): adding %d frames\n",this,frames_to_add); 984 985 while (frames_to_add++) { 986 writeDummyFrame(); 987 } 988 } else if (lag_frames <= -1.0) { 989 // the buffer head is too early 990 // ditch frames until the buffer head is on time 991 char dummy[getBytesPerFrame()]; // one frame of garbage 992 int frames_to_ditch=(int)roundf(lag_frames); 993 debugOutput( DEBUG_LEVEL_VERBOSE, "(%p): ditching %d frames\n",this,-frames_to_ditch); 994 995 while (frames_to_ditch--) { 996 readFrames(1, dummy); 997 } 998 } 999 return true; 827 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 828 "for (%p) to "TIMESTAMP_FORMAT_SPEC" => "TIMESTAMP_FORMAT_SPEC", " 829 "NTS="TIMESTAMP_FORMAT_SPEC", DLL2=%f, RATE=%f\n", 830 this, new_timestamp, ts, m_buffer_next_tail_timestamp, m_dll_e2, getRate()); 1000 831 } 1001 832 … … 1158 989 1159 990 debugOutput( DEBUG_LEVEL_VERBOSE, 1160 "Updated ("TIMESTAMP_FORMAT_SPEC","TIMESTAMP_FORMAT_SPEC") to ("TIMESTAMP_FORMAT_SPEC","TIMESTAMP_FORMAT_SPEC")\n", 991 "Updated ("TIMESTAMP_FORMAT_SPEC","TIMESTAMP_FORMAT_SPEC") " 992 "to ("TIMESTAMP_FORMAT_SPEC","TIMESTAMP_FORMAT_SPEC")\n", 1161 993 m_buffer_tail_timestamp, m_buffer_next_tail_timestamp, 1162 994 m_buffer_tail_timestamp, pred_buffer_next_tail_timestamp); … … 1172 1004 ffado_timestamp_t max_abs_diff = one_update_step * (1.0 + max_deviation); 1173 1005 1174 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, " nbframes: %d, m_update_period: %d \n", nbframes, m_update_period); 1175 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, " tail TS: "TIMESTAMP_FORMAT_SPEC", next tail TS: "TIMESTAMP_FORMAT_SPEC"\n", 1176 m_buffer_tail_timestamp, m_buffer_next_tail_timestamp); 1177 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, " new TS: "TIMESTAMP_FORMAT_SPEC", wrapped new TS: "TIMESTAMP_FORMAT_SPEC"\n", 1178 new_timestamp, ts); 1006 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 1007 " nbframes: %d, m_update_period: %d \n", 1008 nbframes, m_update_period); 1009 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 1010 " tail TS: "TIMESTAMP_FORMAT_SPEC", next tail TS: "TIMESTAMP_FORMAT_SPEC"\n", 1011 m_buffer_tail_timestamp, m_buffer_next_tail_timestamp); 1012 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 1013 " new TS: "TIMESTAMP_FORMAT_SPEC", wrapped new TS: "TIMESTAMP_FORMAT_SPEC"\n", 1014 new_timestamp, ts); 1179 1015 1180 1016 if (diff > max_abs_diff) { … … 1188 1024 } 1189 1025 1190 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "(%p): diff="TIMESTAMP_FORMAT_SPEC" ", 1191 this, diff); 1026 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 1027 "(%p): diff="TIMESTAMP_FORMAT_SPEC" ", 1028 this, diff); 1192 1029 1193 1030 double err = diff; 1194 1195 debugOutputShort(DEBUG_LEVEL_VERY_VERBOSE, "diff2="TIMESTAMP_FORMAT_SPEC" err=%f\n", 1196 diff, err); 1197 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "B: FC=%10u, TS="TIMESTAMP_FORMAT_SPEC", NTS="TIMESTAMP_FORMAT_SPEC"\n", 1198 m_framecounter, m_buffer_tail_timestamp, pred_buffer_next_tail_timestamp); 1031 debugOutputShortExtreme(DEBUG_LEVEL_VERY_VERBOSE, 1032 "diff2="TIMESTAMP_FORMAT_SPEC" err=%f\n", 1033 diff, err); 1034 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 1035 "B: FC=%10u, TS="TIMESTAMP_FORMAT_SPEC", NTS="TIMESTAMP_FORMAT_SPEC"\n", 1036 m_framecounter, m_buffer_tail_timestamp, pred_buffer_next_tail_timestamp); 1199 1037 1200 1038 ENTER_CRITICAL_SECTION; … … 1205 1043 1206 1044 if (m_buffer_next_tail_timestamp >= m_wrap_at) { 1207 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "Unwrapping next tail timestamp: "TIMESTAMP_FORMAT_SPEC"", 1208 m_buffer_next_tail_timestamp); 1045 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 1046 "Unwrapping next tail timestamp: "TIMESTAMP_FORMAT_SPEC"", 1047 m_buffer_next_tail_timestamp); 1209 1048 1210 1049 m_buffer_next_tail_timestamp -= m_wrap_at; 1211 1050 1212 debugOutputShort(DEBUG_LEVEL_VERY_VERBOSE, " => "TIMESTAMP_FORMAT_SPEC"\n", 1213 m_buffer_next_tail_timestamp); 1051 debugOutputShortExtreme(DEBUG_LEVEL_VERY_VERBOSE, 1052 " => "TIMESTAMP_FORMAT_SPEC"\n", 1053 m_buffer_next_tail_timestamp); 1214 1054 1215 1055 } … … 1217 1057 EXIT_CRITICAL_SECTION; 1218 1058 1219 debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "A: TS="TIMESTAMP_FORMAT_SPEC", NTS="TIMESTAMP_FORMAT_SPEC", DLLe2=%f, RATE=%f\n", 1220 m_buffer_tail_timestamp, m_buffer_next_tail_timestamp, m_dll_e2, m_current_rate); 1059 debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 1060 "A: TS="TIMESTAMP_FORMAT_SPEC", NTS="TIMESTAMP_FORMAT_SPEC", DLLe2=%f, RATE=%f\n", 1061 m_buffer_tail_timestamp, m_buffer_next_tail_timestamp, m_dll_e2, m_current_rate); 1221 1062 1222 1063 trunk/libffado/src/libutil/TimestampedBuffer.h
r864 r866 131 131 void setBufferTailTimestamp ( ffado_timestamp_t new_timestamp ); 132 132 void setBufferHeadTimestamp ( ffado_timestamp_t new_timestamp ); 133 134 // sync related, also drops or add frames when necessary135 bool syncBufferHeadToTimestamp ( ffado_timestamp_t ts );136 bool syncBufferTailToTimestamp ( ffado_timestamp_t ts );137 bool syncCorrectLag ( int64_t ts );138 133 139 134 ffado_timestamp_t getTimestampFromTail ( int nframes ); trunk/libffado/tests/test-ffado.cpp
r864 r866 204 204 } 205 205 206 printf("verbose level = % d\n", arguments.verbose);206 printf("verbose level = %ld\n", arguments.verbose); 207 207 setDebugLevel(arguments.verbose); 208 208 … … 275 275 276 276 int devices_on_bus = m_deviceManager->getNbDevices(); 277 printf(" port = % d, devices_on_bus = %d\n", arguments.port, devices_on_bus);277 printf(" port = %ld, devices_on_bus = %d\n", arguments.port, devices_on_bus); 278 278 279 279 for(i=0;i<devices_on_bus;i++) {