Re: 8.4 COPY performance regression on Solaris

Alan Li wrote:
> Hi,
>
> It seems that a COPY of 8M rows to a table to 8.4rc1 takes >30% longer
> than it does to 8.3.7 on Solaris.
>
> Here are the steps I've taken to reproduce this problem on two different
> solaris boxes (Solaris 10 11/06 s10x_u3wos_10 X86 and Solaris 10 8/07
> s10x_u4wos_12b X86). I've tried this on a Linux box, and I do not see
> the problem there.

tried that on my box (though I increased the testset size by 10x to get
more sensible runtimes) and I can reproduce that on Linux(CentoS
5.3/x86_64, Nehalem Xeon E5530) as well. I get ~450000 rows/s on 8.3 and
only ~330000/s on 8.4

on 8.4 I get:

3m59/4m01/3m56s runtime and a profile of

samples % symbol name
636302 19.6577 XLogInsert
415510 12.8366 CopyReadLine
225347 6.9618 DoCopy
131143 4.0515 ParseDateTime
122043 3.7703 DecodeNumber
81730 2.5249 DecodeDate
81045 2.5038 DecodeDateTime
80900 2.4993 pg_verify_mbstr_len
80235 2.4787 pg_next_dst_boundary
67571 2.0875 LWLockAcquire
64548 1.9941 heap_insert
64178 1.9827 LWLockRelease
63609 1.9651 PageAddItem
63402 1.9587 heap_form_tuple
56544 1.7468 timestamp_in
48697 1.5044 heap_fill_tuple
45248 1.3979 pg_atoi
42390 1.3096 IsSystemRelation
41287 1.2755 BufferGetBlockNumber
38936 1.2029 ValidateDate
36619 1.1313 ExecStoreTuple
35367 1.0926 DecodeTime

on 8.3.7 I get 2m58s,2m54s,2m55s

and a profile of:

samples % symbol name
460966 16.2924 XLogInsert
307386 10.8643 CopyReadLine
301745 10.6649 DoCopy
153452 5.4236 pg_next_dst_boundary
119757 4.2327 DecodeNumber
105356 3.7237 heap_formtuple
83456 2.9497 ParseDateTime
83020 2.9343 pg_verify_mbstr_len
72735 2.5708 DecodeDate
70425 2.4891 LWLockAcquire
65820 2.3264 LWLockRelease
61823 2.1851 DecodeDateTime
55895 1.9756 hash_any
51305 1.8133 PageAddItem
47440 1.6767 AllocSetAlloc
47218 1.6689 heap_insert
38912 1.3753 DecodeTime
34871 1.2325 ReadBuffer_common
34519 1.2200 date2j
33093 1.1696 DetermineTimeZoneOffset
31334 1.1075 MemoryContextAllocZero
30951 1.0939 RelationGetBufferForTuple

If I do the same test utilizing WAL bypass the picture changes:

8.3 runtimes:2m16,2min14s,2min22s

and profile:

samples % symbol name
445583 16.7777 CopyReadLine
332772 12.5300 DoCopy
156974 5.9106 pg_next_dst_boundary
131952 4.9684 heap_formtuple
119114 4.4850 DecodeNumber
94340 3.5522 ParseDateTime
81624 3.0734 pg_verify_mbstr_len
75012 2.8245 DecodeDate
74950 2.8221 DecodeDateTime
64467 2.4274 hash_any
62859 2.3669 PageAddItem
62054 2.3365 LWLockAcquire
57209 2.1541 LWLockRelease
45812 1.7250 hash_search_with_hash_value
41530 1.5637 DetermineTimeZoneOffset
40790 1.5359 heap_insert
39694 1.4946 AllocSetAlloc
38855 1.4630 ReadBuffer_common
36056 1.3576 MemoryContextAllocZero
36030 1.3567 DecodeTime
29057 1.0941 UnpinBuffer
28291 1.0653 PinBuffer

8.4 runtime: 2m1s,2m,1m59s

and profile:
404775 17.9532 CopyReadLine
208482 9.2469 DoCopy
148898 6.6042 ParseDateTime
118645 5.2623 DecodeNumber
80972 3.5914 DecodeDate
79005 3.5042 pg_verify_mbstr_len
73645 3.2664 PageAddItem
72167 3.2009 DecodeDateTime
65264 2.8947 heap_form_tuple
52680 2.3365 timestamp_in
46264 2.0520 pg_next_dst_boundary
45819 2.0322 ExecStoreTuple
45745 2.0290 heap_fill_tuple
43690 1.9378 heap_insert
38453 1.7055 InputFunctionCall
37050 1.6433 LWLockAcquire
36853 1.6346 BufferGetBlockNumber
36428 1.6157 heap_compute_data_size
33818 1.5000 DetermineTimeZoneOffset
33468 1.4844 DecodeTime
30896 1.3703 tm2timestamp
30888 1.3700 GetCurrentTransactionId

Stefan