<div dir="ltr"><div class="gmail_extra"><div class="gmail_quote">Hi Dave,</div><div class="gmail_quote"><br></div><div class="gmail_quote">On Tue, May 13, 2014 at 10:11 AM, Austin Schuh <span dir="ltr"><<a href="mailto:austin@peloton-tech.com" target="_blank">austin@peloton-tech.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><div class=""><div class="h5">On Tue, May 13, 2014 at 2:03 AM, Dave Chinner <<a href="mailto:david@fromorbit.com">david@fromorbit.com</a>> wrote:<br>
> On Tue, May 13, 2014 at 12:02:18AM -0700, Austin Schuh wrote:<br>
>> On Mon, May 12, 2014 at 11:39 PM, Dave Chinner <<a href="mailto:david@fromorbit.com">david@fromorbit.com</a>> wrote:<br>
>> > On Mon, May 12, 2014 at 09:03:48PM -0700, Austin Schuh wrote:<br>
>> >> On Mon, May 12, 2014 at 8:46 PM, Dave Chinner <<a href="mailto:david@fromorbit.com">david@fromorbit.com</a>> wrote:<br>
>> >> > On Mon, May 12, 2014 at 06:29:28PM -0700, Austin Schuh wrote:<br>
>> >> >> On Wed, Mar 5, 2014 at 4:53 PM, Austin Schuh <<a href="mailto:austin@peloton-tech.com">austin@peloton-tech.com</a>> wrote:<br>
>> >> >> > Hi Dave,<br>
>> >> >> ><br>
>> >> >> > On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner <<a href="mailto:david@fromorbit.com">david@fromorbit.com</a>> wrote:<br>
>> >> >> >> On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote:<br>
>> >> >> >>> Howdy,<br>
>> >> >> >>><br>
>> >> >> >>> I'm running a config_preempt_rt patched version of the 3.10.11 kernel,<br>
>> >> >> >>> and I'm seeing a couple lockups and crashes which I think are related<br>
>> >> >> >>> to XFS.<br>
>> >> >> >><br>
>> >> >> >> I think they ar emore likely related to RT issues....<br>
>> >> >> >><br>
>> >> >> ><br>
>> >> >> > That very well may be true.<br>
>> >> >> ><br>
>> >> >> >> Cheers,<br>
>> >> >> >><br>
>> >> >> >> Dave.<br>
>> >> >> >> --<br>
>> >> >> >> Dave Chinner<br>
>> >> >><br>
>> >> >> I had the issue reproduce itself today with just the main SSD<br>
>> >> >> installed. This was on a new machine that was built this morning.<br>
>> >> >> There is a lot less going on in this trace than the previous one.<br>
>> >> ><br>
>> >> > The three blocked threads:<br>
>> >> ><br>
>> >> > 1. kworker running IO completion waiting on an inode lock,<br>
>> >> > holding locked pages.<br>
>> >> > 2. kworker running writeback flusher work waiting for a page lock<br>
>> >> > 3. direct flush work waiting for allocation, holding page<br>
>> >> > locks and the inode lock.<br>
>> >> ><br>
>> >> > What's the kworker thread running the allocation work doing?<br>
>> >> ><br>
>> >> > You might need to run `echo w > proc-sysrq-trigger` to get this<br>
>> >> > information...<br>
>> >><br>
>> >> I was able to reproduce the lockup. I ran `echo w ><br>
>> >> /proc/sysrq-trigger` per your suggestion. I don't know how to figure<br>
>> >> out what the kworker thread is doing, but I'll happily do it if you<br>
>> >> can give me some guidance.<br>
>> ><br>
>> > There isn't a worker thread blocked doing an allocation in that<br>
>> > dump, so it doesn't shed any light on the problem at all. try<br>
>> > `echo l > /proc/sysrq-trigger`, followed by `echo t ><br>
>> > /proc/sysrq-trigger` so we can see all the processes running on CPUs<br>
>> > and all the processes in the system...<br>
>> ><br>
>> > Cheers,<br>
>> ><br>
>> > Dave.<br>
>><br>
>> Attached is the output of the two commands you asked for.<br>
><br>
> Nothing there. There's lots of processes waiting for allocation to<br>
> run, and no kworkers running allocation work. This looks more<br>
> like a rt-kernel workqueue issue, not an XFS problem.<br>
><br>
> FWIW, it woul dbe really helpful if you compiled your kernels with<br>
> frame pointers enabled - the stack traces are much more precise and<br>
> readable (i.e. gets rid of all the false/stale entrys) and that<br>
> helps understanding where things are stuck immensely.<br>
><br>
> Cheers,<br>
><br>
> Dave.<br>
<br>
</div></div>Thanks Dave.<br>
<br>
I'll go check with the rt-kernel guys and take it from there. Thanks<br>
for the frame pointers suggestion. I'll make that change the next<br>
time I build a kernel.<br>
<span class=""><font color="#888888"><br>
Austin<br>
</font></span></blockquote></div><br></div><div class="gmail_extra">I found 1 bug in XFS which I fixed, and I've uncovered something else that I'm not completely sure how to fix.</div><div class="gmail_extra"><br>
</div><div class="gmail_extra">In xfs_bmapi_allocate, you create a completion, and use that to wait until the work has finished. Occasionally, I'm seeing a case where I get a context switch after the completion has been completed, but before the workqueue has finished doing it's internal book-keeping. This results in the work being deleted before the workqueue is done using it, corrupting the internal data structures. I fixed it by waiting using flush_work and removing the completion entirely.</div>
<div class="gmail_extra"><br></div><div class="gmail_extra"><div class="gmail_extra"><div class="gmail_extra">--- a/fs/xfs/xfs_bmap_util.c 2014-06-23 12:59:10.008678410 -0700</div><div class="gmail_extra">+++ b/fs/xfs/xfs_bmap_util.c 2014-06-23 12:59:14.116678239 -0700</div>
<div class="gmail_extra">@@ -263,7 +263,6 @@</div><div class="gmail_extra"> current_set_flags_nested(&pflags, PF_FSTRANS);</div><div class="gmail_extra"> </div><div class="gmail_extra"> args->result = __xfs_bmapi_allocate(args);</div>
<div class="gmail_extra">- complete(args->done);</div><div class="gmail_extra"> </div><div class="gmail_extra"> current_restore_flags_nested(&pflags, PF_FSTRANS);</div><div class="gmail_extra"> }</div>
<div class="gmail_extra">@@ -277,16 +276,13 @@</div><div class="gmail_extra"> xfs_bmapi_allocate(</div><div class="gmail_extra"> struct xfs_bmalloca *args)</div><div class="gmail_extra"> {</div><div class="gmail_extra">
- DECLARE_COMPLETION_ONSTACK(done);</div><div class="gmail_extra">-</div><div class="gmail_extra"> if (!args->stack_switch)</div><div class="gmail_extra"> return __xfs_bmapi_allocate(args);</div>
<div class="gmail_extra"> </div><div class="gmail_extra"> </div><div class="gmail_extra">- args->done = &done;</div><div class="gmail_extra"> INIT_WORK_ONSTACK(&args->work, xfs_bmapi_allocate_worker);</div>
<div class="gmail_extra"> queue_work(xfs_alloc_wq, &args->work);</div><div class="gmail_extra">- wait_for_completion(&done);</div><div class="gmail_extra">+ flush_work(&args->work);</div>
<div class="gmail_extra"> destroy_work_on_stack(&args->work);</div><div class="gmail_extra"> return args->result;</div><div class="gmail_extra"> }</div><div><div>--- a/fs/xfs/xfs_bmap_util.h 2014-06-23 12:59:10.008678410 -0700</div>
<div>+++ b/fs/xfs/xfs_bmap_util.h 2014-06-23 12:59:11.708678340 -0700</div><div>@@ -57,7 +57,6 @@</div><div> char conv; /* overwriting unwritten extents */</div><div> char stack_switch;</div>
<div> int flags;</div><div>- struct completion *done;</div><div> struct work_struct work;</div><div> int result;</div><div> };</div></div></div>
</div><div class="gmail_extra"><br></div><div class="gmail_extra">I enabled event tracing (and added a new event which lists the number of workers running in a queue whenever that is changed).</div><div class="gmail_extra">
<br></div><div class="gmail_extra">To me, it looks like work is scheduled from irq/44-ahci-273 that will acquire an inode lock. scp-3986 then acquires the lock, and then goes and schedules work. That work is then scheduled behind the work from irq/44-ahci-273 in the same pool. The first work blocks waiting on the lock, and scp-3986 won't finish and release that lock until the second work gets run.</div>
<div class="gmail_extra"><br></div><div class="gmail_extra">Any ideas on how to deal with this? I think we need to create a new pool to make sure that xfs_bmapi_allocate_worker gets run in a separate thread to avoid this.</div>
<div class="gmail_extra"><br></div><div class="gmail_extra"><div class="gmail_extra"> irq/44-ahci-273 [000] ....1.5 76.340300: workqueue_queue_work: work struct=ffff880406a6b998 function=xfs_end_io workqueue=ffff88040af82000 pool=ffff88042da63fc0 req_cpu=512 cpu=0</div>
<div class="gmail_extra"> irq/44-ahci-273 [000] ....1.5 76.340301: workqueue_activate_work: work struct ffff880406a6b998</div><div class="gmail_extra"><br></div><div class="gmail_extra"> scp-3986 [000] ....1.. 76.342711: xfs_ilock_nowait: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_SHARED caller xfs_map_blocks</div>
<div class="gmail_extra"> scp-3986 [000] ....1.. 76.342714: xfs_iunlock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_SHARED caller xfs_map_blocks</div><div class="gmail_extra"> scp-3986 [000] ....1.. 76.342722: xfs_ilock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_EXCL caller xfs_iomap_write_allocate</div>
<div class="gmail_extra"> scp-3986 [000] ....1.3 76.342729: workqueue_queue_work: work struct=ffff8800a5b8d900 function=xfs_bmapi_allocate_worker workqueue=ffff88040bb36000 pool=ffff88042da63fc0 req_cpu=512 cpu=0</div>
<div class="gmail_extra"> scp-3986 [000] ....1.3 76.342730: workqueue_activate_work: work struct ffff8800a5b8d900</div><div class="gmail_extra"> scp-3986 [000] ....1.4 76.342754: workqueue_queue_work: work struct=ffff88040a6a01c8 function=blk_delay_work workqueue=ffff88040c9f4a00 pool=ffff88042da644c0 req_cpu=512 cpu=0</div>
<div class="gmail_extra"> scp-3986 [000] ....1.4 76.342755: workqueue_activate_work: work struct ffff88040a6a01c8</div><div class="gmail_extra"><br></div><div class="gmail_extra"> kworker/0:2-757 [000] ....1.1 76.342868: workqueue_nr_running: pool=ffff88042da63fc0 nr_running=1</div>
<div class="gmail_extra"> kworker/0:2-757 [000] ....1.. 76.342869: workqueue_execute_start: work struct ffff880406a6b998: function xfs_end_io</div><div class="gmail_extra"> kworker/0:2-757 [000] ....1.. 76.342870: xfs_ilock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_EXCL caller xfs_setfilesize</div>
<div class="gmail_extra"><br></div><div class="gmail_extra"> irq/44-ahci-273 [003] ....1.5 76.419037: workqueue_queue_work: work struct=ffff8800aebc3588 function=xfs_end_io workqueue=ffff88040af82000 pool=ffff88042dbe3fc0 req_cpu=512 cpu=3</div>
<div class="gmail_extra"> irq/44-ahci-273 [003] ....1.5 76.419038: workqueue_activate_work: work struct ffff8800aebc3588</div><div class="gmail_extra"><br></div><div class="gmail_extra"> kworker/3:1-119 [003] ....1.1 76.419105: workqueue_nr_running: pool=ffff88042dbe3fc0 nr_running=1</div>
<div class="gmail_extra"> kworker/3:1-119 [003] ....1.. 76.419106: workqueue_execute_start: work struct ffff8800aebc3588: function xfs_end_io</div><div class="gmail_extra"> kworker/3:1-119 [003] ....1.. 76.419107: xfs_ilock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_EXCL caller xfs_setfilesize</div>
<div class="gmail_extra"><br></div><div class="gmail_extra"> irq/44-ahci-273 [002] ....1.5 76.426120: workqueue_queue_work: work struct=ffff880406a6b930 function=xfs_end_io workqueue=ffff88040af82000 pool=ffff88042db63fc0 req_cpu=512 cpu=2</div>
<div class="gmail_extra"> irq/44-ahci-273 [002] .N..1.5 76.426127: workqueue_activate_work: work struct ffff880406a6b930</div><div class="gmail_extra"> kworker/2:1-72 [002] ....1.1 76.426242: workqueue_nr_running: pool=ffff88042db63fc0 nr_running=1</div>
<div class="gmail_extra"> kworker/2:1-72 [002] ....1.. 76.426243: workqueue_execute_start: work struct ffff880406a6b930: function xfs_end_io</div><div class="gmail_extra"> kworker/2:1-72 [002] ....1.. 76.426244: xfs_ilock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_EXCL caller xfs_setfilesize</div>
<div><br></div><div>Thanks,</div><div> Austin</div></div></div>