Tom Lane wrote:
> Stefan Kaltenbrunner <stefan@kaltenbrunner.cc> writes:
>
>>CREATE INDEX on a 1,8B row table (5 int columns - index created on the
>>first row about 300M distinct values):
>
>
>>before: 11h 51min
>>after: 3h 11min(!)
>
>
> Cool. Does it seem to be I/O bound now? Would you be willing to do it
> over with oprofile turned on?
while it now does a fair amount of IO during the whole operation, it is
not yet IObound afaiks.
profile:
samples % symbol name
103520432 47.9018 inlineApplySortFunction
33382738 15.4471 comparetup_index
25296438 11.7054 tuplesort_heap_siftup
10089122 4.6685 btint4cmp
8395676 3.8849 LogicalTapeRead
2873556 1.3297 tuplesort_heap_insert
2796545 1.2940 tuplesort_gettuple_common
2752345 1.2736 AllocSetFree
2233889 1.0337 IndexBuildHeapScan
2035265 0.9418 heapgettup
1571035 0.7270 LWLockAcquire
1498800 0.6935 readtup_index
1213587 0.5616 index_form_tuple
1097172 0.5077 AllocSetAlloc
1056964 0.4891 heap_fill_tuple
1041172 0.4818 btbuildCallback
990005 0.4581 LWLockRelease
897662 0.4154 slot_deform_tuple
858527 0.3973 LogicalTapeWrite
806849 0.3734 PageAddItem
764136 0.3536 LockBuffer
trace_sort:
LOG: begin index sort: unique = f, workMem = 2048000, randomAccess = f
LOG: switching to external sort with 7315 tapes: CPU 4.07s/13.70u sec
elapsed 17.79 sec
LOG: finished writing run 1 to tape 0: CPU 240.07s/3926.66u sec elapsed
4498.49 sec
LOG: performsort starting: CPU 535.66s/8138.92u sec elapsed 9435.11 sec
LOG: finished writing final run 2 to tape 1: CPU 538.54s/8242.23u sec
elapsed 9541.55 sec
LOG: performsort done (except final merge): CPU 539.39s/8254.83u sec
elapsed 9559.75 sec
LOG: external sort ended, 4398827 disk blocks used: CPU
768.38s/10027.39u sec elapsed 11884.63 sec
Stefan