From mboxrd@z Thu Jan 1 00:00:00 1970 From: Ryusuke Konishi Subject: Re: Deadlock with nilfs on 2.6.31.4 Date: Fri, 23 Oct 2009 02:51:29 +0900 (JST) Message-ID: <20091023.025129.71910838.ryusuke@osrg.net> References: <20091021203847.26acab0a@neptune.home> Mime-Version: 1.0 Content-Transfer-Encoding: QUOTED-PRINTABLE Return-path: In-Reply-To: <20091021203847.26acab0a@neptune.home> Sender: linux-fsdevel-owner@vger.kernel.org List-ID: Content-Type: Text/Plain; charset="iso-8859-1" To: bonbons@linux-vserver.org Cc: users@nilfs.org, linux-fsdevel@vger.kernel.org, ryusuke@osrg.net Hi, On Wed, 21 Oct 2009 20:38:47 +0200, Bruno Pr=E9mont wrote: > Hi, >=20 > nilfs seems to have some dead-locks that put processes in D-state (at > least on my arm system). > This time around it seems that syslog-ng has been hit first. The > previous times it most often was collectd/rrdtool. >=20 > Kernel is vanilla 2.6.31.4 + a patch for USB HID device. System is ar= m, > Feroceon 88FR131, SheevaPlug. nilfs is being used on a SD card > (mmcblk0: mmc0:bc20 SD08G 7.60 GiB, mvsdio driver) >=20 > Bruno >=20 >=20 >=20 > Extracts from dmesg (less attempting to read a logfile produced by sy= slog-ng): > INFO: task less:15839 blocked for more than 120 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this mess= age. > less D c02c8610 0 15839 1742 0x00000001 > [] (schedule+0x2a8/0x3b0) from [] (__mutex_lock_s= lowpath+0x88/0x140) > [] (__mutex_lock_slowpath+0x88/0x140) from [] (ge= neric_file_llseek+0x24/0x64) > [] (generic_file_llseek+0x24/0x64) from [] (vfs_l= lseek+0x54/0x64) > [] (vfs_llseek+0x54/0x64) from [] (sys_llseek+0x7= 4/0xcc) > [] (sys_llseek+0x74/0xcc) from [] (ret_fast_sysca= ll+0x0/0x2c) >=20 >=20 > All stuck processes as listed by SysRq + T: > syslog-ng D c02c8610 0 1698 1 0x00000000 > [] (schedule+0x2a8/0x3b0) from [] (schedule_timeo= ut+0x14c/0x1e8) > [] (schedule_timeout+0x14c/0x1e8) from [] (io_sch= edule_timeout+0x34/0x58) > [] (io_schedule_timeout+0x34/0x58) from [] (conge= stion_wait+0x5c/0x80) > [] (congestion_wait+0x5c/0x80) from [] (balance_d= irty_pages_ratelimited_nr+0xe8/0x290) > [] (balance_dirty_pages_ratelimited_nr+0xe8/0x290) from [] (generic_file_buffered_write+0x10c/0x348) > [] (generic_file_buffered_write+0x10c/0x348) from [] (__generic_file_aio_write_nolock+0x264/0x4f4) > [] (__generic_file_aio_write_nolock+0x264/0x4f4) from [] (generic_file_aio_write+0x74/0xe8) > [] (generic_file_aio_write+0x74/0xe8) from [] (do= _sync_write+0xbc/0x100) > [] (do_sync_write+0xbc/0x100) from [] (vfs_write+= 0xb0/0x164) > [] (vfs_write+0xb0/0x164) from [] (sys_write+0x40= /0x70) > [] (sys_write+0x40/0x70) from [] (ret_fast_syscal= l+0x0/0x2c) > less D c02c8610 0 15839 1742 0x00000001 > [] (schedule+0x2a8/0x3b0) from [] (__mutex_lock_s= lowpath+0x88/0x140) > [] (__mutex_lock_slowpath+0x88/0x140) from [] (ge= neric_file_llseek+0x24/0x64) > [] (generic_file_llseek+0x24/0x64) from [] (vfs_l= lseek+0x54/0x64) > [] (vfs_llseek+0x54/0x64) from [] (sys_llseek+0x7= 4/0xcc) > [] (sys_llseek+0x74/0xcc) from [] (ret_fast_sysca= ll+0x0/0x2c) > sshd D c02c8610 0 15844 15842 0x00000001 > [] (schedule+0x2a8/0x3b0) from [] (schedule_timeo= ut+0x14c/0x1e8) > [] (schedule_timeout+0x14c/0x1e8) from [] (io_sch= edule_timeout+0x34/0x58) > [] (io_schedule_timeout+0x34/0x58) from [] (conge= stion_wait+0x5c/0x80) > [] (congestion_wait+0x5c/0x80) from [] (balance_d= irty_pages_ratelimited_nr+0xe8/0x290) > [] (balance_dirty_pages_ratelimited_nr+0xe8/0x290) from [] (generic_file_buffered_write+0x10c/0x348) > [] (generic_file_buffered_write+0x10c/0x348) from [] (__generic_file_aio_write_nolock+0x264/0x4f4) > [] (__generic_file_aio_write_nolock+0x264/0x4f4) from [] (generic_file_aio_write+0x74/0xe8) > [] (generic_file_aio_write+0x74/0xe8) from [] (do= _sync_write+0xbc/0x100) > [] (do_sync_write+0xbc/0x100) from [] (vfs_write+= 0xb0/0x164) > [] (vfs_write+0xb0/0x164) from [] (sys_write+0x40= /0x70) > [] (sys_write+0x40/0x70) from [] (ret_fast_syscal= l+0x0/0x2c) >=20 > nilfs related processes: > [40049.761881] segctord S c02c8610 0 859 2 0x00000000 > [40049.761894] [] (schedule+0x2a8/0x3b0) from [] = (nilfs_segctor_thread+0x2d4/0x328 [nilfs2]) > [40049.761999] [] (nilfs_segctor_thread+0x2d4/0x328 [nilfs2= ]) from [] (kthread+0x7c/0x84) > [40049.762081] [] (kthread+0x7c/0x84) from [] (ke= rnel_thread_exit+0x0/0x8) > [40049.762101] nilfs_cleaner S c02c8610 0 860 1 0x00000000 > [40049.762115] [] (schedule+0x2a8/0x3b0) from [] = (do_nanosleep+0xb0/0x110) > [40049.762137] [] (do_nanosleep+0xb0/0x110) from [] (hrtimer_nanosleep+0xa4/0x12c) > [40049.762161] [] (hrtimer_nanosleep+0xa4/0x12c) from [] (sys_nanosleep+0x9c/0xa4) > [40049.762181] [] (sys_nanosleep+0x9c/0xa4) from [] (ret_fast_syscall+0x0/0x2c) > [40049.762201] segctord S c02c8610 0 862 2 0x00000000 > [40049.762214] [] (schedule+0x2a8/0x3b0) from [] = (nilfs_segctor_thread+0x2d4/0x328 [nilfs2]) > [40049.762298] [] (nilfs_segctor_thread+0x2d4/0x328 [nilfs2= ]) from [] (kthread+0x7c/0x84) > [40049.762377] [] (kthread+0x7c/0x84) from [] (ke= rnel_thread_exit+0x0/0x8) > [40049.762397] nilfs_cleaner S c02c8610 0 863 1 0x00000000 > [40049.762411] [] (schedule+0x2a8/0x3b0) from [] = (do_nanosleep+0xb0/0x110) > [40049.762433] [] (do_nanosleep+0xb0/0x110) from [] (hrtimer_nanosleep+0xa4/0x12c) > [40049.762455] [] (hrtimer_nanosleep+0xa4/0x12c) from [] (sys_nanosleep+0x9c/0xa4) > [40049.762475] [] (sys_nanosleep+0x9c/0xa4) from [] (ret_fast_syscall+0x0/0x2c) > [40049.762495] segctord S c02c8610 0 865 2 0x00000000 > [40049.762507] [] (schedule+0x2a8/0x3b0) from [] = (nilfs_segctor_thread+0x2d4/0x328 [nilfs2]) > [40049.762591] [] (nilfs_segctor_thread+0x2d4/0x328 [nilfs2= ]) from [] (kthread+0x7c/0x84) > [40049.762670] [] (kthread+0x7c/0x84) from [] (ke= rnel_thread_exit+0x0/0x8) > [40049.762690] nilfs_cleaner S c02c8610 0 866 1 0x00000000 > [40049.762703] [] (schedule+0x2a8/0x3b0) from [] = (do_nanosleep+0xb0/0x110) > [40049.762726] [] (do_nanosleep+0xb0/0x110) from [] (hrtimer_nanosleep+0xa4/0x12c) > [40049.762748] [] (hrtimer_nanosleep+0xa4/0x12c) from [] (sys_nanosleep+0x9c/0xa4) > [40049.762768] [] (sys_nanosleep+0x9c/0xa4) from [] (ret_fast_syscall+0x0/0x2c) Thank you for reporting the issue. According to the log, the log-writer of nilfs looks to be idle even though it has some requests waiting. Could you try the following patch to narrow down the issue ? I'll dig into this issue next week since I'm now away from my office to attend the Linux symposium in Tokyo. Thank you, Ryusuke Konishi diff --git a/fs/nilfs2/segment.c b/fs/nilfs2/segment.c index 51ff3d0..0932571 100644 --- a/fs/nilfs2/segment.c +++ b/fs/nilfs2/segment.c @@ -2471,6 +2471,8 @@ static void nilfs_segctor_notify(struct nilfs_sc_= info *sci, sci->sc_state &=3D ~NILFS_SEGCTOR_COMMIT; =20 if (req->mode =3D=3D SC_LSEG_SR) { + printk(KERN_DEBUG "%s: completed request from=3D%d to=3D%d\n", + __func__, sci->sc_seq_done, req->seq_accepted); sci->sc_seq_done =3D req->seq_accepted; nilfs_segctor_wakeup(sci, req->sc_err ? : req->sb_err); sci->sc_flush_request =3D 0; @@ -2668,6 +2670,11 @@ static int nilfs_segctor_thread(void *arg) if (sci->sc_state & NILFS_SEGCTOR_QUIT) goto end_thread; =20 + printk(KERN_DEBUG + "%s: sequence: req=3D%u, done=3D%u, state=3D%lx, timeout=3D%d= \n", + __func__, sci->sc_seq_request, sci->sc_seq_done, + sci->sc_state, timeout); + if (timeout || sci->sc_seq_request !=3D sci->sc_seq_done) mode =3D SC_LSEG_SR; else if (!sci->sc_flush_request) -- To unsubscribe from this list: send the line "unsubscribe linux-fsdevel= " in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html