Hi Dave,
On Tue, May 13, 2014 at 10:11 AM, Austin Schuh <austin@xxxxxxxxxxxxxxxx> wrote:
Thanks Dave.On Tue, May 13, 2014 at 2:03 AM, Dave Chinner <david@xxxxxxxxxxxxx> wrote:
> On Tue, May 13, 2014 at 12:02:18AM -0700, Austin Schuh wrote:
>> On Mon, May 12, 2014 at 11:39 PM, Dave Chinner <david@xxxxxxxxxxxxx> wrote:
>> > On Mon, May 12, 2014 at 09:03:48PM -0700, Austin Schuh wrote:
>> >> On Mon, May 12, 2014 at 8:46 PM, Dave Chinner <david@xxxxxxxxxxxxx> wrote:
>> >> > On Mon, May 12, 2014 at 06:29:28PM -0700, Austin Schuh wrote:
>> >> >> On Wed, Mar 5, 2014 at 4:53 PM, Austin Schuh <austin@xxxxxxxxxxxxxxxx> wrote:
>> >> >> > Hi Dave,
>> >> >> >
>> >> >> > On Wed, Mar 5, 2014 at 3:35 PM, Dave Chinner <david@xxxxxxxxxxxxx> wrote:
>> >> >> >> On Wed, Mar 05, 2014 at 03:08:16PM -0800, Austin Schuh wrote:
>> >> >> >>> Howdy,
>> >> >> >>>
>> >> >> >>> I'm running a config_preempt_rt patched version of the 3.10.11 kernel,
>> >> >> >>> and I'm seeing a couple lockups and crashes which I think are related
>> >> >> >>> to XFS.
>> >> >> >>
>> >> >> >> I think they ar emore likely related to RT issues....
>> >> >> >>
>> >> >> >
>> >> >> > That very well may be true.
>> >> >> >
>> >> >> >> Cheers,
>> >> >> >>
>> >> >> >> Dave.
>> >> >> >> --
>> >> >> >> Dave Chinner
>> >> >>
>> >> >> I had the issue reproduce itself today with just the main SSD
>> >> >> installed. This was on a new machine that was built this morning.
>> >> >> There is a lot less going on in this trace than the previous one.
>> >> >
>> >> > The three blocked threads:
>> >> >
>> >> > 1. kworker running IO completion waiting on an inode lock,
>> >> > holding locked pages.
>> >> > 2. kworker running writeback flusher work waiting for a page lock
>> >> > 3. direct flush work waiting for allocation, holding page
>> >> > locks and the inode lock.
>> >> >
>> >> > What's the kworker thread running the allocation work doing?
>> >> >
>> >> > You might need to run `echo w > proc-sysrq-trigger` to get this
>> >> > information...
>> >>
>> >> I was able to reproduce the lockup. I ran `echo w >
>> >> /proc/sysrq-trigger` per your suggestion. I don't know how to figure
>> >> out what the kworker thread is doing, but I'll happily do it if you
>> >> can give me some guidance.
>> >
>> > There isn't a worker thread blocked doing an allocation in that
>> > dump, so it doesn't shed any light on the problem at all. try
>> > `echo l > /proc/sysrq-trigger`, followed by `echo t >
>> > /proc/sysrq-trigger` so we can see all the processes running on CPUs
>> > and all the processes in the system...
>> >
>> > Cheers,
>> >
>> > Dave.
>>
>> Attached is the output of the two commands you asked for.
>
> Nothing there. There's lots of processes waiting for allocation to
> run, and no kworkers running allocation work. This looks more
> like a rt-kernel workqueue issue, not an XFS problem.
>
> FWIW, it woul dbe really helpful if you compiled your kernels with
> frame pointers enabled - the stack traces are much more precise and
> readable (i.e. gets rid of all the false/stale entrys) and that
> helps understanding where things are stuck immensely.
>
> Cheers,
>
> Dave.
I'll go check with the rt-kernel guys and take it from there. Thanks
for the frame pointers suggestion. I'll make that change the next
time I build a kernel.
Austin
I found 1 bug in XFS which I fixed, and I've uncovered something else that I'm not completely sure how to fix.
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.
--- a/fs/xfs/xfs_bmap_util.c 2014-06-23 12:59:10.008678410 -0700
+++ b/fs/xfs/xfs_bmap_util.c 2014-06-23 12:59:14.116678239 -0700
@@ -263,7 +263,6 @@
current_set_flags_nested(&pflags, PF_FSTRANS);
args->result = __xfs_bmapi_allocate(args);
- complete(args->done);
current_restore_flags_nested(&pflags, PF_FSTRANS);
}
@@ -277,16 +276,13 @@
xfs_bmapi_allocate(
struct xfs_bmalloca *args)
{
- DECLARE_COMPLETION_ONSTACK(done);
-
if (!args->stack_switch)
return __xfs_bmapi_allocate(args);
- args->done = &done;
INIT_WORK_ONSTACK(&args->work, xfs_bmapi_allocate_worker);
queue_work(xfs_alloc_wq, &args->work);
- wait_for_completion(&done);
+ flush_work(&args->work);
destroy_work_on_stack(&args->work);
return args->result;
}
--- a/fs/xfs/xfs_bmap_util.h 2014-06-23 12:59:10.008678410 -0700
+++ b/fs/xfs/xfs_bmap_util.h 2014-06-23 12:59:11.708678340 -0700
@@ -57,7 +57,6 @@
char conv; /* overwriting unwritten extents */
char stack_switch;
int flags;
- struct completion *done;
struct work_struct work;
int result;
};
I enabled event tracing (and added a new event which lists the number of workers running in a queue whenever that is changed).
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.
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.
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
irq/44-ahci-273 [000] ....1.5 76.340301: workqueue_activate_work: work struct ffff880406a6b998
scp-3986 [000] ....1.. 76.342711: xfs_ilock_nowait: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_SHARED caller xfs_map_blocks
scp-3986 [000] ....1.. 76.342714: xfs_iunlock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_SHARED caller xfs_map_blocks
scp-3986 [000] ....1.. 76.342722: xfs_ilock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_EXCL caller xfs_iomap_write_allocate
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
scp-3986 [000] ....1.3 76.342730: workqueue_activate_work: work struct ffff8800a5b8d900
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
scp-3986 [000] ....1.4 76.342755: workqueue_activate_work: work struct ffff88040a6a01c8
kworker/0:2-757 [000] ....1.1 76.342868: workqueue_nr_running: pool=ffff88042da63fc0 nr_running=1
kworker/0:2-757 [000] ....1.. 76.342869: workqueue_execute_start: work struct ffff880406a6b998: function xfs_end_io
kworker/0:2-757 [000] ....1.. 76.342870: xfs_ilock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_EXCL caller xfs_setfilesize
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
irq/44-ahci-273 [003] ....1.5 76.419038: workqueue_activate_work: work struct ffff8800aebc3588
kworker/3:1-119 [003] ....1.1 76.419105: workqueue_nr_running: pool=ffff88042dbe3fc0 nr_running=1
kworker/3:1-119 [003] ....1.. 76.419106: workqueue_execute_start: work struct ffff8800aebc3588: function xfs_end_io
kworker/3:1-119 [003] ....1.. 76.419107: xfs_ilock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_EXCL caller xfs_setfilesize
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
irq/44-ahci-273 [002] .N..1.5 76.426127: workqueue_activate_work: work struct ffff880406a6b930
kworker/2:1-72 [002] ....1.1 76.426242: workqueue_nr_running: pool=ffff88042db63fc0 nr_running=1
kworker/2:1-72 [002] ....1.. 76.426243: workqueue_execute_start: work struct ffff880406a6b930: function xfs_end_io
kworker/2:1-72 [002] ....1.. 76.426244: xfs_ilock: dev 8:5 ino 0x9794 lock_addr ffff880409fe0090 flags ILOCK_EXCL caller xfs_setfilesize
Thanks,
Austin
_______________________________________________ xfs mailing list xfs@xxxxxxxxxxx http://oss.sgi.com/mailman/listinfo/xfs
