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

On Mon, Jun 18, 2012 at 8:42 PM, Jeff Janes <jeff.janes@gmail.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
write18.80  16.553878           3   4929697           lseek13.51   11.890826           6   1906179     12819 read10.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