On Tue, Jun 19, 2012 at 4:33 PM, Robert Haas <robertmh...@gmail.com> wrote:
> On Mon, Jun 18, 2012 at 8:42 PM, Jeff Janes <jeff.ja...@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 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
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
