From owner-freebsd-hackers Tue Apr 1 14:16:37 1997 Return-Path: Received: (from root@localhost) by freefall.freebsd.org (8.8.5/8.8.5) id OAA06473 for hackers-outgoing; Tue, 1 Apr 1997 14:16:37 -0800 (PST) Received: from spooky.rwwa.com (rwwa.com [198.115.177.3]) by freefall.freebsd.org (8.8.5/8.8.5) with ESMTP id OAA06463 for ; Tue, 1 Apr 1997 14:16:30 -0800 (PST) Received: from spooky.rwwa.com (localhost.rwwa.com [127.0.0.1]) by spooky.rwwa.com (8.7.5/8.7.3) with ESMTP id RAA04747 for ; Tue, 1 Apr 1997 17:16:05 -0500 (EST) Message-Id: <199704012216.RAA04747@spooky.rwwa.com> X-Mailer: exmh version 2.0gamma 1/27/96 To: hackers@freebsd.org Subject: Can anyone here help these people? Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Date: Tue, 01 Apr 1997 17:16:05 -0500 From: Robert Withrow Sender: owner-hackers@freebsd.org X-Loop: FreeBSD.org Precedence: bulk There is an order of magnitude difference in the performance of postgress between FreeBSD and Linux, with FreeBSD loosing. Here is a ktrace that shows the problem... ------- Forwarded Message Return-Path: scrappy@postgreSQL.org Received: from relay1.shore.net (root@relay1.shore.net [192.233.85.129]) by spooky.rwwa.com (8.7.5/8.7.3) with ESMTP id TAA04928 for ; Thu, 27 Mar 1997 19:59:52 -0500 (EST) Received: from hub.org (root@hub.org [207.107.138.200]) by relay1.shore.net (8.8.3/8.8.3) with ESMTP id SAA19485 for ; Thu, 27 Mar 1997 18:42:28 -0500 (EST) Received: from localhost (daemon@localhost) by hub.org (8.8.2/8.7.5) with SMTP id SAA02298; Thu, 27 Mar 1997 18:39:39 -0500 (EST) Received: by hub.org (bulk_mailer v1.5); Thu, 27 Mar 1997 18:39:04 -0500 Received: (from pgsql@localhost) by hub.org (8.8.2/8.7.5) id SAA02241 for hackers-outgoing; Thu, 27 Mar 1997 18:38:56 -0500 (EST) X-Authentication-Warning: hub.org: pgsql set sender to owner-pg95-dev@postgreSQL.org using -f Received: from phssthpok.illusionary.com (phssthpok.illusionary.com [206.174.15.210]) by hub.org (8.8.2/8.7.5) with ESMTP id SAA02226 for ; Thu, 27 Mar 1997 18:38:46 -0500 (EST) Received: from localhost (dglidden@localhost) by phssthpok.illusionary.com (8.8.5/8.8.3) with SMTP id SAA12047 for ; Thu, 27 Mar 1997 18:38:34 -0500 (EST) Date: Thu, 27 Mar 1997 18:38:33 -0500 (EST) From: Derek Glidden To: hackers@postgreSQL.org Subject: [HACKERS] FreeBSD execution traces Message-ID: MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII Sender: owner-pg95-dev@hub.org Reply-To: hackers@hub.org, Derek Glidden Here's a sample of the ktrace from the backend showing one of the first calls of the INSERT query: 247 postgres 0.004788 RET read 8192/0x2000 247 postgres 0.000441 CALL write(0x5,0x158000,0xe) 247 postgres 0.000101 GIO fd 5 wrote 14 bytes "CINSERT 30560\0" 247 postgres 0.000365 RET write 14/0xe 247 postgres 0.000213 CALL read(0x4,0x14a000,0xe000) 247 postgres 0.018655 GIO fd 4 read 3 bytes "Q \0" 247 postgres 0.000082 RET read 3 247 postgres 0.000074 CALL write(0x5,0x158000,0x2) 247 postgres 0.000126 GIO fd 5 wrote 2 bytes "I\0" The number 0.0xxxx is the number of seconds since the previous system call. This is the final end of one of the first INSERT calls made by the client to the backend. Notice that the time between sending the "CINSERT" and receiving the next "Q " is very small. Here's a later call: 247 postgres 0.000182 CALL lseek(0xf,0,0,0,0x2) 247 postgres 0.000069 RET lseek 8192/0x2000 247 postgres 0.000702 CALL write(0x5,0x158000,0xe) 247 postgres 0.000101 GIO fd 5 wrote 14 bytes "CINSERT 30564\0" 247 postgres 0.000046 RET write 14/0xe 247 postgres 0.000190 CALL read(0x4,0x14a000,0xe000) 247 postgres 0.184748 GIO fd 4 read 3 bytes "Q \0" 247 postgres 0.000067 RET read 3 247 postgres 0.000068 CALL write(0x5,0x158000,0x2) 247 postgres 0.000126 GIO fd 5 wrote 2 bytes Notice how long it is before the backend receives the next "Q " after sending the "CINSERT." Now here's what it looks like on the client end: 809 posttest 0.000136 GIO fd 3 wrote 83 bytes "QINSERT INTO Torture VALUES (1, '03-27-1997', 'Data input at 16:00:27 \ 03-27-1997')\0" 809 posttest 0.003786 RET write 83/0x53 809 posttest 0.000124 CALL read(0x4,0x30000,0xe000) 809 posttest 0.000057 GIO fd 4 read 7 bytes "Pblank\0" 809 posttest 0.000034 RET read 7 809 posttest 0.000036 CALL read(0x4,0x30000,0xe000) 809 posttest 0.188054 GIO fd 4 read 14 bytes "CINSERT 42530\0" 809 posttest 0.000050 RET read 14/0xe 809 posttest 0.000056 CALL write(0x3,0x22000,0x3) 809 posttest 0.000126 GIO fd 3 wrote 3 bytes "Q \0" Here it's almost 1/5 of a second between getting the "Pblank" (I don't know what that signifies, maybe it's a clue to something.) after the insert and reading the "CINSERT." (The backend and client dumps are from different runs, so the numbers don't correspond to each other.) It looks like this might actually have something to do with the FreeBSD networking code, because it looks like the backend is writing the message to the socket, but the client isn't getting it until almost 1/5 of a second later. Why INSERT is the only operation that seems to be so slow, though, is beyond me. Perhaps it's just that each INSERT is more or less its own transaction while each SELECT is a single transaction no matter how many tuples it returns? If anyone wants the full trace/dump files, I've got 'em at: http://www.illusionary.com/~dglidden/postgres/ You'll need to either be running FreeBSD and use `kdump` to read the *.trace files, or get the *.dump files which have already been converted to "human-readable" text. - -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=- Derek Glidden http://www.illusionary.com Web development, databases, graphics and general plumbing Linux, FreeBSD, Apache, PostgreSQL, PHP (Say No to NT!) Unsolicited commercial EMail will be proofread for $500 ea. ------- End of Forwarded Message ----------------------------------------------------------------------------- Robert Withrow, Tel: +1 617 592 8935, Net: witr@rwwa.COM