From owner-freebsd-current@FreeBSD.ORG Tue Mar 30 13:43:07 2004 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 2916016A4CE; Tue, 30 Mar 2004 13:43:07 -0800 (PST) Received: from smtp.des.no (flood.des.no [217.116.83.31]) by mx1.FreeBSD.org (Postfix) with ESMTP id 9678743D2F; Tue, 30 Mar 2004 13:43:06 -0800 (PST) (envelope-from des@des.no) Received: by smtp.des.no (Pony Express, from userid 666) id 731FF530D; Tue, 30 Mar 2004 23:43:05 +0200 (CEST) Received: from dwp.des.no (des.no [80.203.228.37]) by smtp.des.no (Pony Express) with ESMTP id 30C59530C; Tue, 30 Mar 2004 23:42:56 +0200 (CEST) Received: by dwp.des.no (Postfix, from userid 2602) id 1A63D33CAA; Tue, 30 Mar 2004 23:42:56 +0200 (CEST) To: Robert Watson References: From: des@des.no (Dag-Erling =?iso-8859-1?q?Sm=F8rgrav?=) Date: Tue, 30 Mar 2004 23:42:56 +0200 In-Reply-To: (Robert Watson's message of "Tue, 30 Mar 2004 15:36:57 -0500 (EST)") Message-ID: User-Agent: Gnus/5.090024 (Oort Gnus v0.24) Emacs/21.3 (berkeley-unix) MIME-Version: 1.0 Content-Type: text/plain; charset=iso-8859-1 Content-Transfer-Encoding: quoted-printable X-Spam-Checker-Version: SpamAssassin 2.63 (2004-01-11) on flood.des.no X-Spam-Level: X-Spam-Status: No, hits=0.0 required=5.0 tests=AWL autolearn=no version=2.63 cc: current@freebsd.org Subject: Re: performance of jailed processes X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 30 Mar 2004 21:43:07 -0000 Robert Watson writes: > Somewhat more painful suggestion, but could you generate ktraces against a > mysql client doing the query inside and out of jail, then using whatever > flag sets relative timestamps on kdump, diff the two and see where the > substantial differences begin? OK, ktrace shows some interesting differences. I used ktrace -tcsw to get syscalls, signals and context switches. Here's mysql outside the jail reading the row returned from the query (from kdump -tcs -R): 12698 mysql 0.000219 CALL read(0x3,0x806b000,0x82af) 12698 mysql 0.000117 RET read 27981/0x6d4d 12698 mysql 0.000029 CALL read(0x3,0x8071d4d,0x1562) 12698 mysql 0.000189 RET read 2896/0xb50 12698 mysql 0.000005 CALL read(0x3,0x807289d,0xa12) 12698 mysql 0.000394 RET read 2578/0xa12 here's mysql inside the jail doing the same thing: 12703 mysql 0.000264 CALL read(0x3,0x8070000,0x82af) 12703 mysql 0.000043 RET read 469/0x1d5 12703 mysql 0.000005 CALL read(0x3,0x80701d5,0x80da) 12703 mysql 1.208382 RET read 4344/0x10f8 12703 mysql 0.001126 CALL read(0x3,0x80712cd,0x6fe2) 12703 mysql 0.000027 RET read 1448/0x5a8 12703 mysql 0.000032 CALL read(0x3,0x8071875,0x6a3a) 12703 mysql 0.000183 RET read 1448/0x5a8 12703 mysql 0.000029 CALL read(0x3,0x8071e1d,0x6492) 12703 mysql 1.197240 RET read 1448/0x5a8 12703 mysql 0.000529 CALL read(0x3,0x80723c5,0x5eea) 12703 mysql 1.199249 RET read 2896/0xb50 12703 mysql 0.000535 CALL read(0x3,0x8072f15,0x539a) 12703 mysql 1.199303 RET read 2896/0xb50 12703 mysql 0.000701 CALL read(0x3,0x8073a65,0x484a) 12703 mysql 0.002045 RET read 2896/0xb50 12703 mysql 0.000028 CALL read(0x3,0x80745b5,0x3cfa) 12703 mysql 1.197229 RET read 1448/0x5a8 12703 mysql 0.000261 CALL read(0x3,0x8074b5d,0x3752) 12703 mysql 1.200116 RET read 2896/0xb50 12703 mysql 0.001101 CALL read(0x3,0x80756ad,0x2c02) 12703 mysql 1.199051 RET read 2896/0xb50 12703 mysql 0.000307 CALL read(0x3,0x80761fd,0x20b2) 12703 mysql 1.200152 RET read 2896/0xb50 12703 mysql 0.000735 CALL read(0x3,0x8076d4d,0x1562) 12703 mysql 1.198556 RET read 2896/0xb50 12703 mysql 0.000135 CALL read(0x3,0x807789d,0xa12) 12703 mysql 0.001835 RET read 2578/0xa12 12703 mysql 0.000208 CALL break(0x8083000) 12703 mysql 0.000009 RET break 0 let's look at an inside trace *with* context switches and see where the longest delays (>=3D 0.1 s) are: # kdump -R | egrep -B1 ' (0\.[1-9]|1\.[0-9])' 12703 mysql 0.000003 CSW stop kernel 12703 mysql 1.193959 CSW resume kernel -- 12703 mysql 0.000086 CSW stop kernel 12703 mysql 1.208101 CSW resume kernel -- 12703 mysql 0.000197 CSW stop kernel 12703 mysql 1.196910 CSW resume kernel -- 12703 mysql 0.000005 CSW stop kernel 12703 mysql 1.199010 CSW resume kernel -- 12703 mysql 0.000216 CSW stop kernel 12703 mysql 1.199035 CSW resume kernel -- 12703 mysql 0.000006 CSW stop kernel 12703 mysql 1.197189 CSW resume kernel -- 12703 mysql 0.000007 CSW stop kernel 12703 mysql 1.199705 CSW resume kernel -- 12703 mysql 0.000747 CSW stop kernel 12703 mysql 1.198046 CSW resume kernel -- 12703 mysql 0.000206 CSW stop kernel 12703 mysql 1.199760 CSW resume kernel -- 12703 mysql 0.000250 CSW stop kernel 12703 mysql 1.198188 CSW resume kernel oops, they're all in context switches... DES --=20 Dag-Erling Sm=F8rgrav - des@des.no