Thread: Logging Parameter Values
Hi, While log_statements logs parameter values with the logged queries, I cannot see parameter values logged for erronous queries and queries catched by log_min_duration_statements. Here are our logging settings: # grep ^log postgresql.conf logging_collector = on # Enable capturing of stderr and csvlog log_directory = '/srv/pg/pg_log' # directory where log files are written, log_filename = '%Y-%m-%d_%H%M%S.log' # log file name pattern, log_rotation_age = 7d # Automatic rotation of logfiles will log_rotation_size = 0MB # Automatic rotation of logfiles will log_min_duration_statement = 1000 # -1 is disabled, 0 logs all statements log_line_prefix = '%d %u %m ' # special values: For instance, consider below log snippets. eray_1_5_1_0 emove 2008-06-19 10:19:50.124 EEST ERROR: function isnull(integer, integer) does not exist at character 195 eray_1_5_1_0 emove 2008-06-19 10:19:50.124 EEST HINT: No function matches the given name and argument types. You mightneed to add explicit type casts. eray_1_5_1_0 emove 2008-06-19 10:19:50.124 EEST STATEMENT: SELECT * FROM mugroup g WHERE g.groupid IN ((... user id=$1)UNION (SELECT ...)) test_1_5_0_0 emove 2008-05-15 15:07:08.631 EEST LOG: duration: 68544.986 ms parse <unnamed>: insert into interprettimelog(...) values ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16) Is this something expected? What might I be missing? How can I make PostgreSQL log parameter values also? Regards.
Volkan YAZICI <yazicivo@ttmail.com> writes:
> While log_statements logs parameter values with the logged queries, I
> cannot see parameter values logged for erronous queries and queries
> catched by log_min_duration_statements.
What PG version are you using? Since 8.2 log_duration should show
parameter values. As for the other, you'd have to turn on
log_statements so that the parameters get logged in advance of the
failure. Once the transaction has failed we can't call user-defined
output functions, since they might try to do things that don't work
inside a failed transaction.
regards, tom lane
On Thu, 19 Jun 2008, Tom Lane <tgl@sss.pgh.pa.us> writes: > What PG version are you using? Since 8.2 log_duration should show > parameter values. I don't want to interrupt your work, but as far as I see from logs -- with the configurations I sent previously -- PostgreSQL doesn't log parameter values for queries dropped into query duration limit. (Using PostgreSQL 8.3.1.) Consider this test case: test# PREPARE foo (int) AS ] SELECT S.i * T.i ] FROM generate_series(1, $1) AS S(i), ] generate_series(1, $1) AS T(i); test# EXECUTE foo (1000); ... # tail -n 2 /srv/pg/pg_log/2008-06-19_141725.log migration_test postgres 2008-06-19 17:58:05.185 EEST LOG: duration: 2315.420 ms statement: EXECUTE foo(1000); migration_test postgres 2008-06-19 17:58:05.185 EEST DETAIL: prepare: PREPARE foo (int) AS SELECT S.i * T.i FROM generate_series(1,$1) AS S(i), generate_series(1, $1) AS T(i); > As for the other, you'd have to turn on log_statements so that the > parameters get logged in advance of the failure. Once the transaction > has failed we can't call user-defined output functions, since they > might try to do things that don't work inside a failed transaction. I see. Regards.
Volkan YAZICI <yazicivo@ttmail.com> writes:
> PostgreSQL 8.3.1.) Consider this test case:
> test# PREPARE foo (int) AS
> ] SELECT S.i * T.i
> ] FROM generate_series(1, $1) AS S(i),
> ] generate_series(1, $1) AS T(i);
> test# EXECUTE foo (1000);
> ...
> # tail -n 2 /srv/pg/pg_log/2008-06-19_141725.log
> migration_test postgres 2008-06-19 17:58:05.185 EEST LOG: duration: 2315.420 ms statement: EXECUTE foo(1000);
> migration_test postgres 2008-06-19 17:58:05.185 EEST DETAIL: prepare: PREPARE foo (int) AS SELECT S.i * T.i FROM
generate_series(1,$1) AS S(i), generate_series(1, $1) AS T(i);
Hmm, we're not on the same page here. I thought you were talking about
protocol-level parameters. In the above example, the parameter values
are shown in the EXECUTE statement, so what else do you need?
regards, tom lane
Volkan YAZICI wrote: > I don't want to interrupt your work, but as far as I see from logs -- > with the configurations I sent previously -- PostgreSQL doesn't log > parameter values for queries dropped into query duration limit. (Using > PostgreSQL 8.3.1.) Consider this test case: > > test# PREPARE foo (int) AS > ] SELECT S.i * T.i > ] FROM generate_series(1, $1) AS S(i), > ] generate_series(1, $1) AS T(i); > > test# EXECUTE foo (1000); > ... > > # tail -n 2 /srv/pg/pg_log/2008-06-19_141725.log > migration_test postgres 2008-06-19 17:58:05.185 EEST LOG: duration: 2315.420 ms statement: EXECUTE foo(1000); The parameter is on the above line, isn't it? > migration_test postgres 2008-06-19 17:58:05.185 EEST DETAIL: prepare: PREPARE foo (int) AS SELECT S.i * T.i FROM generate_series(1,$1) AS S(i), generate_series(1, $1) AS T(i); -- Alvaro Herrera http://www.CommandPrompt.com/ The PostgreSQL Company - Command Prompt, Inc.
On Thu, 19 Jun 2008, Tom Lane <tgl@sss.pgh.pa.us> writes:
> Volkan YAZICI <yazicivo@ttmail.com> writes:
>> # tail -n 2 /srv/pg/pg_log/2008-06-19_141725.log
>> migration_test postgres 2008-06-19 17:58:05.185 EEST LOG: duration: 2315.420 ms statement: EXECUTE foo(1000);
>> migration_test postgres 2008-06-19 17:58:05.185 EEST DETAIL: prepare: PREPARE foo (int) AS SELECT S.i * T.i FROM
generate_series(1,$1) AS S(i), generate_series(1, $1) AS T(i);
>
> Hmm, we're not on the same page here. I thought you were talking about
> protocol-level parameters. In the above example, the parameter values
> are shown in the EXECUTE statement, so what else do you need?
Umm... Bogus test case.
CL-USER> (postmodern:connect-toplevel
"migration_test" "postgres" nil "192.168.1.160")
; No value
CL-USER> (and (postmoder:query
(concatenate 'string
"SELECT S.i * T.*"
" FROM generate_series(1, $1) AS S (i),"
" generate_series(1, $2) AS T (i)")
1000 1000)
nil)
NIL
# tail /srv/pg/pg_log/2008-06-19_141725.log -n 2
migration_test postgres 2008-06-20 09:02:33.695 EEST LOG: duration: 4419.475 ms execute <unnamed>: SELECT S.i * T.*
FROMgenerate_series(1, $1) AS S (i), generate_series(1, $2) AS T (i)
migration_test postgres 2008-06-20 09:02:33.695 EEST DETAIL: parameters: $1 = '1000', $2 = '1000'
Hrm... Now what might have caused the logged statements with missing
parameter values I pasted. I was probably looking at past log files
belongs to some other logging configuration.
Excuse me for the noise. And thanks for the prompt reply.
Regards.