Re: psql vs perl prepared inserts

Neil Conway <neilc(at)samurai(dot)com> writes:
> The intent of prepared statements is to reduce the overhead of running
> the parser, rewriter and planner multiple times for a statement that is
> executed multiple times. For an INSERT query without any sub-selects
> that is not rewritten by any rules, the cost to parse, rewrite and plan
> the statement is trivial.

You'd be surprised ...

I was looking into this just the other day, with a test case that looks
like

create table bench1 (id int NOT NULL,id2 int NOT NULL,id3 int NOT NULL,
dummy1 char(30));
create unique index bench1_index_ on bench1 (id,id2);
create index bench1_index_1 on bench1 (id3);
begin;
insert into bench1 values (0,0,0,'ABCDEFGHIJ');
... 300,000 inserts ...
insert into bench1 values (167151,167151,167151,'CDEFGHIJKL');
commit;

According to gprof, the above-1% functions are

% cumulative self self total
time seconds seconds calls s/call s/call name
6.62 53.38 53.38 300007 0.00 0.00 yyparse
5.31 96.19 42.81 11808781 0.00 0.00 hash_search
4.44 132.00 35.81 61268959 0.00 0.00 AllocSetAlloc
4.23 166.13 34.13 902304 0.00 0.00 XLogInsert
3.20 191.99 25.86 13688735 0.00 0.00 _bt_compare
2.94 215.75 23.76 12158347 0.00 0.00 LWLockAcquire
2.67 237.32 21.58 4500066 0.00 0.00 base_yylex
2.56 258.00 20.68 6000510 0.00 0.00 SearchCatCache
1.99 274.07 16.07 12160856 0.00 0.00 LWLockRelease
1.88 289.25 15.18 13008925 0.00 0.00 hash_any
1.49 301.25 12.01 2452386 0.00 0.00 PinBuffer
1.36 312.25 11.00 1201324 0.00 0.00 fmgr_info_cxt_security
1.36 323.24 10.98 300000 0.00 0.00 planner
1.19 332.81 9.57 20700142 0.00 0.00 MemoryContextAllocZeroAligned

I don't trust gprof's tree-structured breakdown entirely, but it puts
a pretty significant fraction of the blame on parse/plan activities:

3.66 767.69 300007/300007 PostgresMain [4]
[5] 95.6 3.66 767.69 300007 exec_simple_query [5]
6.13 283.12 300007/300007 PortalRun [6]
0.48 167.39 300007/300007 pg_analyze_and_rewrite [9]
0.47 122.85 300007/300007 pg_plan_queries [16]
1.56 93.29 300007/300007 pg_parse_query [23]
0.62 34.78 300007/300007 pg_rewrite_queries [52]
0.99 17.39 300007/300007 PortalDrop [79]
0.56 16.26 600014/600014 finish_xact_command [84]
1.19 6.89 300007/300007 CreatePortal [126]
1.08 2.29 600014/600014 start_xact_command [186]
1.88 0.36 300007/300007 PortalStart [218]
0.76 1.44 300007/300007 pq_puttextmessage [220]
1.35 0.00 300007/600017 set_ps_display [210]
1.27 0.00 300007/300007 CreateCommandTag [271]
0.89 0.22 300007/300007 printtup_create_DR [286]
0.74 0.00 300007/300007 CreateDestReceiver [328]
0.61 0.00 300007/600015 pgstat_report_activity [277]
0.10 0.14 300007/13864259 pfree [112]
0.23 0.00 300007/300007 PortalSetResultFormat [449]
0.19 0.00 300007/300007 IsAbortedTransactionBlockState [474]
0.07 0.00 300007/300007 printtup_destroy [564]
0.05 0.00 300007/300007 PortalDefineQuery [580]
0.03 0.00 300007/300007 EndCommand [617]
0.01 0.00 300007/300007 BeginCommand [670]

That adds up to over 50% of the runtime spent in parse/rewrite/plan.

I haven't gotten around to converting the test case into a program that
can use a prepared INSERT command, but it looks plausible to expect
a factor of 2 or so speedup ... of course, using COPY would completely
blow this away, anyway ...

regards, tom lane