[ECOS] Questions about clock and tm_basic

["Xavier Wang" <xavierwang at ms19 dot url dot com dot tw>]

Hi,

I got some problems about clock, timing and the tm_basic program. The
followings are my understanding of clock primitives of eCos kernel:

- CYGNUM_KERNEL_COUNTERS_CLOCK_OVERRIDE_DENOMINATOR
  or CYGNUM_HAL_RTC_DENOMINATOR is the frequency of timer
  interrupt, e.g. 100Hz (10 ms).

- CYGNUM_KERNEL_COUNTERS_RTC_PERIOD is the number of
  hardware clock ticks between timer interrupt. For example, if the CPU
  is running at 20MHz as well as the hardware clock tick, and that the
  frequency of timer interrupt is 100Hz, then
  CYGNUM_KERNEL_COUNTERS_RTC_PERIOD should be 200K.

- HAL_CLOCK_READ() is to read the number of hardware clock ticks
  since last timer interrupt.

Then I looked into the default settings for MIPS/TX39 platform and found:
    CYGHWR_HAL_MIPS_CPU_FREQ_ACTURE = 49152000
    CYGNUM_HAL_RTC_DENOMINATOR = 100
    CYGNUM_HAL_RTC_PERIOD = 15360
And 49152000 / (15360 * 100) = 32, thus means
    1 raw hardware clock tick = 32 system cycles.
According to Getting Started with eCos (Toshiba TX39 edition), clock
interrupt took 45 row clock ticks, that means it took 45 x 32 = 1440 system
cycles, thus means the clock interrupt took approximate 1400 CPU instructions.
Am I right here?

I'm porting eCos to a MIPS R3000 variance that both frequencies of
CPU and external hardware clock tick are 20MHz. Everything works
fine. But the output of tm_basic confuses me:

<<<<<<<<<<<< begin of tm_basic output >>>>>>>>>>>>

eCos Kernel Timings
Notes: all times are in microseconds (.000001) unless otherwise stated

Reading the hardware clock takes 57 'ticks' overhead
... this value will be factored out of all other measurements
Clock interrupt took   376.77 microseconds (7535 raw clock ticks)

                                 Confidence
     Ave     Min     Max     Var  Ave  Min  Function
  ======  ======  ======  ====== ========== ========
  135.54  123.95  191.00    7.41   85%  47% Create thread
   14.75   12.70   51.45    3.50   95%  95% Yield thread [all suspended]
   16.77   13.25   59.40    4.07   95%  95% Suspend [suspended] thread
   33.45   30.70   61.70    2.71   90%  90% Resume thread
   31.37   27.40   84.35    5.05   95%  95% Set priority
    6.02    4.25   26.25    2.31   95%  71% Get priority
  122.48  114.00  227.10   10.64   95%  85% Kill [suspended] thread
   14.74   12.75   50.55    3.41   95%  95% Yield [no other] thread
   57.20   52.05  122.55    6.99   90%  90% Resume [suspended low prio] thread
   28.90   26.25   61.15    3.11   95%  95% Resume [runnable low prio] thread
   39.10   27.35  107.50    6.54   90%   4% Suspend [runnable] thread
   34.63   32.50   56.75    2.11   90%  95% Yield [only low prio] thread
   20.80   17.50   59.90    3.78   95%  90% Suspend [runnable->not runnable]
  112.75  103.05  227.90   11.76   95%  85% Kill [runnable] thread
   65.13   61.10  123.25    5.54   95%  95% Destroy [dead] thread
  152.30  141.25  265.85   11.37   95%  85% Destroy [runnable] thread
  181.40  165.35  318.25   16.64   90%  85% Resume [high priority] thread
   73.51   68.45  492.40    7.69   96%  96% Thread switch

[skipped]

    6.74    5.10   44.10    2.34   96%  96% Create alarm
   43.94   38.70  118.65    5.77   96%  84% Initialize alarm
    4.08    2.65   27.50    1.99   96%  75% Disable alarm
   36.54   31.20  112.50    5.69   93%  84% Enable alarm
    5.77    3.95   37.35    2.32   96%  75% Delete alarm
   36.04   33.65   82.95    2.93   96%  96% Tick counter [1 alarm]
  113.84  111.10  164.95    3.19   96%  96% Tick counter [many alarms]
   63.53   60.35  123.70    3.76   96%  96% Tick & fire counter [1 alarm]
  386.21  379.35  495.90   10.22   93%  93% Tick & fire counters [>1 together]
  142.18  138.65  196.35    3.73   96%  87% Tick & fire counters [>1 separately]
  317.78  312.60  530.30    4.65   97%  93% Alarm latency [0 threads]
  411.64  329.85  572.30   28.63   56%   9% Alarm latency [2 threads]
  424.18  356.70  587.65   31.63   55%  25% Alarm latency [many threads]
  597.67  574.10 2641.40   31.93   99%  99% Alarm -> thread resume latency

 2265.03    3.65 9991.45    0.00            Clock/interrupt latency

40335.30   80.00214659.16    0.00            Clock DSR latency

  744     744     744  (main stack:  1184)  Thread stack used (1232 total)
All done, main stack            : stack used  1184 size  2256
All done             :  Interrupt stack used   552 size  4096
All done             : Idlethread stack used   640 size  2048

Timing complete - 95670 ms total

PASS:<Basic timing OK>
EXIT:<done>

<<<<<<<<<<<< end of tm_basic output >>>>>>>>>>>>

The followings are my questions about the output result:

1. My MIPS CPU is running at 20MHz and the referenced TX39 is running
    at 50MHz. Thus the performance is expected to be 2.5 times slower.
    But the result showed that my CPU is much slower than that. Weird?

2. Clock interrupt took approximate 7500 instructions. Weird?

3. It seems that clock/interrupt latency and clock DSR latency are too
    long. Furthermore, the determinism of latency seems very poor. Why?
    I had double-checked my code of timing measurement but couldn't
    figure it out still.

Any help will be highly appreciated.
Thanks.

--
Xavier