Changeset 866

Show
Ignore:
Timestamp:
01/20/08 03:59:17 (14 years ago)
Author:
ppalmers
Message:

- weed out some unused functions
- introduce 'debugOutputExtreme' allowing to disable debug statements in the speed-sensitive sections. This should reduce the cpu load on a 'normal' debug build significantly.

Files:

Legend:

Unmodified
Added
Removed
Modified
Copied
Moved
  • trunk/libffado/config.h.in

    r863 r866  
    4040#define SHAREDIR "$SHAREDIR" 
    4141 
    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 
    4347 
    4448#define IEEE1394SERVICE_USE_CYCLETIMER_DLL  1 
  • trunk/libffado/src/debugmodule/debugmodule.h

    r864 r866  
    185185                                     format,                       \ 
    186186                                     ##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 
    187207 
    188208#else 
     
    190210    #define debugOutput( level, format, args... ) 
    191211    #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 ) 
    192217 
    193218#endif 
  • trunk/libffado/src/libieee1394/cycletimer.h

    r864 r866  
    305305    uint64_t timestamp; 
    306306 
    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); 
    309309 
    310310    // reconstruct the full cycle 
     
    345345        timestamp  = new_cycles * TICKS_PER_CYCLE; 
    346346    } 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); 
    350350 
    351351        new_cycles-=8000; // wrap around 
     
    391391    uint64_t timestamp; 
    392392 
    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); 
    395395 
    396396    // reconstruct the full cycle 
     
    431431        timestamp  = new_cycles * TICKS_PER_CYCLE; 
    432432    } 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); 
    436436 
    437437        new_cycles-=8000; // wrap around 
  • trunk/libffado/src/libieee1394/CycleTimerHelper.cpp

    r864 r866  
    165165CycleTimerHelper::Execute() 
    166166{ 
    167     debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "Execute %p...\n", this); 
     167    debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, "Execute %p...\n", this); 
    168168    if (!m_first_run) { 
    169169        // wait for the next update period 
     
    182182        return false; 
    183183    } 
    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); 
    186186 
    187187    if (m_first_run) { 
     
    226226        m_next_time_usecs = local_time + m_usecs_per_update; 
    227227 
    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 
    238237    ENTER_CRITICAL_SECTION; 
    239238    m_current_vars.ticks = (uint64_t)(m_current_time_ticks);// + m_average_offset_ticks); 
     
    270269    if (y_step_in_ticks_int > 0) { 
    271270        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                     y_step_in_ticks_int, time_diff, my_vars.rate, retval); 
     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); 
    274273    } else { 
    275274        retval = substractTicks(offset_in_ticks_int, -y_step_in_ticks_int); 
    276275 
    277276        // 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                     y_step_in_ticks_int, time_diff, my_vars.rate, retval); 
     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); 
    280279    } 
    281280 
  • trunk/libffado/src/libieee1394/IsoHandler.cpp

    r864 r866  
    8383   , m_max_packet_size( 1024 ) 
    8484   , m_irq_interval( -1 ) 
    85    , m_packetcount( 0 ) 
    86    , m_dropped( 0 ) 
    8785   , m_Client( 0 ) 
    8886   , m_poll_timeout( 100 ) 
     
    104102   , m_max_packet_size( max_packet_size ) 
    105103   , m_irq_interval( irq ) 
    106    , m_packetcount( 0 ) 
    107    , m_dropped( 0 ) 
    108104   , m_Client( 0 ) 
    109105   , m_poll_timeout( 100 ) 
     
    126122   , m_max_packet_size( max_packet_size ) 
    127123   , m_irq_interval( irq ) 
    128    , m_packetcount( 0 ) 
    129    , m_dropped( 0 ) 
    130124   , m_Client( 0 ) 
    131125   , m_poll_timeout( 100 ) 
     
    174168IsoHandler::waitForClient() 
    175169{ 
    176     debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "waiting...\n"); 
     170    debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "waiting...\n"); 
    177171    if(m_Client) { 
    178172        bool result; 
     
    182176            result = m_Client->waitForConsumePacket(); 
    183177        } 
    184         debugOutput(DEBUG_LEVEL_VERY_VERBOSE, " returns %d\n", result); 
     178        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, " returns %d\n", result); 
    185179        return result; 
    186180    } else { 
    187         debugOutput(DEBUG_LEVEL_VERBOSE, " no client\n"); 
     181        debugOutputExtreme(DEBUG_LEVEL_VERBOSE, " no client\n"); 
    188182    } 
    189183    return false; 
     
    193187IsoHandler::tryWaitForClient() 
    194188{ 
    195     debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "waiting...\n"); 
     189    debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "waiting...\n"); 
    196190    if(m_Client) { 
    197191        bool result; 
     
    201195            result = m_Client->canConsumePacket(); 
    202196        } 
    203         debugOutput(DEBUG_LEVEL_VERY_VERBOSE, " returns %d\n", result); 
     197        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, " returns %d\n", result); 
    204198        return result; 
    205199    } else { 
    206         debugOutput(DEBUG_LEVEL_VERY_VERBOSE, " no client\n"); 
     200        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, " no client\n"); 
    207201    } 
    208202    return false; 
     
    212206IsoHandler::Execute() 
    213207{ 
    214     debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "%p: Execute thread...\n", this); 
     208    debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, "%p: Execute thread...\n", this); 
    215209 
    216210    // bypass if not running 
     
    224218    // wait for the availability of frames in the client 
    225219    // (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()); 
    227221    if (waitForClient()) { 
    228222#if ISOHANDLER_USE_POLL 
     
    277271bool 
    278272IsoHandler::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", 
    280274                this, getTypeString()); 
    281275    if(m_State == E_Running) { 
     
    288282            return false; 
    289283        } 
    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()); 
    292286        return true; 
    293287    } else { 
     
    427421                                            m_speed, m_prebuffers); 
    428422    } 
    429     debugOutputShort( DEBUG_LEVEL_NORMAL, "  Packet count................: %10d (%5d dropped)\n", 
    430             this->getPacketCount(), this->getDroppedCount()); 
    431423} 
    432424 
     
    478470                    unsigned int cycle, unsigned int dropped) { 
    479471 
    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); 
    486475    if(m_Client) { 
    487476        return m_Client->putPacket(data, length, channel, tag, sy, cycle, dropped); 
     
    497486                    int cycle, unsigned int dropped) { 
    498487 
    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); 
    505491    if(m_Client) { 
    506492        return m_Client->getPacket(data, length, tag, sy, cycle, dropped, m_max_packet_size); 
  • trunk/libffado/src/libieee1394/IsoHandler.h

    r864 r866  
    113113    int getPacketLatency() { return m_irq_interval;}; 
    114114 
    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  
    121115    unsigned int getPreBuffers() {return m_prebuffers;}; 
    122116    void setPreBuffers(unsigned int n) {m_prebuffers=n;}; 
     
    141135    int             m_irq_interval; 
    142136 
    143     int m_packetcount; 
    144     int m_dropped; 
    145137    Streaming::StreamProcessor *m_Client; 
    146138 
  • trunk/libffado/src/libieee1394/IsoHandlerManager.cpp

    r864 r866  
    154154 
    155155    // 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() ); 
    157157    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() ); 
    159159 
    160160    if (err == -1) { 
     
    168168    int nb_rcv = 0; 
    169169    int nb_xmit = 0; 
    170     uint64_t iter_enter = m_service.getCurrentTimeAsUsecs(); 
     170    DEBUG_EXTREME( uint64_t iter_enter = m_service.getCurrentTimeAsUsecs() ); 
    171171    for (i = 0; i < m_poll_nfds_shadow; i++) { 
    172172        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]); 
    175175        } 
    176176        if (m_poll_fds_shadow[i].revents & POLLERR) { 
     
    195195        } 
    196196    } 
    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); 
    202202 
    203203    return true; 
  • trunk/libffado/src/libstreaming/amdtp/AmdtpReceiveStreamProcessor.cpp

    r864 r866  
    161161    #ifdef DEBUG 
    162162    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()); 
    165166    } 
    166167    #endif 
     
    182183                       unsigned int nevents, unsigned int offset) 
    183184{ 
    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); 
    185188 
    186189    bool no_problem=true; 
  • trunk/libffado/src/libstreaming/amdtp/AmdtpTransmitStreamProcessor.cpp

    r864 r866  
    8484    int cycles_until_transmit; 
    8585 
    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 ); 
    8788    // check whether the packet buffer has packets for us to send. 
    8889    // the base timestamp is the one of the next sample in the buffer 
     
    117118 
    118119    if (dropped) { 
    119         debugOutput ( DEBUG_LEVEL_VERBOSE, 
    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) ); 
    125126    } 
    126127    // two different options: 
     
    138139        if ( cycles_until_presentation <= AMDTP_MIN_CYCLES_BEFORE_PRESENTATION ) 
    139140        { 
    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 ); 
    143144            // we are too late 
    144145            return eCRV_XRun; 
     
    148149            unsigned int now_cycle = ( unsigned int ) ( TICKS_TO_CYCLES ( m_1394service.getCycleTimerTicks() ) ); 
    149150 
    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 ); 
    155154 
    156155            // there is still time left to send the packet 
     
    195194        { 
    196195            // we are too late 
    197             debugOutput(DEBUG_LEVEL_VERBOSE
     196            debugOutput(DEBUG_LEVEL_NORMAL
    198197                        "Too late: CY=%04u, TC=%04u, CUT=%04d, TSP=%011llu (%04u)\n", 
    199198                        cycle, 
     
    224223        else 
    225224        { 
    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)); 
    232231#ifdef DEBUG 
    233232            if ( cycles_until_transmit > AMDTP_MAX_CYCLES_TO_TRANSMIT_EARLY + 1 ) 
    234233            { 
    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)); 
    241240            } 
    242241#endif 
     
    256255    if ( m_data_buffer->readFrames ( m_syt_interval, ( char * ) ( data + 8 ) ) ) 
    257256    { 
    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)); 
    260260        return eCRV_OK; 
    261261    } 
     
    271271{ 
    272272    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)); 
    275276 
    276277    packet->sid = m_local_node_id; 
     
    308309{ 
    309310    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) ); 
    312314    packet->sid = m_local_node_id; 
    313315 
     
    10341036        { 
    10351037            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()); 
    10381041            if(pinfo->getPosition() == idx) { 
    10391042                struct _MBLA_port_cache p; 
     
    10491052 
    10501053                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); 
    10531057                goto next_index; 
    10541058            } 
     
    10651069    { 
    10661070        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()); 
    10691074        if ((*it)->getPortType() == Port::E_Midi) { 
    10701075            struct _MIDI_port_cache p; 
     
    10821087 
    10831088            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); 
    10861092        } 
    10871093    } 
  • trunk/libffado/src/libstreaming/generic/StreamProcessor.cpp

    r864 r866  
    388388 
    389389    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); 
    392393        // update some accounting 
    393394        m_last_good_cycle = cycle; 
     
    502503        } 
    503504        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); 
    505507            m_dropped += dropped_cycles; 
    506508            // HACK: this should not be necessary, since the header generation functions should trigger the xrun. 
     
    595597        enum eChildReturnValue result = generateSilentPacketHeader(data, length, tag, sy, cycle, dropped_cycles, max_length); 
    596598        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); 
    599602            // update some accounting 
    600603            m_last_good_cycle = cycle; 
     
    646649        enum eChildReturnValue result = generatePacketHeader(data, length, tag, sy, cycle, dropped_cycles, max_length); 
    647650        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); 
    650654            // update some accounting 
    651655            m_last_good_cycle = cycle; 
     
    743747    } 
    744748 
    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); 
    746752    generateEmptyPacketHeader(data, length, tag, sy, cycle, dropped_cycles, max_length); 
    747753    generateEmptyPacketData(data, length, tag, sy, cycle, dropped_cycles, max_length); 
     
    759765bool StreamProcessor::getFrames(unsigned int nbframes, int64_t ts) { 
    760766    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); 
    762770    assert( getType() == ePT_Receive ); 
    763771    if(isDryRunning()) result = getFramesDry(nbframes, ts); 
     
    788796    lag_ticks = diffTicks(ts, ts_expected); 
    789797    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); 
    792801    if (lag_frames >= 1.0) { 
    793802        // the stream lags 
     
    809818bool StreamProcessor::getFramesDry(unsigned int nbframes, int64_t ts) 
    810819{ 
    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); 
    813823    // dry run on this side means that we put silence in all enabled ports 
    814824    // since there is do data put into the ringbuffer in the dry-running state 
     
    829839{ 
    830840    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); 
    832844    assert( getType() == ePT_Transmit ); 
    833845    if(isDryRunning()) result = putFramesDry(nbframes, ts); 
     
    840852StreamProcessor::putFramesWet(unsigned int nbframes, int64_t ts) 
    841853{ 
    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); 
    843857    // transfer the data 
    844858    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); 
    846861    return true; // FIXME: what about failure? 
    847862} 
     
    850865StreamProcessor::putFramesDry(unsigned int nbframes, int64_t ts) 
    851866{ 
    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); 
    853870    // do nothing 
    854871    return true; 
     
    858875StreamProcessor::putSilenceFrames(unsigned int nbframes, int64_t ts) 
    859876{ 
    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); 
    861880 
    862881    size_t bytes_per_frame = getEventSize() * getEventsPerFrame(); 
     
    16401659bool StreamProcessor::waitForProduce(unsigned int nframes) 
    16411660{ 
    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()); 
    16431664    struct timespec ts; 
    16441665    int result; 
     
    16621683        if (result == -1) { 
    16631684            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()); 
    16651688                pthread_mutex_unlock(&m_activity_cond_lock); 
    16661689                return false; 
    16671690            } else { 
    1668                 debugError("(%p, %s) pthread_cond_timedwait error\n", this, getTypeString()); 
     1691                debugError("(%p, %s) pthread_cond_timedwait error\n",  
     1692                           this, getTypeString()); 
    16691693                pthread_mutex_unlock(&m_activity_cond_lock); 
    16701694                return false; 
     
    16861710bool StreamProcessor::waitForConsume(unsigned int nframes) 
    16871711{ 
    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()); 
    16891715    struct timespec ts; 
    16901716    int result; 
     
    17181744    } 
    17191745    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()); 
    17211749    return true; 
    17221750} 
     
    17371765        unsigned int bufferspace = m_data_buffer->getBufferSpace(); 
    17381766        if(bufferspace >= nframes) { 
    1739 //             debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "enough space (%u)...\n", bufferspace); 
    17401767            return true; 
    17411768        } else return false; 
     
    17681795        unsigned int bufferfill = m_data_buffer->getBufferFill(); 
    17691796        if(bufferfill >= nframes) { 
    1770 //             debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "enough items (%u)...\n", bufferfill); 
    17711797            return true; 
    17721798        } else return false; 
  • trunk/libffado/src/libstreaming/StreamProcessorManager.cpp

    r864 r866  
    711711 
    712712    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()); 
    714716        bool result; 
    715717        if(m_SyncSource->getType() == StreamProcessor::ePT_Receive) { 
     
    770772    //       and the receive processors should have done their transfer. 
    771773    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); 
    774777 
    775778    // this is to notify the client of the delay that we introduced by waiting 
    776779    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); 
    778783 
    779784#ifdef DEBUG 
     
    789794        xmt_bf = (*it)->getBufferFill(); 
    790795    } 
    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); 
    793799 
    794800    // check if xruns occurred on the Iso side. 
     
    832838 */ 
    833839bool StreamProcessorManager::transfer() { 
    834     debugOutput( DEBUG_LEVEL_VERY_VERBOSE, "Transferring period...\n"); 
     840    debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, "Transferring period...\n"); 
    835841    bool retval=true; 
    836842    retval &= transfer(StreamProcessor::ePT_Receive); 
     
    849855bool StreamProcessorManager::transfer(enum StreamProcessor::eProcessorType t) { 
    850856    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",  
    852859        t, m_time_of_transfer, 
    853860        (unsigned int)TICKS_TO_SECS(m_time_of_transfer), 
     
    920927bool StreamProcessorManager::transferSilence(enum StreamProcessor::eProcessorType t) { 
    921928    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",  
    923931        t, m_time_of_transfer, 
    924932        (unsigned int)TICKS_TO_SECS(m_time_of_transfer), 
  • trunk/libffado/src/libutil/TimestampedBuffer.cpp

    r864 r866  
    156156float TimestampedBuffer::calculateRate() { 
    157157    ffado_timestamp_t diff; 
    158      
     158 
    159159    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 
    166167    // the maximal difference we can allow (64secs) 
    167168    const ffado_timestamp_t max=m_wrap_at/((ffado_timestamp_t)2); 
     
    176177    if (rate<0.0) debugError("rate < 0! (%f)\n",rate); 
    177178    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", 
    179181                     this, rate,m_nominal_rate,diff, m_update_period); 
    180182 
     
    532534 */ 
    533535bool 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); 
    536539    int xrun; 
    537540    unsigned int offset = 0; 
     
    642645bool TimestampedBuffer::blockProcessReadFrames(unsigned int nbframes) { 
    643646 
    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); 
    645650 
    646651    int xrun; 
     
    773778    EXIT_CRITICAL_SECTION; 
    774779 
    775     debugOutput(DEBUG_LEVEL_VERY_VERBOSE, "for (%p) to " 
    776                                           TIMESTAMP_FORMAT_SPEC" => "TIMESTAMP_FORMAT_SPEC", NTS=
    777                                           TIMESTAMP_FORMAT_SPEC", DLL2=%f, RATE=%f\n", 
    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()); 
    779784 
    780785} 
     
    820825    EXIT_CRITICAL_SECTION; 
    821826 
    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()); 
    1000831} 
    1001832 
     
    1158989         
    1159990        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", 
    1161993                     m_buffer_tail_timestamp, m_buffer_next_tail_timestamp, 
    1162994                     m_buffer_tail_timestamp, pred_buffer_next_tail_timestamp); 
     
    11721004    ffado_timestamp_t max_abs_diff = one_update_step * (1.0 + max_deviation); 
    11731005     
    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); 
    11791015 
    11801016    if (diff > max_abs_diff) { 
     
    11881024    } 
    11891025 
    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); 
    11921029 
    11931030    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); 
    11991037 
    12001038    ENTER_CRITICAL_SECTION; 
     
    12051043 
    12061044    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); 
    12091048 
    12101049        m_buffer_next_tail_timestamp -= m_wrap_at; 
    12111050 
    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); 
    12141054 
    12151055    } 
     
    12171057    EXIT_CRITICAL_SECTION; 
    12181058 
    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); 
    12211062 
    12221063 
  • trunk/libffado/src/libutil/TimestampedBuffer.h

    r864 r866  
    131131        void setBufferTailTimestamp ( ffado_timestamp_t new_timestamp ); 
    132132        void setBufferHeadTimestamp ( ffado_timestamp_t new_timestamp ); 
    133  
    134         // sync related, also drops or add frames when necessary 
    135         bool syncBufferHeadToTimestamp ( ffado_timestamp_t ts ); 
    136         bool syncBufferTailToTimestamp ( ffado_timestamp_t ts ); 
    137         bool syncCorrectLag ( int64_t ts ); 
    138133 
    139134        ffado_timestamp_t getTimestampFromTail ( int nframes ); 
  • trunk/libffado/tests/test-ffado.cpp

    r864 r866  
    204204    } 
    205205 
    206     printf("verbose level = %d\n", arguments.verbose); 
     206    printf("verbose level = %ld\n", arguments.verbose); 
    207207    setDebugLevel(arguments.verbose); 
    208208 
     
    275275 
    276276            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); 
    278278 
    279279            for(i=0;i<devices_on_bus;i++) {