Re: [patch] voluntary-preempt-2.6.9-rc2-mm4-S7

[Ingo Molnar]

* Lee Revell <rlrevell@xxxxxxxxxxx> wrote:

> Finally, there's this one which makes no sense to me:
> 
> preemption latency trace v1.0.7 on 2.6.9-rc2-mm4-VP-S7
> -------------------------------------------------------
>  latency: 507 us, entries: 45 (45)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:1]
>     -----------------
>     | task: events/0/3, uid:0 nice:-10 policy:0 rt_prio:0
>     -----------------
>  => started at: kernel_fpu_begin+0x15/0x70
>  => ended at:   _mmx_memcpy+0x13a/0x180
> =======>
> 00000001 0.000ms (+0.002ms): kernel_fpu_begin (_mmx_memcpy)
> 00010001 0.002ms (+0.000ms): do_IRQ (_mmx_memcpy)

> 00000002 0.028ms (+0.478ms): preempt_schedule (try_to_wake_up)
> 00000001 0.507ms (+0.000ms): sub_preempt_count (_mmx_memcpy)

> 478 usecs in try_to_wake_up?

no, 478 usecs in _mmx_memcpy - the timer interrupt interrupted that
function and we returned to it after the timer irq. We only know that
the latency happens between try_to_wake_up()'s preempt_schedule() and
_mmax_memcpy. Latency tracing does not capture function exits (would be
too costly) so effects of two functions can add up. The try_to_wake_up()
was simply the last function _entry_ that happened in the timer irq,
that's why it got 'credited' for the latency.

do you still have the stacktrace too that went to the syslog? What
codepath called _mmx_memcpy()?

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