From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S264261AbUHJLKl (ORCPT ); Tue, 10 Aug 2004 07:10:41 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S264297AbUHJLKl (ORCPT ); Tue, 10 Aug 2004 07:10:41 -0400 Received: from mail.gmx.de ([213.165.64.20]:16547 "HELO mail.gmx.net") by vger.kernel.org with SMTP id S264261AbUHJLKb (ORCPT ); Tue, 10 Aug 2004 07:10:31 -0400 X-Authenticated: #4399952 Date: Tue, 10 Aug 2004 13:20:32 +0200 From: Florian Schmidt To: Lee Revell Cc: Ingo Molnar , linux-kernel , Felipe Alfaro Solana Subject: Re: [patch] voluntary-preempt-2.6.8-rc3-O4 Message-Id: <20040810132032.2877f687@mango.fruits.de> In-Reply-To: <1092103522.761.2.camel@mindpipe> References: <1090795742.719.4.camel@mindpipe> <20040726082330.GA22764@elte.hu> <1090830574.6936.96.camel@mindpipe> <20040726083537.GA24948@elte.hu> <1090832436.6936.105.camel@mindpipe> <20040726124059.GA14005@elte.hu> <20040726204720.GA26561@elte.hu> <20040729222657.GA10449@elte.hu> <20040801193043.GA20277@elte.hu> <20040809104649.GA13299@elte.hu> <20040809130558.GA17725@elte.hu> <20040809190201.64dab6ea@mango.fruits.de> <1092103522.761.2.camel@mindpipe> X-Mailer: Sylpheed-Claws 0.9.12 (GTK+ 1.2.10; i386-pc-linux-gnu) Mime-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org X-Mailing-List: linux-kernel@vger.kernel.org On Mon, 09 Aug 2004 22:06:20 -0400 Lee Revell wrote: > > I don't use APIC, since it never worked good for me.. But i wanted > > to report that the mlockall latency still seems to be there.. I can > > easily trigger it with mlockall'ing > ~10000kb. Need to recompile > > with the preempt-timing patch, but here's an xrun trace that > > happened when mlockall'ing 20000kb: > > > > Same results here, the mlockall problem is not fixed by -O4: > > ALSA > /home/rlrevell/cvs/alsa/alsa-driver/alsa-kernel/core/pcm_lib.c:139: > XRUN: pcmC0D2c > [] dump_stack+0x17/0x20 [snip] > (jackd/778): 10984us non-preemptible critical section violated 1100 us > preempt threshold starting at kmap_atomic+0x10/0x60 and ending at > kunmap_atomic+0x8/0x20 [snip] Hi, i just applied the new preempt-timing patch and i made the observation that if jackd is not running then mlocking 500megs of ram doesn't cause the preempt-timing [thresh = 1000] to report anything. But when jackd is running i can easily cause an xrun by mlocking even only 50megs. In this case also a critical section report is printed by the preempt-timing: Aug 10 13:13:05 mango kernel: ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p Aug 10 13:13:05 mango kernel: [] dump_stack+0x1e/0x20 Aug 10 13:13:05 mango kernel: [] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm] Aug 10 13:13:05 mango kernel: [] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx] Aug 10 13:13:05 mango kernel: [] generic_handle_IRQ_event+0x3b/0x70 Aug 10 13:13:05 mango kernel: [] do_IRQ+0xb6/0x170 Aug 10 13:13:05 mango kernel: [] common_interrupt+0x18/0x20 Aug 10 13:13:05 mango kernel: [] get_user_pages+0xd3/0x3d0 Aug 10 13:13:05 mango kernel: [] make_pages_present+0x8d/0xb0 Aug 10 13:13:05 mango kernel: [] mlock_fixup+0xa6/0xc0 Aug 10 13:13:05 mango kernel: [] do_mlockall+0x7b/0x90 Aug 10 13:13:05 mango kernel: [] sys_mlockall+0x9e/0xb0 Aug 10 13:13:05 mango kernel: [] syscall_call+0x7/0xb Aug 10 13:13:05 mango kernel: (mlockall_test/877): 2706us non-preemptible critical section violated 1000 us preempt threshold starting at get_user_pages+0x2f3/0x3d0 and ending at get_user_pages+0xa5/0x3d0 Aug 10 13:13:05 mango kernel: [] dump_stack+0x1e/0x20 Aug 10 13:13:05 mango kernel: [] touch_preempt_timing+0x33/0x40 Aug 10 13:13:05 mango kernel: [] get_user_pages+0xa5/0x3d0 Aug 10 13:13:05 mango kernel: [] make_pages_present+0x8d/0xb0 Aug 10 13:13:05 mango kernel: [] mlock_fixup+0xa6/0xc0 Aug 10 13:13:05 mango kernel: [] do_mlockall+0x7b/0x90 Aug 10 13:13:05 mango kernel: [] sys_mlockall+0x9e/0xb0 Aug 10 13:13:05 mango kernel: [] syscall_call+0x7/0xb So it seems that the combination of the two is somehow triggering this behaviour: ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p [] dump_stack+0x1e/0x20 [] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm] [] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx] [] generic_handle_IRQ_event+0x3b/0x70 [] do_IRQ+0xb6/0x170 [] common_interrupt+0x18/0x20 [] get_user_pages+0x2f3/0x3d0 [] make_pages_present+0x8d/0xb0 [] mlock_fixup+0xa6/0xc0 [] do_mlockall+0x7b/0x90 [] sys_mlockall+0x9e/0xb0 [] syscall_call+0x7/0xb (mlockall_test/862): 2701us non-preemptible critical section violated 1000 us preempt threshold starting at get_user_pages+0x2f3/0x3d0 and ending at get_user_pages+0xa5/0x3d0 [] dump_stack+0x1e/0x20 [] touch_preempt_timing+0x33/0x40 [] get_user_pages+0xa5/0x3d0 [] make_pages_present+0x8d/0xb0 [] mlock_fixup+0xa6/0xc0 [] do_mlockall+0x7b/0x90 [] sys_mlockall+0x9e/0xb0 [] syscall_call+0x7/0xb ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p [] dump_stack+0x1e/0x20 [] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm] [] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx] [] generic_handle_IRQ_event+0x3b/0x70 [] do_IRQ+0xb6/0x170 [] common_interrupt+0x18/0x20 [] check_preempt_timing+0x16/0x100 [] sub_preempt_count+0x45/0x60 [] get_user_pages+0x2e2/0x3d0 [] make_pages_present+0x8d/0xb0 [] mlock_fixup+0xa6/0xc0 [] do_mlockall+0x7b/0x90 [] sys_mlockall+0x9e/0xb0 [] syscall_call+0x7/0xb ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p [] dump_stack+0x1e/0x20 [] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm] [] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx] [] generic_handle_IRQ_event+0x3b/0x70 [] do_IRQ+0xb6/0x170 [] common_interrupt+0x18/0x20 ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p [] dump_stack+0x1e/0x20 [] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm] [] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx] [] generic_handle_IRQ_event+0x3b/0x70 [] do_IRQ+0xb6/0x170 [] common_interrupt+0x18/0x20 ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p [] dump_stack+0x1e/0x20 [] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm] [] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx] [] generic_handle_IRQ_event+0x3b/0x70 [] do_IRQ+0xb6/0x170 [] common_interrupt+0x18/0x20 I also tried to disable syslogd and looked into dmesg to see the xrun reports. i don't know if they differ in any essential way: [] syscall_call+0x7/0xb ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p [] dump_stack+0x1e/0x20 [] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm] [] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx] [] generic_handle_IRQ_event+0x3b/0x70 [] do_IRQ+0xb6/0x170 [] common_interrupt+0x18/0x20 [] __touch_preempt_timing+0x8/0x20 [] touch_preempt_timing+0x3e/0x40 [] get_user_pages+0xa5/0x3d0 [] make_pages_present+0x8d/0xb0 [] mlock_fixup+0xa6/0xc0 [] do_mlockall+0x7b/0x90 [] sys_mlockall+0x9e/0xb0 [] syscall_call+0x7/0xb (mlockall_test/913): 3053us non-preemptible critical section violated 1000 us preempt threshold starting at get_user_pages+0xa5/0x3d0 and ending at get_user_pages+0x2e2/0x3d0 [] dump_stack+0x1e/0x20 [] sub_preempt_count+0x45/0x60 [] get_user_pages+0x2e2/0x3d0 [] make_pages_present+0x8d/0xb0 [] mlock_fixup+0xa6/0xc0 [] do_mlockall+0x7b/0x90 [] sys_mlockall+0x9e/0xb0 [] syscall_call+0x7/0xb ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p [] dump_stack+0x1e/0x20 [] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm] [] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx] [] generic_handle_IRQ_event+0x3b/0x70 [] do_IRQ+0xb6/0x170 [] common_interrupt+0x18/0x20 [] get_user_pages+0x2f3/0x3d0 [] make_pages_present+0x8d/0xb0 [] mlock_fixup+0xa6/0xc0 [] do_mlockall+0x7b/0x90 [] sys_mlockall+0x9e/0xb0 [] syscall_call+0x7/0xb ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p [] dump_stack+0x1e/0x20 [] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm] [] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx] [] generic_handle_IRQ_event+0x3b/0x70 [] do_IRQ+0xb6/0x170 [] common_interrupt+0x18/0x20 ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0c [] dump_stack+0x1e/0x20 [] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm] [] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx] [] generic_handle_IRQ_event+0x3b/0x70 [] do_IRQ+0xb6/0x170 [] common_interrupt+0x18/0x20 [] get_user_pages+0xa5/0x3d0 [] make_pages_present+0x8d/0xb0 [] mlock_fixup+0xa6/0xc0 [] do_mlockall+0x7b/0x90 [] sys_mlockall+0x9e/0xb0 [] syscall_call+0x7/0xb (mlockall_test/916): 2703us non-preemptible critical section violated 1000 us preempt threshold starting at get_user_pages+0xa5/0x3d0 and ending at get_user_pages+0x2e2/0x3d0 [] dump_stack+0x1e/0x20 [] sub_preempt_count+0x45/0x60 [] get_user_pages+0x2e2/0x3d0 [] make_pages_present+0x8d/0xb0 [] mlock_fixup+0xa6/0xc0 [] do_mlockall+0x7b/0x90 [] sys_mlockall+0x9e/0xb0 [] syscall_call+0x7/0xb ALSA sound/core/pcm_lib.c:169: XRUN: pcmC0D0p [] dump_stack+0x1e/0x20 [] snd_pcm_period_elapsed+0x311/0x480 [snd_pcm] [] snd_cs46xx_interrupt+0x1be/0x1f0 [snd_cs46xx] [] generic_handle_IRQ_event+0x3b/0x70 [] do_IRQ+0xb6/0x170 [] common_interrupt+0x18/0x20 [] check_preempt_timing+0x16/0x100 [] sub_preempt_count+0x45/0x60 [] schedule+0x305/0x5b0 [] schedule_timeout+0x5e/0xb0 [] do_poll+0x99/0xc0 [] sys_poll+0x13f/0x240 [] syscall_call+0x7/0xb (qjackctl/859): 5549us non-preemptible critical section violated 1000 us preempt threshold starting at schedule+0x5c/0x5b0 and ending at schedule+0x305/0x5b0 [] dump_stack+0x1e/0x20 [] sub_preempt_count+0x45/0x60 [] schedule+0x305/0x5b0 [] schedule_timeout+0x5e/0xb0 [] do_poll+0x99/0xc0 [] sys_poll+0x13f/0x240 [] syscall_call+0x7/0xb Flo -- Palimm Palimm! http://affenbande.org/~tapas/