Re: Still seeing hangs in xlog_grant_log_space

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

On Fri, Apr 27, 2012 at 1:09 PM, Dave Chinner <david@xxxxxxxxxxxxx> wrote:
> On Fri, Apr 27, 2012 at 11:04:33AM +0200, Juerg Haefliger wrote:
>> On Fri, Apr 27, 2012 at 1:07 AM, Dave Chinner <david@xxxxxxxxxxxxx> wrote:
>> > On Fri, Apr 27, 2012 at 01:00:08AM +0200, Juerg Haefliger wrote:
>> >> On Fri, Apr 27, 2012 at 12:44 AM, Dave Chinner <david@xxxxxxxxxxxxx> wrote:
>> >> > On Thu, Apr 26, 2012 at 02:37:50PM +0200, Juerg Haefliger wrote:
>> >> >> > I'm assuming it is the event trace
>> >> >> > that is causing it to blow out? If so, just the 30-60s either side of
>> >> >> > the hang first showing up is probaby necessary, and that should cut
>> >> >> > the size down greatly....
>> >> >>
>> >> >> Can I shorten the existing trace.dat?
>
> Looks like you can - the "trace-cmd split" option.
>
>> >> >
>> >> > No idea, but that's likely the problem - I don't want the binary
>> >> > trace.dat file. I want the text output of the report command
>> >> > generated from the binary trace.dat file...
>> >>
>> >> Well yes. I did RTFM :-) trace.dat is 15GB.
>> >
>> > OK, that's a lot larger than I expected for a hung filesystem....
>> >
>> >> >> I stopped the trace
>> >> >> automatically 10 secs after the the xlog_... trace showed up in syslog
>> >> >> so effectively some 130+ secs after the hang occured.
>> >
>> > Can you look at the last timestamp in the report file, and trim off
>> > anything from the start that is older than, say, 180s before that?
>>
>> Cut the trace down to 180 secs which brought the filesize down to
>> 93MB: https://region-a.geo-1.objects.hpcloudsvc.com:443/v1.0/AUTH_9630ead2-6194-40df-afd3-7395448d4536/xfs-hang/report-2012-04-24-180secs.tgz
>
> I see the problem - the trace.dat file is hosted on an XFS
> filesystem, so all the writes to the trace.dat file are causing
> events to be logged, which causes writes to the trace.dat file....
>
> taking out al the trace-cmd events:
>
> $ grep -v trace-cmd trace_report_180secs.txt > t.t
> $ ls -l trace_report_180secs.txt t.t
> -rw-r--r-- 1 dave dave 2136941443 Apr 27 18:52 trace_report_180secs.txt
> -rw-r--r-- 1 dave dave    3280629 Apr 27 20:12 t.t
>
> Brings the event trace for that 180s down ifrom 2.1GB to 3.2MB,
> which is much more like I'd expect from a hung filesystem....
>
> Ok, so it looks like there's lots of noise from other XFS
> filesystems to, and from the info.log, the xfs-hang filesystem is on
> device 252:2 (/dev/vg00/tmp):
>
> $ grep "dev 252:2" t.t
> $
>
> And there are no events from that filesystem in the log at all. Ok,
> so what you need to do is find out if there are *any* events from
> that device in the larger log file you have.....
>
> If not, then it is time for advanced trace-cmd mojo. We can tell it
> to filter events only from the PID of the test script and all it's
> children using:
>
> # trace-cmd record -e xfs\* -P <parent-pid> -c
>
> But better would be to use the device number of the relevant
> filesystem to filter the events. The device is 252:2, which means in
> kernel terms is it:
>
>        dev = (major << 20) | minor
>            = 0xfc00002
>
> So you should be able to get just the xfs-hang events via:
>
> # trace-cmd record -e xfs\* -d 'dev == 0xfc00002'
>
> and as long as you don't host log files on /xfs-hang, it'll only
> record the workload running on the xfs-hang filesystem.

Third try: https://region-a.geo-1.objects.hpcloudsvc.com:443/v1.0/AUTH_9630ead2-6194-40df-afd3-7395448d4536/xfs-hang/report-2012-04-27-180secs.tgz
Filtered by device, trace events go to a different filesystem.


> BTW, how often do you see this sort of thing:
>
> [  220.571551] ------------[ cut here ]------------
> [  220.571562] WARNING: at fs/inode.c:280 drop_nlink+0x49/0x50()
> [  220.571564] Hardware name: SE2170s
> [  220.571565] Modules linked in: ipmi_devintf ipmi_si ipmi_msghandler ip6table_filter ip6_tables ipt_MASQUERADE iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack ipt_REJECT xt_CHECKSUM iptable_mangle xt_tcpudp iptable_filter ip_tables x_tables bridge 8021q garp stp coretemp ghash_clmulni_intel aesni_intel cryptd usbhid i7core_edac lp edac_core hid aes_x86_64 parport serio_raw microcode xfs igb hpsa dca
> [  220.571594] Pid: 4637, comm: copy-files Not tainted 3.4.0-rc4 #2
> [  220.571595] Call Trace:
> [  220.571603]  [<ffffffff810508cf>] warn_slowpath_common+0x7f/0xc0
> [  220.571605]  [<ffffffff8105092a>] warn_slowpath_null+0x1a/0x20
> [  220.571607]  [<ffffffff81193319>] drop_nlink+0x49/0x50
> [  220.571628]  [<ffffffffa00701ef>] xfs_droplink+0x2f/0x60 [xfs]
> [  220.571640]  [<ffffffffa0072d58>] xfs_remove+0x2e8/0x3c0 [xfs]
> [  220.571645]  [<ffffffff8163aeee>] ? _raw_spin_lock+0xe/0x20
> [  220.571656]  [<ffffffffa0068248>] xfs_vn_unlink+0x48/0x90 [xfs]
> [  220.571659]  [<ffffffff8118684f>] vfs_unlink+0x9f/0x100
> [  220.571662]  [<ffffffff811893ef>] do_unlinkat+0x1af/0x1e0
> [  220.571668]  [<ffffffff810a8eab>] ? sys_futex+0x7b/0x180
> [  220.571670]  [<ffffffff8118a9a6>] sys_unlink+0x16/0x20
> [  220.571675]  [<ffffffff816431a9>] system_call_fastpath+0x16/0x1b
>
> You might want to run xfs-repair over your filesystems to find out
> how many inodes have bad link counts....

First time I saw it was when I started using 3.4-rc4. I repaired the
fs before I rerun the test that produced the above data.

...Juerg


> Cheers,
>
> Dave.
> --
> Dave Chinner
> david@xxxxxxxxxxxxx

_______________________________________________
xfs mailing list
xfs@xxxxxxxxxxx
http://oss.sgi.com/mailman/listinfo/xfs



[Linux USB Devel]     [Video for Linux]     [Linux Audio Users]     [Photo]     [Yosemite News]    [Yosemite Photos]    [Free Online Dating]     [Linux Kernel]     [Linux SCSI]     [XFree86]

Add to Google Powered by Linux