Robert Schwebel wrote:
quoted text
> On Thu, Jan 17, 2008 at 11:13:26AM +0100, Wolfgang Grandegger wrote:
>>   # ./cyclictest -n -p80 -i1000 -b400
>>
>> [...]
>>
>> Well, I'm not sure if this is the correct way to do it. Is there some
>> doc on how to use the latency tracer and interpret the results?
> 
> Could you put in this kind of log information inline next time? It makes
> it easier to review.

OK.

quoted text
> 
> Let's see ...
> 
>> preemption latency trace v1.1.5 on 2.6.24-rc8-rt1
>> --------------------------------------------------------------------
>>  latency: 39733427 us, #65536/1202801, CPU#0 | (M:rt VP:0, KP:0, SP:1 HP:1)
>>     -----------------
>>     | task: cyclictest-914 (uid:0 nice:0 policy:1 rt_prio:80)
>>     -----------------
> 
> Ok, so cyclictest-914 triggered the tracer. No big surprise at -t 1 :-)
> 
>> cyclicte-914   0D..1   40us+: enqueue_hrtimer+0x50/0x1a0 (   89 5aa9862 c3a6dea8)
> 
> cyclictest-914 goes to sleep for next period. We expect it to wake up
> again at 40 us + 1000 us = 1040 us.
> 
>>       ls-1032  0DNh2  999us+: __trace_start_sched_wakeup+0x154/0x18c <cyclicte-914> (19 -1)
>>       ls-1032  0DNh2 1001us+: try_to_wake_up+0x194/0x1b4 <cyclicte-914> (180 0)
>>       ls-1032  0DNh. 1008us+: clockevents_program_event+0x84/0x1c0 (   89 5ad6bbf 18e8e)
>> cyclicte-914   0D..2 1033us+: __schedule+0x21c/0x444 <ls-1032> (0 180)
>> cyclicte-914   0D..1 1071us+: enqueue_hrtimer+0x50/0x1a0 (   89 5b9daa2 c3a6dea8)
> 
> Looks good, it happened. Next wakeup at about 1071 us + 1000 us = 2071
> us.
> 
>> cyclicte-914   0D..2 2031us+: __schedule+0x21c/0x444 <IRQ-129-682> (150 180)
>> cyclicte-914   0D..1 2072us+: enqueue_hrtimer+0x50/0x1a0 (   89 5c91ce2 c3a6dea8)
> 
> Bingo. Let's get a cup of coffee in the meantime ...
> 
>> cyclicte-914   0D..1 1905066us+: enqueue_hrtimer+0x50/0x1a0 (   91 66210 c3a6dea8)
> 
> Expected arival at 1905066 us + 1000 us = 1906066 us.
> 
>>       ls-1048  0DNh3 1906017us+: __trace_start_sched_wakeup+0x154/0x18c <cyclicte-914> (19 -1)
>>       ls-1048  0DNh3 1906021us : __trace_start_sched_wakeup+0x154/0x18c <cyclicte-914> (19 -1)
>>       ls-1048  0DNh3 1906023us+: try_to_wake_up+0x194/0x1b4 <cyclicte-914> (180 0)
> 
> It's trying hard to wake up ...
> 
>>       ls-1048  0DNh1 1906028us!: clockevents_program_event+0x84/0x1c0 (   91 391676 367eff)
>>       ls-1048  0DNh2 1906274us+: activate_task+0x60/0xa4 <IRQ-193-681> (150 6)
> 
> Between these it should have happened.
> 
>>       ls-1048  0DNh2 1906285us+: __trace_start_sched_wakeup+0x154/0x18c <IRQ-193-681> (49 -1)
>>       ls-1048  0DNh2 1906293us+: __trace_start_sched_wakeup+0x154/0x18c <IRQ-193-681> (49 -1)
>>       ls-1048  0DNh2 1906295us+: try_to_wake_up+0x194/0x1b4 <IRQ-193-681> (150 0)
>> cyclicte-914   0D..2 1906332us : __schedule+0x21c/0x444 <ls-1048> (0 180)
> 
> What is this IRQ-193-681? Can you post your /proc/interrupts and the

bash-3.00# cat /proc/interrupts
           CPU0
129:        179  MPC52xx Peripherals Edge      mpc52xx_psc_uart
133:          0  MPC52xx Peripherals Edge      mpc52xx-fec_ctrl
135:          0  MPC52xx Peripherals Edge      mpc52xx_ata
192:      14853  MPC52xx SDMA Edge      mpc52xx-fec_rx
193:       9488  MPC52xx SDMA Edge      mpc52xx-fec_tx
BAD:          0


quoted text
> output of
> 
> 	ps axHo user,pid,%cpu,%mem,nice,rtprio,policy,tty,stat,start_time,bsdtime,args

