From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Date: Wed, 9 Oct 2013 23:47:33 +0200 From: Jan Kara Message-ID: <20131009214733.GB25608@quack.suse.cz> References: <524DC675.4020201@gmx.de> <524E57BA.805@nod.at> <52517109.90605@gmx.de> <5251C334.3010604@gmx.de> <5251CF94.5040101@gmx.de> <525591AD.4060401@gmx.de> <5255A3E6.6020100@nod.at> MIME-Version: 1.0 Content-Type: text/plain; charset=iso-8859-1 Content-Disposition: inline In-Reply-To: <5255A3E6.6020100@nod.at> Content-Transfer-Encoding: quoted-printable Subject: Re: [uml-devel] BUG: soft lockup for a user mode linux image To: Richard Weinberger Cc: Toralf =?iso-8859-1?Q?F=F6rster?= , Geert Uytterhoeven , UML devel , "linux-mm@kvack.org" , "linux-kernel@vger.kernel.org" , "akpm@linux-foundation.org" , Jan Kara , hannes@cmpxchg.org, darrick.wong@oracle.com, Michal Hocko , Wu Fengguang List-ID: On Wed 09-10-13 20:43:50, Richard Weinberger wrote: > CC'ing mm folks. > Please see below. Added Fenguang to CC since he is the author of this code. > Am 09.10.2013 19:26, schrieb Toralf F=F6rster: > > On 10/08/2013 10:07 PM, Geert Uytterhoeven wrote: > >> On Sun, Oct 6, 2013 at 11:01 PM, Toralf F=F6rster wrote: > >>>> Hmm, now pages_dirtied is zero, according to the backtrace, but th= e BUG_ON() > >>>> asserts its strict positive?!? > >>>> > >>>> Can you please try the following instead of the BUG_ON(): > >>>> > >>>> if (pause < 0) { > >>>> printk("pages_dirtied =3D %lu\n", pages_dirtied); > >>>> printk("task_ratelimit =3D %lu\n", task_ratelimit); > >>>> printk("pause =3D %ld\n", pause); > >>>> } > >>>> > >>>> Gr{oetje,eeting}s, > >>>> > >>>> Geert > >>> I tried it in different ways already - I'm completely unsuccessful = in getting any printk output. > >>> As soon as the issue happens I do have a > >>> > >>> BUG: soft lockup - CPU#0 stuck for 22s! [trinity-child0:1521] > >>> > >>> at stderr of the UML and then no further input is accepted. With um= l_mconsole I'm however able > >>> to run very basic commands like a crash dump, sysrq ond so on. > >> > >> You may get an idea of the magnitude of pages_dirtied by using a cha= in of > >> BUG_ON()s, like: > >> > >> BUG_ON(pages_dirtied > 2000000000); > >> BUG_ON(pages_dirtied > 1000000000); > >> BUG_ON(pages_dirtied > 100000000); > >> BUG_ON(pages_dirtied > 10000000); > >> BUG_ON(pages_dirtied > 1000000); > >> > >> Probably 1 million is already too much for normal operation? > >> > > period =3D HZ * pages_dirtied / task_ratelimit; > > BUG_ON(pages_dirtied > 2000000000); > > BUG_ON(pages_dirtied > 1000000000); <-------------- this is li= ne 1467 >=20 > Summary for mm people: >=20 > Toralf runs trinty on UML/i386. > After some time pages_dirtied becomes very large. > More than 1000000000 pages in this case. Huh, this is really strange. pages_dirtied is passed into balance_dirty_pages() from current->nr_dirtied. So I wonder how a value over 10^9 can get there. After all that is over 4TB so I somewhat doubt t= he task was ever able to dirty that much during its lifetime (but correct me if I'm wrong here, with UML and memory backed disks it is not totally impossible)... I went through the logic of handling ->nr_dirtied but I didn't find any obvious problem there. Hum, maybe one thing - what 'task_ratelimit' values do you see in balance_dirty_pages? If that one wa= s huge, we could possibly accumulate huge current->nr_dirtied. > Thus, period =3D HZ * pages_dirtied / task_ratelimit overflows > and period/pause becomes extremely large. >=20 > It looks like io_schedule_timeout() get's called with a very large time= out. > I don't know why "if (unlikely(pause > max_pause)) {" does not help. >=20 >=20 > > the back trace is : > >=20 > > tfoerste@n22 ~/devel/linux $ gdb --core=3D/mnt/ramdisk/core /home/tfo= erste/devel/linux/linux -batch -ex bt > > [New LWP 6911] > > Core was generated by `/home/tfoerste/devel/linux/linux earlyprintk u= bda=3D/home/tfoerste/virtual/uml/tr'. > > Program terminated with signal 6, Aborted. > > #0 0xb77a7424 in __kernel_vsyscall () > > #0 0xb77a7424 in __kernel_vsyscall () > > #1 0x083bdf35 in kill () > > #2 0x0807296d in uml_abort () at arch/um/os-Linux/util.c:93 > > #3 0x08072ca5 in os_dump_core () at arch/um/os-Linux/util.c:148 > > #4 0x080623c4 in panic_exit (self=3D0x85c1558 ,= unused1=3D0, unused2=3D0x85f76e0 ) at arch/um/kernel/um_arch.= c:240 > > #5 0x0809ba86 in notifier_call_chain (nl=3D0x0, val=3D0, v=3D0x85f76= e0 , nr_to_call=3D-2, nr_calls=3D0x0) at kernel/notifier.c:93 > > #6 0x0809bba1 in __atomic_notifier_call_chain (nh=3D0x85f76c4 , val=3D0, v=3D0x85f76e0 , nr_to_call=3D0, nr_c= alls=3D0x0) at kernel/notifier.c:182 > > #7 0x0809bbdf in atomic_notifier_call_chain (nh=3D0x0, val=3D0, v=3D= 0x0) at kernel/notifier.c:191 > > #8 0x0841b5bc in panic (fmt=3D0x0) at kernel/panic.c:130 > > #9 0x0841c470 in balance_dirty_pages (pages_dirtied=3D23, mapping=3D= ) at mm/page-writeback.c:1467 > > #10 0x080d3595 in balance_dirty_pages_ratelimited (mapping=3D0x6) at = mm/page-writeback.c:1661 > > #11 0x080e4a3f in __do_fault (mm=3D0x45ba3600, vma=3D0x48777b90, addr= ess=3D1084678144, pmd=3D0x0, pgoff=3D0, flags=3D0, orig_pte=3D) at mm/memory.c:3452 > > #12 0x080e6e0f in do_linear_fault (orig_pte=3D..., flags=3D, pmd=3D, address=3D, vma=3D, mm=3D, page_table=3D) at mm/memory.c= :3486 > > #13 handle_pte_fault (flags=3D, pmd=3D,= pte=3D, address=3D, vma=3D,= mm=3D) at mm/memory.c:3710 > > #14 __handle_mm_fault (flags=3D, address=3D, vma=3D, mm=3D) at mm/memory.c:3845 > > #15 handle_mm_fault (mm=3D0x45ba3600, vma=3D0x487034c8, address=3D108= 4678144, flags=3D1) at mm/memory.c:3868 > > #16 0x080e7817 in __get_user_pages (tsk=3D0x48705800, mm=3D0x45ba3600= , start=3D1084678144, nr_pages=3D1025, gup_flags=3D519, pages=3D0x4855800= 0, vmas=3D0x0, nonblocking=3D0x0) at mm/memory.c:1822 > > #17 0x080e7ae3 in get_user_pages (tsk=3D0x0, mm=3D0x0, start=3D0, nr_= pages=3D0, write=3D1, force=3D0, pages=3D0x48777b90, vmas=3D0x6) at mm/me= mory.c:2019 > > #18 0x08143dc6 in aio_setup_ring (ctx=3D) at fs/aio.c:= 340 > > #19 ioctx_alloc (nr_events=3D) at fs/aio.c:605 > > #20 SYSC_io_setup (ctxp=3D, nr_events=3D) at fs/aio.c:1122 > > #21 SyS_io_setup (nr_events=3D65535, ctxp=3D135081984) at fs/aio.c:11= 05 > > #22 0x08062984 in handle_syscall (r=3D0x487059d4) at arch/um/kernel/s= kas/syscall.c:35 > > #23 0x08074fb5 in handle_trap (local_using_sysemu=3D, = regs=3D, pid=3D) at arch/um/os-Linux/skas/p= rocess.c:198 > > #24 userspace (regs=3D0x487059d4) at arch/um/os-Linux/skas/process.c:= 431 > > #25 0x0805f750 in fork_handler () at arch/um/kernel/process.c:160 > > #26 0x00000000 in ?? () Honza --=20 Jan Kara SUSE Labs, CR