preempt timing violations

preempt timing violations

[Lee Revell]

Latency with 2.6.8-rc2 + voluntary-preempt-I4 is the best so far.  After
extended testing there only seem to be a few hot spots.  In several
minutes I saw an 11ms violation, a 14ms violation, and several 2ms
violations.

get_user_pages() is much better in 2.6.8-rc1-mm1 than 2.6.8-rc2.  Is
there any chance of getting the fix into mainline?

In each of these case you can see a preempt timing violation followed by
an XRUN trace.

Jul 25 23:09:27 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D2c
Jul 25 23:09:27 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 23:09:27 mindpipe kernel:  [__crc_totalram_pages+1165/3197748] snd_pcm_period_elapsed+0x2c7/0x400 [snd_pcm]
Jul 25 23:09:27 mindpipe kernel:  [__crc_totalram_pages+65879/3197748] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 25 23:09:27 mindpipe kernel:  [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 25 23:09:27 mindpipe kernel:  [do_IRQ+167/368] do_IRQ+0xa7/0x170
Jul 25 23:09:27 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 25 23:09:27 mindpipe kernel:  [unix_stream_recvmsg+505/1056] unix_stream_recvmsg+0x1f9/0x420
Jul 25 23:09:27 mindpipe kernel:  [sock_aio_read+221/256] sock_aio_read+0xdd/0x100
Jul 25 23:09:27 mindpipe kernel:  [do_sync_read+106/160] do_sync_read+0x6a/0xa0
Jul 25 23:09:27 mindpipe kernel:  [vfs_read+227/272] vfs_read+0xe3/0x110
Jul 25 23:09:27 mindpipe kernel:  [sys_read+46/80] sys_read+0x2e/0x50
Jul 25 23:09:27 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 25 23:09:27 mindpipe kernel: 2ms non-preemptible critical section violated 1 ms preempt threshold starting at unmap_vmas+0x1ff/0x210 and ending at unmap_vmas+0x1f5/0x210
Jul 25 23:09:27 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 23:09:27 mindpipe kernel:  [dec_preempt_count+270/288] dec_preempt_count+0x10e/0x120
Jul 25 23:09:27 mindpipe kernel:  [unmap_vmas+501/528] unmap_vmas+0x1f5/0x210
Jul 25 23:09:27 mindpipe kernel:  [exit_mmap+94/336] exit_mmap+0x5e/0x150
Jul 25 23:09:27 mindpipe kernel:  [mmput+114/160] mmput+0x72/0xa0
Jul 25 23:09:27 mindpipe kernel:  [do_exit+251/1072] do_exit+0xfb/0x430
Jul 25 23:09:27 mindpipe kernel:  [do_group_exit+50/192] do_group_exit+0x32/0xc0
Jul 25 23:09:27 mindpipe kernel:  [get_signal_to_deliver+605/880] get_signal_to_deliver+0x25d/0x370
Jul 25 23:09:27 mindpipe kernel:  [do_signal+86/208] do_signal+0x56/0xd0
Jul 25 23:09:27 mindpipe kernel:  [do_notify_resume+71/80] do_notify_resume+0x47/0x50
Jul 25 23:09:27 mindpipe kernel:  [work_notifysig+19/21] work_notifysig+0x13/0x15
Jul 25 23:09:27 mindpipe kernel: 2ms non-preemptible critical section violated 1 ms preempt threshold starting at unmap_vmas+0x1ff/0x210 and ending at unmap_vmas+0x1f5/0x210
Jul 25 23:09:27 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 23:09:27 mindpipe kernel:  [dec_preempt_count+270/288] dec_preempt_count+0x10e/0x120
Jul 25 23:09:27 mindpipe kernel:  [unmap_vmas+501/528] unmap_vmas+0x1f5/0x210
Jul 25 23:09:27 mindpipe kernel:  [exit_mmap+94/336] exit_mmap+0x5e/0x150
Jul 25 23:09:27 mindpipe kernel:  [mmput+114/160] mmput+0x72/0xa0
Jul 25 23:09:27 mindpipe kernel:  [do_exit+251/1072] do_exit+0xfb/0x430
Jul 25 23:09:27 mindpipe kernel:  [do_group_exit+50/192] do_group_exit+0x32/0xc0
Jul 25 23:09:27 mindpipe kernel:  [get_signal_to_deliver+605/880] get_signal_to_deliver+0x25d/0x370
Jul 25 23:09:27 mindpipe kernel:  [do_signal+86/208] do_signal+0x56/0xd0
Jul 25 23:09:27 mindpipe kernel:  [work_notifysig+19/21] work_notifysig+0x13/0x15
Jul 25 23:09:27 mindpipe kernel: 2ms non-preemptible critical section violated 1 ms preempt threshold starting at unmap_vmas+0x1ff/0x210 and ending at unmap_vmas+0x1f5/0x210
Jul 25 23:09:27 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 23:09:27 mindpipe kernel:  [dec_preempt_count+270/288] dec_preempt_count+0x10e/0x120
Jul 25 23:09:27 mindpipe kernel:  [unmap_vmas+501/528] unmap_vmas+0x1f5/0x210
Jul 25 23:09:27 mindpipe kernel:  [exit_mmap+94/336] exit_mmap+0x5e/0x150
Jul 25 23:09:27 mindpipe kernel:  [mmput+114/160] mmput+0x72/0xa0
Jul 25 23:09:27 mindpipe kernel:  [do_exit+251/1072] do_exit+0xfb/0x430
Jul 25 23:09:27 mindpipe kernel:  [do_group_exit+50/192] do_group_exit+0x32/0xc0
Jul 25 23:09:27 mindpipe kernel:  [get_signal_to_deliver+605/880] get_signal_to_deliver+0x25d/0x370
Jul 25 23:09:27 mindpipe kernel:  [do_signal+86/208] do_signal+0x56/0xd0
Jul 25 23:09:27 mindpipe kernel:  [do_notify_resume+71/80] do_notify_resume+0x47/0x50
Jul 25 23:09:27 mindpipe kernel:  [work_notifysig+19/21] work_notifysig+0x13/0x15
Jul 25 23:09:31 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D2c
Jul 25 23:09:31 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 23:09:31 mindpipe kernel:  [__crc_totalram_pages+1165/3197748] snd_pcm_period_elapsed+0x2c7/0x400 [snd_pcm]
Jul 25 23:09:31 mindpipe kernel:  [__crc_totalram_pages+65879/3197748] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 25 23:09:31 mindpipe kernel:  [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 25 23:09:31 mindpipe kernel:  [do_IRQ+167/368] do_IRQ+0xa7/0x170
Jul 25 23:09:31 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 25 23:09:31 mindpipe kernel:  [do_anonymous_page+126/400] do_anonymous_page+0x7e/0x190
Jul 25 23:09:31 mindpipe kernel:  [do_no_page+78/784] do_no_page+0x4e/0x310
Jul 25 23:09:31 mindpipe kernel:  [handle_mm_fault+193/368] handle_mm_fault+0xc1/0x170
Jul 25 23:09:31 mindpipe kernel:  [get_user_pages+272/880] get_user_pages+0x110/0x370
Jul 25 23:09:31 mindpipe kernel:  [make_pages_present+104/144] make_pages_present+0x68/0x90
Jul 25 23:09:31 mindpipe kernel:  [do_mmap_pgoff+998/1568] do_mmap_pgoff+0x3e6/0x620
Jul 25 23:09:31 mindpipe kernel:  [sys_mmap2+118/176] sys_mmap2+0x76/0xb0
Jul 25 23:09:31 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 25 23:09:31 mindpipe kernel: 11ms non-preemptible critical section violated 1 ms preempt threshold starting at kmap_atomic+0x10/0x60 and ending at kunmap_atomic+0x8/0x20
Jul 25 23:09:31 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 23:09:31 mindpipe kernel:  [dec_preempt_count+270/288] dec_preempt_count+0x10e/0x120
Jul 25 23:09:31 mindpipe kernel:  [kunmap_atomic+8/32] kunmap_atomic+0x8/0x20
Jul 25 23:09:31 mindpipe kernel:  [do_anonymous_page+139/400] do_anonymous_page+0x8b/0x190
Jul 25 23:09:31 mindpipe kernel:  [do_no_page+78/784] do_no_page+0x4e/0x310
Jul 25 23:09:31 mindpipe kernel:  [handle_mm_fault+193/368] handle_mm_fault+0xc1/0x170
Jul 25 23:09:31 mindpipe kernel:  [get_user_pages+272/880] get_user_pages+0x110/0x370
Jul 25 23:09:31 mindpipe kernel:  [make_pages_present+104/144] make_pages_present+0x68/0x90
Jul 25 23:09:31 mindpipe kernel:  [do_mmap_pgoff+998/1568] do_mmap_pgoff+0x3e6/0x620
Jul 25 23:09:31 mindpipe kernel:  [sys_mmap2+118/176] sys_mmap2+0x76/0xb0
Jul 25 23:09:31 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 25 23:27:51 mindpipe kernel: ALSA /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:169: XRUN: pcmC0D2c
Jul 25 23:27:51 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 23:27:51 mindpipe kernel:  [__crc_totalram_pages+1165/3197748] snd_pcm_period_elapsed+0x2c7/0x400 [snd_pcm]
Jul 25 23:27:51 mindpipe kernel:  [__crc_totalram_pages+65879/3197748] snd_emu10k1_interrupt+0xd1/0x3c0 [snd_emu10k1]
Jul 25 23:27:51 mindpipe kernel:  [handle_IRQ_event+51/96] handle_IRQ_event+0x33/0x60
Jul 25 23:27:51 mindpipe kernel:  [do_IRQ+167/368] do_IRQ+0xa7/0x170
Jul 25 23:27:51 mindpipe kernel:  [common_interrupt+24/32] common_interrupt+0x18/0x20
Jul 25 23:27:51 mindpipe kernel:  [write_chan+382/528] write_chan+0x17e/0x210
Jul 25 23:27:51 mindpipe kernel:  [tty_write+459/656] tty_write+0x1cb/0x290
Jul 25 23:27:51 mindpipe kernel:  [vfs_write+188/272] vfs_write+0xbc/0x110
Jul 25 23:27:51 mindpipe kernel:  [sys_write+46/80] sys_write+0x2e/0x50
Jul 25 23:27:51 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Jul 25 23:27:51 mindpipe kernel: 14ms non-preemptible critical section violated 1 ms preempt threshold starting at tty_write+0x1b6/0x290 and ending at schedule+0x2fd/0x5b0
Jul 25 23:27:51 mindpipe kernel:  [dump_stack+23/32] dump_stack+0x17/0x20
Jul 25 23:27:51 mindpipe kernel:  [dec_preempt_count+270/288] dec_preempt_count+0x10e/0x120
Jul 25 23:27:51 mindpipe kernel:  [schedule+765/1456] schedule+0x2fd/0x5b0
Jul 25 23:27:51 mindpipe kernel:  [schedule_timeout+87/160] schedule_timeout+0x57/0xa0
Jul 25 23:27:51 mindpipe kernel:  [do_poll+161/192] do_poll+0xa1/0xc0
Jul 25 23:27:51 mindpipe kernel:  [sys_poll+305/544] sys_poll+0x131/0x220
Jul 25 23:27:51 mindpipe kernel:  [syscall_call+7/11] syscall_call+0x7/0xb

Re: preempt timing violations

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> Latency with 2.6.8-rc2 + voluntary-preempt-I4 is the best so far. 
> After extended testing there only seem to be a few hot spots.  In
> several minutes I saw an 11ms violation, a 14ms violation, and several
> 2ms violations.
> 
> get_user_pages() is much better in 2.6.8-rc1-mm1 than 2.6.8-rc2.  Is
> there any chance of getting the fix into mainline?

in -J3 i've added a cond_resched to the latency-generating point of
get_user_pages(). (The biggest latencies happen via
make_pages_present(), which gets triggered by mlockall()/MAP_LOCKED.)

> 2ms non-preemptible critical section violated 1 ms preempt threshold
> starting at unmap_vmas+0x1ff/0x210 and ending at
> unmap_vmas+0x1f5/0x210

this is the normal sys_exit()->exit_mmap()->unmap_vmas() path. It's
weird that it generated a 2ms latency. What are the values of
voluntary_preemption and kernel_preemption on your current kernel? With
a 2:0 setting we ought to have a reschedule point every 32 pages.  Do
you know which application triggers this latency and is it easy to
reproduce?

> 14ms non-preemptible critical section violated 1 ms preempt threshold 
> starting at tty_write+0x1b6/0x290 and ending at schedule+0x2fd/0x5b0

does this one trigger when you are using the VGA console? (or fbcon)?

it's not immediately obvious to me precisely where this latency comes
from, it would be nice to know how to reproduce it.

	Ingo

Re: preempt timing violations

[Lee Revell]

On Mon, 2004-07-26 at 04:50, Ingo Molnar wrote:
> * Lee Revell <rlrevell@joe-job.com> wrote:
> 
> > Latency with 2.6.8-rc2 + voluntary-preempt-I4 is the best so far. 
> > After extended testing there only seem to be a few hot spots.  In
> > several minutes I saw an 11ms violation, a 14ms violation, and several
> > 2ms violations.
> > 
> > get_user_pages() is much better in 2.6.8-rc1-mm1 than 2.6.8-rc2.  Is
> > there any chance of getting the fix into mainline?
> 
> in -J3 i've added a cond_resched to the latency-generating point of
> get_user_pages(). (The biggest latencies happen via
> make_pages_present(), which gets triggered by mlockall()/MAP_LOCKED.)
> 

OK, great, this is the biggest remaing issue with -I4, because jackd
does that a lot.

> > 2ms non-preemptible critical section violated 1 ms preempt threshold
> > starting at unmap_vmas+0x1ff/0x210 and ending at
> > unmap_vmas+0x1f5/0x210
> 
> this is the normal sys_exit()->exit_mmap()->unmap_vmas() path. It's
> weird that it generated a 2ms latency. What are the values of
> voluntary_preemption and kernel_preemption on your current kernel? With
> a 2:0 setting we ought to have a reschedule point every 32 pages.  Do
> you know which application triggers this latency and is it easy to
> reproduce?
> 

2 and 1.  Now that I think about it, this could have happened during
bootup, before my rc.local set these.  I will try passing them on the
kernel command line. 

Not sure I understand the difference between 2:1 and 2:0.   Would the
latter make the kernel only preemptible at the voluntary preemption
points?

> > 14ms non-preemptible critical section violated 1 ms preempt threshold 
> > starting at tty_write+0x1b6/0x290 and ending at schedule+0x2fd/0x5b0
> 
> does this one trigger when you are using the VGA console? (or fbcon)?
> 
> it's not immediately obvious to me precisely where this latency comes
> from, it would be nice to know how to reproduce it.

It think this one was caused by switching virtual consoles.  At one
point Andrew Morton suggested I remove the (un)lock_kernel calls from
do_tty_write.  This fixed the problem, with no detectable side effects. 
Maybe this could be incorporated into voluntary-preempt, it would be
useful to have more than one person to test it.

Lee

Re: preempt timing violations

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> > this is the normal sys_exit()->exit_mmap()->unmap_vmas() path. It's
> > weird that it generated a 2ms latency. What are the values of
> > voluntary_preemption and kernel_preemption on your current kernel? With
> > a 2:0 setting we ought to have a reschedule point every 32 pages.  Do
> > you know which application triggers this latency and is it easy to
> > reproduce?
> > 
> 
> 2 and 1.  Now that I think about it, this could have happened during
> bootup, before my rc.local set these.  I will try passing them on the
> kernel command line. 

hm, if you enabled kernel_preemption then the get_user_pages() fix in
-J3 should already be available via normal kernel preemption, because
make_pages_present() is preemptible. I am wondering whether the
preempt-timing patch properly deals with CONFIG_PREEMPT? Did those
latencies get accompanied by a real Alsa XRUN as well? (assuming you can
set the XRUN threshold to be close to the preempt-timing threshold.)

> Not sure I understand the difference between 2:1 and 2:0.  Would the
> latter make the kernel only preemptible at the voluntary preemption
> points?

yes, this is the default on bootup. 1:0 is in essence what we are using
in the latest development kernels of Fedora Core 3, hence the focus and
distinction. It is an intermediate preemptability step between the
vanilla kernel and full CONFIG_PREEMPT. If the concept produces a stable
enough kernel for use in bigger distros such as FC3 it could pave the
way for more mainstream acceptance of CONFIG_PREEMPT.

> > does this one trigger when you are using the VGA console? (or fbcon)?
> > 
> > it's not immediately obvious to me precisely where this latency comes
> > from, it would be nice to know how to reproduce it.
> 
> It think this one was caused by switching virtual consoles.  At one
> point Andrew Morton suggested I remove the (un)lock_kernel calls from
> do_tty_write.  This fixed the problem, with no detectable side
> effects.  Maybe this could be incorporated into voluntary-preempt, it
> would be useful to have more than one person to test it.

if it's the text consoles that you used then most latencies are caused
by the text-video-RAM copying. Even today's fast videocards do that with
very bad performance - especially since we often do copies within
videoram too. Such a copying of ~6K of videoram can easily take 3-4
msecs.

If the tty layer is run without the kernel lock then this copying
becomes preemptible. Could you send me the current tty-unlock patch that
you are using? (i've seen some early ones.)

	Ingo

Re: preempt timing violations

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> 2 and 1.  Now that I think about it, this could have happened during
> bootup, before my rc.local set these.  I will try passing them on the
> kernel command line. 

the kernel command line option for immediate 2:1 is:

  "voluntary-preempt=2 preempt=1"

	Ingo

Re: preempt timing violations (unmap_vmas)

[Rudo Thomas]

Hello.

> > 2ms non-preemptible critical section violated 1 ms preempt threshold
> > starting at unmap_vmas+0x1ff/0x210 and ending at
> > unmap_vmas+0x1f5/0x210
> 
> this is the normal sys_exit()->exit_mmap()->unmap_vmas() path. It's
> weird that it generated a 2ms latency. What are the values of
> voluntary_preemption and kernel_preemption on your current kernel? With
> a 2:0 setting we ought to have a reschedule point every 32 pages.  Do
> you know which application triggers this latency and is it easy to
> reproduce?

I discovered that I got two of these in a row. The settings are 2:1, but I am
not able to reproduce it.

Rudo.