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 might need 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.* FROM generate_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.