Insert Times

I'm trying to track down some performance issues where time (in
milliseconds) is critical. One thing that I've noticed is that it
seems like the first insert takes an inordinate amount of time.
Inserts after the first one are acceptable. My production environment
is like this:

Solaris 9
JBoss
Java 1.4.2
PostgreSQL 7.3 JDBC drivers
PostgreSQL 7.3.2 database

I've isolated the problem in order to more accurately recreate it by
using the following table definition and insert statement:

gregqa=# \d one
Table "public.one"
Column | Type | Modifiers
--------+------------------------+-----------
id | integer |
msg | character varying(255) |

explain analyze insert into one (id, msg) values (1, 'blah');

I'm currently using Jython (Python written in Java) and the JDBC
drivers to recreate the problem with this code:

from java.sql import *
from java.lang import Class

Class.forName("org.postgresql.Driver")
db =
DriverManager.getConnection("jdbc:postgresql://localhost:5432/blah",
"blah", "")

for i in range(5):
query = "EXPLAIN ANALYZE INSERT INTO one (id, msg) VALUES (1,
'blah');"
print query

st = db.createStatement()
rs = st.executeQuery(query)
rsmd = rs.getMetaData()
cols = rsmd.getColumnCount()
cols_range = range(1, cols + 1)

while rs.next():
for col in cols_range:
print rs.getString(col)

rs.close()
st.close()

db.close()

When I run this code (which will execute the query 5 times before
finishing), here's the output I get:

[bert:~/tmp] > env CLASSPATH=pg73jdbc3.jar jython dbquery.py
EXPLAIN ANALYZE INSERT INTO one (id, msg) VALUES (1, 'blah');
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.02..0.02 rows=1
loops=1)
Total runtime: 0.59 msec
EXPLAIN ANALYZE INSERT INTO one (id, msg) VALUES (1, 'blah');
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.02..0.02 rows=1
loops=1)
Total runtime: 0.17 msec
EXPLAIN ANALYZE INSERT INTO one (id, msg) VALUES (1, 'blah');
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.01..0.01 rows=1
loops=1)
Total runtime: 0.12 msec
EXPLAIN ANALYZE INSERT INTO one (id, msg) VALUES (1, 'blah');
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.01..0.01 rows=1
loops=1)
Total runtime: 0.12 msec
EXPLAIN ANALYZE INSERT INTO one (id, msg) VALUES (1, 'blah');
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.01..0.01 rows=1
loops=1)
Total runtime: 0.12 msec

[bert:~/tmp] > env CLASSPATH=pg73jdbc3.jar jython dbquery.py
EXPLAIN ANALYZE INSERT INTO one (id, msg) VALUES (1, 'blah');
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.02..0.02 rows=1
loops=1)
Total runtime: 0.55 msec
EXPLAIN ANALYZE INSERT INTO one (id, msg) VALUES (1, 'blah');
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.02..0.02 rows=1
loops=1)
Total runtime: 0.15 msec
EXPLAIN ANALYZE INSERT INTO one (id, msg) VALUES (1, 'blah');
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.01..0.01 rows=1
loops=1)
Total runtime: 0.13 msec
EXPLAIN ANALYZE INSERT INTO one (id, msg) VALUES (1, 'blah');
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.01..0.02 rows=1
loops=1)
Total runtime: 0.13 msec
EXPLAIN ANALYZE INSERT INTO one (id, msg) VALUES (1, 'blah');
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.01..0.02 rows=1
loops=1)
Total runtime: 0.17 msec

(I ran it twice to show that it is consistently repeatable)

Now, of course this query isn't very interesting and shouldn't take
very long, but it does illustrate the time difference between the first
query and the last four. On my bigger insert query, it's taking 79msec
for the first query and ~0.9msec for the last four. Any ideas as to
why the first query would take so long? I can provide more information
if necessary, but I think the example is pretty simple as is.

--
PC Drew