>>> >> >> > 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
>> 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:
> Filtered by device, trace events go to a different filesystem.
Did anybody have a chance to look at the data?
>> 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.
>> Dave Chinner