Nikolay Pavlov
2007-May-07 15:16 UTC
Unstable behavior of the system with tds version = 4.2 (maybe a kernel bug?)
Hello. I have a very strange and 100% reproducible behavior of the
several FreeBSD servers (5.4, 5.5, 6.1, 6.2 releases).
The only thing that triggers this anomaly is a TDS protocol version in
freetds.conf file. If i am using "tds version = 4.2" (the default)
all is fine:
last pid: 1342; load averages: 0.14, 0.11, 0.11 up 0+00:23:27 09:37:45
279 processes: 1 running, 278 sleeping
CPU states: 4.0% user, 0.0% nice, 0.4% system, 0.8% interrupt, 94.8% idle
Mem: 405M Active, 12M Inact, 65M Wired, 16K Cache, 20M Buf, 507M Free
Swap: 2032M Total, 2032M Free
PID USERNAME THR PRI NICE SIZE RES STATE TIME WCPU COMMAND
1294 www 1 96 0 13840K 10980K select 0:00 0.20% httpd
1269 www 1 96 0 13360K 10496K select 0:01 0.15% httpd
1250 www 1 96 0 14620K 11720K select 0:00 0.10% httpd
1049 www 1 96 0 13832K 10972K select 0:01 0.05% httpd
1286 www 1 96 0 13832K 10972K select 0:01 0.05% httpd
1102 www 1 4 0 13860K 11000K accept 0:00 0.05% httpd
1263 www 1 96 0 13360K 10500K select 0:00 0.05% httpd
1320 root 1 96 0 2784K 1984K RUN 0:04 0.00% top
1042 root 1 96 0 12908K 9704K select 0:01 0.00% httpd
1143 www 1 4 0 13844K 10980K accept 0:01 0.00% httpd
But whenever i am changing it to "tds version = 8.0" my system gets
very
unstable and heavy overloaded:
last pid: 1626; load averages: 4.60, 1.12, 0.46 up 0+00:25:45 09:40:03
279 processes: 24 running, 254 sleeping, 1 lock
CPU states: 21.9% user, 0.0% nice, 78.1% system, 0.0% interrupt, 0.0%
idle
Mem: 191M Active, 14M Inact, 67M Wired, 16K Cache, 21M Buf, 717M Free
Swap: 2032M Total, 2032M Free
PID USERNAME THR PRI NICE SIZE RES STATE TIME WCPU COMMAND
1368 www 1 100 0 14604K 11744K RUN 0:04 11.66% httpd
1382 www 1 100 0 14604K 11744K RUN 0:02 7.05% httpd
1384 www 1 100 0 14612K 11752K RUN 0:02 6.77% httpd
1389 www 1 100 0 14604K 11744K RUN 0:02 6.21% httpd
1392 www 1 100 0 14604K 11748K RUN 0:02 5.45% httpd
1395 www 1 100 0 14604K 11744K RUN 0:01 5.45% httpd
1397 www 1 100 0 14612K 11752K RUN 0:01 4.47% httpd
1408 www 1 100 0 14604K 11744K RUN 0:01 3.70% httpd
1423 www 1 100 0 14604K 11764K RUN 0:01 2.50% httpd
1422 www 1 100 0 14612K 11752K RUN 0:01 2.50% httpd
1425 www 1 100 0 14604K 11744K RUN 0:00 2.43% httpd
1431 www 1 100 0 14604K 11744K RUN 0:00 2.29% httpd
1432 www 1 100 0 14604K 11744K RUN 0:00 1.93% httpd
1438 www 1 100 0 14604K 11744K RUN 0:00 1.93% httpd
1439 www 1 100 0 14604K 11744K RUN 0:00 1.86% httpd
Please pay attention to the high load in kernel space. This is actualy
why i am thinking about possible kernel bug (i am not sure of course :)
Here is the end of ktrace output from "ktrace httpd -X" command
and the strange thing is that i am getting SIGBUS every time the php
script calls the gal_save_cookie (MSSQL stored procedure).
It's running normal with "tds version = 4.2"
1839 httpd GIO fd 15 wrote 298 bytes
0x0000 0101 012a 0000 0100 6700 6100 6c00 5f00 7300 6100 7600 6500 5f00
6300 6f00 6f00 6b00 6900 6500 |...*....g.a.l._.s.a.v.e._.c.o.o.k.i.e.|
0x0026 5f00 6900 6e00 6600 6f00 2000 4000 7000 6900 6400 3d00 3100 3200
3300 3700 3500 2c00 2000 4000 |_.i.n.f.o. .@.p.i.d.=.1.2.3.7.5.,. .@.|
0x004c 6700 7500 6500 7300 7400 6900 6400 3d00 3100 3000 3600 3700 3800
3800 3100 3700 3400 2c00 2000 |g.u.e.s.t.i.d.=.1.0.6.7.8.8.1.7.4.,. .|
0x0072 4000 7300 6900 7400 6500 6900 6400 3d00 3100 3200 3300 3800 3100
2c00 2000 4000 7000 6b00 5f00 |@.s.i.t.e.i.d.=.1.2.3.8.1.,. .@.p.k._.|
0x0098 6700 6100 6c00 6900 6400 3d00 3800 3900 3000 3200 2c00 2000 4000
7000 7400 7900 7000 6500 3d00 |g.a.l.i.d.=.8.9.0.2.,. .@.p.t.y.p.e.=.|
0x00be 2700 5200 2700 2000 2c00 2000 4000 7200 6500 6600 3d00 2700 6800
7400 7400 7000 3a00 2f00 2f00 |'.R.'. .,.
.@.r.e.f.=.'.h.t.t.p.:././.|
0x00e4 7700 7700 7700 2e00 7400 6900 6100 7600 6100 2e00 6300 6f00 6d00
2f00 6d00 6f00 7600 6900 6500 |w.w.w...t.i.a.v.a...c.o.m./.m.o.v.i.e.|
0x010a 7300 2f00 7000 6900 7300 7300 6500 6400 6f00 6e00 3000 2e00 7000
6800 7000 2700 |s./.p.i.s.s.e.d.o.n.0...p.h.p.'.|
1839 httpd RET sendto 298/0x12a
1839 httpd CALL gettimeofday(0xbfbfa0d8,0)
1839 httpd RET gettimeofday 0
1839 httpd CALL select(0x10,0xbfbfa130,0,0,0)
1839 httpd RET select 1
1839 httpd CALL recvfrom(0xf,0xbfbfa1f0,0x8,0x20000,0,0)
1839 httpd GIO fd 15 read 8 bytes
0x0000 0401 004e 0061 0100
|...N.a..|
1839 httpd RET recvfrom 8
1839 httpd CALL gettimeofday(0xbfbfa0d8,0)
1839 httpd RET gettimeofday 0
1839 httpd CALL gettimeofday(0xbfbfa0d8,0)
1839 httpd RET gettimeofday 0
1839 httpd CALL select(0x10,0xbfbfa130,0,0,0)
1839 httpd RET select 1
1839 httpd CALL recvfrom(0xf,0x82af200,0x46,0x20000,0,0)
1839 httpd GIO fd 15 read 70 bytes
0x0000 ff01 00c0 0000 0000 00ff 1100 c500 0100 0000 8101 0000 0001 0026
0800 d108 4e75 5d06 0000 0000 |.........................&....Nu].....|
0x0026 ff11 00c1 0001 0000 00ff 0100 ca00 0100 0000 7900 0000 00fe 0000
e000 0100 0000 |..................y.............|
1839 httpd RET recvfrom 70/0x46
1839 httpd CALL gettimeofday(0xbfbfa0d8,0)
1839 httpd RET gettimeofday 0
1839 httpd PSIG SIGBUS SIG_DFL
The ending portion of the freetds debug log with the similar request:
net.c:673:Sending packet
0000 01 01 02 76 00 00 01 00-67 00 61 00 6c 00 5f 00 |...v.... g.a.l._.|
0010 73 00 61 00 76 00 65 00-5f 00 63 00 6f 00 6f 00 |s.a.v.e. _.c.o.o.|
0020 6b 00 69 00 65 00 5f 00-69 00 6e 00 66 00 6f 00 |k.i.e._. i.n.f.o.|
0030 20 00 40 00 70 00 69 00-64 00 3d 00 31 00 32 00 | .@.p.i. d.=.1.2.|
0040 33 00 37 00 35 00 2c 00-20 00 40 00 67 00 75 00 |3.7.5.,. .@.g.u.|
0050 65 00 73 00 74 00 69 00-64 00 3d 00 31 00 30 00 |e.s.t.i. d.=.1.0.|
0060 36 00 37 00 31 00 31 00-35 00 38 00 33 00 2c 00 |6.7.1.1. 5.8.3.,.|
0070 20 00 40 00 73 00 69 00-74 00 65 00 69 00 64 00 | .@.s.i. t.e.i.d.|
0080 3d 00 32 00 31 00 30 00-33 00 31 00 2c 00 20 00 |=.2.1.0. 3.1.,. .|
0090 40 00 70 00 6b 00 5f 00-67 00 61 00 6c 00 69 00 |@.p.k._. g.a.l.i.|
00a0 64 00 3d 00 38 00 31 00-35 00 33 00 2c 00 20 00 |d.=.8.1. 5.3.,. .|
00b0 40 00 70 00 74 00 79 00-70 00 65 00 3d 00 27 00 |@.p.t.y. p.e.=.'.|
00c0 52 00 27 00 20 00 2c 00-20 00 40 00 72 00 65 00 |R.'. .,. .@.r.e.|
00d0 66 00 3d 00 27 00 68 00-74 00 74 00 70 00 3a 00 |f.=.'.h. t.t.p.:.|
00e0 2f 00 2f 00 77 00 77 00-77 00 2e 00 70 00 65 00 |/./.w.w. w...p.e.|
00f0 72 00 76 00 65 00 72 00-73 00 69 00 75 00 73 00 |r.v.e.r. s.i.u.s.|
0100 2e 00 63 00 6f 00 6d 00-2f 00 33 00 74 00 68 00 |..c.o.m. /.3.t.h.|
0110 75 00 6d 00 62 00 73 00-2f 00 61 00 2f 00 61 00 |u.m.b.s. /.a./.a.|
0120 6c 00 6c 00 2f 00 32 00-34 00 30 00 78 00 31 00 |l.l./.2. 4.0.x.1.|
0130 38 00 30 00 2f 00 6d 00-6f 00 76 00 69 00 65 00 |8.0./.m. o.v.i.e.|
0140 73 00 2f 00 6d 00 69 00-73 00 73 00 69 00 6f 00 |s./.m.i. s.s.i.o.|
0150 6e 00 61 00 72 00 79 00-5f 00 73 00 6f 00 72 00 |n.a.r.y. _.s.o.r.|
0160 74 00 5f 00 64 00 61 00-74 00 65 00 5f 00 64 00 |t._.d.a. t.e._.d.|
0170 65 00 73 00 63 00 5f 00-30 00 2e 00 70 00 68 00 |e.s.c._. 0...p.h.|
0180 70 00 3f 00 6d 00 70 00-6c 00 6f 00 3d 00 33 00 |p.?.m.p. l.o.=.3.|
0190 26 00 6d 00 70 00 74 00-73 00 3d 00 31 00 32 00 |&.m.p.t. s.=.1.2.|
01a0 30 00 78 00 31 00 36 00-30 00 26 00 6d 00 70 00 |0.x.1.6. 0.&.m.p.|
01b0 6c 00 69 00 3d 00 33 00-30 00 30 00 26 00 6d 00 |l.i.=.3. 0.0.&.m.|
01c0 70 00 73 00 6f 00 3d 00-72 00 61 00 6e 00 6b 00 |p.s.o.=. r.a.n.k.|
01d0 69 00 6e 00 67 00 5f 00-64 00 65 00 73 00 63 00 |i.n.g._. d.e.s.c.|
01e0 26 00 73 00 70 00 64 00-74 00 3d 00 33 00 74 00 |&.s.p.d. t.=.3.t.|
01f0 68 00 75 00 6d 00 62 00-73 00 26 00 73 00 70 00 |h.u.m.b. s.&.s.p.|
0200 74 00 73 00 3d 00 32 00-34 00 30 00 78 00 31 00 |t.s.=.2. 4.0.x.1.|
0210 38 00 30 00 26 00 73 00-70 00 73 00 6f 00 3d 00 |8.0.&.s. p.s.o.=.|
0220 64 00 61 00 74 00 65 00-5f 00 64 00 65 00 73 00 |d.a.t.e. _.d.e.s.|
0230 63 00 26 00 67 00 6c 00-73 00 63 00 3d 00 61 00 |c.&.g.l. s.c.=.a.|
0240 26 00 67 00 6c 00 73 00-77 00 3d 00 6e 00 6f 00 |&.g.l.s. w.=.n.o.|
0250 26 00 67 00 6c 00 65 00-78 00 3d 00 61 00 6c 00 |&.g.l.e. x.=.a.l.|
0260 6c 00 26 00 67 00 6c 00-61 00 75 00 3d 00 79 00 |l.&.g.l. a.u.=.y.|
0270 65 00 73 00 27 00 - |e.s.'.|
ct.c:214:setting command state from READY to SENT
ct.c:930:ct_send() succeeded
ct.c:1064:ct_results()
util.c:119:Changing query state from PENDING to READING
net.c:446:Received header
0000 04 01 00 4e 00 7c 01 00- |...N.|..|
net.c:542:Received packet
0000 ff 01 00 c0 00 00 00 00-00 ff 11 00 c5 00 01 00 |........ ........|
0010 00 00 81 01 00 00 00 01-00 26 08 00 d1 08 1f 4a |........ .&.....J|
0020 5c 06 00 00 00 00 ff 11-00 c1 00 01 00 00 00 ff |\....... ........|
0030 01 00 ca 00 01 00 00 00-79 00 00 00 00 fe 00 00 |........ y.......|
0040 e0 00 01 00 00 00 - |......|
token.c:526:processing result tokens. marker is ff(DONEINPROC)
token.c:2143:tds_process_end: more_results = 1
was_cancelled = 0
error = 0
done_count_valid = 0
util.c:119:Changing query state from READING to PENDING
ct.c:1121:ct_results() process_result_tokens returned 1 (type 4054)
util.c:119:Changing query state from PENDING to READING
token.c:526:processing result tokens. marker is ff(DONEINPROC)
token.c:2143:tds_process_end: more_results = 1
was_cancelled = 0
error = 0
done_count_valid = 1
token.c:2175: rows_affected = 1
util.c:119:Changing query state from READING to PENDING
ct.c:1121:ct_results() process_result_tokens returned 1 (type 4054)
util.c:119:Changing query state from PENDING to READING
token.c:526:processing result tokens. marker is 81(TDS7_RESULT)
mem.c:519:tds_free_all_results()
token.c:1472:processing TDS7 result. set current_results to
tds->res_info
token.c:1414:tds7_get_data_info:
colname = (0 bytes)
type = 38 (integer-null)
server's type = 38 (integer-null)
column_varint_size = 1
column_size = 8 (8 on server)
util.c:119:Changing query state from READING to PENDING
ct.c:1121:ct_results() process_result_tokens returned 1 (type 4049)
util.c:119:Changing query state from PENDING to READING
token.c:526:processing result tokens. marker is d1(ROW)
util.c:119:Changing query state from READING to PENDING
ct.c:1121:ct_results() process_result_tokens returned 1 (type 4040)
ct.c:2323:ct_res_info()
ct.c:2342:ct_res_info(): Number of columns is 1
ct.c:2267:ct_describe()
ct.c:1858:_ct_get_client_type(type 38, user 0, size 8)
ct.c:2288:ct_describe() datafmt->datatype = 20 server type 38
ct.c:1398:ct_bind() datafmt count = 1 column_number = 1
ct.c:1454:ct_fetch()
util.c:119:Changing query state from PENDING to READING
token.c:526:processing result tokens. marker is d1(ROW)
token.c:1863:tds_get_data: column 0, type 38, varint size 1
token.c:1920:processing row. column size is 8
util.c:119:Changing query state from READING to PENDING
ct.c:1519:inside ct_fetch()process_row_tokens returned 1
ct.c:1670:_ct_bind_data()
ct.c:1677:_ct_bind_data(): column_type: 38 column_len: 8
ct.c:1971:_ct_get_server_type(0)
ct.c:1858:_ct_get_client_type(type 38, user 0, size 8)
cs.c:351:cs_convert()
ct.c:1971:_ct_get_server_type(20)
ct.c:1971:_ct_get_server_type(0)
cs.c:358:cs_convert() srctype = 127 (8) desttype = 47 (9)
cs.c:520:cs_convert() calling tds_convert
cs.c:523:cs_convert() tds_convert returned 9
cs.c:654:cs_convert() FMT_NULLTERM
cs.c:656:not enough room for data + a null terminator - error
cs.c:706:cs_convert() returning 0
ct.c:1729:cs_convert-result = 1
ct.c:1732:
convert failed for 20
And finaly here is a debug session (for the second output of
the top utility in this email):
db> show pcpu
cpuid = 0
curthread = 0xc6ffc780: pid 1439 "httpd"
curpcb = 0xef45fd90
fpcurthread = none
idlethread = 0xc6a82600: pid 10 "idle"
APIC ID = 0
currentldt = 0x50
spin locks held:
db> bt 1439
Tracing pid 1439 tid 100162 td 0xc6ffc780
kdb_enter(c0918279) at kdb_enter+0x2b
siointr1(c6bc0800,c0a470e0,0,c0918085,56e,...) at siointr1+0xd5
siointr(c6bc0800) at siointr+0x21
intr_execute_handlers(c6a7c4c8,ef45faf4,4,ef45fb3c,c08652d3,...) at
intr_execute_handlers+0xe1
lapic_handle_intr(38) at lapic_handle_intr+0x2e
Xapic_isr1() at Xapic_isr1+0x33
--- interrupt, eip = 0xc086e46b, esp = 0xef45fb38, ebp = 0xef45fb3c ---
spinlock_exit(c0a290b8,ef45fb64,c0696f0d,c09e56c0,0,...) at spinlock_exit+0x27
_mtx_unlock_spin_flags(c09e56c0,0,c08f8bdb,6a0,c7031bd4,...) at
_mtx_unlock_spin_flags+0xa0
witness_lock_list_get(c09eeee0,c7031bd4,1,c02,ef45fba0,...) at
witness_lock_list_get+0x8d
witness_lock(c7031bd4,8,c0911a15,c02) at witness_lock+0xae
_sx_xlock(c7031bd4,c0911a15,c02) at _sx_xlock+0x8c
_vm_map_lock_read(c7031b90,c0911a15,c02,145fbe0,c6ffb280,...) at
_vm_map_lock_read+0x37
vm_map_lookup(ef45fc70,43203000,1,ef45fc74,ef45fc64,ef45fc68,ef45fc4b,ef45fc4c)
at vm_map_lookup+0x28
vm_fault(c7031b90,43203000,1,0,c6ffc780,...) at vm_fault+0x65
trap_pfault(ef45fd38,1,43203a47,43203a47,0,...) at trap_pfault+0xee
trap(3b,3b,3b,8093ffc,82bbf44,...) at trap+0x1eb
calltrap() at calltrap+0x5
--- trap 0xc, eip = 0x43203a47, esp = 0xbfbf9d1c, ebp = 0xbfbf9d38 ---
db> bt 1368
Tracing pid 1368 tid 100113 td 0xc6f3fc00
sched_switch(c6f3fc00,0,2) at sched_switch+0x177
mi_switch(2,0,c09e0340,0,c08f6642,...) at mi_switch+0x270
critical_exit(c6f3fc00,ef39eb24,c0865500,0,c6f30008,...) at critical_exit+0x8b
lapic_handle_timer(0) at lapic_handle_timer+0xc9
Xtimerint(c0a29940,ef39eb5c,c0696f5c,c09e56c0,0,...) at Xtimerint+0x30
_mtx_unlock_spin_flags(c09e56c0,0,c08f8bdb,6ac,c09e56c0,...) at
_mtx_unlock_spin_flags+0xa0
witness_lock_list_free(c0a29940) at witness_lock_list_free+0x40
witness_unlock(c6eb23bc,8,c0911a15,c16,c71376a4,...) at witness_unlock+0x1b6
_sx_xunlock(c6eb23bc,c0911a15,c16) at _sx_xunlock+0x64
_vm_map_unlock_read(c6eb2378,c0911a15,c16,1000000,1,...) at
_vm_map_unlock_read+0x37
vm_map_lookup(ef39ec70,90a6000,1,ef39ec74,ef39ec64,ef39ec68,ef39ec4b,ef39ec4c)
at vm_map_lookup+0x6b
vm_fault(c6eb2378,90a6000,1,0,c6f3fc00,...) at vm_fault+0x65
trap_pfault(ef39ed38,1,90a646e,90a646e,0,...) at trap_pfault+0xee
trap(3b,3b,3b,8093ffc,82bbf14,...) at trap+0x1eb
calltrap() at calltrap+0x5
--- trap 0xc, eip = 0x90a646e, esp = 0xbfbf9d1c, ebp = 0xbfbf9d38 ---
db> bt 1382
Tracing pid 1382 tid 100252 td 0xc7114780
sched_switch(c7114780,0,2) at sched_switch+0x177
mi_switch(2,0,c09e0340,0,c08f6642,...) at mi_switch+0x270
critical_exit(c7114780,ef572b6c,c0865500,0,200008,...) at critical_exit+0x8b
lapic_handle_timer(0) at lapic_handle_timer+0xc9
Xtimerint(c7233aac,8,c0911a15,af3,c7199068,...) at Xtimerint+0x30
_sx_xunlock(c7233aac,c0911a15,af3) at _sx_xunlock+0x64
_vm_map_unlock_read(c7233a68,c0911a15,af3,c07d6d3b,c7233a68,...) at
_vm_map_unlock_read+0x37
vm_map_growstack(c7199000,63656000) at vm_map_growstack+0xd0
vm_fault(c7233a68,63656000,1,0,c7114780,...) at vm_fault+0xca
trap_pfault(ef572d38,1,63656c65,63656c65,0,...) at trap_pfault+0xee
trap(3b,3b,3b,8093ffc,82bbf30,...) at trap+0x1eb
calltrap() at calltrap+0x5
--- trap 0xc, eip = 0x63656c65, esp = 0xbfbf9d1c, ebp = 0xbfbf9d38 ---
db> show locks
db> show alllocks
Process 1471 (httpd) thread 0xc7092600 (100209)
exclusive sx user map r = 0 (0xc6f2ebd4) locked @ /usr/src/sys/vm/vm_map.c:3074
Process 1469 (httpd) thread 0xc7092300 (100211)
exclusive sleep mutex vnode interlock r = 0 (0xc72ab4dc) locked @
/usr/src/sys/kern/vfs_vnops.c:806
Process 1432 (httpd) thread 0xc6f7f300 (100141)
exclusive sleep mutex process lock r = 0 (0xc6fbc280) locked @
/usr/src/sys/kern/kern_sig.c:1530
Process 1431 (httpd) thread 0xc6f7f180 (100142)
exclusive sx user map r = 0 (0xc6eb2cfc) locked @ /usr/src/sys/vm/vm_map.c:2786
Process 1382 (httpd) thread 0xc7114780 (100252)
exclusive sx user map r = 0 (0xc7233aac) locked @ /usr/src/sys/vm/vm_map.c:2786
db> show lockedvnods
Locked vnodes
After this debug session i have sent a "killall -9 httpd" command, but
found one process still spining on top with a load in kernel space:
last pid: 1628; load averages: 2.60, 1.11, 0.50
up 0+00:26:39 09:40:57
23 processes: 2 running, 21 sleeping
CPU states: 4.1% user, 0.0% nice, 95.5% system, 0.4% interrupt, 0.0%
idle
Mem: 15M Active, 11M Inact, 62M Wired, 16K Cache, 21M Buf, 900M Free
Swap: 2032M Total, 2032M Free
PID USERNAME THR PRI NICE SIZE RES STATE TIME WCPU COMMAND
1431 www 1 132 0 14604K 11744K RUN 0:50 92.14% httpd
1012 root 1 20 0 3044K 2864K pause 0:01 0.00% zsh
999 quetzal 1 96 0 6312K 3320K select 0:00 0.00% sshd
1000 quetzal 1 20 0 2920K 2644K pause 0:00 0.00% zsh
607 root 1 96 0 6756K 5028K select 0:00 0.00% snmpd
635 root 1 96 0 3044K 1884K select 0:00 0.00% ntpd
347 _pflogd 1 -58 0 1664K 1264K bpf 0:00 0.00% pflogd
997 root 1 4 0 6316K 3300K sbwait 0:00 0.00% sshd
1628 root 1 96 0 2372K 1576K RUN 0:00 0.00% top
342 root 1 4 0 1600K 1204K sbwait 0:00 0.00% pflogd
692 root 1 96 0 3548K 2892K select 0:00 0.00% sendmail
536 root 1 96 0 1416K 1044K select 0:00 0.00% syslogd
797 root 1 8 0 1428K 1120K nanslp 0:00 0.00% cron
996 root 1 5 0 1384K 964K ttyin 0:00 0.00% getty
993 root 1 5 0 1384K 964K ttyin 0:00 0.00% getty
995 root 1 5 0 1384K 964K ttyin 0:00 0.00% getty
994 root 1 5 0 1384K 964K ttyin 0:00 0.00% getty
db> bt 1431
Tracing pid 1431 tid 100142 td 0xc6f7f180
kdb_enter(c0918279) at kdb_enter+0x2b
siointr1(c6bc0800,c0a470e0,0,c0918085,56e,...) at siointr1+0xd5
siointr(c6bc0800) at siointr+0x21
intr_execute_handlers(c6a7c4c8,ef3c1b6c,4,ef3c1bb4,c08652d3,...) at
intr_execute_handlers+0xe1
lapic_handle_intr(38) at lapic_handle_intr+0x2e
Xapic_isr1() at Xapic_isr1+0x33
--- interrupt, eip = 0xc06d72ae, esp = 0xef3c1bb0, ebp = 0xef3c1bb4 ---
strncmp(c08f5277,c08f8d78,3) at strncmp+0x16
fixup_filename(c08f5277,ef3c1ccc,c07cfe81,ef3c1c70,c09ee3f0,...) at
fixup_filename+0x24
witness_checkorder(c512daa8,9,c08f5277,6b7) at witness_checkorder+0x72
_mtx_lock_flags(c512daa8,0,c08f5277,6b7,c08f5277,...) at _mtx_lock_flags+0x78
do_tdsignal(c6f7f180,b,1,ef3c1c90,c066b3ca,...) at do_tdsignal+0xd1
tdsignal(c6f7f180,b,1,c512daa8,0,c08f5277,62c) at tdsignal+0x44
trapsignal(c6f7f180,b,c) at trapsignal+0x392
trap(3b,3b,3b,8093ffc,82bbf9c,...) at trap+0x53c
calltrap() at calltrap+0x5
--- trap 0xc, eip = 0x7375616c, esp = 0xbfbf9d1c, ebp = 0xbfbf9d38 ---
db> show pcpu
cpuid = 0
curthread = 0xc6f7f180: pid 1431 "httpd"
curpcb = 0xef3c1d90
fpcurthread = none
idlethread = 0xc6a82600: pid 10 "idle"
APIC ID = 0
currentldt = 0x50
spin locks held:
db> show alllocks
Process 1431 (httpd) thread 0xc6f7f180 (100142)
exclusive sleep mutex process lock r = 0 (0xc6fbc498) locked @
/usr/src/sys/kern/kern_sig.c:1530
root@tracker6:~# uname -a
FreeBSD tracker6 6.2-RELEASE-p4 FreeBSD 6.2-RELEASE-p4 #0:
Fri May 4 12:09:08 EDT 2007 root@tracker6:/usr/obj/usr/src/sys/DEBUG i386