search for: start_this_handl

jbd2_journal_restart() would restart a handle. In this function, it calls start_this_handle(). Before calling start_this_handle()?subtract 1 from transaction->t_updates. If start_this_handle() succeeds, transaction->t_updates increases by 1 in it. But if start_this_handle() fails, transaction->t_updates does not increase. So, when commit the handle's transaction in jbd2_jour...

...ile from /root to /tmp repeatedly. While doing this test, I eventually see the copying stop, and any attempts to access /tmp fail - if I even do ls /tmp the command will hang. I suspect kjournald because of the following ps output: PID PPID WCHAN:20 PCPU %MEM PSR COMM 8847 99 start_this_handle 1.1 0.0 28 pdflush 8853 99 schedule_timeout 0.2 0.0 7 pdflush 188 1 kswapd 0.0 0.0 19 kswapd0 8051 1 mtd_blktrans_thread 0.0 0.0 22 mtdblockd 8243 1 kjournald 0.0 0.0 0 kjournald 8305 1 sched...

...and accessed mostly via NFS. v1 quotas are enabled. The stacktrace lines below are from a lightly editted "echo t > /proc/sysrq-trigger" output. A substantial number of nfsd threads a waiting to "start a handle": nfsd Call Trace: [sleep_on+75/124] [start_this_handle+205/368] [journal_start+149/196] [ext3_dirty_inode+116/268] [__mark_inode_dirty+50/168] [update_atime+75/80] [do_generic_file_read+1158/1172] [generic_file_read+147/400] [file_read_actor+0/224] [nfsd_read+477/636] [nfsd3_proc_read+295/388] [nfsd_dispatc...

...0x26 [<f8a841f0>] nfsd [nfsd] 0x0 The qmail-local processes (that should be delivering mail to the data parition) are in the following state: qmail-local D C02F3488 2400 11369 13960 11371 11348 (NOTLB) Call Trace: [<c0118ecb>] sleep_on [kernel] 0x4b [<f885d225>] start_this_handle [jbd] 0xc5 [<f885d37d>] journal_start_Rsmp_89deb980 [jbd] 0xbd [<f887297e>] ext3_dirty_inode [ext3] 0x6e [<c014ce7e>] link_path_walk [kernel] 0xa3e [<c0156f2e>] __mark_inode_dirty [kernel] 0x2e [<c01588b1>] update_atime [kernel] 0x51 [<c01303af>] do_generi...

...ng time executing various ext3 file system functions. I added some debug code to these system threads in order to find out where they are spending their time in the hopes that I can identify a place where they may be experiencing unexpected delays. This debugging lead me to look at the code in start_this_handle(), contained in file fs/jbd/transaction.c, and I have a question concerning the wake_up() logic for the thread which may go to sleep on <j_wait_transaction_locked>. The thread will sleep as long as <j_barrier_count> is non-zero: repeat: spin_lock(&jou...

...:53:14 localhost kernel: f5a2e9a0 e5fa9640 f6b55fa4 c01662b8 f75da800 e5fa9640 f75da800 c01615da Jul 4 20:53:14 localhost kernel: e5fa9640 f5a2e9a0 f6b55efc 00000000 e5fa9640 f5a2e9a0 f6d2ff80 f33b9380 Jul 4 20:53:14 localhost kernel: Call Trace: [ext3_reserve_inode_write+50/172] [start_this_handle+284/352] [ext3_mark_inode_dirty+26/52] [ext3_dirty_inode+163/276] [__mark_inode_dirty+50/188] Jul 4 20:53:14 localhost kernel: [update_atime+75/80] [link_path_walk+2038/2328] [path_walk+26/28] [__user_walk+53/80] [sys_stat64+25/112] [system_call+51/56] Jul 4 20:53:14 localhost kernel: Jul...

...alled, I get an oops: [[[LVM is in the process of calling PV_FLUSH ioctl => invalidate_buffers()]]] Attempt to refile free buffer Unable to handle kernel NULL pointer dereference at virtual address 00000000 <kdb stuff> refile_buffer cleanup_transaction log_do_checkpoint log_wait_for_space start_this_handle journal_start ext3_file_write do_readv_writev sys_write The oops is from "*(char *)0 = 0" added by the ext3 patch, but I take it that trying to refile a free buffer is fundamentally a bad thing. The oops is caused from __invalidate_buffers() calling put_last_free(bh) on the device buf...

...read+7c/130> Trace; c0129270 <file_read_actor+0/e0> Trace; c01506f1 <read_dquot+91/100> Trace; c0150c9f <dqget+15f/1e0> Trace; c0151856 <dquot_initialize+a6/180> Trace; c015cf7b <ext3_new_inode+8cb/a10> Trace; c016bc77 <__jbd_kmalloc+27/80> Trace; c0165874 <start_this_handle+114/150> Trace; c016595c <journal_start+ac/d0> Trace; c0161951 <ext3_create+81/110> Trace; c014239a <vfs_create+10a/160> Trace; c014219d <lookup_hash+8d/c0> Trace; c014253c <open_namei+14c/630> Trace; c014a11c <dput+1c/150> Trace; c0129270 <file_read_actor...

...g 9 17:57:40 boeaet34 kernel: <t3_forget: forgetting bcopy 1 Aug 9 17:57:40 boeaet34 kernel: <saction.c,sactional_head 1d8c2d, 525): saction.c, 5ead 1d8c2d40, fosact, 525): dsaction.c, 1069): jonal_head 1d8c2: extn_add: orphan inode 22>(transaction.c_access: bufferansaction.c, 52ge1396): start_this_handle: New handle 1e83d8c0 going live. Aug 9 17:57:40 boeaet34 kernel: 8c>(transacti: journal_head 1de27ec0 Aug 9 17:57:40 boeaet34 kernel: <saction.c,, sactioead 1d8c2d40, force_copy 0sact, 525): dsactionnal_head 1d8c2d: ext3_orphan_add: n_add: ansaction.c, 5ge1328): journal_stop: Ha96): start_...

