>>> >> >> > 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. Did anybody have a chance to look at the data? Thanks ...Juerg > >> 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
