Re: problems with set_config, work_mem, maintenance_work_mem, and sorting

On Tue, Feb 28, 2012 at 2:51 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Jon Nelson <jnelson+pgsql@jamponi.net> writes:
>> On Tue, Feb 28, 2012 at 1:28 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>>> Jon Nelson <jnelson+pgsql@jamponi.net> writes:
>>>> Why does PostgreSQL /sometimes/ use the globally-configured values and
>>>> sometimes use the values that come from the connection?
>
>>> You sure those log entries are all from the same process?
>
>> If I am understanding this correctly, yes. They all share the same pid.
>
> Hmph ... does seem a bit weird.  Can you turn on log_statements and
> identify which operations aren't using the session values?

I had log_min_duration_statement = 1000.

An example:

LOG:  00000: begin tuple sort: nkeys = 3, workMem = 131072, randomAccess = f
LOCATION:  tuplesort_begin_heap, tuplesort.c:573
STATEMENT:  INSERT INTO (new table) SELECT (bunch of stuff here) FROM
.. ORDER BY ...

and also some CREATE TABLE ... statements:

LOG:  00000: begin index sort: unique = f, workMem = 131072, randomAccess = f
LOCATION:  tuplesort_begin_index_btree, tuplesort.c:642
STATEMENT:  CREATE TABLE <tablename> (LIKE some_other_tablename)

I also see this:

LOG:  00000: begin tuple sort: nkeys = 2, workMem = 131072, randomAccess = f
LOCATION:  tuplesort_begin_heap, tuplesort.c:573
STATEMENT: SELECT <bunch of stuff from system catalogs>

which is the ORM library (SQLAlchemy) doing a reflection of the
table(s) involved.
The statement is from the same backend (pid) and takes place
chronologically *after* the following:

LOG:  00000: begin tuple sort: nkeys = 2, workMem = 1048576, randomAccess = f
LOCATION:  tuplesort_begin_heap, tuplesort.c:573
STATEMENT: <more reflection stuff>

Is that useful?

If that's not enough, I can crank the logging up.
What would you like to see for 'log_statements' (if what I've provided
you above is not enough).

--
Jon