Thread: pgbench create index anomoly

While setting up for the compressed sort testing...

NOTICE:  ALTER TABLE / ADD PRIMARY KEY will create implicit index "accounts_pkey" for table "accounts"
LOG:  begin index sort: unique = t, workMem = 16384, randomAccess = f
LOG:  begin index sort: unique = t, workMem = 16384, randomAccess = f
LOG:  begin index sort: unique = f, workMem = 1024, randomAccess = f
LOG:  begin index sort: unique = f, workMem = 1024, randomAccess = f
LOG:  switching to external sort with 59 tapes: CPU 0.11s/0.16u sec elapsed 3.80 sec
LOG:  switching to external sort with 59 tapes: CPU 0.11s/0.16u sec elapsed 3.80 sec
LOG:  internal sort ended, 25 KB used: CPU 160.53s/881.21u sec elapsed 4418.76 sec
LOG:  internal sort ended, 25 KB used: CPU 160.53s/881.21u sec elapsed 4418.76 sec
LOG:  performsort starting: CPU 160.53s/881.21u sec elapsed 4418.76 sec
LOG:  performsort starting: CPU 160.53s/881.21u sec elapsed 4418.76 sec
LOG:  finished writing final run 1 to tape 0: CPU 160.53s/881.79u sec elapsed 4419.35 sec
LOG:  finished writing final run 1 to tape 0: CPU 160.53s/881.79u sec elapsed 4419.35 sec
LOG:  performsort done: CPU 160.53s/881.79u sec elapsed 4419.41 sec
LOG:  performsort done: CPU 160.53s/881.79u sec elapsed 4419.41 sec
LOG:  external sort ended, 135814 disk blocks used: CPU 175.95s/1067.13u sec elapsed 4796.85 sec
LOG:  external sort ended, 135814 disk blocks used: CPU 175.95s/1067.13u sec elapsed 4796.85 sec

What's with the second workMem setting?

bench=# show work_mem;1024

bench=# show maintenance_work_mem ;16384

From one of the other sorts:
NOTICE:  ALTER TABLE / ADD PRIMARY KEY will create implicit index "tellers_pkey" for table "tell
ers"
LOG:  begin index sort: unique = t, workMem = 16384, randomAccess = f
LOG:  begin index sort: unique = t, workMem = 16384, randomAccess = f
LOG:  begin index sort: unique = f, workMem = 1024, randomAccess = f
LOG:  begin index sort: unique = f, workMem = 1024, randomAccess = f
LOG:  internal sort ended, 25 KB used: CPU 0.00s/0.01u sec elapsed 0.13 sec
LOG:  internal sort ended, 25 KB used: CPU 0.00s/0.01u sec elapsed 0.13 sec
LOG:  performsort starting: CPU 0.00s/0.01u sec elapsed 0.13 sec
LOG:  performsort starting: CPU 0.00s/0.01u sec elapsed 0.13 sec
LOG:  performsort done: CPU 0.00s/0.01u sec elapsed 0.13 sec
LOG:  performsort done: CPU 0.00s/0.01u sec elapsed 0.13 sec
LOG:  internal sort ended, 1706 KB used: CPU 0.01s/0.01u sec elapsed 0.16 sec
LOG:  internal sort ended, 1706 KB used: CPU 0.01s/0.01u sec elapsed 0.16 sec

Since that used 1.7M, it seems that it wasn't using the 1024 limit (unless that
code's broken). I'm just wondering where that other log message came from (note
also that it's indicating a non-unique sort).
-- 
Jim C. Nasby, Sr. Engineering Consultant      jnasby@pervasive.com
Pervasive Software      http://pervasive.com    work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf       cell: 512-569-9461

On Mon, 2006-05-22 at 14:01 -0500, Jim C. Nasby wrote:
> While setting up for the compressed sort testing...
> 
> NOTICE:  ALTER TABLE / ADD PRIMARY KEY will create implicit index "accounts_pkey" for table "accounts"
> LOG:  begin index sort: unique = t, workMem = 16384, randomAccess = f
> LOG:  begin index sort: unique = t, workMem = 16384, randomAccess = f

If you set log_line prefix to something that allows us to differentiate
those lines we might be able to identify them. The second line could
well be from a heap sort executed on a different backend; 1024 is the
default work_mem. Some psql commands use hidden SQL with an ORDER BY, so
you can sometimes be a little confused from the log.

Happy to look into it if there really is something wierd going on.

--  Simon Riggs EnterpriseDB          http://www.enterprisedb.com

On Mon, May 22, 2006 at 08:54:20PM +0100, Simon Riggs wrote:
> On Mon, 2006-05-22 at 14:01 -0500, Jim C. Nasby wrote:
> > While setting up for the compressed sort testing...
> > 
> > NOTICE:  ALTER TABLE / ADD PRIMARY KEY will create implicit index "accounts_pkey" for table "accounts"
> > LOG:  begin index sort: unique = t, workMem = 16384, randomAccess = f
> > LOG:  begin index sort: unique = t, workMem = 16384, randomAccess = f
> 
> If you set log_line prefix to something that allows us to differentiate
> those lines we might be able to identify them. The second line could

Such as?

There's nothing else running on this instance, so everything you see is
because of pgbench. And it did that for every ALTER TABLE. I'm assuming
this is actually a backend issue of some kind and not pgbench, since I
don't find the string 'work' anywhere in it's source.

> well be from a heap sort executed on a different backend; 1024 is the
> default work_mem. Some psql commands use hidden SQL with an ORDER BY, so
> you can sometimes be a little confused from the log.
> 
> Happy to look into it if there really is something wierd going on.
-- 
Jim C. Nasby, Sr. Engineering Consultant      jnasby@pervasive.com
Pervasive Software      http://pervasive.com    work: 512-231-6117
vcard: http://jim.nasby.net/pervasive.vcf       cell: 512-569-9461

"Jim C. Nasby" <jnasby@pervasive.com> writes:
> What's with the second workMem setting?

That's the second sort bucket for recently-dead tuples (which still have
to be indexed, but shouldn't be fed into the unique-checking sort).
We assume there won't be a lot of them, hence don't use
maintenance_work_mem to size that sort.
        regards, tom lane