Package: linux-image-3.2.0-4-amd64
Version: 3.2.46-1
Hello,
During extensive testing of NFS4 file server (Debian 7 guest on VMware / Proxmox VE-KVM) that shares
XFS filesystems over network we've hit problem with occasional system hangups caused by nfsd and
xfsaild processes.
When this issue occurs, 2 from 4 cpus are 100% loaded (one with nfsd, second with xfsaild) and two
other CPU-s are trying to handle other processes but i/o wait is almost 100% for those CPU-s and
system is unusable (sometimes it's possible to ssh into system after long waiting, sometimes it's
not possible; scp seems to work better in this situation, console is always blank and unresponsible,
pings work ok).
top output during "hangup":
top - 00:55:20 up 13:44, 3 users, load average: 34.00, 34.01, 33.93
Tasks: 175 total, 9 running, 164 sleeping, 0 stopped, 2 zombie
%Cpu0 : 0.0 us,100.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0
st
%Cpu1 : 0.3 us, 0.7 sy, 0.0 ni, 0.0 id, 98.7 wa, 0.0 hi, 0.0 si, 0.3
st
%Cpu2 : 0.0 us, 0.0 sy, 0.0 ni, 0.0 id, 99.7 wa, 0.0 hi, 0.0 si, 0.3
st
%Cpu3 : 0.0 us,100.0 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0
st
KiB Mem: 4061340 total, 2122328 used, 1939012 free, 2072 buffers
KiB Swap: 524284 total, 0 used, 524284 free, 1165292 cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
15094 root 20 0 23312 1708 1140 R 0.7 0.0 0:00.11 top
1242 root 20 0 0 0 0 S 0.3 0.0 0:09.71 xfsaild/dm-4
14895 sshl 20 0 71176 2396 1564 S 0.3 0.1 0:00.33 sshd
1 root 20 0 10648 808 672 S 0.0 0.0 0:01.78 init
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 1:29.80 ksoftirqd/0
5 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kworker/u:0
[...]
See attached /proc/sched_debug dump from "hangup" time, that indicates nfsd and xfsaild as cpu0 and
cpu3 holders.
We've managed to recreate this issue a few times (every test requred VM restoring from backup and
6-24 hours of intensive NFS operations to hit hangup) and every time xfsaild proces in sched_debug
was connected with dm-5 device on our system (see xfsaild/dm-5 in attached sched_debug dump).
The very last messages that syslog managed to send to remote syslog server were always like in
attached syslog.txt extract.
Device dm-5 was bound to XFS filesystem with high agcount (agcount=81 was effect of growing this FS
from small to bigger size); xfs_info output for this FS:
meta-data=/dev/mapper/vg1-tmp isize=256 agcount=81, agsize=16320 blks
= sectsz=512 attr=2
data = bsize=4096 blocks=1310720, imaxpct=25
= sunit=64 swidth=128 blks
naming =version 2 bsize=4096 ascii-ci=0
log =internal bsize=4096 blocks=1216, version=2
= sectsz=512 sunit=64 blks, lazy-count=1
realtime =none extsz=4096 blocks=0, rtextents=0
After reformatting this XFS filesystem (agcount=4 after reformatting) and repeating tests, we didn't
manage to hit this issue any more, so problem may be connected with XFS and high agcount and
intensive operations on such XFS filesystem (maybe some races in kernel code near XFS?).
Regards,
Pawel
IB Development Team
http://dev.ib.pl/
Sched Debug Version: v0.10, 3.2.0-4-amd64 #1
ktime : 47413060.422986
sched_clk : 48401420.774630
cpu_clk : 47413060.423095
jiffies : 4306745560
sched_clock_stable : 0
sysctl_sched
.sysctl_sched_latency : 18.000000
.sysctl_sched_min_granularity : 2.250000
.sysctl_sched_wakeup_granularity : 3.000000
.sysctl_sched_child_runs_first : 0
.sysctl_sched_features : 24119
.sysctl_sched_tunable_scaling : 1 (logaritmic)
cpu#0, 1995.190 MHz
.nr_running : 4
.load : 2048
.nr_switches : 87608906
.nr_load_updates : 10669061
.nr_uninterruptible : 320
.next_balance : 4306.745619
.curr->pid : 2344
.clock : 25463350.262748
.cpu_load[0] : 2048
.cpu_load[1] : 2048
.cpu_load[2] : 2048
.cpu_load[3] : 2048
.cpu_load[4] : 2048
cfs_rq[0]:/
.exec_clock : 0.000000
.MIN_vruntime : 1394281.606368
.min_vruntime : 1394290.559425
.max_vruntime : 1394281.606368
.spread : 0.000000
.spread0 : 0.000000
.nr_spread_over : 0
.nr_running : 2
.load : 2048
.load_avg : 0.000000
.load_period : 0.000000
.load_contrib : 0
.load_tg : 0
rt_rq[0]:
.rt_nr_running : 1
.rt_throttled : 0
.rt_time : 0.000000
.rt_runtime : 950.000000
runnable tasks:
task PID tree-key switches prio exec-runtime
sum-exec sum-sleep
----------------------------------------------------------------------------------------------------------
migration/0 6 0.999999 1473 0 0
0 0.000000 0.000000 0.000000 /
watchdog/0 7 0.999999 6367 0 0
0 0.000000 0.000000 0.000000 /
R nfsd 2344 1394285.137076 3254608 120 0
0 0.000000 0.000000 0.000000 /
kworker/0:1 2728 1394281.606368 2671709 120 0
0 0.000000 0.000000 0.000000 /
cpu#1, 1995.190 MHz
.nr_running : 1
.load : 1024
.nr_switches : 4809728
.nr_load_updates : 6691004
.nr_uninterruptible : -119
.next_balance : 4306.745575
.curr->pid : 14953
.clock : 47413060.078390
.cpu_load[0] : 1024
.cpu_load[1] : 512
.cpu_load[2] : 256
.cpu_load[3] : 128
.cpu_load[4] : 64
cfs_rq[1]:/
.exec_clock : 0.000000
.MIN_vruntime : 0.000001
.min_vruntime : 261922.387542
.max_vruntime : 0.000001
.spread : 0.000000
.spread0 : -1132368.171883
.nr_spread_over : 0
.nr_running : 1
.load : 1024
.load_avg : 0.000000
.load_period : 0.000000
.load_contrib : 0
.load_tg : 0
rt_rq[1]:
.rt_nr_running : 0
.rt_throttled : 0
.rt_time : 0.000000
.rt_runtime : 950.000000
runnable tasks:
task PID tree-key switches prio exec-runtime
sum-exec sum-sleep
----------------------------------------------------------------------------------------------------------
R sftp-server 14953 261913.549913 1116 120 0
0 0.000000 0.000000 0.000000 /
cpu#2, 1995.190 MHz
.nr_running : 0
.load : 0
.nr_switches : 3721231
.nr_load_updates : 6611424
.nr_uninterruptible : -33
.next_balance : 4306.745561
.curr->pid : 0
.clock : 47413060.043647
.cpu_load[0] : 0
.cpu_load[1] : 0
.cpu_load[2] : 0
.cpu_load[3] : 0
.cpu_load[4] : 0
cfs_rq[2]:/
.exec_clock : 0.000000
.MIN_vruntime : 0.000001
.min_vruntime : 214277.057748
.max_vruntime : 0.000001
.spread : 0.000000
.spread0 : -1180013.501677
.nr_spread_over : 0
.nr_running : 0
.load : 0
.load_avg : 0.000000
.load_period : 0.000000
.load_contrib : 0
.load_tg : 0
rt_rq[2]:
.rt_nr_running : 0
.rt_throttled : 0
.rt_time : 0.000000
.rt_runtime : 950.000000
runnable tasks:
task PID tree-key switches prio exec-runtime
sum-exec sum-sleep
----------------------------------------------------------------------------------------------------------
cpu#3, 1995.190 MHz
.nr_running : 4
.load : 2048
.nr_switches : 2056627
.nr_load_updates : 6561753
.nr_uninterruptible : -142
.next_balance : 4306.745621
.curr->pid : 1244
.clock : 25463348.029955
.cpu_load[0] : 2048
.cpu_load[1] : 2048
.cpu_load[2] : 2048
.cpu_load[3] : 2048
.cpu_load[4] : 2048
cfs_rq[3]:/
.exec_clock : 0.000000
.MIN_vruntime : 168626.285950
.min_vruntime : 168635.285950
.max_vruntime : 168626.285950
.spread : 0.000000
.spread0 : -1225655.273475
.nr_spread_over : 0
.nr_running : 2
.load : 2048
.load_avg : 0.000000
.load_period : 0.000000
.load_contrib : 0
.load_tg : 0
rt_rq[3]:
.rt_nr_running : 1
.rt_throttled : 0
.rt_time : 0.000000
.rt_runtime : 950.000000
runnable tasks:
task PID tree-key switches prio exec-runtime
sum-exec sum-sleep
----------------------------------------------------------------------------------------------------------
migration/3 17 3.998888 2332 0 0
0 0.000000 0.000000 0.000000 /
watchdog/3 20 5.999999 6367 0 0
0 0.000000 0.000000 0.000000 /
kworker/3:1 31 168626.285950 24750 120 0
0 0.000000 0.000000 0.000000 /
R xfsaild/dm-5 1244 168635.285950 591983 120 0
0 0.000000 0.000000 0.000000 /
2013-11-03 12:14:48 hd4dnf01 kernel: [ 119.632225] NFSD: failed to write
recovery record (err -17); please check that /var/lib/nfs/v4recovery exists and
is writeable
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.020027] BUG: soft lockup - CPU#0
stuck for 22s! [nfsd:2441]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.022968] Modules linked in:
act_police cls_basic cls_flow cls_fw cls_u32 sch_tbf sch_prio sch_htb sch_hfsc
sch_ingress sch_sfq xt_statistic xt_CT xt_time xt_connlimit xt_realm
xt_addrtype iptable_raw xt_comment xt_recent xt_policy ipt_ULOG ipt_REJECT
ipt_REDIRECT ipt_NETMAP ipt_MASQUERADE ipt_ECN ipt_ecn ipt_CLUSTERIP ipt_ah
xt_set ip_set nf_nat_tftp nf_nat_snmp_basic nf_conntrack_snmp nf_nat_sip
nf_nat_pptp nf_nat_proto_gre nf_nat_irc nf_nat_h323 nf_nat_ftp nf_nat_amanda
ts_kmp nf_conntrack_amanda nf_conntrack_sane nf_conntrack_tftp nf_conntrack_sip
nf_conntrack_proto_udplite nf_conntrack_proto_sctp nf_conntrack_pptp
nf_conntrack_proto_gre nf_conntrack_netlink nf_conntrack_netbios_ns
nf_conntrack_broadcast nf_conntrack_irc nf_conntrack_h323 nf_conntrack_ftp
xt_TPROXY nf_defrag_ipv6 ip6_tables nf_tproxy_core xt_tcpmss xt_pkttype
xt_physdev xt_owner xt_NFQUEUE xt_NFLOG nfnetlink_log xt_multiport xt_mark
xt_mac xt_limit xt_length xt_iprange xt_helper xt_hashlimit xt_DSCP xt_dsc
2013-11-03 12:14:48 hd4dnf01 kernel: p xt_dccp xt_conntrack xt_connmark
xt_CLASSIFY xt_AUDIT ipt_LOG xt_tcpudp xt_state iptable_nat nf_nat
nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack iptable_mangle nfnetlink
iptable_filter ip_tables x_tables nfsd nfs nfs_acl auth_rpcgss fscache lockd
sunrpc loop snd_pcm snd_page_alloc snd_timer snd soundcore pcspkr joydev
psmouse serio_raw i2c_piix4 i2c_core virtio_balloon evdev processor thermal_sys
button xfs dm_mod usbhid hid ata_generic virtio_net virtio_blk floppy ata_piix
uhci_hcd ehci_hcd libata usbcore scsi_mod virtio_pci virtio_ring virtio
usb_common [last unloaded: scsi_wait_scan]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023156] CPU 0
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023158] Modules linked in:
act_police cls_basic cls_flow cls_fw cls_u32 sch_tbf sch_prio sch_htb sch_hfsc
sch_ingress sch_sfq xt_statistic xt_CT xt_time xt_connlimit xt_realm
xt_addrtype iptable_raw xt_comment xt_recent xt_policy ipt_ULOG ipt_REJECT
ipt_REDIRECT ipt_NETMAP ipt_MASQUERADE ipt_ECN ipt_ecn ipt_CLUSTERIP ipt_ah
xt_set ip_set nf_nat_tftp nf_nat_snmp_basic nf_conntrack_snmp nf_nat_sip
nf_nat_pptp nf_nat_proto_gre nf_nat_irc nf_nat_h323 nf_nat_ftp nf_nat_amanda
ts_kmp nf_conntrack_amanda nf_conntrack_sane nf_conntrack_tftp nf_conntrack_sip
nf_conntrack_proto_udplite nf_conntrack_proto_sctp nf_conntrack_pptp
nf_conntrack_proto_gre nf_conntrack_netlink nf_conntrack_netbios_ns
nf_conntrack_broadcast nf_conntrack_irc nf_conntrack_h323 nf_conntrack_ftp
xt_TPROXY nf_defrag_ipv6 ip6_tables nf_tproxy_core xt_tcpmss xt_pkttype
xt_physdev xt_owner xt_NFQUEUE xt_NFLOG nfnetlink_log xt_multiport xt_mark
xt_mac xt_limit xt_length xt_iprange xt_helper xt_hashlimit xt_DSCP xt_dsc
2013-11-03 12:14:48 hd4dnf01 kernel: p xt_dccp xt_conntrack xt_connmark
xt_CLASSIFY xt_AUDIT ipt_LOG xt_tcpudp xt_state iptable_nat nf_nat
nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack iptable_mangle nfnetlink
iptable_filter ip_tables x_tables nfsd nfs nfs_acl auth_rpcgss fscache lockd
sunrpc loop snd_pcm snd_page_alloc snd_timer snd soundcore pcspkr joydev
psmouse serio_raw i2c_piix4 i2c_core virtio_balloon evdev processor thermal_sys
button xfs dm_mod usbhid hid ata_generic virtio_net virtio_blk floppy ata_piix
uhci_hcd ehci_hcd libata usbcore scsi_mod virtio_pci virtio_ring virtio
usb_common [last unloaded: scsi_wait_scan]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023300]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023305] Pid: 2441, comm: nfsd Not
tainted 3.2.0-4-amd64 #1 Debian 3.2.46-1 Bochs Bochs
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023311] RIP:
0010:[<ffffffff81070e3a>] [<ffffffff81070e3a>] do_raw_spin_lock+0x15/0x1b
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023341] RSP: 0018:ffff880118e3bd08
EFLAGS: 00000297
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023345] RAX: 000000002fcc2fcb RBX:
ffff88011881a000 RCX: 00000000000e326a
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023349] RDX: 0000000000002fcc RSI:
00000000000e326b RDI: ffff8801187ed6a8
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023353] RBP: ffff8801187ed600 R08:
0000000000000004 R09: 0000000000000004
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023357] R10: 0000000000000000 R11:
0000000000000001 R12: ffffffff811ae5ff
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023360] R13: ffffffffa015848d R14:
0000000000000005 R15: ffff88011881a000
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023366] FS: 0000000000000000(0000)
GS:ffff88011fc00000(0000) knlGS:0000000000000000
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023370] CS: 0010 DS: 0000 ES: 0000
CR0: 000000008005003b
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023374] CR2: 0000000001ae8000 CR3:
00000001189b7000 CR4: 00000000000006f0
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023385] DR0: 0000000000000000 DR1:
0000000000000000 DR2: 0000000000000000
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023397] DR3: 0000000000000000 DR6:
00000000ffff0ff0 DR7: 0000000000000400
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023402] Process nfsd (pid: 2441,
threadinfo ffff880118e3a000, task ffff880117409020)
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.023405] Stack:
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] ffffffffa015b0c5
ffff880100000000 0000000000014400 ffff880115ef2800
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] ffff880117978040
0000000000008000 ffff88007e09b680 0000000000000020
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] ffff880115ef2980
ffff880117978180 ffffffffa02eac60 0000000000000098
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] Call Trace:
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa015b0c5>] ?
_xfs_log_force_lsn+0x7e/0x205 [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa02eac60>] ?
nfsd_unlink+0xfd/0x145 [nfsd]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa02f3880>] ?
nfsd4_remove+0x39/0x87 [nfsd]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa02f288c>] ?
nfsd4_proc_compound+0x243/0x40f [nfsd]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa02e67cd>] ?
nfsd_dispatch+0xd7/0x1ba [nfsd]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa0229bef>] ?
svc_process_common+0x2c3/0x4c4 [sunrpc]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffff8103f57d>] ?
try_to_wake_up+0x197/0x197
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa022a000>] ?
svc_process+0x110/0x12c [sunrpc]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa02e60e3>] ?
nfsd+0xe3/0x127 [nfsd]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa02e6000>] ?
0xffffffffa02e5fff
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffff8105f48d>] ?
kthread+0x76/0x7e
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffff81355cb4>] ?
kernel_thread_helper+0x4/0x10
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffff8105f417>] ?
kthread_worker_fn+0x139/0x139
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffff81355cb0>] ?
gs_change+0x13/0x13
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] Code: 05 e8 8b 2c 14 00 c3
f0 81 2f 00 00 10 00 74 05 e8 5c 2c 14 00 c3 b8 00 00 01 00 f0 0f c1 07 89 c2
c1 ea 10 66 39 d0 74 07 f3 90 <66> 8b 07 eb f4 c3 8b 17 31 c0 89 d1 c1 e9 10 66
39 ca 75 14 8d
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] Call Trace:
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa015b0c5>] ?
_xfs_log_force_lsn+0x7e/0x205 [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa02eac60>] ?
nfsd_unlink+0xfd/0x145 [nfsd]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa02f3880>] ?
nfsd4_remove+0x39/0x87 [nfsd]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa02f288c>] ?
nfsd4_proc_compound+0x243/0x40f [nfsd]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa02e67cd>] ?
nfsd_dispatch+0xd7/0x1ba [nfsd]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa0229bef>] ?
svc_process_common+0x2c3/0x4c4 [sunrpc]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffff8103f57d>] ?
try_to_wake_up+0x197/0x197
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa022a000>] ?
svc_process+0x110/0x12c [sunrpc]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa02e60e3>] ?
nfsd+0xe3/0x127 [nfsd]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffffa02e6000>] ?
0xffffffffa02e5fff
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffff8105f48d>] ?
kthread+0x76/0x7e
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffff81355cb4>] ?
kernel_thread_helper+0x4/0x10
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffff8105f417>] ?
kthread_worker_fn+0x139/0x139
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.024015] [<ffffffff81355cb0>] ?
gs_change+0x13/0x13
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.040024] BUG: soft lockup - CPU#1
stuck for 22s! [xfsaild/dm-5:1253]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042209] Modules linked in:
act_police cls_basic cls_flow cls_fw cls_u32 sch_tbf sch_prio sch_htb sch_hfsc
sch_ingress sch_sfq xt_statistic xt_CT xt_time xt_connlimit xt_realm
xt_addrtype iptable_raw xt_comment xt_recent xt_policy ipt_ULOG ipt_REJECT
ipt_REDIRECT ipt_NETMAP ipt_MASQUERADE ipt_ECN ipt_ecn ipt_CLUSTERIP ipt_ah
xt_set ip_set nf_nat_tftp nf_nat_snmp_basic nf_conntrack_snmp nf_nat_sip
nf_nat_pptp nf_nat_proto_gre nf_nat_irc nf_nat_h323 nf_nat_ftp nf_nat_amanda
ts_kmp nf_conntrack_amanda nf_conntrack_sane nf_conntrack_tftp nf_conntrack_sip
nf_conntrack_proto_udplite nf_conntrack_proto_sctp nf_conntrack_pptp
nf_conntrack_proto_gre nf_conntrack_netlink nf_conntrack_netbios_ns
nf_conntrack_broadcast nf_conntrack_irc nf_conntrack_h323 nf_conntrack_ftp
xt_TPROXY nf_defrag_ipv6 ip6_tables nf_tproxy_core xt_tcpmss xt_pkttype
xt_physdev xt_owner xt_NFQUEUE xt_NFLOG nfnetlink_log xt_multiport xt_mark
xt_mac xt_limit xt_length xt_iprange xt_helper xt_hashlimit xt_DSCP xt_dsc
2013-11-03 12:14:48 hd4dnf01 kernel: p xt_dccp xt_conntrack xt_connmark
xt_CLASSIFY xt_AUDIT ipt_LOG xt_tcpudp xt_state iptable_nat nf_nat
nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack iptable_mangle nfnetlink
iptable_filter ip_tables x_tables nfsd nfs nfs_acl auth_rpcgss fscache lockd
sunrpc loop snd_pcm snd_page_alloc snd_timer snd soundcore pcspkr joydev
psmouse serio_raw i2c_piix4 i2c_core virtio_balloon evdev processor thermal_sys
button xfs dm_mod usbhid hid ata_generic virtio_net virtio_blk floppy ata_piix
uhci_hcd ehci_hcd libata usbcore scsi_mod virtio_pci virtio_ring virtio
usb_common [last unloaded: scsi_wait_scan]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042400] CPU 1
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042402] Modules linked in:
act_police cls_basic cls_flow cls_fw cls_u32 sch_tbf sch_prio sch_htb sch_hfsc
sch_ingress sch_sfq xt_statistic xt_CT xt_time xt_connlimit xt_realm
xt_addrtype iptable_raw xt_comment xt_recent xt_policy ipt_ULOG ipt_REJECT
ipt_REDIRECT ipt_NETMAP ipt_MASQUERADE ipt_ECN ipt_ecn ipt_CLUSTERIP ipt_ah
xt_set ip_set nf_nat_tftp nf_nat_snmp_basic nf_conntrack_snmp nf_nat_sip
nf_nat_pptp nf_nat_proto_gre nf_nat_irc nf_nat_h323 nf_nat_ftp nf_nat_amanda
ts_kmp nf_conntrack_amanda nf_conntrack_sane nf_conntrack_tftp nf_conntrack_sip
nf_conntrack_proto_udplite nf_conntrack_proto_sctp nf_conntrack_pptp
nf_conntrack_proto_gre nf_conntrack_netlink nf_conntrack_netbios_ns
nf_conntrack_broadcast nf_conntrack_irc nf_conntrack_h323 nf_conntrack_ftp
xt_TPROXY nf_defrag_ipv6 ip6_tables nf_tproxy_core xt_tcpmss xt_pkttype
xt_physdev xt_owner xt_NFQUEUE xt_NFLOG nfnetlink_log xt_multiport xt_mark
xt_mac xt_limit xt_length xt_iprange xt_helper xt_hashlimit xt_DSCP xt_dsc
2013-11-03 12:14:48 hd4dnf01 kernel: p xt_dccp xt_conntrack xt_connmark
xt_CLASSIFY xt_AUDIT ipt_LOG xt_tcpudp xt_state iptable_nat nf_nat
nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack iptable_mangle nfnetlink
iptable_filter ip_tables x_tables nfsd nfs nfs_acl auth_rpcgss fscache lockd
sunrpc loop snd_pcm snd_page_alloc snd_timer snd soundcore pcspkr joydev
psmouse serio_raw i2c_piix4 i2c_core virtio_balloon evdev processor thermal_sys
button xfs dm_mod usbhid hid ata_generic virtio_net virtio_blk floppy ata_piix
uhci_hcd ehci_hcd libata usbcore scsi_mod virtio_pci virtio_ring virtio
usb_common [last unloaded: scsi_wait_scan]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042529]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042534] Pid: 1253, comm:
xfsaild/dm-5 Not tainted 3.2.0-4-amd64 #1 Debian 3.2.46-1 Bochs Bochs
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042541] RIP:
0010:[<ffffffff81070e3a>] [<ffffffff81070e3a>] do_raw_spin_lock+0x15/0x1b
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042567] RSP: 0018:ffff8801163d9d68
EFLAGS: 00000297
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042571] RAX: 000000004c824c81 RBX:
0000000000000001 RCX: 0000000000000e00
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042575] RDX: 0000000000004c82 RSI:
ffff8801187ed6a8 RDI: ffff88011786d878
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042579] RBP: ffff880117c19680 R08:
0000000000000000 R09: 0000000000000000
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042595] R10: 0000000000000000 R11:
ffff88011881a000 R12: 0000000000014400
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042599] R13: ffff88011786d798 R14:
ffff88011786d758 R15: 000000000000001c
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042604] FS: 0000000000000000(0000)
GS:ffff88011fc80000(0000) knlGS:0000000000000000
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042608] CS: 0010 DS: 0000 ES: 0000
CR0: 000000008005003b
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042612] CR2: 00000000022ad038 CR3:
0000000118ff4000 CR4: 00000000000006e0
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042624] DR0: 0000000000000000 DR1:
0000000000000000 DR2: 0000000000000000
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042636] DR3: 0000000000000000 DR6:
00000000ffff0ff0 DR7: 0000000000000400
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042640] Process xfsaild/dm-5 (pid:
1253, threadinfo ffff8801163d8000, task ffff88011743eab0)
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.042644] Stack:
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] ffffffffa015dcb8
ffff8801187ed600 ffffffffa015a42c ffff8801187ed600
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] ffffffffa015a48f
ffff880117c19680 ffff8801187ed600 0000000000000000
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] ffffffffa015af54
0000000000000000 ffff88011881a000 ffff8800c125fcb8
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] Call Trace:
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015dcb8>] ?
xfs_ail_min_lsn+0xd/0x2b [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015a42c>] ?
xlog_assign_tail_lsn+0x11/0x26 [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015a48f>] ?
xlog_state_release_iclog+0x4e/0x8f [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015af54>] ?
_xfs_log_force+0xe7/0x1ae [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015b026>] ?
xfs_log_force+0xb/0x2c [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa01185d1>] ?
xfs_buf_trylock+0x41/0x80 [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015c715>] ?
xfs_buf_item_trylock+0x22/0x73 [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015df39>] ?
xfsaild+0x197/0x46b [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015dda2>] ?
xfs_trans_ail_cursor_first+0x79/0x79 [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffff8105f48d>] ?
kthread+0x76/0x7e
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffff81355cb4>] ?
kernel_thread_helper+0x4/0x10
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffff8105f417>] ?
kthread_worker_fn+0x139/0x139
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffff81355cb0>] ?
gs_change+0x13/0x13
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] Code: 05 e8 8b 2c 14 00 c3
f0 81 2f 00 00 10 00 74 05 e8 5c 2c 14 00 c3 b8 00 00 01 00 f0 0f c1 07 89 c2
c1 ea 10 66 39 d0 74 07 f3 90 <66> 8b 07 eb f4 c3 8b 17 31 c0 89 d1 c1 e9 10 66
39 ca 75 14 8d
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] Call Trace:
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015dcb8>] ?
xfs_ail_min_lsn+0xd/0x2b [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015a42c>] ?
xlog_assign_tail_lsn+0x11/0x26 [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015a48f>] ?
xlog_state_release_iclog+0x4e/0x8f [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015af54>] ?
_xfs_log_force+0xe7/0x1ae [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015b026>] ?
xfs_log_force+0xb/0x2c [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa01185d1>] ?
xfs_buf_trylock+0x41/0x80 [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015c715>] ?
xfs_buf_item_trylock+0x22/0x73 [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015df39>] ?
xfsaild+0x197/0x46b [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffffa015dda2>] ?
xfs_trans_ail_cursor_first+0x79/0x79 [xfs]
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffff8105f48d>] ?
kthread+0x76/0x7e
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffff81355cb4>] ?
kernel_thread_helper+0x4/0x10
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffff8105f417>] ?
kthread_worker_fn+0x139/0x139
2013-11-03 12:14:48 hd4dnf01 kernel: [24596.044012] [<ffffffff81355cb0>] ?
gs_change+0x13/0x13
