Re: performance regression in 9.2 when loading lots of small tables

On Mon, Jun 18, 2012 at 8:42 PM, Jeff Janes <jeff(dot)janes(at)gmail(dot)com> wrote:
> There was a regression introduced in 9.2 that effects the creation and
> loading of lots of small tables in a single transaction.
>
> It affects the loading of a pg_dump file which has a large number of
> small tables (10,000 schemas, one table per schema, 10 rows per
> table).  I did not test other schema configurations, so these
> specifics might not be needed to invoke the problem.
>
> It causes the loading of a dump with "psql -1 -f " to run at half the
> previous speed.  Speed of loading without the -1 is not changed.

I tried to figure out why this was happening. I tried it out on the
IBM POWER7 box after building from
f5297bdfe4c4a47376c41b96161fb55c2294a0b1 and it ran for about 14
minutes. 'time' reports that psql used 38 seconds of user time and 11
seconds of system time. The remaining time was presumably spent
waiting for the backend and/or the kernel.

I ran the backend under strace -cf and it had this to say:

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
45.31 39.888639 10 3836379 write
18.80 16.553878 3 4929697 lseek
13.51 11.890826 6 1906179 12819 read
10.24 9.011690 7 1372354 5995 recv
6.27 5.517929 5 1107766 brk
2.07 1.818345 91 20068 fsync
1.46 1.281999 15 87260 send
1.15 1.015621 24 42527 11334 open

I did a separate run using perf and it had this to say:

Events: 1M cycles
+ 13.18% postgres postgres [.] FlushRelationBuffers
+ 9.65% postgres postgres [.] comparetup_index_btree
+ 9.34% swapper [kernel.kallsyms] [k]
.pseries_dedicated_idle_sleep
+ 4.41% postgres postgres [.] CopyReadLine
+ 4.23% postgres postgres [.] tuplesort_heap_siftup
+ 4.17% postgres postgres [.] LockReassignCurrentOwner
+ 3.88% postgres postgres [.] pg_mbstrlen_with_len
+ 2.74% postgres postgres [.] pg_verify_mbstr_len
+ 2.46% postgres postgres [.] NextCopyFromRawFields
+ 2.44% postgres postgres [.] btint4cmp
+ 2.08% postgres libc-2.14.90.so [.] memcpy
+ 2.06% postgres postgres [.] hash_seq_search
+ 1.55% postgres [kernel.kallsyms] [k] .__copy_tofrom_user
+ 1.29% postgres libc-2.14.90.so [.]
__GI_____strtoll_l_internal
+ 1.16% postgres postgres [.] pg_utf_mblen

There are certainly opportunities for optimization there but it's sure
not obvious to me what it has to do with either of the commits you
mention. I haven't actually verified that there's a regression on
this box as result of either of those commits, though: I just profiled
master. Maybe I better go check that.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company