From owner-freebsd-stable@FreeBSD.ORG Mon May 7 15:16:30 2007 Return-Path: X-Original-To: freebsd-stable@freebsd.org Delivered-To: freebsd-stable@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [69.147.83.52]) by hub.freebsd.org (Postfix) with ESMTP id 48D6916A402 for ; Mon, 7 May 2007 15:16:30 +0000 (UTC) (envelope-from quetzal@zone3000.net) Received: from mx1.sitevalley.com (sitevalley.com [209.67.60.43]) by mx1.freebsd.org (Postfix) with SMTP id C5AD513C468 for ; Mon, 7 May 2007 15:16:29 +0000 (UTC) (envelope-from quetzal@zone3000.net) Received: from zone3000.kharkov.ua (HELO localhost) (217.144.69.37) by 209.67.61.254 with SMTP; 7 May 2007 15:16:24 -0000 Date: Mon, 7 May 2007 18:15:58 +0300 From: Nikolay Pavlov To: freebsd-stable@freebsd.org Message-ID: <20070507151558.GA87836@zone3000.net> Mail-Followup-To: Nikolay Pavlov , freebsd-stable@freebsd.org MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline X-Operating-System: FreeBSD 6.1-RELEASE-p10 User-Agent: mutt-ng/devel-r804 (FreeBSD) Subject: Unstable behavior of the system with tds version = 4.2 (maybe a kernel bug?) X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 07 May 2007 15:16:30 -0000 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