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

On Tue, Jun 19, 2012 at 4:33 PM, Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
> 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.

I built REL9_1_STABLE from commit
1643031e5fe02d2de9ae6b8f86ef9ffd09fe7d3f and it took 19m45.250s, even
slower than master. So something is different in my environment
versus yours.

I ran this build with perf also, and got this:

38.77% postgres postgres [.] FlushRelationBuffers
6.80% swapper [kernel.kallsyms] [k]
.pseries_dedicated_idle_sleep
4.84% postgres postgres [.] comparetup_index_btree
3.23% postgres postgres [.] CopyReadLine
2.24% postgres postgres [.] tuplesort_heap_siftup
2.23% postgres postgres [.] pg_mbstrlen_with_len
2.08% postgres postgres [.] LockReassignCurrentOwner
2.01% postgres postgres [.] pg_verify_mbstr_len
1.90% postgres postgres [.] NextCopyFromRawFields
1.62% postgres postgres [.] btint4cmp
1.41% postgres libc-2.14.90.so [.] memcpy
1.39% postgres postgres [.] LWLockAcquire
1.22% postgres postgres [.] LWLockRelease
1.19% postgres postgres [.] pg_utf_mblen
1.05% postgres [kernel.kallsyms] [k] .__copy_tofrom_user

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