Changeset 912

Show
Ignore:
Timestamp:
03/08/08 03:56:56 (14 years ago)
Author:
ppalmers
Message:

fix bug in cycle timer dll

Files:

Legend:

Unmodified
Added
Removed
Modified
Copied
Moved
  • trunk/libffado/src/libieee1394/CycleTimerHelper.cpp

    r904 r912  
    4545#define DLL_COEFF_C   (DLL_OMEGA * DLL_OMEGA) 
    4646 
    47 #define UPDATES_WITH_HIGH_BANDWIDTH 200 
     47// is 5 sec 
     48#define UPDATES_WITH_HIGH_BANDWIDTH \ 
     49         (5000000 / IEEE1394SERVICE_CYCLETIMER_DLL_UPDATE_INTERVAL_USEC) 
    4850 
    4951/* 
     
    230232        cycle_timer_ticks = CYCLE_TIMER_TO_TICKS(cycle_timer); 
    231233        diff_ticks = diffTicks(cycle_timer_ticks, (int64_t)m_next_time_ticks); 
     234 
     235        // check for unrealistic CTR reads (NEC controller does that sometimes) 
    232236        if(diff_ticks < -((double)TICKS_PER_HALFCYCLE)) { 
    233             debugOutput(DEBUG_LEVEL_VERBOSE, "have to retry, diff = %f\n",diff_ticks); 
     237            debugOutput(DEBUG_LEVEL_VERBOSE,  
     238                        "have to retry CTR read, diff unrealistic: diff: %f, max: %f\n",  
     239                        diff_ticks, -((double)TICKS_PER_HALFCYCLE)); 
    234240        } 
    235241 
     
    238244    debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, " read : CTR: %11lu, local: %17llu\n", 
    239245                        cycle_timer, local_time); 
     246        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 
     247                           "  ctr   : 0x%08X %11llu (%03us %04ucy %04uticks)\n", 
     248                           (uint32_t)cycle_timer, (uint64_t)cycle_timer_ticks, 
     249                           (unsigned int)TICKS_TO_SECS( (uint64_t)cycle_timer_ticks ), 
     250                           (unsigned int)TICKS_TO_CYCLES( (uint64_t)cycle_timer_ticks ), 
     251                           (unsigned int)TICKS_TO_OFFSET( (uint64_t)cycle_timer_ticks ) ); 
    240252 
    241253    if (m_first_run) { 
     
    246258        m_current_time_ticks = CYCLE_TIMER_TO_TICKS( cycle_timer ); 
    247259        m_next_time_ticks = addTicks( (uint64_t)m_current_time_ticks, (uint64_t)m_dll_e2); 
    248         debugOutput( DEBUG_LEVEL_VERBOSE, " First run\n"); 
    249         debugOutput( DEBUG_LEVEL_VERBOSE, "  usecs/update: %lu, ticks/update: %lu, m_dll_e2: %f\n", 
    250                                           m_usecs_per_update, m_ticks_per_update, m_dll_e2); 
    251         debugOutput( DEBUG_LEVEL_VERBOSE, "  usecs current: %f, next: %f\n", m_current_time_usecs, m_next_time_usecs); 
    252         debugOutput( DEBUG_LEVEL_VERBOSE, "  ticks current: %f, next: %f\n", m_current_time_ticks, m_next_time_ticks); 
     260        debugOutput(DEBUG_LEVEL_VERBOSE, " First run\n"); 
     261        debugOutput(DEBUG_LEVEL_VERBOSE, 
     262                    "  usecs/update: %lu, ticks/update: %lu, m_dll_e2: %f\n", 
     263                    m_usecs_per_update, m_ticks_per_update, m_dll_e2); 
     264        debugOutput(DEBUG_LEVEL_VERBOSE, 
     265                    "  usecs current: %f, next: %f\n", 
     266                    m_current_time_usecs, m_next_time_usecs); 
     267        debugOutput(DEBUG_LEVEL_VERBOSE, 
     268                    "  ticks current: %f, next: %f\n", 
     269                    m_current_time_ticks, m_next_time_ticks); 
    253270        m_first_run = false; 
    254271    } else { 
     272        // calculate next sleep time 
    255273        m_sleep_until += m_usecs_per_update; 
    256274 
     275        // correct for the latency between the wakeup and the actual CTR 
     276        // read. The only time we can trust is the time returned by the 
     277        // CTR read kernel call, since that (should be) atomically read 
     278        // together with the ctr register itself. 
     279 
     280        // if we are usecs_late usecs late  
     281        // the cycle timer has ticked approx ticks_late ticks too much 
     282        // if we are woken up early (which shouldn't happen according to POSIX) 
     283        // the cycle timer has ticked approx -ticks_late too little 
     284        int64_t ticks_late = (usecs_late * TICKS_PER_SECOND) / 1000000LL; 
     285        // the corrected difference between predicted and actual ctr 
     286        // i.e. DLL error signal 
    257287        double diff_ticks_corr; 
    258         // correct for late wakeup 
    259         int64_t ticks_late = (usecs_late * TICKS_PER_SECOND) / 1000000LL; 
    260288        if (ticks_late > 0) { 
    261             // if we are usecs_late usecs late  
    262             // the cycle timer has ticked approx ticks_late ticks too much 
    263             cycle_timer_ticks = substractTicks(cycle_timer_ticks, ticks_late); 
    264289            diff_ticks_corr = diff_ticks - ticks_late; 
     290            debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 
     291                               "diff_ticks_corr=%f, diff_ticks = %f, ticks_late = %lld\n", 
     292                               diff_ticks_corr, diff_ticks, ticks_late); 
    265293        } else { 
    266294            debugError("Early wakeup, should not happen!\n"); 
    267295            // recover 
    268             cycle_timer_ticks = addTicks(cycle_timer_ticks, -ticks_late); 
    269296            diff_ticks_corr = diff_ticks + ticks_late; 
    270297        } 
     
    286313            m_high_bw_updates--; 
    287314            if (m_high_bw_updates == 0) { 
    288                 debugOutput(DEBUG_LEVEL_VERBOSE, "Switching to low-bandwidth coefficients\n"); 
     315                debugOutput(DEBUG_LEVEL_VERBOSE, 
     316                            "Switching to low-bandwidth coefficients\n"); 
    289317            } 
    290318        } else { 
     
    293321        } 
    294322 
    295         // do the calculation in 'tick space' 
    296         int64_t tmp = (uint64_t)(coeff_b * diff_ticks_corr); 
    297         if(m_dll_e2 > 0) { 
    298             tmp = addTicks(tmp, (uint64_t)m_dll_e2); 
    299         } else { 
    300             tmp = substractTicks(tmp, (uint64_t)(-m_dll_e2)); 
    301         } 
    302         if(tmp < 0) { 
    303             debugWarning("negative slope: %lld!\n", tmp); 
    304         } 
    305         m_next_time_ticks = addTicks((uint64_t)m_current_time_ticks, tmp); 
    306  
    307         // it should be ok to not do this in tick space since it's value 
    308         // is approx equal to the rate, being 24.576 ticks/usec 
     323        // it should be ok to not do this in tick space  
     324        // since diff_ticks_corr should not be near wrapping 
     325        // (otherwise we are out of range. we need a few calls 
     326        //  w/o wrapping for this to work. That should not be 
     327        //  an issue as long as the update interval is smaller 
     328        //  than the wrapping interval.) 
     329        // and coeff_b < 1, hence tmp is not near wrapping 
     330 
     331        double step_ticks = (coeff_b * diff_ticks_corr); 
     332        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 
     333                           "diff_ticks_corr=%f, step_ticks=%f\n", 
     334                           diff_ticks_corr, step_ticks); 
     335 
     336        // the same goes for m_dll_e2, which should be approx equal 
     337        // to the ticks/usec rate (= 24.576) hence also not near 
     338        // wrapping 
     339        step_ticks += m_dll_e2; 
     340        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 
     341                           "add %f ticks to step_ticks => step_ticks=%f\n", 
     342                           m_dll_e2, step_ticks); 
     343 
     344        // it can't be that we have to update to a value in the past 
     345        if(step_ticks < 0) { 
     346            debugError("negative step: %f! (correcting to nominal)\n", step_ticks); 
     347            // recover to an estimated value 
     348            step_ticks = (double)m_ticks_per_update; 
     349        } 
     350 
     351        if(step_ticks > TICKS_PER_SECOND) { 
     352            debugWarning("rather large step: %f ticks (> 1sec)\n", step_ticks); 
     353        } 
     354 
     355        // now add the step ticks with wrapping. 
     356        m_next_time_ticks = (double)(addTicks((uint64_t)m_current_time_ticks, (uint64_t)step_ticks)); 
     357 
     358        // update the DLL state 
    309359        m_dll_e2 += coeff_c * diff_ticks_corr; 
    310  
    311         // For jitter graphs 
    312         // debugOutputShort(DEBUG_LEVEL_NORMAL, "0123456789 %f %f %f %lld %lld %lld\n",  
    313         //                 diff_ticks, diff_ticks_corr, m_dll_e2, cycle_timer_ticks, (int64_t)m_next_time_ticks, usecs_late); 
    314360 
    315361        // update the y-axis values 
     
    317363        m_next_time_usecs += m_usecs_per_update; 
    318364 
    319         debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, " usecs: current: %f next: %f usecs_late=%lld ticks_late=%lld\n", 
    320                             m_current_time_usecs, m_next_time_usecs, usecs_late, ticks_late); 
    321         debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, " ticks: current: %f next: %f diff=%f\n", 
    322                             m_current_time_ticks, m_next_time_ticks, diff_ticks); 
    323         debugOutputExtreme( DEBUG_LEVEL_VERY_VERBOSE, " state: local: %11llu, dll_e2: %f, rate: %f\n", 
    324                             local_time, m_dll_e2, getRate()); 
     365        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE,  
     366                           " usecs: current: %f next: %f usecs_late=%lld ticks_late=%lld\n", 
     367                           m_current_time_usecs, m_next_time_usecs, usecs_late, ticks_late); 
     368        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 
     369                           " ticks: current: %f next: %f diff=%f\n", 
     370                           m_current_time_ticks, m_next_time_ticks, diff_ticks); 
     371        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 
     372                           " ticks: current: %011llu (%03us %04ucy %04uticks)\n", 
     373                           (uint64_t)m_current_time_ticks, 
     374                           (unsigned int)TICKS_TO_SECS( (uint64_t)m_current_time_ticks ), 
     375                           (unsigned int)TICKS_TO_CYCLES( (uint64_t)m_current_time_ticks ), 
     376                           (unsigned int)TICKS_TO_OFFSET( (uint64_t)m_current_time_ticks ) ); 
     377        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 
     378                           " ticks: next   : %011llu (%03us %04ucy %04uticks)\n", 
     379                           (uint64_t)m_next_time_ticks, 
     380                           (unsigned int)TICKS_TO_SECS( (uint64_t)m_next_time_ticks ), 
     381                           (unsigned int)TICKS_TO_CYCLES( (uint64_t)m_next_time_ticks ), 
     382                           (unsigned int)TICKS_TO_OFFSET( (uint64_t)m_next_time_ticks ) ); 
     383 
     384        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, 
     385                           " state: local: %11llu, dll_e2: %f, rate: %f\n", 
     386                           local_time, m_dll_e2, getRate()); 
    325387    } 
    326388 
     
    360422    if (y_step_in_ticks_int > 0) { 
    361423        retval = addTicks(offset_in_ticks_int, y_step_in_ticks_int); 
    362         debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "y_step_in_ticks_int > 0: %lld, time_diff: %f, rate: %f, retval: %lu\n",  
    363                     y_step_in_ticks_int, time_diff, my_vars.rate, retval); 
     424/*        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "y_step_in_ticks_int > 0: %lld, time_diff: %f, rate: %f, retval: %lu\n",  
     425                    y_step_in_ticks_int, time_diff, my_vars.rate, retval);*/ 
    364426    } else { 
    365427        retval = substractTicks(offset_in_ticks_int, -y_step_in_ticks_int); 
    366428 
    367429        // this can happen if the update thread was woken up earlier than it should have been 
    368         debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "y_step_in_ticks_int <= 0: %lld, time_diff: %f, rate: %f, retval: %lu\n",  
    369                     y_step_in_ticks_int, time_diff, my_vars.rate, retval); 
     430/*        debugOutputExtreme(DEBUG_LEVEL_VERY_VERBOSE, "y_step_in_ticks_int <= 0: %lld, time_diff: %f, rate: %f, retval: %lu\n",  
     431                    y_step_in_ticks_int, time_diff, my_vars.rate, retval);*/ 
    370432    } 
    371433