Thread: Insert Times

Insert Times

From

PC Drew

Date:

26 January 2004, 20:01:17

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

Re: Insert Times

From

"Brad Gawne"

Date:

27 January 2004, 02:14:20

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@postgresql.org
[mailto:pgsql-performance-owner@postgresql.org] On Behalf Of PC Drew
Sent: January 26, 2004 16:00
To: pgsql-performance@postgresql.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

Re: Insert Times

From

"Leeuw van der, Tim"

Date:

27 January 2004, 06:39:19

Hi,

My personal feeling on this is, that the long time taken for the first query
is for loading all sorts of libraries, JVM startup overhead etc.

What if you first do some SELECT (whatever), on a different table, to warm
up the JVM and the database?

regards,

--Tim

THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY
MATERIAL and is thus for use only by the intended recipient. If you received
this in error, please contact the sender and delete the e-mail and its
attachments from all computers.

Re: Insert Times

From

"PC Drew"

Date:

27 January 2004, 13:06:50

I tested this out and saw no improvement:

EXPLAIN ANALYZE SELECT * FROM one;
Seq Scan on one  (cost=0.00..20.00 rows=1000 width=404) (actual time=0.04..0.50 rows=51 loops=1)
Total runtime: 0.75 msec
EXPLAIN ANALYZE SELECT * FROM one;
Seq Scan on one  (cost=0.00..20.00 rows=1000 width=404) (actual time=0.06..0.50 rows=51 loops=1)
Total runtime: 0.64 msec
EXPLAIN ANALYZE SELECT * FROM one;
Seq Scan on one  (cost=0.00..20.00 rows=1000 width=404) (actual time=0.04..0.40 rows=51 loops=1)
Total runtime: 0.54 msec
EXPLAIN ANALYZE SELECT * FROM one;
Seq Scan on one  (cost=0.00..20.00 rows=1000 width=404) (actual time=0.04..0.41 rows=51 loops=1)
Total runtime: 0.54 msec
EXPLAIN ANALYZE SELECT * FROM one;
Seq Scan on one  (cost=0.00..20.00 rows=1000 width=404) (actual time=0.04..0.41 rows=51 loops=1)
Total runtime: 0.53 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.85 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.02..0.02 rows=1 loops=1)
Total runtime: 0.14 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.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.02 rows=1 loops=1)
Total runtime: 0.12 msec



-----Original Message-----
From:    Leeuw van der, Tim [mailto:tim.leeuwvander@nl.unisys.com]
Sent:    Tue 1/27/2004 12:38 AM
To:    PC Drew; pgsql-performance@postgresql.org
Cc:
Subject:    RE: [PERFORM] Insert Times

Hi,

My personal feeling on this is, that the long time taken for the first query
is for loading all sorts of libraries, JVM startup overhead etc.

What if you first do some SELECT (whatever), on a different table, to warm
up the JVM and the database?

regards,

--Tim

THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY
MATERIAL and is thus for use only by the intended recipient. If you received
this in error, please contact the sender and delete the e-mail and its
attachments from all computers.

Re: Insert Times

From

Alan Stange

Date:

27 January 2004, 14:59:00

PC Drew wrote:

>I tested this out and saw no improvement:
>
>
I'd still suspect some class loading issues and HotSpot compilation
issues are polluting your numbers.    Try using a PreparedStatement to
another table first in order to make sure that classes bytecode has been
loaded.   There are some command line options to the JVM to have it
print out some status info when it is loading classes and compiling
methods; you might want to turn on those options as well.

-- Alan

>EXPLAIN ANALYZE SELECT * FROM one;
>Seq Scan on one  (cost=0.00..20.00 rows=1000 width=404) (actual time=0.04..0.50 rows=51 loops=1)
>Total runtime: 0.75 msec
>EXPLAIN ANALYZE SELECT * FROM one;
>Seq Scan on one  (cost=0.00..20.00 rows=1000 width=404) (actual time=0.06..0.50 rows=51 loops=1)
>Total runtime: 0.64 msec
>EXPLAIN ANALYZE SELECT * FROM one;
>Seq Scan on one  (cost=0.00..20.00 rows=1000 width=404) (actual time=0.04..0.40 rows=51 loops=1)
>Total runtime: 0.54 msec
>EXPLAIN ANALYZE SELECT * FROM one;
>Seq Scan on one  (cost=0.00..20.00 rows=1000 width=404) (actual time=0.04..0.41 rows=51 loops=1)
>Total runtime: 0.54 msec
>EXPLAIN ANALYZE SELECT * FROM one;
>Seq Scan on one  (cost=0.00..20.00 rows=1000 width=404) (actual time=0.04..0.41 rows=51 loops=1)
>Total runtime: 0.53 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.85 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.02..0.02 rows=1 loops=1)
>Total runtime: 0.14 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.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.02 rows=1 loops=1)
>Total runtime: 0.12 msec
>
>
>
>-----Original Message-----
>From:    Leeuw van der, Tim [mailto:tim.leeuwvander@nl.unisys.com]
>Sent:    Tue 1/27/2004 12:38 AM
>To:    PC Drew; pgsql-performance@postgresql.org
>Cc:
>Subject:    RE: [PERFORM] Insert Times
>
>Hi,
>
>My personal feeling on this is, that the long time taken for the first query
>is for loading all sorts of libraries, JVM startup overhead etc.
>
>What if you first do some SELECT (whatever), on a different table, to warm
>up the JVM and the database?
>
>regards,
>
>--Tim
>
>THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY
>MATERIAL and is thus for use only by the intended recipient. If you received
>this in error, please contact the sender and delete the e-mail and its
>attachments from all computers.
>
>
>
>
>---------------------------(end of broadcast)---------------------------
>TIP 8: explain analyze is your friend
>
>