time,args# ps axHo
user,pid,%cpu,%mem,nice,rtprio,policy,tty,stat,start_time,bsd
USER       PID %CPU %MEM  NI RTPRIO POL TT       STAT START   TIME COMMAND
root         1  1.0  1.0   0      - TS  ?        Ss   00:00   0:00 init
[3]
root         2  0.0  0.0  -5      - TS  ?        S<   00:00   0:00
[kthreadd]
root         3  0.0  0.0   -     99 FF  ?        S<   00:00   0:00
[posix_cpu_t]
root         4  0.0  0.0   -     50 FF  ?        S<   00:00   0:00
[softirq-hig]
root         5  1.4  0.0   -     50 FF  ?        S<   00:00   0:01
[softirq-tim]
root         6  0.7  0.0   -     50 FF  ?        S<   00:00   0:00
[softirq-net]
root         7  2.4  0.0   -     50 FF  ?        S<   00:00   0:02
[softirq-net]
root         8  0.0  0.0   -     50 FF  ?        S<   00:00   0:00
[softirq-blo]
root         9  0.0  0.0   -     50 FF  ?        S<   00:00   0:00
[softirq-tas]
root        10  0.0  0.0   -     50 FF  ?        S<   00:00   0:00
[softirq-sch]
root        11  0.0  0.0   -     50 FF  ?        S<   00:00   0:00
[softirq-hrt]
root        12  0.4  0.0   -     50 FF  ?        S<   00:00   0:00
[softirq-rcu]
root        13  0.0  0.0   -     99 FF  ?        S<   00:00   0:00
[watchdog/0]
root        14  0.0  0.0 -10      - TS  ?        S<   00:00   0:00
[desched/0]
root        15  0.0  0.0   -      1 FF  ?        S<   00:00   0:00
[events/0]
root        16  0.2  0.0  -5      - TS  ?        S<   00:00   0:00 [khelper]
root        68  0.0  0.0  -5      - TS  ?        S<   00:00   0:00
[kblockd/0]
root        75  0.0  0.0  -5      - TS  ?        S<   00:00   0:00 [ata/0]
root        76  0.0  0.0  -5      - TS  ?        S<   00:00   0:00 [ata_aux]
root        93  0.0  0.0   -      1 FF  ?        S<   00:00   0:00
[krcupreempt]
root        94  0.0  0.0   0      - TS  ?        S    00:00   0:00 [pdflush]
root        95  0.0  0.0   0      - TS  ?        S    00:00   0:00 [pdflush]
root        96  0.0  0.0  -5      - TS  ?        S<   00:00   0:00 [kswapd0]
root        97  0.0  0.0  -5      - TS  ?        S<   00:00   0:00 [aio/0]
root       675  0.0  0.0   -     50 FF  ?        S<   00:00   0:00 [IRQ-135]
root       676  0.0  0.0  -5      - TS  ?        S<   00:00   0:00
[scsi_eh_0]
root       678  0.1  0.0  -5      - TS  ?        S<   00:00   0:00
[rpciod/0]
root       679  0.0  0.0   -     50 FF  ?        S<   00:00   0:00 [IRQ-133]
root       680  1.1  0.0   -     50 FF  ?        S<   00:00   0:01 [IRQ-192]
root       681  0.9  0.0   -     50 FF  ?        S<   00:00   0:00 [IRQ-193]
root       682  0.0  0.0   -     50 FF  ?        S<   00:00   0:00 [IRQ-129]
root       848  0.1  1.3   0      - TS  ?        Ss   00:00   0:00
syslogd -m 0
root       850  0.0  0.6   0      - TS  ?        Ss   00:00   0:00 klogd -x
root       884  0.1  1.6   0      - TS  ?        Ss   00:00   0:00
xinetd -staya
root       890  0.2  2.2   0      - TS  ?        Ss   00:00   0:00 login
-- root
root       891  0.3  2.8   0      - TS  ?        Ss   00:00   0:00 -bash
root       913  5.2  1.6   0      - TS  ?        Ss   00:00   0:03
in.telnetd: 1
root       914  0.1  2.2   0      - TS  ?        Ss   00:00   0:00 login
-- root
root       915  1.4  2.8   0      - TS  ttyp0    Ss   00:00   0:00 -bash
root       938  8.4  1.1   0      - TS  ttyp0    Sl+  00:00   0:03
./cyclictest
root       938  5.5  1.1   -     99 FF  ttyp0    Sl+  00:00   0:02
./cyclictest
root       941  0.0  1.7   0      - TS  ?        R+   00:01   0:00 ps
axHo user,
bash-3.00#

Wolfgang.

quoted text
> Robert

--
unsubscribe notice
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/