Re: CREATE INDEX rather sluggish

Tom Lane wrote:

>Gavin Hamill <gdh(at)laterooms(dot)com> writes:
>
>
>>The table has just under six million rows - should it really be taking
>>nearly six minutes to add an index?
>>
>>
>
>Try running it with trace_sort enabled to get more info about where the
>time is going.
>
>We've been doing some considerable work on the sorting code in the last
>couple months, so 8.2 should be better, but I'd like to verify that
>you're not seeing something we don't know about.
>
>
>
OKies, I dropped the db, created again so it's all clean, ran pg_restore
again with trace_sort on - here's the output from one of the larger
CREATE INDEXes:

2006-03-30 16:48:53 BST LOG: begin index sort: unique = f, workMem =
262144, randomAccess = f
2006-03-30 16:49:04 BST LOG: switching to external sort: CPU
0.88s/9.99u sec elapsed 10.90 sec

2006-03-30 16:49:44 BST LOG: autovacuum: processing database "postgres"
2006-03-30 16:50:38 BST LOG: performsort starting: CPU 1.69s/102.73u
sec elapsed 104.58 sec
2006-03-30 16:50:44 BST LOG: autovacuum: processing database "laterooms"
2006-03-30 16:51:44 BST LOG: autovacuum: processing database "postgres"
2006-03-30 16:52:23 BST LOG: finished writing run 1: CPU 2.40s/206.53u
sec elapsed 209.30 sec
2006-03-30 16:52:39 BST LOG: finished writing final run 2: CPU
2.51s/222.98u sec elapsed 225.89 sec
2006-03-30 16:52:40 BST LOG: performsort done (except final merge): CPU
2.59s/223.99u sec elapsed 226.98 sec
2006-03-30 16:52:44 BST LOG: autovacuum: processing database "laterooms"
2006-03-30 16:52:53 BST LOG: external sort ended, 21292 disk blocks
used: CPU 3.65s/233.10u sec elapsed 239.35 sec
2006-03-30 16:52:53 BST LOG: duration: 239381.535 ms statement: CREATE
INDEX ix_keyword_lowertext ON "Keyword" USING btree ("LowerText");

During all this, there's been about 900KB/sec of disk activity. The
disks are RAID1 and will happily sustain 50MB/sec with minimal system
overhead.

I'm guessing then that an external sort means disk-based...

>>maintenance_work_mem = 262144
>>
>>
>
>Fooling with this might affect the results some.
>
>

OK will tinker with that - it's not a massive problem since I hope I
never have to do a pg_restore once the live server is running fulltime :)

Right - I bumped maintenance_work_mem up to 1GB, tried dropping the
index and recreating, and sure enough it's an internal sort now,
chopping 10% off the time taken:

2006-03-30 21:15:57 BST LOG: begin index sort: unique = f, workMem =
1048576, randomAccess = f
2006-03-30 21:16:03 BST LOG: autovacuum: processing database "laterooms"
2006-03-30 21:16:12 BST LOG: performsort starting: CPU 1.20s/13.85u sec
elapsed 15.07 sec
2006-03-30 21:17:03 BST LOG: autovacuum: processing database "laterooms"
2006-03-30 21:18:03 BST LOG: autovacuum: processing database "laterooms"
2006-03-30 21:19:03 BST LOG: autovacuum: processing database "laterooms"
2006-03-30 21:19:28 BST LOG: performsort done: CPU 1.20s/210.34u sec
elapsed 211.69 sec
2006-03-30 21:19:36 BST LOG: internal sort ended, 336538 KB used: CPU
2.06s/212.61u sec elapsed 218.80 sec
2006-03-30 21:19:36 BST LOG: duration: 218847.055 ms statement: CREATE
INDEX ix_keyword_lowertext on "Keyword" USING btree ("LowerText");

If that's reasonable performance from 8.1, then that's fine - I just
didn't want to be inadvertantly running way under average :)

Cheers,
Gavin.