Tom Lane wrote:
Gavin Hamill <gdh@xxxxxxxxxxxxx> 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.