...d the fact that __jbd2_log_wait_for_space() and jbd2_get_transaction() requires j_state_lock to be write locked. Theodore Ts'o (3): jbd2: Use atomic variables to avoid taking t_handle_lock in jbd2_journal_stop jbd2: Change j_state_lock to be a rwlock_t jbd2: Remove t_handle_lock from start_this_handle() fs/ext4/inode.c | 4 +- fs/ext4/super.c | 4 +- fs/jbd2/checkpoint.c | 18 +++--- fs/jbd2/commit.c | 42 ++++++------ fs/jbd2/journal.c | 94 +++++++++++++-------------- fs/jbd2/transaction.c | 172 ++++++++++++++++++++++++++++--------------------- fs/ocfs2/j...

...800035d35f0 0000000000000286 0000000000012f00 ffff8800036dbfd8 [ 1200.060410] 0000000000012f00 ffff8800035d35f0 ffff8801feb137b0 ffff8801feffc4f8 [ 1200.060417] 0000000000000002 ffffffffa00316c0 ffff8800036dbb30 ffff880004414368 [ 1200.060426] Call Trace: [ 1200.060432] [<ffffffffa00316c0>] ? start_this_handle+0x5a0/0x5a0 [jbd2] [ 1200.060439] [<ffffffff815114a9>] ? io_schedule+0x99/0x120 [ 1200.060447] [<ffffffffa00316ca>] ? sleep_on_shadow_bh+0xa/0x10 [jbd2] [ 1200.060452] [<ffffffff8151182c>] ? __wait_on_bit+0x5c/0x90 [ 1200.060459] [<ffffffffa00316c0>] ? start_this_handle+0x5...

...ent ext3 filesystem (both on LVs), and running pvscan (i.e. invalidate_buffers) repeatedly. At one point, I got several free buffers reported in cleanup_transaction. After that (this is the first time it happened) my kernel compile deadlocked and the kernel is stuck on: ext3_create journal_start start_this_handle log_wait_for_space log_do_checkpoint cleanup_transaction* __wake_up* The last 2 (*) functions appear and disappear from the KDB "bt" output, so I assume they are being called, but never finishing the transaction. I've added more debugging to determine which device's buffers are...

...x54f/0x56b [jbd] May 19 09:56:38 spf1 kernel: [<c0154c35>] __find_get_block+0xb5/0xbe May 19 09:56:38 spf1 kernel: [<c0125009>] __mod_timer+0xf1/0xfb May 19 09:56:38 spf1 kernel: [<f8839899>] __log_wait_for_space+0xa4/0xc7 [jbd] May 19 09:56:38 spf1 kernel: [<f8836383>] start_this_handle+0x2f8/0x33e [jbd] May 19 09:56:38 spf1 kernel: [<c011a545>] __wake_up+0x29/0x3c May 19 09:56:38 spf1 kernel: [<f8836478>] journal_start+0x78/0x9e [jbd] May 19 09:56:38 spf1 kernel: [<f886edea>] ext3_prepare_write+0x32/0xf4 [ext3] May 19 09:56:38 spf1 kernel: [<c013a424&g...

...Code: c6 05 00 00 00 00 00 e9 a6 00 00 00 90 80 7e 29 01 76 0a bb >>EIP; c012c25f <refile_buffer+17/d0> <===== Trace; c015f9bb <cleanup_transaction+12b/158> Trace; c015fbae <log_do_checkpoint+1c6/220> Trace; c015f86d <log_wait_for_space+8d/b0> Trace; c015c98b <start_this_handle+307/3a8> Trace; c015caa3 <journal_start+77/a0> Trace; c0152986 <ext3_notify_change+14a/360> Trace; c0120176 <do_generic_file_read+8d2/8e0> Trace; c0139638 <notify_change+40/64> Trace; c0129067 <do_truncate+5f/ac> Trace; c01329bc <open_namei+474/4d4> Trace; c0...

I got this.. The system was usuable, but not very. If I tried to access the ext3 volume, it would hang. Reboot hung too, complaining about too many open files. Any ideas? I have no idea what triggered it; this is a big file/web/mail server, with all of that on the ext3 volume. And I've never run ksymoops before, but I think I did it right. - Josh Assertion failure in

...6] ffff8103fcdf6890 ffff8103ff08c6d0 ffff8103fcdf6b18 0000000300008850 [79918.755380] ffff810000021e80 0000000000000000 00000000ffffffff 0000000000000000 [79918.755383] Call Trace: [79918.755386] [<ffffffff80295cdc>] fallback_alloc+0xe7/0x1e1 [79918.755400] [<ffffffffa0182a2d>] :jbd:start_this_handle+0x11b/0x304 [79918.755405] [<ffffffff80246171>] autoremove_wake_function+0x0/0x2e [79918.755409] [<ffffffff80278dfa>] pagevec_lookup_tag+0x1a/0x21 [79918.755418] [<ffffffffa0182cb1>] :jbd:journal_start+0x9b/0xd2 [79918.755426] [<ffffffffa0182cf6>] :jbd:journal_force_com...