Re: 8.x index insert performance

Second try... no attachment this time.

I've finally gotten around to profiling the back end.  Here is a more
precise description of what I'm doing:

I am copying data into two tables, order_main and order_transition
(table defs at the end of this post).  The order_transition table has
roughly double the number of rows as the order_main table.

My program is a C program using the libpq copy api which effectively
simulates our real application.  It reads data from two data files, and
appends copy-formatted data into two in-memory buffers.  After 10,000
order_transitions, it copies the order_main data, then the
order_transition data, then commits.  The test program is running on a
different machine than the DB.

After each batch it writes a record to stdout with the amount of time it
took to copy and commit the data (time only includes pg time, not the
time it took to build the buffers).  A graph showing the performance
characteristics is here:

<http://kkcsm.net/pgcpy.jpg>

The horizontal axis is number of transitions * 10000 that have been
written.  The vertical axis is time in milliseconds to copy and commit
the data.  The commit time is very consistent up until about 60,000,000
rows, then performance drops and times become much less consistent.

I profiled the backend at three points, on batches 4, 6042 and 6067.
The first is right after start, the second is right before we hit the
wall, and the third is one of the initial slow batches.

I'm including inline the first 20 lines of gprof output for each batch.
Please let me know if this is insufficient.  I'll supply any necessary
further info.

Since this thread is stale, I'll repeat relevant hardware/software
stats:  server is a dual, dual-core opteron with 4GB RAM.  Disk is an
EMC Symmetrix connected via FC.  Data, index, logs on three separate
LUNS.  OS is SuSE Enterprise 9.  Postgres version is 8.1.b4.
shared_buffers=32768, fsync=off.

Thanks in advance for your help.

-K

---------------------------
> head -n 20 gprof.txt.4.777.47
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls   s/call   s/call  name
 10.92      0.38     0.38    55027     0.00     0.00  XLogInsert
  6.90      0.62     0.24   702994     0.00     0.00  _bt_compare
  5.46      0.81     0.19        2     0.10     1.64  DoCopy
  4.60      0.97     0.16    16077     0.00     0.00  CopyReadLine
  3.74      1.10     0.13   484243     0.00     0.00  bttextcmp
  2.87      1.20     0.10    93640     0.00     0.00  _bt_binsrch
  2.59      1.29     0.09   484243     0.00     0.00  varstr_cmp
  2.59      1.38     0.09   364292     0.00     0.00  LWLockRelease
  2.30      1.46     0.08   703394     0.00     0.00  FunctionCall2
  2.01      1.53     0.07   138025     0.00     0.00  hash_any
  2.01      1.60     0.07   133176     0.00     0.00  ReadBuffer
  2.01      1.67     0.07   364110     0.00     0.00  LWLockAcquire
  2.01      1.74     0.07   132563     0.00     0.00  PinBuffer
  1.72      1.80     0.06    38950     0.00     0.00  _bt_insertonpg
  1.72      1.86     0.06    38767     0.00     0.00  _bt_mkscankey

---------------------------
> head -n 20 gprof.txt.6042.1344.84
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls   s/call   s/call  name
  9.67      0.52     0.52    50431     0.00     0.00  XLogInsert
  7.71      0.94     0.42  1045427     0.00     0.00  _bt_compare
  5.95      1.26     0.32   713392     0.00     0.00  bttextcmp
  4.28      1.49     0.23  1045814     0.00     0.00  FunctionCall2
  3.35      1.67     0.18   155756     0.00     0.00  _bt_binsrch
  2.60      1.81     0.14   713392     0.00     0.00  varstr_cmp
  2.60      1.95     0.14   475524     0.00     0.00  LWLockAcquire
  2.60      2.09     0.14   191837     0.00     0.00  ReadBuffer
  2.60      2.23     0.14        2     0.07     2.52  DoCopy
  2.60      2.37     0.14   197393     0.00     0.00  hash_search
  2.60      2.51     0.14   197205     0.00     0.00  hash_any
  2.23      2.63     0.12   190481     0.00     0.00  PinBuffer
  2.04      2.74     0.11   345866     0.00     0.00  AllocSetAlloc
  1.86      2.84     0.10   475788     0.00     0.00  LWLockRelease
  1.86      2.94     0.10    29620     0.00     0.00  pg_localtime

---------------------------
> head -n 20 gprof.txt.6067.9883.31
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls   s/call   s/call  name
 17.17      1.14     1.14    51231     0.00     0.00  XLogInsert
 10.82      1.85     0.72  1065556     0.00     0.00  _bt_compare
  4.77      2.17     0.32   158378     0.00     0.00  _bt_binsrch
  3.18      2.38     0.21   202921     0.00     0.00  hash_search
  3.18      2.59     0.21   742891     0.00     0.00  bttextcmp
  2.87      2.78     0.19  1485787     0.00     0.00  pg_detoast_datum
  2.87      2.97     0.19  1065325     0.00     0.00  FunctionCall2
  2.65      3.14     0.18   490373     0.00     0.00  LWLockAcquire
  2.27      3.29     0.15        2     0.08     3.08  DoCopy
  2.27      3.44     0.15   490908     0.00     0.00  LWLockRelease
  1.97      3.57     0.13   195049     0.00     0.00  ReadBuffer
  1.97      3.70     0.13   742891     0.00     0.00  varstr_cmp
  1.66      3.81     0.11   462134     0.00     0.00  LockBuffer
  1.51      3.91     0.10   191345     0.00     0.00  PinBuffer
  1.51      4.01     0.10   195049     0.00     0.00  UnpinBuffer

---------------------------
create table order_main (
    ord_id varchar(12) not null,
    firm_id varchar not null,
    firm_sub_id varchar not null,
    cl_ord_id varchar not null,
    clearing_firm varchar not null,
    clearing_account varchar not null,
    symbol varchar not null,
    side varchar(1) not null,
    size integer not null,
    price numeric(10,4) not null,
    expire_time timestamp with time zone,
    flags varchar(7) not null
);

create unique index order_main_pk on order_main (
    ord_id
) tablespace idx_space;

create index order_main_ak1 on order_main (
    cl_ord_id
) tablespace idx_space;


create table order_transition (
    collating_seq bigint not null,
    ord_id varchar(12) not null,
    cl_ord_id varchar,
    sending_time timestamp with time zone not null,
    transact_time timestamp with time zone not null,
    flags varchar(6) not null,
    exec_id varchar(12),
    size integer,
    price numeric(10,4),
    remainder integer,
    contra varchar
);

create unique index order_transition_pk on order_transition (
    collating_seq
) tablespace idx_space;

create index order_transition_ak1 on order_transition (
    ord_id
) tablespace idx_space;

create index order_transition_ak2 on order_transition (
    cl_ord_id
)
tablespace idx_space
where cl_ord_id is not null;

create index order_transition_ak3 on order_transition (
    exec_id
)
tablespace idx_space
where exec_id is not null;