Hi all,
Chris Cappuccio kindly asked me if I can reproduce his PF NAT problem in
lab.
His mail:
On my NAT cluster I recently switched from nat-to source-hash $key to
nat-to round-robin and started getting hangs. The boxes would hang where
the network would stop responding and one core would be at 100% with
softnet.
Commands at the console would hang like ifconfig or even reboot. I'm
curious if you might be able to reproduce this in your own testing. It
seems to take around 24 hours in my case but I also have pfsync and
pflow turned on.
I've manage to reproduce his problem and pf conf with which I can
trigger hang is
set skip on { lo ix2 }
set limit states 5000000
match out on ix1 nat-to 49/27 round-robin
#match out on ix1 nat-to 49/27
block
pass
I'm sending traffic from host connected to ix0 to host connected to ix1
and that host is default gateway.
Traffic is 100 Kpps (very low) of UDP from random 16/16 port 9 to random
48/28 port 9. And I'm sniffing traffic on linux port connected to ix1.
As box behaves exactly as Chris described.
vmstat, top and ddb output are inline and in attachment.
After 10 sec of traffic box stops to do NAT or forward traffic and at
that point I'm immediately stopping traffic.
immediately after traffic is stopped
r620-1# vmstat -m | egrep "Name|pf"
Name Size Requests Fail InUse Pgreq Pgrel Npage Hiwat Minpg
Maxpg Idle
pfrule 1360 3 0 3 1 0 1 1 0
8 0
pfstate 336 461459 0 461398 38450 0 38450 38450 0
8 0
pfstkey 120 692184 0 692097 20973 0 20973 20973 0
8 0
pfstitem 24 692184 0 692097 4170 0 4170 4170 0
8 0
pfruleitem 16 230726 0 230700 927 0 927 927 0
8 0
pfosfpen 112 714 0 714 21 0 21 21 0
8 0
pfosfp 40 714 0 423 5 0 5 5 0
8 0
after 10 minutes
r620-1# vmstat -m | egrep "Name|pf"
Name Size Requests Fail InUse Pgreq Pgrel Npage Hiwat Minpg
Maxpg Idle
pfrule 1360 3 0 3 1 0 1 1 0
8 0
pfstate 336 461459 0 461398 38450 0 38450 38450 0
8 0
pfstkey 120 692184 0 692097 20973 0 20973 20973 0
8 0
pfstitem 24 692184 0 692097 4170 0 4170 4170 0
8 0
pfruleitem 16 230726 0 230700 927 0 927 927 0
8 0
pfosfpen 112 714 0 714 21 0 21 21 0
8 0
pfosfp 40 714 0 423 5 0 5 5 0
8 0
It seems that pf states are never cleared and what I can see with
tcpdump on host connected to ix1 is that pf nat only to 49.0.0.0.
immediately after traffic is stopped
PID TID PRI NICE SIZE RES STATE WAIT TIME CPU COMMAND
43797 410290 54 0 0K 900K onproc/3 - 0:03 91.21% softnet
40810 512893 10 0 0K 900K idle pf_lock 0:04 0.88% softnet
82004 472857 10 0 0K 900K idle pf_lock 0:03 0.68% softnet
7921 447270 10 0 0K 900K idle netlock 0:02 0.24% softnet
after 10 minutes
PID TID PRI NICE SIZE RES STATE WAIT TIME CPU COMMAND
43797 410290 64 0 0K 900K onproc/3 - 0:03 99.02% softnet
17097 135479 -22 0 0K 900K sleep/5 - 14:38 0.00% idle5
8526 296669 28 0 0K 900K onproc/0 - 14:35 0.00% idle0
66780 349165 28 0 0K 900K onproc/4 - 14:34 0.00% idle4
26781 248132 28 0 0K 900K onproc/1 - 14:33 0.00% idle1
21078 476731 28 0 0K 900K onproc/2 - 14:04 0.00% idle2
39533 504239 -22 0 0K 900K sleep/3 - 11:47 0.00% idle3
40810 512893 10 0 0K 900K idle pf_lock 0:04 0.00% softnet
82004 472857 10 0 0K 900K idle pf_lock 0:03 0.00% softnet
7921 447270 10 0 0K 900K idle netlock 0:02 0.00% softnet
at this point if one wants to do ifconifg or pfctl -vsi or some other
network command, that command hangs and box needs to be rebooted from
idrac or you can drop to ddb :)
r620-1# Stopped at db_enter+0x10: popq %rbp
ddb{0}> trace
db_enter() at db_enter+0x10
comintr(ffff800000082000) at comintr+0x2de
intr_handler(ffff800022d4d620,ffff80000007a080) at intr_handler+0x6e
Xintr_ioapic_edge16_untramp() at Xintr_ioapic_edge16_untramp+0x18f
acpicpu_idle() at acpicpu_idle+0x203
sched_idle(ffffffff822a4ff0) at sched_idle+0x280
end trace frame: 0x0, count: -6
ddb{0}>
ddb{0}> show reg
rdi 0x2f8
rsi 0
rbp 0xffff800022d4d550
rbx 0x82252bf9 __kernel_virt_to_phys+0x2252bf9
rdx 0x2f8
rcx 0x286
rax 0xffffffff82252b00 kstat_pv_tree_RBT_INFO+0x10
r8 0xffffffff82364040 w_locklistdata+0x330
r9 0xffff800022d4d770
r10 0
r11 0x8119b24451f54eee
r12 0xffff800000170000
r13 0xffff800000086158
r14 0xffff800000082000
r15 0xffff80000002ed00
rip 0xffffffff8145ceb0 db_enter+0x10
cs 0x8
rflags 0x286
rsp 0xffff800022d4d550
ss 0x10
db_enter+0x10: popq %rbp
ddb{0}>
ddb{0}> show locks
exclusive kernel_lock &kernel_lock r = 0 (0xffffffff8247bc08)
#0 witness_lock+0x311
#1 intr_handler+0x44
#2 Xintr_ioapic_edge16_untramp+0x18f
#3 acpicpu_idle+0x203
#4 sched_idle+0x280
#5 proc_trampoline+0x1c
ddb{0}>
ddb{0}> show all locks
Process 75647 (sensors) thread 0xffff8000ffffe000 (500594)
exclusive rwlock sensor r = 0 (0xffff8000000314a0)
#0 witness_lock+0x311
#1 sensor_task_work+0x26
#2 taskq_thread+0x11a
#3 proc_trampoline+0x1c
shared rwlock sensors r = 0 (0xffff800000031b70)
#0 witness_lock+0x311
#1 taskq_thread+0x10d
#2 proc_trampoline+0x1c
Process 43797 (softnet) thread 0xffff8000ffffe540 (310290)
exclusive rwlock pf_lock r = 0 (0xffffffff822b0ea8)
#0 witness_lock+0x311
#1 rw_enter+0x292
#2 pf_test+0x11fc
#3 ip_output+0x6b7
#4 ip_forward+0x2da
#5 ip_input_if+0x353
#6 ipv4_input+0x39
#7 ether_input+0x3b1
#8 if_input_process+0x6f
#9 ifiq_process+0x69
#10 taskq_thread+0x11a
#11 proc_trampoline+0x1c
shared rwlock netlock r = 0 (0xffffffff822dffa0)
#0 witness_lock+0x311
#1 if_input_process+0x43
#2 ifiq_process+0x69
#3 taskq_thread+0x11a
#4 proc_trampoline+0x1c
shared rwlock softnet r = 0 (0xffff800000031370)
#0 witness_lock+0x311
#1 taskq_thread+0x10d
#2 proc_trampoline+0x1c
Process 40810 (softnet) thread 0xffff8000ffffea80 (412893)
shared rwlock netlock r = 0 (0xffffffff822dffa0)
#0 witness_lock+0x311
#1 if_input_process+0x43
#2 ifiq_process+0x69
#3 taskq_thread+0x11a
#4 proc_trampoline+0x1c
shared rwlock softnet r = 0 (0xffff800000031270)
#0 witness_lock+0x311
#1 taskq_thread+0x10d
#2 proc_trampoline+0x1c
Process 82004 (softnet) thread 0xffff8000ffffed20 (372857)
shared rwlock netlock r = 0 (0xffffffff822dffa0)
#0 witness_lock+0x311
#1 if_input_process+0x43
#2 ifiq_process+0x69
#3 taskq_thread+0x11a
#4 proc_trampoline+0x1c
shared rwlock softnet r = 0 (0xffff800000031170)
#0 witness_lock+0x311
#1 taskq_thread+0x10d
#2 proc_trampoline+0x1c
Process 7921 (softnet) thread 0xffff8000ffffefc0 (347270)
shared rwlock softnet r = 0 (0xffff800000031070)
#0 witness_lock+0x311
#1 taskq_thread+0x10d
#2 proc_trampoline+0x1c
Process 96824 (systq) thread 0xffff8000fffff500 (303098)
shared rwlock systq r = 0 (0xffffffff822a8cf0)
#0 witness_lock+0x311
#1 taskq_thread+0x10d
#2 proc_trampoline+0x1c
Process 31537 (softclock) thread 0xffff8000fffff7a0 (397164)
shared rwlock timeout r = 0 (0xffffffff822ab0c8)
#0 witness_lock+0x311
#1 timeout_run+0x88
#2 softclock_thread+0x11d
#3 proc_trampoline+0x1c
Process 8526 (idle0) thread 0xffff8000fffffa40 (196669)
exclusive kernel_lock &kernel_lock r = 0 (0xffffffff8247bc08)
#0 witness_lock+0x311
#1 intr_handler+0x44
#2 Xintr_ioapic_edge16_untramp+0x18f
#3 acpicpu_idle+0x203
#4 sched_idle+0x280
#5 proc_trampoline+0x1c
ddb{0}>
ddb{0}> ps
PID TID PPID UID S FLAGS WAIT COMMAND
89019 78559 41112 83 3 0x1100012 netlock ntpd
12465 409372 41112 83 3 0x1100012 netlock ntpd
16530 46288 1 0 3 0x100083 ttyin ksh
51679 258849 1 0 3 0x100098 kqread cron
32638 230713 26219 95 3 0x1100092 kqread smtpd
11424 259708 26219 103 3 0x1100092 kqread smtpd
31704 480673 26219 95 3 0x1100092 kqread smtpd
63399 221016 26219 95 3 0x100092 kqread smtpd
90229 10675 26219 95 3 0x1100092 kqread smtpd
96251 305221 26219 95 3 0x1100092 kqread smtpd
26219 309011 1 0 3 0x100080 kqread smtpd
34920 497035 1 0 3 0x88 kqread sshd
41112 27008 1 0 3 0x100080 kqread ntpd
75762 122344 8428 83 3 0x100012 netlock ntpd
8428 41188 1 83 3 0x1100092 kqread ntpd
14240 470123 38180 73 3 0x1100090 kqread syslogd
38180 41265 1 0 3 0x100082 netio syslogd
93299 71436 0 0 3 0x14200 bored smr
43677 56247 0 0 3 0x14200 pgzero zerothread
47260 300285 0 0 3 0x14200 aiodoned aiodoned
17531 110382 0 0 3 0x14200 syncer update
99223 387898 0 0 3 0x14200 cleaner cleaner
13968 53355 0 0 3 0x14200 reaper reaper
58909 457909 0 0 3 0x14200 pgdaemon pagedaemon
32859 117108 0 0 3 0x14200 usbtsk usbtask
37632 434410 0 0 3 0x14200 usbatsk usbatsk
76190 421706 0 0 3 0x40014200 acpi0 acpi0
17097 35479 0 0 7 0x40014200 idle5
66780 249165 0 0 7 0x40014200 idle4
39533 404239 0 0 3 0x40014200 idle3
21078 376731 0 0 7 0x40014200 idle2
26781 148132 0 0 7 0x40014200 idle1
75647 500594 0 0 2 0x40014200 sensors
43797 310290 0 0 7 0x14200 softnet
40810 412893 0 0 3 0x14200 pf_lock softnet
82004 372857 0 0 3 0x14200 pf_lock softnet
7921 347270 0 0 3 0x14200 netlock softnet
91193 248353 0 0 3 0x14200 bored systqmp
96824 303098 0 0 3 0x14200 netlock systq
31537 397164 0 0 3 0x40014200 netlock softclock
* 8526 196669 0 0 7 0x40014200 idle0
1 230059 0 0 3 0x82 wait init
0 0 -1 0 3 0x10200 scheduler swapper
ddb{0}>
ddb{0}> ps /o
TID PID UID PRFLAGS PFLAGS CPU COMMAND
310290 43797 0 0x14000 0x200 3 softnet
ddb{0}>
ddb{0}> trace /t 0t310290
end trace frame: 0x0, count: -1
ddb{0}> trace /t 0t412893
sleep_finish(ffff800022d71040,1) at sleep_finish+0xfe
rw_enter(ffffffff822b0e98,1) at rw_enter+0x232
pf_test(2,3,ffff80000009b048,ffff800022d71318) at pf_test+0x11fc
ip_output(fffffd80a4363700,0,ffff800022d714a8,1,0,0,e11895f503ebac2b) at
ip_output+0x6b7
ip_forward(fffffd80a4363700,ffff800000095048,fffffd83b4550a10,0) at
ip_forward+0x2da
ip_input_if(ffff800022d715e8,ffff800022d715f4,4,0,ffff800000095048) at
ip_input_if+0x353
ipv4_input(ffff800000095048,fffffd80a4363700) at ipv4_input+0x39
ether_input(ffff800000095048,fffffd80a4363700) at ether_input+0x3b1
if_input_process(ffff800000095048,ffff800022d716d8) at if_input_process+0x6f
ifiq_process(ffff800000099900) at ifiq_process+0x69
taskq_thread(ffff800000031200) at taskq_thread+0x11a
end trace frame: 0x0, count: -11
ddb{0}> trace /t 0t372857
sleep_finish(ffff800022d6aef0,1) at sleep_finish+0xfe
rw_enter(ffffffff822b0e98,1) at rw_enter+0x232
pf_test(2,1,ffff800000095048,ffff800022d6b1d8) at pf_test+0x11fc
ip_input_if(ffff800022d6b1d8,ffff800022d6b1e4,4,0,ffff800000095048) at
ip_input_if+0xcd
ipv4_input(ffff800000095048,fffffd80a3aba400) at ipv4_input+0x39
ether_input(ffff800000095048,fffffd80a3aba400) at ether_input+0x3b1
if_input_process(ffff800000095048,ffff800022d6b2c8) at if_input_process+0x6f
ifiq_process(ffff800000099800) at ifiq_process+0x69
taskq_thread(ffff800000031100) at taskq_thread+0x11a
end trace frame: 0x0, count: -9
ddb{0}> trace /t 0t347270
sleep_finish(ffff800022d65cf0,1) at sleep_finish+0xfe
rw_enter(ffffffff822dff90,1) at rw_enter+0x232
if_netisr(0) at if_netisr+0x16
taskq_thread(ffff800000031000) at taskq_thread+0x11a
end trace frame: 0x0, count: -4
ddb{0}> trace /t 0t248353
sleep_finish(ffff800022d5eed0,1) at sleep_finish+0xfe
msleep(ffffffff822a8d10,ffffffff822a8d28,20,ffffffff81f67c51,0) at
msleep+0xc7
taskq_next_work(ffffffff822a8d10,ffff800022d5ef98) at taskq_next_work+0x61
taskq_thread(ffffffff822a8d10) at taskq_thread+0xfb
end trace frame: 0x0, count: -4
ddb{0}> trace /t 0t303098
sleep_finish(ffff800022d59d60,1) at sleep_finish+0xfe
rw_enter(ffffffff822dff90,1) at rw_enter+0x232
pf_purge(ffffffff822f1010) at pf_purge+0x34
taskq_thread(ffffffff822a8c80) at taskq_thread+0x11a
end trace frame: 0x0, count: -4
ddb{0}> trace /t 0t397164
sleep_finish(ffff800022d53a90,1) at sleep_finish+0xfe
rw_enter(ffffffff822dff90,1) at rw_enter+0x232
igmp_fasttimo() at igmp_fasttimo+0x13
pffasttimo(ffffffff824979b8) at pffasttimo+0xc7
timeout_run(ffffffff824979b8) at timeout_run+0x93
softclock_thread(ffff8000fffff7a0) at softclock_thread+0x11d
end trace frame: 0x0, count: -6
ddb{0}> trace /t 0t196669
sched_idle(ffffffff822a4ff0) at sched_idle+0x280
end trace frame: 0x0, count: -1
ddb{0}>
ddb{0}> trace /t 0t500594
sched_peg_curproc(ffff80002251bff0) at sched_peg_curproc+0x65
cpu_hz_update_sensor(ffff80002251bff0) at cpu_hz_update_sensor+0x1d
sensor_task_work(ffff800000031400) at sensor_task_work+0x44
taskq_thread(ffff800000031b00) at taskq_thread+0x11a
end trace frame: 0x0, count: -4
ddb{0}>immediately after traffic is stopped
r620-1# vmstat -m | egrep "Name|pf"
Name Size Requests Fail InUse Pgreq Pgrel Npage Hiwat Minpg Maxpg Idle
pfrule 1360 3 0 3 1 0 1 1 0 8 0
pfstate 336 461459 0 461398 38450 0 38450 38450 0 8 0
pfstkey 120 692184 0 692097 20973 0 20973 20973 0 8 0
pfstitem 24 692184 0 692097 4170 0 4170 4170 0 8 0
pfruleitem 16 230726 0 230700 927 0 927 927 0 8 0
pfosfpen 112 714 0 714 21 0 21 21 0 8 0
pfosfp 40 714 0 423 5 0 5 5 0 8 0
after 10 minutes
r620-1# vmstat -m | egrep "Name|pf"
Name Size Requests Fail InUse Pgreq Pgrel Npage Hiwat Minpg Maxpg Idle
pfrule 1360 3 0 3 1 0 1 1 0 8 0
pfstate 336 461459 0 461398 38450 0 38450 38450 0 8 0
pfstkey 120 692184 0 692097 20973 0 20973 20973 0 8 0
pfstitem 24 692184 0 692097 4170 0 4170 4170 0 8 0
pfruleitem 16 230726 0 230700 927 0 927 927 0 8 0
pfosfpen 112 714 0 714 21 0 21 21 0 8 0
pfosfp 40 714 0 423 5 0 5 5 0 8 0
It seems that pf states are never cleared and what I can see with tcpdump on
host connected to ix1 is that pf nat only to 49.0.0.0.
immediately after traffic is stopped
PID TID PRI NICE SIZE RES STATE WAIT TIME CPU COMMAND
43797 410290 54 0 0K 900K onproc/3 - 0:03 91.21% softnet
40810 512893 10 0 0K 900K idle pf_lock 0:04 0.88% softnet
82004 472857 10 0 0K 900K idle pf_lock 0:03 0.68% softnet
7921 447270 10 0 0K 900K idle netlock 0:02 0.24% softnet
after 10 minutes
PID TID PRI NICE SIZE RES STATE WAIT TIME CPU COMMAND
43797 410290 64 0 0K 900K onproc/3 - 0:03 99.02% softnet
17097 135479 -22 0 0K 900K sleep/5 - 14:38 0.00% idle5
8526 296669 28 0 0K 900K onproc/0 - 14:35 0.00% idle0
66780 349165 28 0 0K 900K onproc/4 - 14:34 0.00% idle4
26781 248132 28 0 0K 900K onproc/1 - 14:33 0.00% idle1
21078 476731 28 0 0K 900K onproc/2 - 14:04 0.00% idle2
39533 504239 -22 0 0K 900K sleep/3 - 11:47 0.00% idle3
40810 512893 10 0 0K 900K idle pf_lock 0:04 0.00% softnet
82004 472857 10 0 0K 900K idle pf_lock 0:03 0.00% softnet
7921 447270 10 0 0K 900K idle netlock 0:02 0.00% softnet
at this point if one wants to do ifconifg or pfctl -vsi or some other network
command, that command hangs and box needs to be rebooted from idrac or you can
drop to ddb :)
r620-1# Stopped at db_enter+0x10: popq %rbp
ddb{0}> trace
db_enter() at db_enter+0x10
comintr(ffff800000082000) at comintr+0x2de
intr_handler(ffff800022d4d620,ffff80000007a080) at intr_handler+0x6e
Xintr_ioapic_edge16_untramp() at Xintr_ioapic_edge16_untramp+0x18f
acpicpu_idle() at acpicpu_idle+0x203
sched_idle(ffffffff822a4ff0) at sched_idle+0x280
end trace frame: 0x0, count: -6
ddb{0}>
ddb{0}> show reg
rdi 0x2f8
rsi 0
rbp 0xffff800022d4d550
rbx 0x82252bf9 __kernel_virt_to_phys+0x2252bf9
rdx 0x2f8
rcx 0x286
rax 0xffffffff82252b00 kstat_pv_tree_RBT_INFO+0x10
r8 0xffffffff82364040 w_locklistdata+0x330
r9 0xffff800022d4d770
r10 0
r11 0x8119b24451f54eee
r12 0xffff800000170000
r13 0xffff800000086158
r14 0xffff800000082000
r15 0xffff80000002ed00
rip 0xffffffff8145ceb0 db_enter+0x10
cs 0x8
rflags 0x286
rsp 0xffff800022d4d550
ss 0x10
db_enter+0x10: popq %rbp
ddb{0}>
ddb{0}> show locks
exclusive kernel_lock &kernel_lock r = 0 (0xffffffff8247bc08)
#0 witness_lock+0x311
#1 intr_handler+0x44
#2 Xintr_ioapic_edge16_untramp+0x18f
#3 acpicpu_idle+0x203
#4 sched_idle+0x280
#5 proc_trampoline+0x1c
ddb{0}>
ddb{0}> show all locks
Process 75647 (sensors) thread 0xffff8000ffffe000 (500594)
exclusive rwlock sensor r = 0 (0xffff8000000314a0)
#0 witness_lock+0x311
#1 sensor_task_work+0x26
#2 taskq_thread+0x11a
#3 proc_trampoline+0x1c
shared rwlock sensors r = 0 (0xffff800000031b70)
#0 witness_lock+0x311
#1 taskq_thread+0x10d
#2 proc_trampoline+0x1c
Process 43797 (softnet) thread 0xffff8000ffffe540 (310290)
exclusive rwlock pf_lock r = 0 (0xffffffff822b0ea8)
#0 witness_lock+0x311
#1 rw_enter+0x292
#2 pf_test+0x11fc
#3 ip_output+0x6b7
#4 ip_forward+0x2da
#5 ip_input_if+0x353
#6 ipv4_input+0x39
#7 ether_input+0x3b1
#8 if_input_process+0x6f
#9 ifiq_process+0x69
#10 taskq_thread+0x11a
#11 proc_trampoline+0x1c
shared rwlock netlock r = 0 (0xffffffff822dffa0)
#0 witness_lock+0x311
#1 if_input_process+0x43
#2 ifiq_process+0x69
#3 taskq_thread+0x11a
#4 proc_trampoline+0x1c
shared rwlock softnet r = 0 (0xffff800000031370)
#0 witness_lock+0x311
#1 taskq_thread+0x10d
#2 proc_trampoline+0x1c
Process 40810 (softnet) thread 0xffff8000ffffea80 (412893)
shared rwlock netlock r = 0 (0xffffffff822dffa0)
#0 witness_lock+0x311
#1 if_input_process+0x43
#2 ifiq_process+0x69
#3 taskq_thread+0x11a
#4 proc_trampoline+0x1c
shared rwlock softnet r = 0 (0xffff800000031270)
#0 witness_lock+0x311
#1 taskq_thread+0x10d
#2 proc_trampoline+0x1c
Process 82004 (softnet) thread 0xffff8000ffffed20 (372857)
shared rwlock netlock r = 0 (0xffffffff822dffa0)
#0 witness_lock+0x311
#1 if_input_process+0x43
#2 ifiq_process+0x69
#3 taskq_thread+0x11a
#4 proc_trampoline+0x1c
shared rwlock softnet r = 0 (0xffff800000031170)
#0 witness_lock+0x311
#1 taskq_thread+0x10d
#2 proc_trampoline+0x1c
Process 7921 (softnet) thread 0xffff8000ffffefc0 (347270)
shared rwlock softnet r = 0 (0xffff800000031070)
#0 witness_lock+0x311
#1 taskq_thread+0x10d
#2 proc_trampoline+0x1c
Process 96824 (systq) thread 0xffff8000fffff500 (303098)
shared rwlock systq r = 0 (0xffffffff822a8cf0)
#0 witness_lock+0x311
#1 taskq_thread+0x10d
#2 proc_trampoline+0x1c
Process 31537 (softclock) thread 0xffff8000fffff7a0 (397164)
shared rwlock timeout r = 0 (0xffffffff822ab0c8)
#0 witness_lock+0x311
#1 timeout_run+0x88
#2 softclock_thread+0x11d
#3 proc_trampoline+0x1c
Process 8526 (idle0) thread 0xffff8000fffffa40 (196669)
exclusive kernel_lock &kernel_lock r = 0 (0xffffffff8247bc08)
#0 witness_lock+0x311
#1 intr_handler+0x44
#2 Xintr_ioapic_edge16_untramp+0x18f
#3 acpicpu_idle+0x203
#4 sched_idle+0x280
#5 proc_trampoline+0x1c
ddb{0}>
ddb{0}> ps
PID TID PPID UID S FLAGS WAIT COMMAND
89019 78559 41112 83 3 0x1100012 netlock ntpd
12465 409372 41112 83 3 0x1100012 netlock ntpd
16530 46288 1 0 3 0x100083 ttyin ksh
51679 258849 1 0 3 0x100098 kqread cron
32638 230713 26219 95 3 0x1100092 kqread smtpd
11424 259708 26219 103 3 0x1100092 kqread smtpd
31704 480673 26219 95 3 0x1100092 kqread smtpd
63399 221016 26219 95 3 0x100092 kqread smtpd
90229 10675 26219 95 3 0x1100092 kqread smtpd
96251 305221 26219 95 3 0x1100092 kqread smtpd
26219 309011 1 0 3 0x100080 kqread smtpd
34920 497035 1 0 3 0x88 kqread sshd
41112 27008 1 0 3 0x100080 kqread ntpd
75762 122344 8428 83 3 0x100012 netlock ntpd
8428 41188 1 83 3 0x1100092 kqread ntpd
14240 470123 38180 73 3 0x1100090 kqread syslogd
38180 41265 1 0 3 0x100082 netio syslogd
93299 71436 0 0 3 0x14200 bored smr
43677 56247 0 0 3 0x14200 pgzero zerothread
47260 300285 0 0 3 0x14200 aiodoned aiodoned
17531 110382 0 0 3 0x14200 syncer update
99223 387898 0 0 3 0x14200 cleaner cleaner
13968 53355 0 0 3 0x14200 reaper reaper
58909 457909 0 0 3 0x14200 pgdaemon pagedaemon
32859 117108 0 0 3 0x14200 usbtsk usbtask
37632 434410 0 0 3 0x14200 usbatsk usbatsk
76190 421706 0 0 3 0x40014200 acpi0 acpi0
17097 35479 0 0 7 0x40014200 idle5
66780 249165 0 0 7 0x40014200 idle4
39533 404239 0 0 3 0x40014200 idle3
21078 376731 0 0 7 0x40014200 idle2
26781 148132 0 0 7 0x40014200 idle1
75647 500594 0 0 2 0x40014200 sensors
43797 310290 0 0 7 0x14200 softnet
40810 412893 0 0 3 0x14200 pf_lock softnet
82004 372857 0 0 3 0x14200 pf_lock softnet
7921 347270 0 0 3 0x14200 netlock softnet
91193 248353 0 0 3 0x14200 bored systqmp
96824 303098 0 0 3 0x14200 netlock systq
31537 397164 0 0 3 0x40014200 netlock softclock
* 8526 196669 0 0 7 0x40014200 idle0
1 230059 0 0 3 0x82 wait init
0 0 -1 0 3 0x10200 scheduler swapper
ddb{0}>
ddb{0}> ps /o
TID PID UID PRFLAGS PFLAGS CPU COMMAND
310290 43797 0 0x14000 0x200 3 softnet
ddb{0}>
ddb{0}> trace /t 0t310290
end trace frame: 0x0, count: -1
ddb{0}> trace /t 0t412893
sleep_finish(ffff800022d71040,1) at sleep_finish+0xfe
rw_enter(ffffffff822b0e98,1) at rw_enter+0x232
pf_test(2,3,ffff80000009b048,ffff800022d71318) at pf_test+0x11fc
ip_output(fffffd80a4363700,0,ffff800022d714a8,1,0,0,e11895f503ebac2b) at
ip_output+0x6b7
ip_forward(fffffd80a4363700,ffff800000095048,fffffd83b4550a10,0) at
ip_forward+0x2da
ip_input_if(ffff800022d715e8,ffff800022d715f4,4,0,ffff800000095048) at
ip_input_if+0x353
ipv4_input(ffff800000095048,fffffd80a4363700) at ipv4_input+0x39
ether_input(ffff800000095048,fffffd80a4363700) at ether_input+0x3b1
if_input_process(ffff800000095048,ffff800022d716d8) at if_input_process+0x6f
ifiq_process(ffff800000099900) at ifiq_process+0x69
taskq_thread(ffff800000031200) at taskq_thread+0x11a
end trace frame: 0x0, count: -11
ddb{0}> trace /t 0t372857
sleep_finish(ffff800022d6aef0,1) at sleep_finish+0xfe
rw_enter(ffffffff822b0e98,1) at rw_enter+0x232
pf_test(2,1,ffff800000095048,ffff800022d6b1d8) at pf_test+0x11fc
ip_input_if(ffff800022d6b1d8,ffff800022d6b1e4,4,0,ffff800000095048) at
ip_input_if+0xcd
ipv4_input(ffff800000095048,fffffd80a3aba400) at ipv4_input+0x39
ether_input(ffff800000095048,fffffd80a3aba400) at ether_input+0x3b1
if_input_process(ffff800000095048,ffff800022d6b2c8) at if_input_process+0x6f
ifiq_process(ffff800000099800) at ifiq_process+0x69
taskq_thread(ffff800000031100) at taskq_thread+0x11a
end trace frame: 0x0, count: -9
ddb{0}> trace /t 0t347270
sleep_finish(ffff800022d65cf0,1) at sleep_finish+0xfe
rw_enter(ffffffff822dff90,1) at rw_enter+0x232
if_netisr(0) at if_netisr+0x16
taskq_thread(ffff800000031000) at taskq_thread+0x11a
end trace frame: 0x0, count: -4
ddb{0}> trace /t 0t248353
sleep_finish(ffff800022d5eed0,1) at sleep_finish+0xfe
msleep(ffffffff822a8d10,ffffffff822a8d28,20,ffffffff81f67c51,0) at msleep+0xc7
taskq_next_work(ffffffff822a8d10,ffff800022d5ef98) at taskq_next_work+0x61
taskq_thread(ffffffff822a8d10) at taskq_thread+0xfb
end trace frame: 0x0, count: -4
ddb{0}> trace /t 0t303098
sleep_finish(ffff800022d59d60,1) at sleep_finish+0xfe
rw_enter(ffffffff822dff90,1) at rw_enter+0x232
pf_purge(ffffffff822f1010) at pf_purge+0x34
taskq_thread(ffffffff822a8c80) at taskq_thread+0x11a
end trace frame: 0x0, count: -4
ddb{0}> trace /t 0t397164
sleep_finish(ffff800022d53a90,1) at sleep_finish+0xfe
rw_enter(ffffffff822dff90,1) at rw_enter+0x232
igmp_fasttimo() at igmp_fasttimo+0x13
pffasttimo(ffffffff824979b8) at pffasttimo+0xc7
timeout_run(ffffffff824979b8) at timeout_run+0x93
softclock_thread(ffff8000fffff7a0) at softclock_thread+0x11d
end trace frame: 0x0, count: -6
ddb{0}> trace /t 0t196669
sched_idle(ffffffff822a4ff0) at sched_idle+0x280
end trace frame: 0x0, count: -1
ddb{0}>
ddb{0}> trace /t 0t500594
sched_peg_curproc(ffff80002251bff0) at sched_peg_curproc+0x65
cpu_hz_update_sensor(ffff80002251bff0) at cpu_hz_update_sensor+0x1d
sensor_task_work(ffff800000031400) at sensor_task_work+0x44
taskq_thread(ffff800000031b00) at taskq_thread+0x11a
end trace frame: 0x0, count: -4
ddb{0}>
