Date: Tue, 01 Apr 1997 17:16:05 -0500 From: Robert Withrow <witr@rwwa.com> To: hackers@freebsd.org Subject: Can anyone here help these people? Message-ID: <199704012216.RAA04747@spooky.rwwa.com>
next in thread | raw e-mail | index | archive | help
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 <witr@rwwa.com>; 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 <witr@rwwa.com>; 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
<hackers@postgresql.org>; 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 <hackers@postgresql.org>; Thu, 27 Mar
1997 18:38:34 -0500 (EST)
Date: Thu, 27 Mar 1997 18:38:33 -0500 (EST)
From: Derek Glidden <dglidden@illusionary.com>
To: hackers@postgreSQL.org
Subject: [HACKERS] FreeBSD execution traces
Message-ID: <Pine.NEB.3.95q.970327182239.11955A-100000@phssthpok.illusionary.co
m>
MIME-Version: 1.0
Content-Type: TEXT/PLAIN; charset=US-ASCII
Sender: owner-pg95-dev@hub.org
Reply-To: hackers@hub.org, Derek Glidden <dglidden@illusionary.com>
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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?199704012216.RAA04747>