Re: [PERFORM] insert performance for win32

[Merlin Moncure]

> On Tuesday 06 September 2005 19:11, Merlin Moncure wrote:
> Here's the timeofday ... i'll do the gprof as soon as I can.
> Every 50000 rows...
>
> Wed Sep 07 13:58:13.860378 2005 CEST
> Wed Sep 07 13:58:20.926983 2005 CEST
> Wed Sep 07 13:58:27.928385 2005 CEST
> Wed Sep 07 13:58:35.472813 2005 CEST
> Wed Sep 07 13:58:42.825709 2005 CEST
> Wed Sep 07 13:58:50.789486 2005 CEST
> Wed Sep 07 13:58:57.553869 2005 CEST
> Wed Sep 07 13:59:04.298136 2005 CEST
> Wed Sep 07 13:59:11.066059 2005 CEST
> Wed Sep 07 13:59:19.368694 2005 CEST

ok, I've been in crunching profile profile graphs, and so far have been
only been able to draw following conclusions.

For bulk, 'in-transaction' insert:
1. win32 is slower than linux.  win32 time for each insert grows with #
inserts in xact, linux does not (or grows much slower).  Win32 starts
out about 3x slower and grows to 10x slower after 250k inserts.

2. ran a 50k profile vs. 250k profile.  Nothing jumps out as being
slower or faster: most time is spent in yyparse on either side.  From
this my preliminary conclusion is that there is something going on in
the win32 api which is not showing in the profile.

3. The mingw gprof cumulative seconds does not show measurable growth in
cpu time/insert in 50k/250k profile.

I'm now talking suggestions about where to look for performance problems
:(.
Merlin

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
       choose an index scan if your joining column's datatypes do not
       match

[Tom Lane-2]

"Merlin Moncure" <merlin.moncure@...> writes:
> ok, I've been in crunching profile profile graphs, and so far have been
> only been able to draw following conclusions.

> For bulk, 'in-transaction' insert:
> 1. win32 is slower than linux.  win32 time for each insert grows with #
> inserts in xact, linux does not (or grows much slower).  Win32 starts
> out about 3x slower and grows to 10x slower after 250k inserts.

Just to be clear: what you were testing was
        BEGIN;
        INSERT ... VALUES (...);
        repeat insert many times
        COMMIT;
with each statement issued as a separate PQexec() operation, correct?
Was this set up as a psql script, or specialized C code?  (If a psql
script, I wonder whether it's psql that's chewing the time.)

> 2. ran a 50k profile vs. 250k profile.  Nothing jumps out as being
> slower or faster: most time is spent in yyparse on either side.  From
> this my preliminary conclusion is that there is something going on in
> the win32 api which is not showing in the profile.

Hmm.  Client/server data transport maybe?  It would be interesting to
try inserting the same data in other ways:
        * COPY from client
        * COPY from disk file
        * INSERT/SELECT from another table
and see whether you see a similar slowdown.

                        regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
       subscribe-nomail command to majordomo@... so that your
       message can get through to the mailing list cleanly

[Merlin Moncure]

Tom Lane wrote:
> Just to be clear: what you were testing was
> BEGIN;
> INSERT ... VALUES (...);
> repeat insert many times
> COMMIT;
roger.

> with each statement issued as a separate PQexec() operation, correct?
> Was this set up as a psql script, or specialized C code?  (If a psql
> script, I wonder whether it's psql that's chewing the time.)

I thought that too.  I'm running dump file piped to psql in quiet mode,
output redirected to file.  Here is the profile for psql:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total          
 time   seconds   seconds    calls   s/call   s/call  name    
 40.74      1.65     1.65   499988     0.00     0.00  yylex
 10.37      2.07     0.42   249994     0.00     0.00  SendQuery
  7.41      2.37     0.30  1499959     0.00     0.00  GetVariable
  7.16      2.66     0.29        1     0.29     3.71  MainLoop
  4.94      2.86     0.20   499988     0.00     0.00  psql_scan
  3.95      3.02     0.16   249999     0.00     0.00  SetVariable
  3.46      3.16     0.14  5999686     0.00     0.00  emit
  2.47      3.26     0.10                             pg_strcasecmp

which tells nothing.  I think next step is to write libpq app running
the test case and compare execparams vs. exec vs. psql.  win32 has
excellent hardware timer which I can use.

The mingw gprof self seconds, btw, are low and unreliable.  One thing I
do know is that I block commented out vast sections of the file /*...*/.
on 200k rec load, times were
to load 50k recs in a single transaction, with 2nd and 3rd 50 recs
commented.
          commented  time
block 1       no      30
block 2       yes     39
block 3       yes     24
block 4       no      69

this suggests psql read time is constant (but rather slow) but per
insert time grows.

> > 2. ran a 50k profile vs. 250k profile.  Nothing jumps out as being
> > slower or faster: most time is spent in yyparse on either side.
From
> > this my preliminary conclusion is that there is something going on
in
> > the win32 api which is not showing in the profile.
>
> Hmm.  Client/server data transport maybe?  It would be interesting to
> try inserting the same data in other ways:
> * COPY from client

runs super fast (500k recs in a few seconds)

> * INSERT/SELECT from another table
> and see whether you see a similar slowdown.

the command I used to generate test file, insert ... select from
generate_series runs super quick, as does create table as select..

merlin

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

               http://www.postgresql.org/docs/faq