Markus Gebert
2012-Nov-13 18:30 UTC
thread taskq / unp_gc() using 100% cpu and stalling unix socket IPC
Hi there
We have a pair of servers running FreeBSD 9.1-RC3 that act as transparent layer
7 loadbalancer (relayd) and pop/imap proxy (dovecot). Only one of them is active
at a given time, it's a failover setup. From time to time the active one
gets in a state in which the 'thread taskq' thread uses up 100% of one
cpu on its own, like here:
----
PID USERNAME PRI NICE SIZE RES STATE C TIME WCPU COMMAND
0 root 8 0 0K 3968K CPU12 12 9:49 100.00%
kernel{thread taskq}
----
Most of the userland processes get stalled and if the sitation is not resolved,
their network services stop responding alltogether after some time. This affects
relayd and dovecot for sure, but not sshd.
When processes are slow, they often block in states like '*unp_l' or
'pipewr' according to top, and overall cpu time spent in kernel grows by
factors (and system load too). See [0], [1], [2] for top screenshots when things
work badly. Under normal circumstances load is below 5 and systime below 5%.
Load during daytime makes this situation more likely to occur. At the same time
it does _not_ seem to be triggered by any sudden load peaks (e.g. more network
connections etc.), so I guess it's some kind of race condition.
Today I had the chance to get a few ddb traces of the 'thread taskq'
while the problem was occuring. Every few seconds I ran a ddb script and
continued. I got five samples, after that ddb became unresponsive. All of them
show the thread executing in unp_gc() like here:
----
unp_gc() at unp_gc+0x81
taskqueue_run_locked() at taskqueue_run_locked+0x85
taskqueue_thread_loop() at taskqueue_thread_loop+0x46
fork_exit() at fork_exit+0x11f
fork_trampoline() at fork_trampoline+0xe
----
See all samples under [3].
This is consistent with some textdumps and ddb sessions I've done. Also, the
sysctl 'net.local.taskcount' seems to increase at much higher rates when
the problem occurs.
To me it looks like the unix socket GC is triggered way too often and/or running
too long, which uses cpu and worse, causes a lot of contention around the
unp_list_lock which in turn causes delays for all processes relaying on unix
sockets for IPC.
I don't know why the unp_gc() is called so often and what's triggering
this.
Sometimes this condition only lasts for a few seconds and then resolves itself
before the thread taskq reaches 100% cpu usage. Sometimes it will last, render
dovecot/relayd unresponsive and can only be resolved by taking load off the
system (forcefully restart services).
Booting a kernel with INVARIANTS and WITNESS did not bring much more clues. The
system ends up panicing with 'soabort: so_count' after a few minutes of
load, but the trace[4] does not seem related to unix sockets, so that might be
another problem.
System info, boot dmesg and some configs can be found under [5].
I hope somebody can help me debug this further.
Markus
[0]
last pid: 10227; load averages: 18.81, 13.02, 8.09
up 0+18:14:55 13:07:53
136 processes: 4 running, 53 sleeping, 1 waiting, 78 lock
CPU 0: 5.9% user, 0.0% nice, 54.5% system, 3.5% interrupt, 36.1% idle
CPU 1: 5.9% user, 0.0% nice, 56.5% system, 3.1% interrupt, 34.5% idle
CPU 2: 4.3% user, 0.0% nice, 58.8% system, 3.9% interrupt, 32.9% idle
CPU 3: 6.3% user, 0.0% nice, 60.4% system, 2.0% interrupt, 31.4% idle
CPU 4: 3.5% user, 0.0% nice, 59.2% system, 2.7% interrupt, 34.5% idle
CPU 5: 3.9% user, 0.0% nice, 60.0% system, 1.6% interrupt, 34.5% idle
CPU 6: 4.3% user, 0.0% nice, 62.0% system, 1.2% interrupt, 32.5% idle
CPU 7: 8.6% user, 0.0% nice, 56.9% system, 0.8% interrupt, 33.7% idle
CPU 8: 5.1% user, 0.0% nice, 59.1% system, 0.0% interrupt, 35.8% idle
CPU 9: 7.1% user, 0.0% nice, 56.3% system, 0.0% interrupt, 36.6% idle
CPU 10: 4.7% user, 0.0% nice, 61.0% system, 0.0% interrupt, 34.3% idle
CPU 11: 5.5% user, 0.0% nice, 60.8% system, 0.0% interrupt, 33.7% idle
CPU 12: 6.3% user, 0.0% nice, 61.8% system, 0.4% interrupt, 31.5% idle
CPU 13: 8.3% user, 0.0% nice, 57.1% system, 0.0% interrupt, 34.6% idle
CPU 14: 9.1% user, 0.0% nice, 58.3% system, 0.0% interrupt, 32.7% idle
CPU 15: 7.9% user, 0.0% nice, 55.9% system, 0.0% interrupt, 36.2% idle
CPU 16: 13.4% user, 0.0% nice, 52.8% system, 0.0% interrupt, 33.9% idle
CPU 17: 9.8% user, 0.0% nice, 55.3% system, 0.0% interrupt, 34.9% idle
CPU 18: 5.9% user, 0.0% nice, 62.0% system, 0.0% interrupt, 32.2% idle
CPU 19: 5.1% user, 0.0% nice, 62.6% system, 0.0% interrupt, 32.3% idle
CPU 20: 5.5% user, 0.0% nice, 60.8% system, 0.0% interrupt, 33.7% idle
CPU 21: 10.6% user, 0.0% nice, 57.1% system, 0.0% interrupt, 32.3% idle
CPU 22: 5.9% user, 0.0% nice, 58.8% system, 0.0% interrupt, 35.3% idle
CPU 23: 6.3% user, 0.0% nice, 59.6% system, 0.0% interrupt, 34.1% idle
Mem: 3551M Active, 1351M Inact, 2905M Wired, 8K Cache, 7488K Buf, 85G Free
ARC: 1073M Total, 107M MRU, 828M MFU, 784K Anon, 7647K Header, 130M Other
Swap: 8192M Total, 8192M Free
PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
11 root 24 155 ki31 0K 384K CPU23 23 431.4H 847.95% idle
0 root 248 -8 0 0K 3968K - 1 10:24 89.45% kernel
2880 _relayd 1 79 0 69608K 54764K *unp_l 22 18:47 25.68% relayd
2879 _relayd 1 80 0 49128K 34232K *unp_l 6 9:22 25.29% relayd
2881 _relayd 1 79 0 73704K 57092K *unp_l 9 2:54 24.76% relayd
2877 _relayd 1 79 0 2948M 2936M *unp_l 1 24:25 24.27% relayd
2873 root 1 79 0 22584K 4180K *unp_l 23 1:38 23.68% relayd
3017 root 1 79 0 19860K 2316K *unp_l 2 2:58 22.66% log
2878 _relayd 1 79 0 57320K 42428K *unp_l 3 17:27 22.27% relayd
3010 dovenull 1 31 0 67240K 39408K CPU6 6 4:06 22.27%
imap-login
7607 dovecot 1 78 0 58036K 9580K *unp_l 23 1:02 22.27% auth
3009 dovenull 1 78 0 67240K 39756K *unp_l 17 3:06 21.88%
imap-login
3004 dovenull 1 78 0 63144K 36512K *unp_l 8 1:42 21.29%
imap-login
2998 dovenull 1 78 0 67240K 39556K *unp_l 13 2:47 21.09%
imap-login
7619 dovenull 1 43 0 50856K 25264K *unp_l 12 0:53 21.09%
imap-login
3006 dovenull 1 78 0 63144K 38464K *unp_l 15 3:14 20.65%
imap-login
83740 dovenull 1 78 0 59048K 30956K *unp_l 12 1:57 20.65%
imap-login
2993 dovenull 1 47 0 63144K 37984K *unp_l 17 1:39 20.65%
imap-login
3007 dovenull 1 78 0 63144K 38736K *unp_l 21 3:19 20.56%
imap-login
2994 dovenull 1 78 0 67240K 40144K *unp_l 11 3:52 20.46%
imap-login
7679 dovenull 1 78 0 50856K 24804K *unp_l 4 0:54 20.46%
imap-login
7690 dovenull 1 78 0 50856K 25444K *unp_l 17 0:50 20.46%
imap-login
3008 dovenull 1 78 0 67240K 39248K *unp_l 15 3:16 20.36%
imap-login
3001 dovenull 1 78 0 59048K 34072K *unp_l 21 1:45 20.26%
imap-login
84187 dovenull 1 78 0 63144K 38116K *unp_l 4 3:19 20.07%
imap-login
3000 dovenull 1 78 0 63144K 38832K *unp_l 6 3:40 19.97%
imap-login
83594 dovenull 1 78 0 54952K 28620K *unp_l 9 1:39 19.97%
imap-login
2992 dovenull 1 78 0 67240K 39876K *unp_l 0 3:27 19.87%
imap-login
3012 dovenull 1 78 0 63144K 39064K *unp_l 22 3:03 19.78%
imap-login
87238 dovenull 1 77 0 63144K 39028K *unp_l 1 2:45 19.78%
imap-login
87057 dovenull 1 77 0 67240K 39388K *unp_l 3 2:58 19.68%
imap-login
86973 dovenull 1 77 0 63144K 38464K *unp_l 2 2:52 19.68%
imap-login
85175 dovenull 1 77 0 63144K 38832K *unp_l 12 2:57 19.58%
imap-login
7618 dovenull 1 78 0 54952K 26424K *unp_l 2 0:53 19.58%
imap-login
2995 dovenull 1 77 0 67240K 40504K *unp_l 16 3:02 19.48%
imap-login
86151 dovenull 1 77 0 63144K 38484K *unp_l 11 2:53 19.48%
imap-login
83822 dovenull 1 78 0 63144K 36436K *unp_l 9 2:21 19.48%
imap-login
86132 dovenull 1 78 0 63144K 37948K *unp_l 7 2:59 19.38%
imap-login
7689 dovenull 1 78 0 50856K 25064K *unp_l 19 0:55 19.38%
imap-login
84186 dovenull 1 77 0 63144K 38252K *unp_l 18 2:54 19.09%
imap-login
2999 dovenull 1 77 0 63144K 37760K *unp_l 13 2:00 19.09%
imap-login
3011 dovenull 1 36 0 63144K 36624K *unp_l 3 1:48 19.09%
imap-login
2996 dovenull 1 45 0 63144K 38972K *unp_l 7 3:24 18.99%
imap-login
83731 dovenull 1 45 0 54952K 28824K *unp_l 8 1:48 18.80%
imap-login
3002 dovenull 1 36 0 50856K 22748K *unp_l 19 0:55 18.65%
imap-login
25589 dovenull 1 40 0 63144K 37164K *unp_l 4 1:42 18.46%
imap-login
3021 dovecot 1 77 0 23952K 8924K *unp_l 10 2:04 18.36% director
2997 dovenull 1 77 0 63144K 38872K *unp_l 16 3:13 18.26%
imap-login
[1]
last pid: 15656; load averages: 29.20, 16.70, 10.67
up 0+18:43:35 13:36:33
525 processes: 44 running, 426 sleeping, 55 waiting
CPU 0: 1.9% user, 0.0% nice, 67.4% system, 1.5% interrupt, 29.1% idle
CPU 1: 1.9% user, 0.0% nice, 72.8% system, 0.8% interrupt, 24.5% idle
CPU 2: 0.8% user, 0.0% nice, 70.1% system, 0.8% interrupt, 28.4% idle
CPU 3: 1.5% user, 0.0% nice, 70.1% system, 1.9% interrupt, 26.4% idle
CPU 4: 0.0% user, 0.0% nice, 73.6% system, 0.8% interrupt, 25.7% idle
CPU 5: 1.9% user, 0.0% nice, 69.0% system, 0.8% interrupt, 28.4% idle
CPU 6: 0.8% user, 0.0% nice, 69.7% system, 1.5% interrupt, 28.0% idle
CPU 7: 0.0% user, 0.0% nice, 73.2% system, 3.1% interrupt, 23.8% idle
CPU 8: 2.3% user, 0.0% nice, 77.8% system, 0.0% interrupt, 19.9% idle
CPU 9: 2.3% user, 0.0% nice, 74.3% system, 0.0% interrupt, 23.4% idle
CPU 10: 1.1% user, 0.0% nice, 75.1% system, 0.0% interrupt, 23.8% idle
CPU 11: 1.2% user, 0.0% nice, 65.0% system, 0.0% interrupt, 33.8% idle
CPU 12: 0.0% user, 0.0% nice, 77.0% system, 0.0% interrupt, 23.0% idle
CPU 13: 0.8% user, 0.0% nice, 76.2% system, 0.0% interrupt, 23.0% idle
CPU 14: 1.1% user, 0.0% nice, 75.1% system, 0.0% interrupt, 23.8% idle
CPU 15: 0.8% user, 0.0% nice, 75.9% system, 0.0% interrupt, 23.4% idle
CPU 16: 0.8% user, 0.0% nice, 73.6% system, 0.0% interrupt, 25.7% idle
CPU 17: 2.3% user, 0.0% nice, 74.3% system, 0.0% interrupt, 23.4% idle
CPU 18: 1.1% user, 0.0% nice, 70.5% system, 0.0% interrupt, 28.4% idle
CPU 19: 0.8% user, 0.0% nice, 73.6% system, 0.0% interrupt, 25.7% idle
CPU 20: 3.4% user, 0.0% nice, 75.9% system, 0.0% interrupt, 20.7% idle
CPU 21: 1.9% user, 0.0% nice, 76.6% system, 0.0% interrupt, 21.5% idle
CPU 22: 1.9% user, 0.0% nice, 75.5% system, 0.0% interrupt, 22.6% idle
CPU 23: 1.1% user, 0.0% nice, 75.5% system, 0.0% interrupt, 23.4% idle
Mem: 688M Active, 1431M Inact, 3064M Wired, 8K Cache, 7488K Buf, 88G Free
ARC: 1212M Total, 107M MRU, 965M MFU, 1040K Anon, 8010K Header, 131M Other
Swap: 8192M Total, 8192M Free
PID USERNAME PRI NICE SIZE RES STATE C TIME WCPU COMMAND
0 root 8 0 0K 3968K CPU12 12 9:49 100.00%
kernel{thread taskq}
2873 root 84 0 22584K 4180K CPU1 1 2:53 44.58% relayd
2879 _relayd 84 0 49128K 34268K CPU9 1 12:17 43.26% relayd
2877 _relayd 52 0 69608K 54400K kqread 22 30:07 39.45% relayd
2880 _relayd 84 0 65512K 50692K CPU21 21 23:22 39.36% relayd
2878 _relayd 52 0 57320K 42432K kqread 14 21:54 39.16% relayd
2881 _relayd 83 0 49128K 31572K CPU4 4 4:34 38.67% relayd
7607 dovecot 82 0 58036K 10528K CPU16 16 2:31 37.50% auth
3017 root 83 0 19860K 2316K CPU6 6 4:25 36.47% log
3021 dovecot 82 0 23952K 8924K CPU5 5 3:19 34.47% director
11 root 155 ki31 0K 384K CPU11 11 18.4H 32.96% idle{idle:
cpu11}
11 root 155 ki31 0K 384K RUN 4 18.4H 32.86% idle{idle:
cpu4}
11 root 155 ki31 0K 384K RUN 3 18.4H 32.76% idle{idle:
cpu3}
11 root 155 ki31 0K 384K RUN 2 18.4H 32.67% idle{idle:
cpu2}
11 root 155 ki31 0K 384K RUN 9 18.4H 32.57% idle{idle:
cpu9}
11 root 155 ki31 0K 384K RUN 5 18.4H 32.57% idle{idle:
cpu5}
11 root 155 ki31 0K 384K RUN 0 18.4H 32.37% idle{idle:
cpu0}
11 root 155 ki31 0K 384K CPU22 22 18.3H 32.37% idle{idle:
cpu22}
11 root 155 ki31 0K 384K RUN 7 18.4H 32.28% idle{idle:
cpu7}
11 root 155 ki31 0K 384K CPU14 14 18.3H 32.08% idle{idle:
cpu14}
11 root 155 ki31 0K 384K RUN 6 18.4H 31.88% idle{idle:
cpu6}
11 root 155 ki31 0K 384K RUN 1 18.4H 31.79% idle{idle:
cpu1}
11 root 155 ki31 0K 384K RUN 19 18.3H 31.59% idle{idle:
cpu19}
11 root 155 ki31 0K 384K RUN 8 18.4H 30.96% idle{idle:
cpu8}
7619 dovenull 81 0 59048K 32864K CPU20 20 2:01 30.96% imap-login
11 root 155 ki31 0K 384K CPU18 18 18.3H 30.76% idle{idle:
cpu18}
11 root 155 ki31 0K 384K RUN 13 18.3H 30.57% idle{idle:
cpu13}
11 root 155 ki31 0K 384K RUN 12 18.3H 30.47% idle{idle:
cpu12}
11 root 155 ki31 0K 384K RUN 20 18.3H 30.08% idle{idle:
cpu20}
11 root 155 ki31 0K 384K RUN 10 18.4H 29.88% idle{idle:
cpu10}
11 root 155 ki31 0K 384K RUN 23 18.3H 29.79% idle{idle:
cpu23}
11 root 155 ki31 0K 384K RUN 15 18.3H 29.59% idle{idle:
cpu15}
11 root 155 ki31 0K 384K RUN 16 18.3H 29.59% idle{idle:
cpu16}
2968 dovenull 52 0 38568K 12240K pipewr 4 5:24 29.39% pop3-login
11 root 155 ki31 0K 384K RUN 17 18.3H 29.30% idle{idle:
cpu17}
2970 dovenull 52 0 42664K 15968K pipewr 10 7:18 28.66% pop3-login
2983 dovenull 52 0 38568K 11984K pipewr 5 5:03 28.66% pop3-login
2976 dovenull 52 0 42664K 17896K pipewr 23 7:46 28.56% pop3-login
2974 dovenull 52 0 46760K 19156K pipewr 16 7:40 28.47% pop3-login
2969 dovenull 52 0 38568K 13764K pipewr 12 5:13 28.27% pop3-login
2990 dovenull 52 0 42664K 16096K pipewr 0 7:22 28.17% pop3-login
2984 dovenull 52 0 38568K 12796K pipewr 14 5:43 28.08% pop3-login
2988 dovenull 52 0 42664K 16068K pipewr 2 6:42 27.98% pop3-login
11 root 155 ki31 0K 384K RUN 21 18.3H 27.88% idle{idle:
cpu21}
2971 dovenull 52 0 38568K 10724K pipewr 0 2:06 27.88% pop3-login
2989 dovenull 52 0 38568K 12428K pipewr 10 5:21 27.78% pop3-login
2972 dovenull 52 0 42664K 17876K pipewr 5 7:42 27.69% pop3-login
2987 dovenull 52 0 42664K 14992K pipewr 16 5:23 27.69% pop3-login
2981 dovenull 52 0 42664K 16060K pipewr 19 7:32 27.59% pop3-login
[2]
last pid: 38598; load averages: 42.11, 22.97, 11.77
up 0+20:46:40 15:39:38
520 processes: 96 running, 369 sleeping, 55 waiting
CPU: 2.8% user, 0.0% nice, 82.3% system, 0.4% interrupt, 14.5% idle
Mem: 939M Active, 837M Inact, 3787M Wired, 8K Cache, 7488K Buf, 88G Free
ARC: 1884M Total, 108M MRU, 1633M MFU, 914K Anon, 9764K Header, 132M Other
Swap: 8192M Total, 8192M Free
PID USERNAME PRI NICE SIZE RES STATE C TIME WCPU COMMAND
0 root 8 0 0K 3968K CPU20 14 16:09 100.00%
kernel{thread taskq}
2880 _relayd 100 0 65512K 50128K RUN 11 44:06 89.79% relayd
2881 _relayd 100 0 61416K 44116K RUN 10 8:13 89.45% relayd
15779 dovenull 98 0 38568K 13236K RUN 17 3:28 86.28% pop3-login
15771 dovenull 99 0 38568K 12672K RUN 2 5:17 86.08% pop3-login
15761 dovenull 98 0 38568K 13212K RUN 23 5:15 84.77% pop3-login
15768 dovenull 99 0 38568K 13268K RUN 12 5:43 84.18% pop3-login
15775 dovenull 98 0 42664K 14536K RUN 7 4:05 84.08% pop3-login
17610 dovenull 98 0 50856K 26204K RUN 18 2:09 83.50% imap-login
16944 dovenull 98 0 54952K 28332K RUN 20 1:42 83.40% imap-login
15803 dovenull 98 0 67240K 39640K RUN 15 2:48 83.06% imap-login
15800 dovenull 98 0 63144K 38892K RUN 9 3:15 82.86% imap-login
20530 dovenull 98 0 63144K 38136K RUN 4 2:57 82.76% imap-login
12 root -92 - 0K 880K WAIT 0 6:16 82.47% intr{irq274:
ix1:que }
12 root -92 - 0K 880K WAIT 1 6:16 82.37% intr{irq275:
ix1:que }
12 root -92 - 0K 880K WAIT 7 6:05 82.28% intr{irq281:
ix1:que }
12 root -92 - 0K 880K WAIT 2 6:00 82.28% intr{irq276:
ix1:que }
12 root -92 - 0K 880K WAIT 6 5:50 82.28% intr{irq280:
ix1:que }
12 root -60 - 0K 880K WAIT 0 3:20 82.18% intr{swi4:
clock}
12 root -92 - 0K 880K WAIT 4 6:10 82.08% intr{irq278:
ix1:que }
12 root -92 - 0K 880K WAIT 5 5:59 81.98% intr{irq279:
ix1:que }
0 root -92 0 0K 3968K - 23 0:47 81.88% kernel{ix1
que}
0 root -92 0 0K 3968K - 5 0:43 80.18% kernel{ix0
que}
17945 root 95 0 16592K 4056K CPU7 0 0:08 75.10% top
15765 dovenull 77 0 46760K 20468K RUN 2 5:41 19.48% pop3-login
15762 dovenull 78 0 46760K 20708K RUN 20 5:45 19.38% pop3-login
15773 dovenull 78 0 42664K 14928K RUN 4 3:41 19.38% pop3-login
15781 dovenull 77 0 42664K 13136K RUN 9 3:01 18.90% pop3-login
15777 dovenull 77 0 42664K 15840K RUN 1 3:15 18.55% pop3-login
15772 dovenull 77 0 42664K 14484K RUN 0 5:15 18.46% pop3-login
15782 dovenull 77 0 38568K 13368K RUN 6 3:20 17.87% pop3-login
15764 dovenull 77 0 42664K 14816K RUN 20 5:54 17.77% pop3-login
15759 dovenull 77 0 42664K 16616K RUN 4 1:06 17.77% pop3-login
15780 dovenull 76 0 42664K 13684K RUN 22 3:19 12.89% pop3-login
[3]
db:0:kdb.enter.sysctl> run lockinfo
db:1:lockinfo> show locks
No such command
db:1:locks> show alllocks
No such command
db:1:alllocks> show lockedvnods
Locked vnodes
db:0:kdb.enter.sysctl> trace 100058
Tracing pid 0 tid 100058 td 0xfffffe00262fc000
cpustop_handler() at cpustop_handler+0x28
ipi_nmi_handler() at ipi_nmi_handler+0x3d
trap() at trap+0x2ea
nmi_calltrap() at nmi_calltrap+0x8
--- trap 0x13, rip = 0xffffffff809a2a3e, rsp = 0xffffff800039efe0, rbp =
0xffffff975cf4aa10 ---
unp_gc() at unp_gc+0x20e
taskqueue_run_locked() at taskqueue_run_locked+0x85
taskqueue_thread_loop() at taskqueue_thread_loop+0x46
fork_exit() at fork_exit+0x11f
fork_trampoline() at fork_trampoline+0xe
--- trap 0, rip = 0, rsp = 0xffffff975cf4abb0, rbp = 0 ---
db:0:kdb.enter.sysctl> capture off
db:0:kdb.enter.sysctl> run lockinfo
db:1:lockinfo> show locks
No such command
db:1:locks> show alllocks
No such command
db:1:alllocks> show lockedvnods
Locked vnodes
db:0:kdb.enter.sysctl> trace 100058
Tracing pid 0 tid 100058 td 0xfffffe00262fc000
cpustop_handler() at cpustop_handler+0x28
ipi_nmi_handler() at ipi_nmi_handler+0x3d
trap() at trap+0x2ea
nmi_calltrap() at nmi_calltrap+0x8
--- trap 0x13, rip = 0xffffffff809a29a6, rsp = 0xffffff800039efe0, rbp =
0xffffff975cf4aa10 ---
unp_gc() at unp_gc+0x176
taskqueue_run_locked() at taskqueue_run_locked+0x85
taskqueue_thread_loop() at taskqueue_thread_loop+0x46
fork_exit() at fork_exit+0x11f
fork_trampoline() at fork_trampoline+0xe
--- trap 0, rip = 0, rsp = 0xffffff975cf4abb0, rbp = 0 ---
db:0:kdb.enter.sysctl> capture off
db:0:kdb.enter.sysctl> run lockinfo
db:1:lockinfo> show locks
No such command
db:1:locks> show alllocks
No such command
db:1:alllocks> show lockedvnods
Locked vnodes
db:0:kdb.enter.sysctl> trace 100058
Tracing pid 0 tid 100058 td 0xfffffe00262fc000
cpustop_handler() at cpustop_handler+0x28
ipi_nmi_handler() at ipi_nmi_handler+0x3d
trap() at trap+0x2ea
nmi_calltrap() at nmi_calltrap+0x8
--- trap 0x13, rip = 0xffffffff809a2997, rsp = 0xffffff80003a5fe0, rbp =
0xffffff975cf4aa10 ---
unp_gc() at unp_gc+0x167
taskqueue_run_locked() at taskqueue_run_locked+0x85
taskqueue_thread_loop() at taskqueue_thread_loop+0x46
fork_exit() at fork_exit+0x11f
fork_trampoline() at fork_trampoline+0xe
--- trap 0, rip = 0, rsp = 0xffffff975cf4abb0, rbp = 0 ---
db:0:kdb.enter.sysctl> capture off
db:0:kdb.enter.sysctl> run lockinfo
db:1:lockinfo> show locks
No such command
db:1:locks> show alllocks
No such command
db:1:alllocks> show lockedvnods
Locked vnodes
db:0:kdb.enter.sysctl> trace 100058
Tracing pid 0 tid 100058 td 0xfffffe00262fc000
cpustop_handler() at cpustop_handler+0x28
ipi_nmi_handler() at ipi_nmi_handler+0x3d
trap() at trap+0x2ea
nmi_calltrap() at nmi_calltrap+0x8
--- trap 0x13, rip = 0xffffffff809a28b1, rsp = 0xffffff8000374fe0, rbp =
0xffffff975cf4aa10 ---
unp_gc() at unp_gc+0x81
taskqueue_run_locked() at taskqueue_run_locked+0x85
taskqueue_thread_loop() at taskqueue_thread_loop+0x46
fork_exit() at fork_exit+0x11f
fork_trampoline() at fork_trampoline+0xe
--- trap 0, rip = 0, rsp = 0xffffff975cf4abb0, rbp = 0 ---
db:0:kdb.enter.sysctl> capture off
db:0:kdb.enter.sysctl> run lockinfo
db:1:lockinfo> show locks
No such command
db:1:locks> show alllocks
No such command
db:1:alllocks> show lockedvnods
Locked vnodes
db:0:kdb.enter.sysctl> trace 100058
Tracing pid 0 tid 100058 td 0xfffffe00262fc000
cpustop_handler() at cpustop_handler+0x28
ipi_nmi_handler() at ipi_nmi_handler+0x3d
trap() at trap+0x2ea
nmi_calltrap() at nmi_calltrap+0x8
--- trap 0x13, rip = 0xffffffff809a28b1, rsp = 0xffffff80003b3fe0, rbp =
0xffffff975cf4aa10 ---
unp_gc() at unp_gc+0x81
taskqueue_run_locked() at taskqueue_run_locked+0x85
taskqueue_thread_loop() at taskqueue_thread_loop+0x46
fork_exit() at fork_exit+0x11f
fork_trampoline() at fork_trampoline+0xe
--- trap 0, rip = 0, rsp = 0xffffff975cf4abb0, rbp = 0 ---
db:0:kdb.enter.sysctl> capture off
[4]
db:0:lockedvnods> show pcpu
cpuid = 0
dynamic pcpu = 0x800380
curthread = 0xfffffe00264b8000: pid 12 "irq265: ix0:que 0"
curpcb = 0xffffff9a3ea71bc0
fpcurthread = none
idlethread = 0xfffffe00262bc470: tid 100003 "idle: cpu0"
curpmap = 0xffffffff812d5af0
tssp = 0xffffffff814e0960
commontssp = 0xffffffff814e0960
rsp0 = 0xffffff9a3ea71bc0
gs32p = 0xffffffff814deab8
ldt = 0xffffffff814deaf8
tss = 0xffffffff814deae8
spin locks held:
db:0:pcpu> bt
Tracing pid 12 tid 100069 td 0xfffffe00264b8000
kdb_enter() at kdb_enter+0x3b
panic() at panic+0x1d1
soabort() at soabort+0x99
syncache_expand() at syncache_expand+0x306
tcp_input() at tcp_input+0x1033
ip_input() at ip_input+0xbd
netisr_dispatch_src() at netisr_dispatch_src+0x152
ether_demux() at ether_demux+0x17d
ether_nh_input() at ether_nh_input+0x20e
netisr_dispatch_src() at netisr_dispatch_src+0x152
ether_demux() at ether_demux+0x86
ether_nh_input() at ether_nh_input+0x20e
netisr_dispatch_src() at netisr_dispatch_src+0x152
ixgbe_rxeof() at ixgbe_rxeof+0x1b9
ixgbe_msix_que() at ixgbe_msix_que+0x8d
intr_event_execute_handlers() at intr_event_execute_handlers+0x6a
ithread_loop() at ithread_loop+0xb4
fork_exit() at fork_exit+0x135
fork_trampoline() at fork_trampoline+0xe
[5]
FreeBSD XY.hostpoint.net 9.1-RC3 FreeBSD 9.1-RC3 #4 r242695: Wed Nov 7 11:33:17
UTC 2012 root at XY.hostpoint.ch:/usr/obj/usr/src/sys/HOSTPOINT amd64
kernconf:
----
include GENERIC
ident HOSTPOINT
# ipfw
options IPFIREWALL
options IPFIREWALL_VERBOSE
options IPFIREWALL_VERBOSE_LIMIT=5
options IPFIREWALL_DEFAULT_TO_ACCEPT
options IPFIREWALL_FORWARD
options IPDIVERT
# ddb for debugging and textdumps
options KDB # Enable kernel debugger support.
options DDB # Support DDB.
# dtrace
options KDTRACE_HOOKS # all architectures - enable general DTrace
hooks
options DDB_CTF # all architectures - kernel ELF linker
loads CTF data
options KDTRACE_FRAME # amd64-only
makeoptions DEBUG="-g"
makeoptions WITH_CTF=1
----
dmesg boot:
----
Copyright (c) 1992-2012 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 9.1-RC3 #4 r242695: Wed Nov 7 11:33:17 UTC 2012
root at XY.hostpoint.ch:/usr/obj/usr/src/sys/HOSTPOINT amd64
CPU: Intel(R) Xeon(R) CPU E5-2440 0 @ 2.40GHz (2400.05-MHz K8-class CPU)
Origin = "GenuineIntel" Id = 0x206d7 Family = 6 Model = 2d
Stepping = 7
Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
Features2=0x1fbee3ff<SSE3,PCLMULQDQ,DTES64,MON,DS_CPL,VMX,SMX,EST,TM2,SSSE3,CX16,xTPR,PDCM,PCID,DCA,SSE4.1,SSE4.2,x2APIC,POPCNT,TSCDLT,AESNI,XSAVE,OSXSAVE,AVX>
AMD Features=0x2c100800<SYSCALL,NX,Page1GB,RDTSCP,LM>
AMD Features2=0x1<LAHF>
TSC: P-state invariant, performance statistics
real memory = 103079215104 (98304 MB)
avail memory = 99335512064 (94733 MB)
Event timer "LAPIC" quality 600
ACPI APIC Table: <DELL PE_SC3 >
FreeBSD/SMP: Multiprocessor System Detected: 24 CPUs
FreeBSD/SMP: 2 package(s) x 6 core(s) x 2 SMT threads
cpu0 (BSP): APIC ID: 0
cpu1 (AP): APIC ID: 1
cpu2 (AP): APIC ID: 2
cpu3 (AP): APIC ID: 3
cpu4 (AP): APIC ID: 4
cpu5 (AP): APIC ID: 5
cpu6 (AP): APIC ID: 6
cpu7 (AP): APIC ID: 7
cpu8 (AP): APIC ID: 8
cpu9 (AP): APIC ID: 9
cpu10 (AP): APIC ID: 10
cpu11 (AP): APIC ID: 11
cpu12 (AP): APIC ID: 32
cpu13 (AP): APIC ID: 33
cpu14 (AP): APIC ID: 34
cpu15 (AP): APIC ID: 35
cpu16 (AP): APIC ID: 36
cpu17 (AP): APIC ID: 37
cpu18 (AP): APIC ID: 38
cpu19 (AP): APIC ID: 39
cpu20 (AP): APIC ID: 40
cpu21 (AP): APIC ID: 41
cpu22 (AP): APIC ID: 42
cpu23 (AP): APIC ID: 43
Security policy loaded: TrustedBSD MAC/seeotheruids (mac_seeotheruids)
ioapic1: Changing APIC ID to 1
ioapic2: Changing APIC ID to 2
ioapic0 <Version 2.0> irqs 0-23 on motherboard
ioapic1 <Version 2.0> irqs 32-55 on motherboard
ioapic2 <Version 2.0> irqs 64-87 on motherboard
kbd1 at kbdmux0
acpi0: <DELL PE_SC3> on motherboard
acpi0: Power Button (fixed)
cpu0: <ACPI CPU> on acpi0
cpu1: <ACPI CPU> on acpi0
cpu2: <ACPI CPU> on acpi0
cpu3: <ACPI CPU> on acpi0
cpu4: <ACPI CPU> on acpi0
cpu5: <ACPI CPU> on acpi0
cpu6: <ACPI CPU> on acpi0
cpu7: <ACPI CPU> on acpi0
cpu8: <ACPI CPU> on acpi0
cpu9: <ACPI CPU> on acpi0
cpu10: <ACPI CPU> on acpi0
cpu11: <ACPI CPU> on acpi0
cpu12: <ACPI CPU> on acpi0
cpu13: <ACPI CPU> on acpi0
cpu14: <ACPI CPU> on acpi0
cpu15: <ACPI CPU> on acpi0
cpu16: <ACPI CPU> on acpi0
cpu17: <ACPI CPU> on acpi0
cpu18: <ACPI CPU> on acpi0
cpu19: <ACPI CPU> on acpi0
cpu20: <ACPI CPU> on acpi0
cpu21: <ACPI CPU> on acpi0
cpu22: <ACPI CPU> on acpi0
cpu23: <ACPI CPU> on acpi0
atrtc0: <AT realtime clock> port 0x70-0x7f irq 8 on acpi0
Event timer "RTC" frequency 32768 Hz quality 0
attimer0: <AT timer> port 0x40-0x5f irq 0 on acpi0
Timecounter "i8254" frequency 1193182 Hz quality 0
Event timer "i8254" frequency 1193182 Hz quality 100
hpet0: <High Precision Event Timer> iomem 0xfed00000-0xfed003ff on acpi0
Timecounter "HPET" frequency 14318180 Hz quality 950
Event timer "HPET" frequency 14318180 Hz quality 450
Event timer "HPET1" frequency 14318180 Hz quality 440
Event timer "HPET2" frequency 14318180 Hz quality 440
Event timer "HPET3" frequency 14318180 Hz quality 440
Event timer "HPET4" frequency 14318180 Hz quality 440
Event timer "HPET5" frequency 14318180 Hz quality 440
Event timer "HPET6" frequency 14318180 Hz quality 440
Event timer "HPET7" frequency 14318180 Hz quality 440
Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x808-0x80b on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
pcib1: <ACPI PCI-PCI bridge> irq 53 at device 1.0 on pci0
pci1: <ACPI PCI bus> on pcib1
mfi0: <Dell PERC H710 Mini (monolithics)> port 0xfc00-0xfcff mem
0xdcffc000-0xdcffffff,0xdcf80000-0xdcfbffff irq 34 at device 0.0 on pci1
mfi0: Using MSI
mfi0: Megaraid SAS driver Ver 4.23
mfi0: MaxCmd = 3f0 MaxSgl = 46 state = b73c03f0
pcib2: <ACPI PCI-PCI bridge> irq 53 at device 3.0 on pci0
pci8: <ACPI PCI bus> on pcib2
ix0: <Intel(R) PRO/10GbE PCI-Express Network Driver, Version - 2.4.8> mem
0xd9000000-0xd91fffff,0xd95f8000-0xd95fbfff irq 52 at device 0.0 on pci8
ix0: Using MSIX interrupts with 9 vectors
ix0: Ethernet address: a0:36:9f:08:cd:4c
ix0: PCI Express Bus: Speed 5.0Gb/s Width x8
ix1: <Intel(R) PRO/10GbE PCI-Express Network Driver, Version - 2.4.8> mem
0xd9200000-0xd93fffff,0xd95fc000-0xd95fffff irq 48 at device 0.1 on pci8
ix1: Using MSIX interrupts with 9 vectors
ix1: Ethernet address: a0:36:9f:08:cd:4e
ix1: PCI Express Bus: Speed 5.0Gb/s Width x8
pci0: <base peripheral> at device 5.0 (no driver attached)
pci0: <base peripheral> at device 5.2 (no driver attached)
pcib3: <PCI-PCI bridge> irq 16 at device 17.0 on pci0
pci9: <PCI bus> on pcib3
pci0: <simple comms> at device 22.0 (no driver attached)
pci0: <simple comms> at device 22.1 (no driver attached)
ehci0: <EHCI (generic) USB 2.0 controller> mem 0xdf8fd000-0xdf8fd3ff irq
23 at device 26.0 on pci0
usbus0: EHCI version 1.0
usbus0 on ehci0
pcib4: <ACPI PCI-PCI bridge> at device 28.0 on pci0
pci10: <ACPI PCI bus> on pcib4
pcib5: <ACPI PCI-PCI bridge> irq 16 at device 28.4 on pci0
pci2: <ACPI PCI bus> on pcib5
bge0: <Broadcom NetXtreme Gigabit Ethernet, ASIC rev. 0x5720000> mem
0xd96a0000-0xd96affff,0xd96b0000-0xd96bffff,0xd96c0000-0xd96cffff irq 16 at
device 0.0 on pci2
bge0: CHIP ID 0x05720000; ASIC REV 0x5720; CHIP REV 0x57200; PCI-E
bge0: Try again
miibus0: <MII bus> on bge0
brgphy0: <BCM5720C 1000BASE-T media interface> PHY 1 on miibus0
brgphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT,
1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto, auto-flow
bge0: Ethernet address: d4:ae:52:a4:3c:de
bge1: <Broadcom NetXtreme Gigabit Ethernet, ASIC rev. 0x5720000> mem
0xd96d0000-0xd96dffff,0xd96e0000-0xd96effff,0xd96f0000-0xd96fffff irq 17 at
device 0.1 on pci2
bge1: CHIP ID 0x05720000; ASIC REV 0x5720; CHIP REV 0x57200; PCI-E
miibus1: <MII bus> on bge1
brgphy1: <BCM5720C 1000BASE-T media interface> PHY 2 on miibus1
brgphy1: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT,
1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto, auto-flow
bge1: Ethernet address: d4:ae:52:a4:3c:df
pcib6: <ACPI PCI-PCI bridge> irq 19 at device 28.7 on pci0
pci3: <ACPI PCI bus> on pcib6
pcib7: <PCI-PCI bridge> at device 0.0 on pci3
pci4: <PCI bus> on pcib7
pcib8: <PCI-PCI bridge> at device 0.0 on pci4
pci5: <PCI bus> on pcib8
pcib9: <PCI-PCI bridge> at device 0.0 on pci5
pci6: <PCI bus> on pcib9
vgapci0: <VGA-compatible display> mem
0xd8000000-0xd8ffffff,0xdeffc000-0xdeffffff,0xde000000-0xde7fffff irq 19 at
device 0.0 on pci6
pcib10: <PCI-PCI bridge> at device 1.0 on pci4
pci7: <PCI bus> on pcib10
ehci1: <EHCI (generic) USB 2.0 controller> mem 0xdf8fe000-0xdf8fe3ff irq
22 at device 29.0 on pci0
usbus1: EHCI version 1.0
usbus1 on ehci1
pcib11: <PCI-PCI bridge> at device 30.0 on pci0
pci11: <PCI bus> on pcib11
isab0: <PCI-ISA bridge> at device 31.0 on pci0
isa0: <ISA bus> on isab0
ahci0: <Intel Patsburg AHCI SATA controller> port
0xece8-0xecef,0xecf8-0xecfb,0xecf0-0xecf7,0xecfc-0xecff,0xecc0-0xecdf mem
0xdf8ff000-0xdf8ff7ff irq 20 at device 31.2 on pci0
ahci0: AHCI v1.30 with 6 3Gbps ports, Port Multiplier not supported
ahcich0: <AHCI channel> at channel 0 on ahci0
ahcich1: <AHCI channel> at channel 1 on ahci0
ahcich2: <AHCI channel> at channel 2 on ahci0
ahcich3: <AHCI channel> at channel 3 on ahci0
ahcich4: <AHCI channel> at channel 4 on ahci0
pcib12: <ACPI Host-PCI bridge> on acpi0
pci64: <ACPI PCI bus> on pcib12
pcib13: <ACPI PCI-PCI bridge> irq 85 at device 3.0 on pci64
pci65: <ACPI PCI bus> on pcib13
pci64: <base peripheral> at device 5.0 (no driver attached)
pci64: <base peripheral> at device 5.2 (no driver attached)
pcib14: <ACPI Host-PCI bridge> on acpi0
pci63: <ACPI PCI bus> on pcib14
pci63: <base peripheral> at device 8.0 (no driver attached)
pci63: <base peripheral> at device 9.0 (no driver attached)
pci63: <base peripheral> at device 10.0 (no driver attached)
pci63: <base peripheral> at device 10.1 (no driver attached)
pci63: <base peripheral> at device 10.2 (no driver attached)
pci63: <base peripheral> at device 10.3 (no driver attached)
pci63: <base peripheral> at device 11.0 (no driver attached)
pci63: <base peripheral> at device 11.3 (no driver attached)
pci63: <base peripheral> at device 12.0 (no driver attached)
pci63: <base peripheral> at device 12.1 (no driver attached)
pci63: <base peripheral> at device 12.2 (no driver attached)
pci63: <base peripheral> at device 12.6 (no driver attached)
pci63: <base peripheral> at device 12.7 (no driver attached)
pci63: <base peripheral> at device 13.0 (no driver attached)
pci63: <base peripheral> at device 13.1 (no driver attached)
pci63: <base peripheral> at device 13.2 (no driver attached)
pci63: <base peripheral> at device 13.6 (no driver attached)
pci63: <base peripheral> at device 14.0 (no driver attached)
pci63: <dasp> at device 14.1 (no driver attached)
pci63: <base peripheral> at device 15.0 (no driver attached)
pci63: <base peripheral> at device 15.1 (no driver attached)
pci63: <base peripheral> at device 15.2 (no driver attached)
pci63: <base peripheral> at device 15.3 (no driver attached)
pci63: <base peripheral> at device 15.4 (no driver attached)
pci63: <base peripheral> at device 15.5 (no driver attached)
pci63: <base peripheral> at device 15.6 (no driver attached)
pci63: <base peripheral> at device 16.0 (no driver attached)
pci63: <base peripheral> at device 16.1 (no driver attached)
pci63: <base peripheral> at device 16.2 (no driver attached)
pci63: <base peripheral> at device 16.3 (no driver attached)
pci63: <base peripheral> at device 16.5 (no driver attached)
pci63: <base peripheral> at device 16.6 (no driver attached)
pci63: <base peripheral> at device 16.7 (no driver attached)
pci63: <base peripheral> at device 17.0 (no driver attached)
pci63: <base peripheral> at device 19.0 (no driver attached)
pci63: <dasp> at device 19.1 (no driver attached)
pci63: <dasp> at device 19.4 (no driver attached)
pci63: <dasp> at device 19.5 (no driver attached)
pci63: <base peripheral> at device 19.6 (no driver attached)
pcib15: <ACPI Host-PCI bridge> on acpi0
pci127: <ACPI PCI bus> on pcib15
pci127: <base peripheral> at device 8.0 (no driver attached)
pci127: <base peripheral> at device 9.0 (no driver attached)
pci127: <base peripheral> at device 10.0 (no driver attached)
pci127: <base peripheral> at device 10.1 (no driver attached)
pci127: <base peripheral> at device 10.2 (no driver attached)
pci127: <base peripheral> at device 10.3 (no driver attached)
pci127: <base peripheral> at device 11.0 (no driver attached)
pci127: <base peripheral> at device 11.3 (no driver attached)
pci127: <base peripheral> at device 12.0 (no driver attached)
pci127: <base peripheral> at device 12.1 (no driver attached)
pci127: <base peripheral> at device 12.2 (no driver attached)
pci127: <base peripheral> at device 12.6 (no driver attached)
pci127: <base peripheral> at device 12.7 (no driver attached)
pci127: <base peripheral> at device 13.0 (no driver attached)
pci127: <base peripheral> at device 13.1 (no driver attached)
pci127: <base peripheral> at device 13.2 (no driver attached)
pci127: <base peripheral> at device 13.6 (no driver attached)
pci127: <base peripheral> at device 14.0 (no driver attached)
pci127: <dasp> at device 14.1 (no driver attached)
pci127: <base peripheral> at device 15.0 (no driver attached)
pci127: <base peripheral> at device 15.1 (no driver attached)
pci127: <base peripheral> at device 15.2 (no driver attached)
pci127: <base peripheral> at device 15.3 (no driver attached)
pci127: <base peripheral> at device 15.4 (no driver attached)
pci127: <base peripheral> at device 15.5 (no driver attached)
pci127: <base peripheral> at device 15.6 (no driver attached)
pci127: <base peripheral> at device 16.0 (no driver attached)
pci127: <base peripheral> at device 16.1 (no driver attached)
pci127: <base peripheral> at device 16.2 (no driver attached)
pci127: <base peripheral> at device 16.3 (no driver attached)
pci127: <base peripheral> at device 16.5 (no driver attached)
pci127: <base peripheral> at device 16.6 (no driver attached)
pci127: <base peripheral> at device 16.7 (no driver attached)
pci127: <base peripheral> at device 17.0 (no driver attached)
pci127: <base peripheral> at device 19.0 (no driver attached)
pci127: <dasp> at device 19.1 (no driver attached)
pci127: <dasp> at device 19.4 (no driver attached)
pci127: <dasp> at device 19.5 (no driver attached)
pci127: <base peripheral> at device 19.6 (no driver attached)
uart1: <16550 or compatible> port 0x2f8-0x2ff irq 3 on acpi0
uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
uart0: console (9600,n,8,1)
orm0: <ISA Option ROMs> at iomem
0xc0000-0xc7fff,0xcc000-0xccfff,0xec000-0xeffff on isa0
sc0: <System console> at flags 0x100 on isa0
sc0: VGA <16 virtual consoles, flags=0x300>
vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
ppc0: cannot reserve I/O port range
ctl: CAM Target Layer loaded
est0: <Enhanced SpeedStep Frequency Control> on cpu0
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est0 attach returned 6
p4tcc0: <CPU Frequency Thermal Control> on cpu0
est1: <Enhanced SpeedStep Frequency Control> on cpu1
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est1 attach returned 6
p4tcc1: <CPU Frequency Thermal Control> on cpu1
est2: <Enhanced SpeedStep Frequency Control> on cpu2
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est2 attach returned 6
p4tcc2: <CPU Frequency Thermal Control> on cpu2
est3: <Enhanced SpeedStep Frequency Control> on cpu3
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est3 attach returned 6
p4tcc3: <CPU Frequency Thermal Control> on cpu3
est4: <Enhanced SpeedStep Frequency Control> on cpu4
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est4 attach returned 6
p4tcc4: <CPU Frequency Thermal Control> on cpu4
est5: <Enhanced SpeedStep Frequency Control> on cpu5
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est5 attach returned 6
p4tcc5: <CPU Frequency Thermal Control> on cpu5
est6: <Enhanced SpeedStep Frequency Control> on cpu6
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est6 attach returned 6
p4tcc6: <CPU Frequency Thermal Control> on cpu6
est7: <Enhanced SpeedStep Frequency Control> on cpu7
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est7 attach returned 6
p4tcc7: <CPU Frequency Thermal Control> on cpu7
est8: <Enhanced SpeedStep Frequency Control> on cpu8
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est8 attach returned 6
p4tcc8: <CPU Frequency Thermal Control> on cpu8
est9: <Enhanced SpeedStep Frequency Control> on cpu9
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est9 attach returned 6
p4tcc9: <CPU Frequency Thermal Control> on cpu9
est10: <Enhanced SpeedStep Frequency Control> on cpu10
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est10 attach returned 6
p4tcc10: <CPU Frequency Thermal Control> on cpu10
est11: <Enhanced SpeedStep Frequency Control> on cpu11
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est11 attach returned 6
p4tcc11: <CPU Frequency Thermal Control> on cpu11
est12: <Enhanced SpeedStep Frequency Control> on cpu12
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est12 attach returned 6
p4tcc12: <CPU Frequency Thermal Control> on cpu12
est13: <Enhanced SpeedStep Frequency Control> on cpu13
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est13 attach returned 6
p4tcc13: <CPU Frequency Thermal Control> on cpu13
est14: <Enhanced SpeedStep Frequency Control> on cpu14
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est14 attach returned 6
p4tcc14: <CPU Frequency Thermal Control> on cpu14
est15: <Enhanced SpeedStep Frequency Control> on cpu15
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est15 attach returned 6
p4tcc15: <CPU Frequency Thermal Control> on cpu15
est16: <Enhanced SpeedStep Frequency Control> on cpu16
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est16 attach returned 6
p4tcc16: <CPU Frequency Thermal Control> on cpu16
est17: <Enhanced SpeedStep Frequency Control> on cpu17
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est17 attach returned 6
p4tcc17: <CPU Frequency Thermal Control> on cpu17
est18: <Enhanced SpeedStep Frequency Control> on cpu18
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est18 attach returned 6
p4tcc18: <CPU Frequency Thermal Control> on cpu18
est19: <Enhanced SpeedStep Frequency Control> on cpu19
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est19 attach returned 6
p4tcc19: <CPU Frequency Thermal Control> on cpu19
est20: <Enhanced SpeedStep Frequency Control> on cpu20
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est20 attach returned 6
p4tcc20: <CPU Frequency Thermal Control> on cpu20
est21: <Enhanced SpeedStep Frequency Control> on cpu21
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est21 attach returned 6
p4tcc21: <CPU Frequency Thermal Control> on cpu21
est22: <Enhanced SpeedStep Frequency Control> on cpu22
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est22 attach returned 6
p4tcc22: <CPU Frequency Thermal Control> on cpu22
est23: <Enhanced SpeedStep Frequency Control> on cpu23
est: CPU supports Enhanced Speedstep, but is not recognized.
est: cpu_vendor GenuineIntel, msr 23b500001b00
device_attach: est23 attach returned 6
p4tcc23: <CPU Frequency Thermal Control> on cpu23
ZFS filesystem version 5
ZFS storage pool version 28
Timecounters tick every 1.000 msec
ipfw2 (+ipv6) initialized, divert enabled, nat loadable, rule-based forwarding
enabled, default to accept, logging disabled
mfi0: 1828 (406136473s/0x0020/info) - Shutdown command received from host
mfi0: 1829 (boot + 4s/0x0020/info) - Firmware initialization started (PCI ID
005b/1000/1f38/1028)
mfi0: 1830 (boot + 4s/0x0020/info) - Firmware version 3.130.05-1587
mfi0: 1831 (boot + 5s/0x0008/info) - Battery Present
mfi0: 1832 (boot + 5s/0x0020/info) - Package version 21.0.2-0001
mfi0: 1833 (boot + 5s/0x0020/info) - Board Revision A00
mfi0: 1834 (boot + 19s/0x0004/info) - Enclosure PD 20(c None/p1) communication
restored
mfi0: 1835 (boot + 19s/0x0002/info) - Inserted: Encl PD 20
usbus0: 480Mbps High Speed USB v2.0
usbus1: 480Mbps High Speed USB v2.0
ugen0.1: <Intel> at usbus0
uhub0: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus0
ugen1.1: <Intel> at usbus1
uhub1: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus1
mfid0 on mfi0
mfid0: 285568MB (584843264 sectors) RAID volume (no label) is optimal
mfid1 on mfi0
mfid1: 285568MB (584843264 sectors) RAID volume (no label) is optimal
mfi0: 1836 (boot + 19s/0x0002/info) - Inserted: PD 20(c None/p1) Info:
enclPd=20, scsiType=d, portMap=00, sasAddr=5e4ae020b6ff2c00,0000000000000000
mfi0: 1837 (boot + 19s/0x0002/info) - Inserted: PD 00(e0x20/s0)
mfi0: 1838 (boot + 19s/0x0002/info) - Inserted: PD 00(e0x20/s0) Info: enclPd=20,
scsiType=0, portMap=00, sasAddr=5000c50054b863ad,0000000000000000
mfi0: 1839 (boot + 19s/0x0002/info) - Inserted: PD 01(e0x20/s1)
mfi0: 1840 (boot + 19s/0x0002/info) - Inserted: PD 01(e0x20/s1) Info: enclPd=20,
scsiType=0, portMap=01, sasAddr=5000c50054b62409,0000000000000000
mfi0: 1841 (406136547s/0x0020/info) - Time established as 11/13/12 15:42:27; (53
seconds since power on)
mfi0: 1842 (406136564s/0x0008/info) - Battery temperature is normal
uhub0: 2 ports with 2 removable, self powered
uhub1: 2 ports with 2 removable, self powered
mfi0: 1843 (406136564s/0x0008/info) - Current capacity of the battery is above
threshold
mfi0: 1844 (406136789s/0x0020/info) - Host driver is loaded and operational
ugen0.2: <vendor 0x8087> at usbus0
uhub2: <vendor 0x8087 product 0x0024, class 9/0, rev 2.00/0.00, addr 2> on
usbus0
ugen1.2: <vendor 0x8087> at usbus1
uhub3: <vendor 0x8087 product 0x0024, class 9/0, rev 2.00/0.00, addr 2> on
usbus1
SMP: AP CPU #1 Launched!
SMP: AP CPU #20 Launched!
SMP: AP CPU #9 Launched!
SMP: AP CPU #15 Launched!
SMP: AP CPU #4 Launched!
SMP: AP CPU #7 Launched!
SMP: AP CPU #10 Launched!
SMP: AP CPU #14 Launched!
SMP: AP CPU #6 Launched!
SMP: AP CPU #23 Launched!
SMP: AP CPU #2 Launched!
SMP: AP CPU #8 Launched!
SMP: AP CPU #22 Launched!
SMP: AP CPU #17 Launched!
SMP: AP CPU #5 Launched!
SMP: AP CPU #3 Launched!
SMP: AP CPU #21 Launched!
SMP: AP CPU #16 Launched!
SMP: AP CPU #12 Launched!
SMP: AP CPU #13 Launched!
SMP: AP CPU #19 Launched!
SMP: AP CPU #11 Launched!
SMP: AP CPU #18 Launched!
Timecounter "TSC-low" frequency 9375184 Hz quality 1000
Root mount waiting for: usbus1 usbus0
uhub2: 6 ports with 6 removable, self powered
uhub3: 8 ports with 8 removable, self powered
ugen0.3: <no manufacturer> at usbus0
uhub4: <no manufacturer Gadget USB HUB, class 9/0, rev 2.00/0.00, addr 3>
on usbus0
Root mount waiting for: usbus0
uhub4: 6 ports with 6 removable, self powered
ugen0.4: <Avocent> at usbus0
ukbd0: <Keyboard> on usbus0
kbd0 at ukbd0
ums0: <Mouse> on usbus0
ums0: 3 buttons and [Z] coordinates ID=0
ums1: <Mouse REL> on usbus0
Root mount waiting for: usbus0
ums1: 3 buttons and [XYZ] coordinates ID=0
Root mount waiting for: usbus0
ugen0.5: <Avocent> at usbus0
umass0: <SCSI Transparent Interface 0> on usbus0
umass0: SCSI over Bulk-Only; quirks = 0x0000
umass0:6:0:-1: Attached to scbus6
cd0 at umass-sim0 bus 0 scbus6 target 0 lun 0
cd0: <iDRAC Virtual CD 0329> Removable CD-ROM SCSI-0 device
cd0: 40.000MB/s transfers
cd0: Attempt to query device size failed: NOT READY, Medium not present
da0 at umass-sim0 bus 0 scbus6 target 0 lun 1
da0: <iDRAC Virtual Floppy 0329> Removable Direct Access SCSI-0 device
da0: 40.000MB/s transfers
da0: 524MB (1073741 512 byte sectors: 64H 32S/T 524C)
Trying to mount root from zfs:zroot []...
ix0: 2 link states coalesced
ix1: 2 link states coalesced
ix0: 2 link states coalesced
----
network related loader.conf settings:
----
dev.bge.0.msi="0"
dev.bge.1.msi="0"
net.inet.tcp.syncache.hashsize=32768
net.inet.tcp.syncache.bucketlimit=32
net.inet.tcp.syncache.cachelimit=1048576
net.inet.tcp.tcbhashsize=1048576
net.inet.tcp.hostcache.hashsize=65536
net.inet.tcp.hostcache.cachelimit=1966080
----
network related part of sysctl.conf:
----
net.inet.ip.fw.verbose=0
net.inet.ip.redirect=0
net.inet.icmp.drop_redirect=1
net.inet.tcp.drop_synfin=1
#net.inet.tcp.icmp_may_rst=0
#net.inet.udp.blackhole=1
#net.inet.tcp.blackhole=2
net.inet6.ip6.accept_rtadv=0
net.inet6.icmp6.rediraccept=0
kern.ipc.maxsockets=1000000
net.inet.tcp.maxtcptw=200000
kern.ipc.nmbclusters=262144
net.inet.tcp.recvspace=65536
net.inet.tcp.sendspace=65536
kern.ipc.somaxconn=10240
net.inet.ip.portrange.first=2048
net.inet.ip.portrange.last=65535
net.inet.tcp.msl=5000
net.inet.tcp.fast_finwait2_recycle=1
net.inet.ip.intr_queue_maxlen=4096
#net.inet.tcp.ecn.enable=1
net.inet.icmp.icmplim=5000
----
Markus Gebert
2012-Nov-14 00:41 UTC
thread taskq / unp_gc() using 100% cpu and stalling unix socket IPC
On 13.11.2012, at 19:30, Markus Gebert <markus.gebert at hostpoint.ch> wrote:> To me it looks like the unix socket GC is triggered way too often and/or running too long, which uses cpu and worse, causes a lot of contention around the unp_list_lock which in turn causes delays for all processes relaying on unix sockets for IPC. > > I don't know why the unp_gc() is called so often and what's triggering this.I have a guess now. Dovecot and relayd both use unix sockets heavily. According to dtrace uipc_detach() gets called quite often by dovecot closing unix sockets. Each time uipc_detach() is called unp_gc_task is taskqueue_enqueue()d if fds are inflight. in uipc_detach(): 682 if (local_unp_rights) 683 taskqueue_enqueue(taskqueue_thread, &unp_gc_task); We use relayd in a way that keeps the source address of the client when connecting to the backend server (transparent load balancing). This requires IP_BINDANY on the socket which cannot be set by unprivileged processes, so relayd sends the socket fd to the parent process just to set the socket option and send it back. This means an fd gets transferred twice for every new backend connection. So we have dovecot calling uipc_detach() often and relayd making it likely that fds are inflight (unp_rights > 0). With a certain amount of load this could cause unp_gc_task to be added to the thread taskq too often, slowing everything unix socket related down by holding global locks in unp_gc(). I don't know if the slowdown can even cause a negative feedback loop at some point by inreasing the chance of fds being inflight. This would explain why sometimes the condition goes away by itself and sometimes requires intervention (taking load away for a moment). I'll look into a way to (dis)prove all this tomorrow. Ideas still welcome :-). Markus