Skip to contentSkip to conversation

New: ext3/4 with synchronous writes gets wedged by Postfix

Bugme-new Andrew Morton 2 participants 2 messages May 5, 2009 – May 12, 2009 1 message not in the archive

lore
Share & tools
lore

Andrew Morton

author
#1 lore raw
In reply to a message not in the archive

(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).

Quoted 18 lines · On Sun, 3 May 2009 19:48:21 GMT [email protected] wrote:

http://bugzilla.kernel.org/show_bug.cgi?id=13232

Summary: ext3/4 with synchronous writes gets wedged by Postfix
Product: File System
Version: 2.5
Kernel Version: 2.6.29.2
Platform: All
OS/Version: Linux
Tree: Mainline
Status: NEW
Severity: normal
Priority: P1
Component: ext3
AssignedTo: [email protected]
ReportedBy: [email protected]
Regression: Yes

Quoted 2 lines

Latest working kernel version: 2.6.28.9
Earliest failing kernel version: 2.6.29

A very very bad regression.

Quoted 38 lines

Distribution: Ubuntu 8.04 LTS
Hardware Environment: Intel 875p chipset (ICH5), P4 with HT Software Environment: Postfix 2.5.1-2ubuntu1.2

Problem Description:

With its queue directory on an ext3 or journalled ext4 file system, mounted with the 'sync' option (or with the 'S' attribute on the individual queue directories, which is a config option for the Ubuntu package), sending more than a few messages in quick succession through Postfix causes Postfix and any other process attempting to modify the file system afterwards (e.g. by updating the atime when listing a directory) to hang in uninterruptible sleep. sync(1) will also hang afterwards. If the FS is mounted noatime, it is still possible to read from it, although trying to list the affected queue directories still causes ls to hang (the list of affected directories seems to vary, but may include at least "active" and "maildrop").

This happens whether the filesystem is on a hard disk or a RAM disk (/dev/ramX, not tmpfs). Enabling or disabling barriers, or changing the journalling mode doesn't help.

Ext2 seems to be unaffected, as does non-journalled ext4. XFS, Reiser and JFS are also fine. The hang doesn't occur if the queue directories have the 'D' attribute (and a non-sync mount) instead of 'S'.

Nothing appears in dmesg at the time of the hang, but here's the output from SysRq-W afterwards (ext3 FS, kernel 2.6.29.2, non-SMP, PREEMPT_NONE):

SysRq : Show Blocked State
task PC stack pid father
kjournald D c01384df 0 2525 2
cfcb5f0c 00000082 de27d500 c01384df cfcb5ef4 c02cb5c0 00000001 de32ca00 de324814 dd037ebc de324814 de324934 dd037ebc cfcb5f5c cfcb5f90 c01bd4bb 00000046 c0424110 de324a0c de324814 de324800 00000000 00000002 dd037e80

Quoted 13 lines
Call Trace:
 [<c01384df>] ? trace_hardirqs_on+0xb/0xd
 [<c01bd4bb>] journal_commit_transaction+0xea/0xeaf
 [<c02c534a>] ? _spin_unlock_irqrestore+0x38/0x3f
 [<c0138489>] ? trace_hardirqs_on_caller+0x145/0x190
 [<c012b6ee>] ? autoremove_wake_function+0x0/0x38
 [<c0122a25>] ? del_timer+0x50/0x59
 [<c01c0c75>] kjournald+0xad/0x1bb
 [<c012b6ee>] ? autoremove_wake_function+0x0/0x38
 [<c01c0bc8>] ? kjournald+0x0/0x1bb
 [<c012b442>] kthread+0x37/0x59
 [<c012b40b>] ? kthread+0x0/0x59
 [<c0103667>] kernel_thread_helper+0x7/0x10

