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. 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 output of ps axHo user,pid,%cpu,%mem,nice,rtprio,policy,tty,stat,start_time,bsdtime,args Robert -- Dipl.-Ing. Robert Schwebel | http://www.pengutronix.de Pengutronix - Linux Solutions for Science and Industry Handelsregister: Amtsgericht Hildesheim, HRA 2686 Hannoversche Str. 2, 31134 Hildesheim, Germany Phone: +49-5121-206917-0 | Fax: +49-5121-206917-9 - To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
