Date: Thu, 4 Apr 2019 15:07:04 -0300
From: Alvaro Herrera <alvherre@2ndquadrant.com>
To: Justin Pryzby <pryzby@telsasoft.com>
Cc: Arthur Zakirov <a.zakirov@postgrespro.ru>, pgsql-hackers@postgresql.org
Subject: Re: query logging of prepared statements
Message-ID: <20190404180704.GA31569@alvherre.pgsql>
MIME-Version: 1.0
Content-Type: text/plain; charset=iso-8859-1
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <20190304183150.GK29584@telsasoft.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Precedence: bulk

On 2019-Mar-04, Justin Pryzby wrote:

> Thanks for reviewing.  I'm also interested in discussion about whether this
> change is undesirable for someone else for some reason ?  For me, the existing
> output seems duplicative and "denormalized".  :)

Some digging turned up that the function you're removing was added by
commit 893632be4e17.  The commit message mentions output for testlibpq3,
so I ran that against a patched server.  With log_min_duration_statement=0
I get this, which looks good:

2019-04-04 14:59:15.529 -03 [31723] LOG:  duration: 0.108 ms  statement: SET search_path = testlibpq3
2019-04-04 14:59:15.530 -03 [31723] LOG:  duration: 0.303 ms  parse <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 14:59:15.530 -03 [31723] LOG:  duration: 0.231 ms  bind <unnamed>
2019-04-04 14:59:15.530 -03 [31723] DETAIL:  parameters: $1 = 'joe''s place'
2019-04-04 14:59:15.530 -03 [31723] LOG:  duration: 0.016 ms  execute <unnamed>
2019-04-04 14:59:15.530 -03 [31723] DETAIL:  parameters: $1 = 'joe''s place'
2019-04-04 14:59:15.530 -03 [31723] LOG:  duration: 0.096 ms  parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 14:59:15.530 -03 [31723] LOG:  duration: 0.053 ms  bind <unnamed>
2019-04-04 14:59:15.530 -03 [31723] DETAIL:  parameters: $1 = '2'
2019-04-04 14:59:15.530 -03 [31723] LOG:  duration: 0.007 ms  execute <unnamed>
2019-04-04 14:59:15.530 -03 [31723] DETAIL:  parameters: $1 = '2'

An unpatched server emits this:

2019-04-04 15:03:01.176 -03 [1165] LOG:  duration: 0.163 ms  statement: SET search_path = testlibpq3
2019-04-04 15:03:01.176 -03 [1165] LOG:  duration: 0.475 ms  parse <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:03:01.177 -03 [1165] LOG:  duration: 0.403 ms  bind <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:03:01.177 -03 [1165] DETAIL:  parameters: $1 = 'joe''s place'
2019-04-04 15:03:01.177 -03 [1165] LOG:  duration: 0.028 ms  execute <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:03:01.177 -03 [1165] DETAIL:  parameters: $1 = 'joe''s place'
2019-04-04 15:03:01.177 -03 [1165] LOG:  duration: 0.177 ms  parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:03:01.177 -03 [1165] LOG:  duration: 0.096 ms  bind <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:03:01.177 -03 [1165] DETAIL:  parameters: $1 = '2'
2019-04-04 15:03:01.177 -03 [1165] LOG:  duration: 0.014 ms  execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:03:01.177 -03 [1165] DETAIL:  parameters: $1 = '2'

Note that with your patch we no longer get the statement in the "bind" and
"execute" lines, which seems good; that was far too noisy.


However, turning duration logging off and using log_statement=all, this is what
I get:

2019-04-04 14:58:42.564 -03 [31685] LOG:  statement: SET search_path = testlibpq3
2019-04-04 14:58:42.565 -03 [31685] LOG:  execute <unnamed>
2019-04-04 14:58:42.565 -03 [31685] DETAIL:  parameters: $1 = 'joe''s place'
2019-04-04 14:58:42.565 -03 [31685] LOG:  execute <unnamed>
2019-04-04 14:58:42.565 -03 [31685] DETAIL:  parameters: $1 = '2'

which does not look good -- the statement is nowhere to be seen.  The commit
message quotes this as desirable output:

    LOG:  statement: execute <unnamed>: SELECT * FROM test1 WHERE t = $1
    DETAIL:  parameters: $1 = 'joe''s place'
    LOG:  statement: execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
    DETAIL:  parameters: $1 = '2'

which is approximately what I get with an unpatched server:

2019-04-04 15:04:25.718 -03 [1235] LOG:  statement: SET search_path = testlibpq3
2019-04-04 15:04:25.719 -03 [1235] LOG:  execute <unnamed>: SELECT * FROM test1 WHERE t = $1
2019-04-04 15:04:25.719 -03 [1235] DETAIL:  parameters: $1 = 'joe''s place'
2019-04-04 15:04:25.720 -03 [1235] LOG:  execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
2019-04-04 15:04:25.720 -03 [1235] DETAIL:  parameters: $1 = '2'

So I think this needs a bit more work.

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services