I assume this is

	while (commit_transaction->t_updates) {
		DEFINE_WAIT(wait);

		prepare_to_wait(&journal->j_wait_updates, &wait,
					TASK_UNINTERRUPTIBLE);
		if (commit_transaction->t_updates) {
			spin_unlock(&commit_transaction->t_handle_lock);
			spin_unlock(&journal->j_state_lock);
			schedule();

I'm wondering about

: commit e219cca082f52e7dfea41f3be264b7b5eb204227
: Author: Theodore Ts'o <[email protected]>
: AuthorDate: Thu Nov 6 22:37:59 2008 -0500
: Commit: Theodore Ts'o <[email protected]>
: CommitDate: Thu Nov 6 22:37:59 2008 -0500
:
: jbd: don't give up looking for space so easily in __log_wait_for_space

but that patch was present in 2.6.28.

Quoted 150 lines

pickup D c01384df 0 2597 2594
cfaa9e5c 00000086 df9faa80 c01384df cfaa9e44 00000282 cfaa9e74 de32ca00 cfaa9e5c c012b8b7 00000002 de324800 0000014f cfaa9e74 cfaa9e94 c01c0539 00000000 de3248c8 de324910 de324814 00000000 df9faa80 c012b6ee de3248e4

Call Trace:
 [<c01384df>] ? trace_hardirqs_on+0xb/0xd
 [<c012b8b7>] ? prepare_to_wait+0x42/0x4a
 [<c01c0539>] log_wait_commit+0x90/0xf7
 [<c012b6ee>] ? autoremove_wake_function+0x0/0x38
 [<c01bba9d>] journal_stop+0x1c8/0x288
 [<c01b4236>] __ext3_journal_stop+0x1c/0x38
 [<c01aeb96>] ext3_delete_inode+0x90/0xc2
 [<c01aeb06>] ? ext3_delete_inode+0x0/0xc2
 [<c017ab82>] generic_delete_inode+0x72/0x100
 [<c02c4ee1>] ? _spin_lock+0x3a/0x40
 [<c017ad4c>] generic_drop_inode+0x13c/0x1da
 [<c01d4068>] ? _atomic_dec_and_lock+0x10/0x38
 [<c017a4e7>] iput+0x47/0x4e
 [<c0173db0>] do_unlinkat+0xc1/0x137
 [<c0102f87>] ? sysenter_exit+0xf/0x18
 [<c0138489>] ? trace_hardirqs_on_caller+0x145/0x190
 [<c0173e36>] sys_unlink+0x10/0x12
 [<c0102f55>] sysenter_do_call+0x12/0x35

qmgr D c01384df 0 2598 2594
cfe23e60 00000082 df9fa200 c01384df cfe23e48 c02cb5c0 cfe23e78 de32cf00 cfe23e60 c012b8b7 00000002 de324800 0000014f cfe23e78 cfe23e98 c01c0539 00000000 de3248c8 de324910 de324814 00000000 df9fa200 c012b6ee cfaa9e80

Call Trace:
 [<c01384df>] ? trace_hardirqs_on+0xb/0xd
 [<c012b8b7>] ? prepare_to_wait+0x42/0x4a
 [<c01c0539>] log_wait_commit+0x90/0xf7
 [<c012b6ee>] ? autoremove_wake_function+0x0/0x38
 [<c01bba9d>] journal_stop+0x1c8/0x288
 [<c01ac11e>] ? ext3_mark_iloc_dirty+0x1d8/0x34b
 [<c01b4236>] __ext3_journal_stop+0x1c/0x38
 [<c01b309d>] ext3_unlink+0x70/0x157
 [<c0172344>] ? vfs_unlink+0x45/0xb0
 [<c0172358>] vfs_unlink+0x59/0xb0
 [<c0173e17>] do_unlinkat+0x128/0x137
 [<c0102f87>] ? sysenter_exit+0xf/0x18
 [<c0138489>] ? trace_hardirqs_on_caller+0x145/0x190
 [<c0173e36>] sys_unlink+0x10/0x12
 [<c0102f55>] sysenter_do_call+0x12/0x35

local D c01384df 0 2654 2594
de369c74 00000096 df9f8880 c01384df de369c5c 00000286 00000000 de183b80 de324814 de324800 de324814 dd037e80 de324800 de324880 de369cc4 c01bc306 c0138489 00000246 00000046 00000001 de324a0c de324814 de324814 df59c060

Call Trace:
 [<c01384df>] ? trace_hardirqs_on+0xb/0xd
 [<c01bc306>] start_this_handle+0x1c2/0x361
 [<c0138489>] ? trace_hardirqs_on_caller+0x145/0x190
 [<c012b6ee>] ? autoremove_wake_function+0x0/0x38
 [<c01bc54a>] journal_start+0xa5/0x100
 [<c01b43ac>] ext3_journal_start_sb+0x48/0x4d
 [<c01aec4c>] ext3_write_begin+0x84/0x1c6
 [<c0139fe2>] ? __lock_acquire+0x32b/0xa21
 [<c014749e>] generic_file_buffered_write+0xe1/0x292
 [<c0147a94>] __generic_file_aio_write_nolock+0x25c/0x4ab
 [<c0138489>] ? trace_hardirqs_on_caller+0x145/0x190
 [<c0147f63>] generic_file_aio_write+0x66/0xda
 [<c0138f6b>] ? validate_chain+0x3f5/0x1141
 [<c01aad03>] ext3_file_write+0x27/0xa8
 [<c016a972>] do_sync_write+0xcc/0x102
 [<c012b6ee>] ? autoremove_wake_function+0x0/0x38
 [<c016b16d>] vfs_write+0x8b/0x11f
 [<c0102f87>] ? sysenter_exit+0xf/0x18
 [<c016a8a6>] ? do_sync_write+0x0/0x102
 [<c016b577>] sys_write+0x3d/0x64
 [<c0102f55>] sysenter_do_call+0x12/0x35

postdrop D c01384df 0 2664 2663
cfcbfd6c 00000086 dd13f700 c01384df cfcbfd54 c02cb5c0 00000001 deedc780 c03a1690 c1402348 c03a1690 cfcbfd7c c1402348 cfcbfd90 cfcbfd9c c017a55b dd758c48 00000007 00000000 dd13f700 c012b726 c1402364 c1402364 00152b13

Call Trace:
 [<c01384df>] ? trace_hardirqs_on+0xb/0xd
 [<c017a55b>] __wait_on_freeing_inode+0x6d/0x88
 [<c012b726>] ? wake_bit_function+0x0/0x47
 [<c017a5b5>] find_inode_fast+0x3f/0x4a
 [<c017ba05>] insert_inode_locked+0x50/0xeb
 [<c01ab90b>] ext3_new_inode+0x738/0x88f
 [<c01bc550>] ? journal_start+0xab/0x100
 [<c01b259a>] ext3_create+0x59/0xbf
 [<c01722c4>] vfs_create+0x75/0xb0
 [<c02c4dda>] ? _spin_unlock+0x1d/0x20
 [<c01b2541>] ? ext3_create+0x0/0xbf
 [<c0174bc3>] do_filp_open+0x644/0x713
 [<c02c4dda>] ? _spin_unlock+0x1d/0x20
 [<c01692ce>] do_sys_open+0x45/0xce
 [<c0102f87>] ? sysenter_exit+0xf/0x18
 [<c0138489>] ? trace_hardirqs_on_caller+0x145/0x190
 [<c01693a3>] sys_open+0x23/0x2b
 [<c0102f55>] sysenter_do_call+0x12/0x35
Sched Debug Version: v0.08, 2.6.29.2-test #1
now at 166155.025991 msecs
  .sysctl_sched_latency                    : 20.000000
  .sysctl_sched_min_granularity            : 4.000000
  .sysctl_sched_wakeup_granularity         : 5.000000
  .sysctl_sched_child_runs_first           : 0.000001
  .sysctl_sched_features                   : 24191

cpu#0, 2798.181 MHz

  .nr_running                    : 2
  .load                          : 2048
  .nr_switches                   : 284843
  .nr_load_updates               : 6497
  .nr_uninterruptible            : 5
  .jiffies                       : 4294953911
  .next_balance                  : 0.000000
  .curr->pid                     : 2466
  .clock                         : 166154.370058
  .cpu_load[0]                   : 0
  .cpu_load[1]                   : 4
  .cpu_load[2]                   : 76
  .cpu_load[3]                   : 160
  .cpu_load[4]                   : 196

cfs_rq[0]:

  .exec_clock                    : 0.000000
  .MIN_vruntime                  : 24407.116340
  .min_vruntime                  : 24407.114218
  .max_vruntime                  : 24407.116340
  .spread                        : 0.000000
  .spread0                       : 0.000000
  .nr_running                    : 2
  .load                          : 2048
  .nr_spread_over                : 0

rt_rq[0]:

  .rt_nr_running                 : 0
  .rt_throttled                  : 0
  .rt_time                       : 0.000000
  .rt_runtime                    : 950.000000

runnable tasks:
task PID tree-key switches prio exec-runtime
sum-exec sum-sleep
----------------------------------------------------------------------------------------------------------

            Xorg  2163     24407.116340     28791   120               0        
      0               0.000000               0.000000               0.000000
R           bash  2466     24387.418829       274   120               0        
      0               0.000000               0.000000               0.000000

Steps to reproduce:

# mount -o remount,sync /var
  (or wherever queue_directory points to in the Postfix config)
# while true; do sendmail testaddr@localhost </dev/null; done
#2 lore raw

Hi,

Quoted 25 lines

(switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface).

Quoted 6 lines

SysRq : Show Blocked State
task PC stack pid father
kjournald D c01384df 0 2525 2
cfcb5f0c 00000082 de27d500 c01384df cfcb5ef4 c02cb5c0 00000001 de32ca00 de324814 dd037ebc de324814 de324934 dd037ebc cfcb5f5c cfcb5f90 c01bd4bb 00000046 c0424110 de324a0c de324814 de324800 00000000 00000002 dd037e80

Quoted 13 lines
Call Trace:
 [<c01384df>] ? trace_hardirqs_on+0xb/0xd
 [<c01bd4bb>] journal_commit_transaction+0xea/0xeaf
 [<c02c534a>] ? _spin_unlock_irqrestore+0x38/0x3f
 [<c0138489>] ? trace_hardirqs_on_caller+0x145/0x190
 [<c012b6ee>] ? autoremove_wake_function+0x0/0x38
 [<c0122a25>] ? del_timer+0x50/0x59
 [<c01c0c75>] kjournald+0xad/0x1bb
 [<c012b6ee>] ? autoremove_wake_function+0x0/0x38
 [<c01c0bc8>] ? kjournald+0x0/0x1bb
 [<c012b442>] kthread+0x37/0x59
 [<c012b40b>] ? kthread+0x0/0x59
 [<c0103667>] kernel_thread_helper+0x7/0x10

I assume this is

Quoted 9 lines
	while (commit_transaction->t_updates) {
		DEFINE_WAIT(wait);

		prepare_to_wait(&journal->j_wait_updates, &wait,
					TASK_UNINTERRUPTIBLE);
		if (commit_transaction->t_updates) {
			spin_unlock(&commit_transaction->t_handle_lock);
			spin_unlock(&journal->j_state_lock);
			schedule();

Yes.

Quoted 11 lines

I'm wondering about

: commit e219cca082f52e7dfea41f3be264b7b5eb204227
: Author: Theodore Ts'o <[email protected]>
: AuthorDate: Thu Nov 6 22:37:59 2008 -0500
: Commit: Theodore Ts'o <[email protected]>
: CommitDate: Thu Nov 6 22:37:59 2008 -0500
:
: jbd: don't give up looking for space so easily in __log_wait_for_space

but that patch was present in 2.6.28.

Hmm, I don't see what made this deadlock happening - as far as I can
see it's there for quite some time. See below...

Quoted 15 lines
Quoted 15 lines

pickup D c01384df 0 2597 2594
cfaa9e5c 00000086 df9faa80 c01384df cfaa9e44 00000282 cfaa9e74 de32ca00 cfaa9e5c c012b8b7 00000002 de324800 0000014f cfaa9e74 cfaa9e94 c01c0539 00000000 de3248c8 de324910 de324814 00000000 df9faa80 c012b6ee de3248e4

Call Trace:
 [<c01384df>] ? trace_hardirqs_on+0xb/0xd
 [<c012b8b7>] ? prepare_to_wait+0x42/0x4a
 [<c01c0539>] log_wait_commit+0x90/0xf7
 [<c012b6ee>] ? autoremove_wake_function+0x0/0x38
 [<c01bba9d>] journal_stop+0x1c8/0x288
 [<c01b4236>] __ext3_journal_stop+0x1c/0x38
 [<c01aeb96>] ext3_delete_inode+0x90/0xc2
 [<c01aeb06>] ? ext3_delete_inode+0x0/0xc2
 [<c017ab82>] generic_delete_inode+0x72/0x100
 [<c02c4ee1>] ? _spin_lock+0x3a/0x40
Quoted 8 lines
Quoted 8 lines
 [<c017ad4c>] generic_drop_inode+0x13c/0x1da
 [<c01d4068>] ? _atomic_dec_and_lock+0x10/0x38
 [<c017a4e7>] iput+0x47/0x4e
 [<c0173db0>] do_unlinkat+0xc1/0x137
 [<c0102f87>] ? sysenter_exit+0xf/0x18
 [<c0138489>] ? trace_hardirqs_on_caller+0x145/0x190
 [<c0173e36>] sys_unlink+0x10/0x12
 [<c0102f55>] sysenter_do_call+0x12/0x35

In generic_delete_inode() we mark inode as I_FREEING. Then
ext3_delete_inode() is called and because of O_SYNC it starts a transaction commit and waits for it.

Quoted 15 lines
Quoted 15 lines

postdrop D c01384df 0 2664 2663
cfcbfd6c 00000086 dd13f700 c01384df cfcbfd54 c02cb5c0 00000001 deedc780 c03a1690 c1402348 c03a1690 cfcbfd7c c1402348 cfcbfd90 cfcbfd9c c017a55b dd758c48 00000007 00000000 dd13f700 c012b726 c1402364 c1402364 00152b13

Call Trace:
 [<c01384df>] ? trace_hardirqs_on+0xb/0xd
 [<c017a55b>] __wait_on_freeing_inode+0x6d/0x88
 [<c012b726>] ? wake_bit_function+0x0/0x47
 [<c017a5b5>] find_inode_fast+0x3f/0x4a
 [<c017ba05>] insert_inode_locked+0x50/0xeb
 [<c01ab90b>] ext3_new_inode+0x738/0x88f
 [<c01bc550>] ? journal_start+0xab/0x100
 [<c01b259a>] ext3_create+0x59/0xbf
 [<c01722c4>] vfs_create+0x75/0xb0
 [<c02c4dda>] ? _spin_unlock+0x1d/0x20
Quoted 8 lines
Quoted 8 lines

[<c01b2541>] ? ext3_create+0x0/0xbf

 [<c0174bc3>] do_filp_open+0x644/0x713
 [<c02c4dda>] ? _spin_unlock+0x1d/0x20
 [<c01692ce>] do_sys_open+0x45/0xce
 [<c0102f87>] ? sysenter_exit+0xf/0x18
 [<c0138489>] ? trace_hardirqs_on_caller+0x145/0x190
 [<c01693a3>] sys_open+0x23/0x2b
 [<c0102f55>] sysenter_do_call+0x12/0x35

Here, we have started a transaction in ext3_create() and then wait in
find_inode_fast() for I_FREEING to be cleared (obviously we have reallocated the inode and squeezed the allocation before journal_stop() from the delete was called).
Nasty deadlock and I don't see how to fix it now - have to go home for
today... Tomorrow I'll have a look what we can do about it.

Honza

Signature · 2 lines
Jan Kara <[email protected]>
SuSE CR Labs