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

Drew,

Just a guess because I don't know PostGres that well, but it could be the
SQL parse time and once the statement is parsed, it may be pinned in parse
cache for subsequent calls.

Regards,
Brad Gawne

-----Original Message-----
From: pgsql-performance-owner(at)postgresql(dot)org
[mailto:pgsql-performance-owner(at)postgresql(dot)org] On Behalf Of PC Drew
Sent: January 26, 2004 16:00
To: pgsql-performance(at)postgresql(dot)org
Subject: [PERFORM] 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

---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faqs/FAQ.html