<table cellspacing="0" cellpadding="0" border="0" ><tr><td valign="top" style="font: inherit;">David,<br><br>&nbsp;&nbsp;&nbsp; You said you were keeping the apache log files on OCFS2.<br><br>&nbsp;&nbsp;&nbsp;&nbsp; Are you using the same log file (access_log and error_log) for all the nodes? That is a single access_log that is writen by both nodes simultaneosly?<br><br>Regards,<br>Luis<br><br>--- On <b>Tue, 1/27/09, Sunil Mushran <i>&lt;sunil.mushran@oracle.com&gt;</i></b> wrote:<br><blockquote style="border-left: 2px solid rgb(16, 16, 255); margin-left: 5px; padding-left: 5px;">From: Sunil Mushran &lt;sunil.mushran@oracle.com&gt;<br>Subject: Re: [Ocfs2-users] ocfs2 hangs during webserver usage<br>To: "David Johle" &lt;djohle@industrialinfo.com&gt;<br>Cc: ocfs2-users@oss.oracle.com<br>Date: Tuesday, January 27, 2009, 5:20 PM<br><br><pre>If ioutil is 99%, it means the SAN is having a hard time keeping up.<br>The number of IOPS provides more information
 but that does not change<br>the first fact.<br><br>The issue seen today is different. The write() caused the fs to extend<br>the file, which in turn made it allocate the entire range. This is because<br>ocfs2 1.2 lacks sparse file support. In ocfs2 1.4, we would only allocate<br>the blocks around the write offset leaving a hole in between.<br><br>The problem is that when we allocate, we also need to init (zero) all the<br>pages. That's what it is doing. The larger the extend, the more the pages<br>it needs to init. The softlockup is because it is taking time to complete<br>that task. This is technically a mm issue. You should not encounter this<br>in ocfs2 1.4 (with sparse file enabled).<br><br>Sunil<br><br>David Johle wrote:<br>&gt; Even if the reads are scattered about the disk, I do find it hard to <br>&gt; believe that the SAN can't keep up with 100 IOPs.<br>&gt;<br>&gt; I will look into the blktrace for sure ... expect a reply on that
 soon.<br>&gt;<br>&gt;<br>&gt;<br>&gt; And FWIW, today it did more than just slow down or lag for a bit, it <br>&gt; actually hung for real.  Tons of processes in D state making load <br>&gt; average go up to 280+ and one process spinning at 100% (but not <br>&gt; actually doing anything according to strace).<br>&gt;<br>&gt; I did get some interesting output from syslog which might provide some <br>&gt; more insight:<br>&gt;<br>&gt; Jan 27 11:12:08 wolf kernel: BUG: soft lockup - CPU#7 stuck for 10s! <br>&gt; [vsftpd:9868]<br>&gt; Jan 27 11:12:08 wolf kernel: CPU 7:<br>&gt; Jan 27 11:12:08 wolf kernel: Modules linked in: mptctl mptbase <br>&gt; ipmi_devintf ipmi_si ipmi_msghandler dell_rbu ocfs2(U) dm_round_robin <br>&gt; ocfs2_dlmfs(U) ocfs2_dlm(U) ocfs2_nodemanager(U) configfs ipv6 <br>&gt; xfrm_nalgo crypto_api ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_co <br>&gt; re ib_addr iscsi_tcp libiscsi scsi_transport_iscsi dm_multipath video <br>&gt; sbs
 backlight i2c_ec i2c_core button battery asus_acpi acpi_me <br>&gt; mhotplug ac parport_pc lp parport joydev ata_piix libata sg i5000_edac <br>&gt; ide_cd serio_raw bnx2 e1000e shpchp edac_mc cdrom pcspkr dm_s napshot <br>&gt; dm_zero dm_mirror dm_mod megaraid_sas sd_mod scsi_mod ext3 jbd <br>&gt; uhci_hcd ohci_hcd ehci_hcd<br>&gt; Jan 27 11:12:08 wolf kernel: Pid: 9868, comm: vsftpd Tainted: G      <br>&gt; 2.6.18-92.1.10.el5 #1<br>&gt; Jan 27 11:12:08 wolf kernel: RIP: 0010:[&lt;ffffffff80013584&gt;]  <br>&gt; [&lt;ffffffff80013584&gt;] find_lock_page+0x97/0xa1<br>&gt; Jan 27 11:12:08 wolf kernel: RSP: 0018:ffff81010f281a80  EFLAGS: 00000216<br>&gt; Jan 27 11:12:08 wolf kernel: RAX: 0000000000000000 RBX: <br>&gt; ffff810101bacce8 RCX: 0000000000000000<br>&gt; Jan 27 11:12:08 wolf kernel: RDX: ffff810101bacce8 RSI: <br>&gt; 0000000000001000 RDI: ffff81012ae8e930<br>&gt; Jan 27 11:12:08 wolf kernel: RBP: ffffffff8000e53a R08: <br>&gt; ffff81000000eb00
 R09: 0000000000000000<br>&gt; Jan 27 11:12:08 wolf kernel: R10: ffff810101bacce8 R11: <br>&gt; 00000000fffffffa R12: ffffffffffffff10<br>&gt; Jan 27 11:12:08 wolf kernel: R13: ffff810086718858 R14: <br>&gt; ffff810101bacce8 R15: ffff81000ab92900<br>&gt; Jan 27 11:12:08 wolf kernel: FS:  00002b5f58634670(0000) <br>&gt; GS:ffff81012fca13c0(0000) knlGS:0000000000000000<br>&gt; Jan 27 11:12:08 wolf kernel: CS:  0010 DS: 0000 ES: 0000 CR0: <br>&gt; 000000008005003b<br>&gt; Jan 27 11:12:08 wolf kernel: CR2: 000000001bd46070 CR3: <br>&gt; 0000000128540000 CR4: 00000000000006e0<br>&gt; Jan 27 11:12:08 wolf kernel:<br>&gt; Jan 27 11:12:08 wolf kernel: Call Trace:<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff800259f5&gt;] <br>&gt; find_or_create_page+0x1e/0x75<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff800d9684&gt;] <br>&gt; cont_prepare_write+0x59/0x26e<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff884be743&gt;] <br>&gt;
 :ocfs2:ocfs2_get_block+0x0/0x970<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff884bf3c3&gt;] <br>&gt; :ocfs2:ocfs2_prepare_write+0x176/0x1d5<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff8000fbbe&gt;] <br>&gt; generic_file_buffered_write+0x26c/0x6d3<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff884bc9b5&gt;] <br>&gt; :ocfs2:ocfs2_insert_extent+0xbda/0xcc9<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff8000df88&gt;] <br>&gt; current_fs_time+0x3b/0x40<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff80016064&gt;] <br>&gt; __generic_file_aio_write_nolock+0x36c/0x3b8<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff884cd1a7&gt;] <br>&gt; :ocfs2:ocfs2_extend_file+0xcbb/0xd49<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff800c03b3&gt;] <br>&gt; generic_file_aio_write_nolock+0x20/0x6c<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff800c077f&gt;] <br>&gt; generic_file_write_nolock+0x8f/0xa8<br>&gt; Jan 27 11:12:08 wolf kernel: 
 [&lt;ffffffff8009df7c&gt;] <br>&gt; autoremove_wake_function+0x0/0x2e<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff800645ec&gt;]<br>__down_read+0x12/0x92<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff884cd88e&gt;] <br>&gt; :ocfs2:ocfs2_file_write+0x1cb/0x28a<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff8001646c&gt;]<br>vfs_write+0xce/0x174<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff80016d39&gt;]<br>sys_write+0x45/0x6e<br>&gt; Jan 27 11:12:08 wolf kernel:  [&lt;ffffffff8005d116&gt;]<br>system_call+0x7e/0x83<br>&gt;<br>&gt;<br>&gt;<br>&gt;<br>&gt; There were many more of these, with varying functions at the copy of <br>&gt; the call stack, for example:<br>&gt;<br>&gt; Jan 27 11:11:22 wolf kernel:  [&lt;ffffffff800d96de&gt;] <br>&gt; cont_prepare_write+0xb3/0x26e<br>&gt;<br>&gt; Jan 27 11:11:48 wolf kernel:  [&lt;ffffffff800171f4&gt;] <br>&gt; __block_commit_write+0x71/0xa2<br>&gt;<br>&gt; Jan 27 11:12:08 wolf kernel: 
 [&lt;ffffffff800259f5&gt;] <br>&gt; find_or_create_page+0x1e/0x75<br>&gt;<br>&gt; Jan 27 11:12:58 wolf kernel:  [&lt;ffffffff8003993a&gt;] <br>&gt; generic_commit_write+0x23/0x40<br>&gt;<br>&gt; Jan 27 11:14:38 wolf kernel:  [&lt;ffffffff884be743&gt;] <br>&gt; :ocfs2:ocfs2_get_block+0x0/0x970<br>&gt;<br>&gt;<br>&gt;<br>&gt;<br>&gt;<br>&gt;<br>&gt;<br>&gt; At 07:04 PM 1/26/2009, Sunil Mushran wrote:<br>&gt;&gt; The high util is coinciding with higher read activity. See rKb/s. <br>&gt;&gt; While the<br>&gt;&gt; numbers are small, it could be resulting in higher util because the <br>&gt;&gt; ios are<br>&gt;&gt; scattered all over the disk. If that is the case, we need to identify <br>&gt;&gt; the<br>&gt;&gt; process.<br>&gt;&gt;<br>&gt;&gt; Do you have blktrace installed? If not, install it.<br>&gt;&gt;<br>&gt;&gt; Then run,<br>&gt;&gt; $ btrace -a read /dev/sdX1<br>&gt;&gt;<br>&gt;&gt; This will give you the view from the block layer. Now when you
 hit<br>that<br>&gt;&gt; slowdown window, the blktrace output will show you the process doing<br>the<br>&gt;&gt; reads. The 5th column is the pid. See man pages for blktrace, btrace<br>and<br>&gt;&gt; blkparse for more.<br>&gt;&gt;<br>&gt;&gt; BTW, that one node shows the writing process waiting at<br>&gt;&gt; "ocfs2_wait_for_status_completion" is to be expected. It is<br>waiting for<br>&gt;&gt; the other node to release the lock. And that node is waiting on the io<br>&gt;&gt; to complete before it can release the lock.<br>&gt;&gt;<br>&gt;&gt; David Johle wrote:<br>&gt;&gt;&gt; [snip older stuff]<br>&gt;<br><br><br>_______________________________________________<br>Ocfs2-users mailing list<br>Ocfs2-users@oss.oracle.com<br>http://oss.oracle.com/mailman/listinfo/ocfs2-users<br></pre></blockquote></td></tr></table><br>