[Ocfs2-users] ocfs2 hangs during webserver usage

[David Johle]

Even if the reads are scattered about the disk, I do find it hard to 
believe that the SAN can't keep up with 100 IOPs.

I will look into the blktrace for sure ... expect a reply on that soon.



And FWIW, today it did more than just slow down or lag for a bit, it 
actually hung for real.  Tons of processes in D state making load 
average go up to 280+ and one process spinning at 100% (but not 
actually doing anything according to strace).

I did get some interesting output from syslog which might provide 
some more insight:

Jan 27 11:12:08 wolf kernel: BUG: soft lockup - CPU#7 stuck for 10s! 
[vsftpd:9868]
Jan 27 11:12:08 wolf kernel: CPU 7:
Jan 27 11:12:08 wolf kernel: Modules linked in: mptctl mptbase 
ipmi_devintf ipmi_si ipmi_msghandler dell_rbu ocfs2(U) dm_round_robin 
ocfs2_dlmfs(U) ocfs2_dlm(U) ocfs2_nodemanager(U) configfs ipv6 
xfrm_nalgo crypto_api ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_co 
re ib_addr iscsi_tcp libiscsi scsi_transport_iscsi dm_multipath video 
sbs backlight i2c_ec i2c_core button battery asus_acpi acpi_me 
mhotplug ac parport_pc lp parport joydev ata_piix libata sg 
i5000_edac ide_cd serio_raw bnx2 e1000e shpchp edac_mc cdrom pcspkr 
dm_s napshot dm_zero dm_mirror dm_mod megaraid_sas sd_mod scsi_mod 
ext3 jbd uhci_hcd ohci_hcd ehci_hcd
Jan 27 11:12:08 wolf kernel: Pid: 9868, comm: vsftpd Tainted: 
G      2.6.18-92.1.10.el5 #1
Jan 27 11:12:08 wolf kernel: RIP: 
0010:[<ffffffff80013584>]  [<ffffffff80013584>] find_lock_page+0x97/0xa1
Jan 27 11:12:08 wolf kernel: RSP: 0018:ffff81010f281a80  EFLAGS: 00000216
Jan 27 11:12:08 wolf kernel: RAX: 0000000000000000 RBX: 
ffff810101bacce8 RCX: 0000000000000000
Jan 27 11:12:08 wolf kernel: RDX: ffff810101bacce8 RSI: 
0000000000001000 RDI: ffff81012ae8e930
Jan 27 11:12:08 wolf kernel: RBP: ffffffff8000e53a R08: 
ffff81000000eb00 R09: 0000000000000000
Jan 27 11:12:08 wolf kernel: R10: ffff810101bacce8 R11: 
00000000fffffffa R12: ffffffffffffff10
Jan 27 11:12:08 wolf kernel: R13: ffff810086718858 R14: 
ffff810101bacce8 R15: ffff81000ab92900
Jan 27 11:12:08 wolf kernel: FS:  00002b5f58634670(0000) 
GS:ffff81012fca13c0(0000) knlGS:0000000000000000
Jan 27 11:12:08 wolf kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
Jan 27 11:12:08 wolf kernel: CR2: 000000001bd46070 CR3: 
0000000128540000 CR4: 00000000000006e0
Jan 27 11:12:08 wolf kernel:
Jan 27 11:12:08 wolf kernel: Call Trace:
Jan 27 11:12:08 wolf kernel:  [<ffffffff800259f5>] 
find_or_create_page+0x1e/0x75
Jan 27 11:12:08 wolf kernel:  [<ffffffff800d9684>] 
cont_prepare_write+0x59/0x26e
Jan 27 11:12:08 wolf kernel:  [<ffffffff884be743>] 
:ocfs2:ocfs2_get_block+0x0/0x970
Jan 27 11:12:08 wolf kernel:  [<ffffffff884bf3c3>] 
:ocfs2:ocfs2_prepare_write+0x176/0x1d5
Jan 27 11:12:08 wolf kernel:  [<ffffffff8000fbbe>] 
generic_file_buffered_write+0x26c/0x6d3
Jan 27 11:12:08 wolf kernel:  [<ffffffff884bc9b5>] 
:ocfs2:ocfs2_insert_extent+0xbda/0xcc9
Jan 27 11:12:08 wolf kernel:  [<ffffffff8000df88>] current_fs_time+0x3b/0x40
Jan 27 11:12:08 wolf kernel:  [<ffffffff80016064>] 
__generic_file_aio_write_nolock+0x36c/0x3b8
Jan 27 11:12:08 wolf kernel:  [<ffffffff884cd1a7>] 
:ocfs2:ocfs2_extend_file+0xcbb/0xd49
Jan 27 11:12:08 wolf kernel:  [<ffffffff800c03b3>] 
generic_file_aio_write_nolock+0x20/0x6c
Jan 27 11:12:08 wolf kernel:  [<ffffffff800c077f>] 
generic_file_write_nolock+0x8f/0xa8
Jan 27 11:12:08 wolf kernel:  [<ffffffff8009df7c>] 
autoremove_wake_function+0x0/0x2e
Jan 27 11:12:08 wolf kernel:  [<ffffffff800645ec>] __down_read+0x12/0x92
Jan 27 11:12:08 wolf kernel:  [<ffffffff884cd88e>] 
:ocfs2:ocfs2_file_write+0x1cb/0x28a
Jan 27 11:12:08 wolf kernel:  [<ffffffff8001646c>] vfs_write+0xce/0x174
Jan 27 11:12:08 wolf kernel:  [<ffffffff80016d39>] sys_write+0x45/0x6e
Jan 27 11:12:08 wolf kernel:  [<ffffffff8005d116>] system_call+0x7e/0x83




There were many more of these, with varying functions at the copy of 
the call stack, for example:

Jan 27 11:11:22 wolf kernel:  [<ffffffff800d96de>] 
cont_prepare_write+0xb3/0x26e

Jan 27 11:11:48 wolf kernel:  [<ffffffff800171f4>] 
__block_commit_write+0x71/0xa2

Jan 27 11:12:08 wolf kernel:  [<ffffffff800259f5>] 
find_or_create_page+0x1e/0x75

Jan 27 11:12:58 wolf kernel:  [<ffffffff8003993a>] 
generic_commit_write+0x23/0x40

Jan 27 11:14:38 wolf kernel:  [<ffffffff884be743>] 
:ocfs2:ocfs2_get_block+0x0/0x970







At 07:04 PM 1/26/2009, Sunil Mushran wrote:
>The high util is coinciding with higher read activity. See rKb/s. While the
>numbers are small, it could be resulting in higher util because the ios are
>scattered all over the disk. If that is the case, we need to identify the
>process.
>
>Do you have blktrace installed? If not, install it.
>
>Then run,
>$ btrace -a read /dev/sdX1
>
>This will give you the view from the block layer. Now when you hit that
>slowdown window, the blktrace output will show you the process doing the
>reads. The 5th column is the pid. See man pages for blktrace, btrace and
>blkparse for more.
>
>BTW, that one node shows the writing process waiting at
>"ocfs2_wait_for_status_completion" is to be expected. It is waiting for
>the other node to release the lock. And that node is waiting on the io
>to complete before it can release the lock.
>
>David Johle wrote:
>>[snip older stuff]