Thread: Transaction ID not logged if no explicit transaction used
Hi, I've been fooling around on a test environment where I wanted to run some PITR tests using recovery_target_xid. So I started setting up postgresql.conf with log_statement='ddl' (and 'mod' also) and the %x placeholder in log_line_prefix: Odd result was that I always got a zero as the xid. So after some chats (and a power outage at home :( ) I tried setting log_statement to 'none' and log_min_duration_statement = 0 with the same log_line_prefix: I ran these commands to test: data=# create table test_xid (id int); CREATE TABLE data=# begin; BEGIN data=# drop table test_xid; DROP TABLE data=# end; COMMIT Which give these logs: <2016-02-10 17:41:19 EST [5729]: [1] xid=0 db=data,user=postgres,app=psql,client=[local]>LOG: duration: 17.242 ms statement: create table test_xid (id int); <2016-02-10 17:41:21 EST [5729]: [2] xid=0 db=data,user=postgres,app=psql,client=[local]>LOG: duration: 0.055 ms statement: begin; <2016-02-10 17:41:32 EST [5729]: [3] xid=31063 db=data,user=postgres,app=psql,client=[local]>LOG: duration: 6.858 ms statement: drop table test_xid; <2016-02-10 17:41:34 EST [5729]: [4] xid=0 db=data,user=postgres,app=psql,client=[local]>LOG: duration: 2.540 ms statement: end; It's clear that if the command isn't executed in an explicit transaction, you don't get the xid in the logs. Very annoying! Worst, I guess most people would want the xid of a DROP TABLE to be logged, as well as with other DDLs and/or DMLs with log_statement configured accordingly. I suppose this is not so simple to achieve. So, my question is: Is this a bug, or a feature? I recall being able to log xids on DDLs but can't find the correct settings now. -- Martín Marqués http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
On 02/10/2016 02:58 PM, Martín Marqués wrote: > Hi, > > I've been fooling around on a test environment where I wanted to run > some PITR tests using recovery_target_xid. > > So I started setting up postgresql.conf with log_statement='ddl' (and > 'mod' also) and the %x placeholder in log_line_prefix: > > Odd result was that I always got a zero as the xid. > > > So after some chats (and a power outage at home :( ) I tried setting > log_statement to 'none' and log_min_duration_statement = 0 with the same > log_line_prefix: > > I ran these commands to test: > > data=# create table test_xid (id int); > CREATE TABLE > data=# begin; > BEGIN > data=# drop table test_xid; > DROP TABLE > data=# end; > COMMIT > > Which give these logs: > > <2016-02-10 17:41:19 EST [5729]: [1] xid=0 > db=data,user=postgres,app=psql,client=[local]>LOG: duration: 17.242 ms > statement: create table test_xid (id int); > <2016-02-10 17:41:21 EST [5729]: [2] xid=0 > db=data,user=postgres,app=psql,client=[local]>LOG: duration: 0.055 ms > statement: begin; > <2016-02-10 17:41:32 EST [5729]: [3] xid=31063 > db=data,user=postgres,app=psql,client=[local]>LOG: duration: 6.858 ms > statement: drop table test_xid; > <2016-02-10 17:41:34 EST [5729]: [4] xid=0 > db=data,user=postgres,app=psql,client=[local]>LOG: duration: 2.540 ms > statement: end; > > It's clear that if the command isn't executed in an explicit > transaction, you don't get the xid in the logs. Very annoying! > > Worst, I guess most people would want the xid of a DROP TABLE to be > logged, as well as with other DDLs and/or DMLs with log_statement > configured accordingly. I suppose this is not so simple to achieve. > > So, my question is: Is this a bug, or a feature? I recall being able to > log xids on DDLs but can't find the correct settings now. Maybe?: %v Virtual transaction ID (backendID/localXID) -- Adrian Klaver adrian.klaver@aklaver.com
=?UTF-8?Q?Mart=c3=adn_Marqu=c3=a9s?= <martin@2ndquadrant.com> writes:
> [ log_line_prefix %x frequently reports zero ]
> <2016-02-10 17:41:19 EST [5729]: [1] xid=0
> db=data,user=postgres,app=psql,client=[local]>LOG: duration: 17.242 ms
> statement: create table test_xid (id int);
> <2016-02-10 17:41:21 EST [5729]: [2] xid=0
> db=data,user=postgres,app=psql,client=[local]>LOG: duration: 0.055 ms
> statement: begin;
> <2016-02-10 17:41:32 EST [5729]: [3] xid=31063
> db=data,user=postgres,app=psql,client=[local]>LOG: duration: 6.858 ms
> statement: drop table test_xid;
> <2016-02-10 17:41:34 EST [5729]: [4] xid=0
> db=data,user=postgres,app=psql,client=[local]>LOG: duration: 2.540 ms
> statement: end;
> It's clear that if the command isn't executed in an explicit
> transaction, you don't get the xid in the logs. Very annoying!
Think you're outta luck on that. If we logged the duration before
commit, it would be entirely misleading for short commands, because
the time needed to commit wouldn't be included. So we log it after,
when there's no longer any active transaction.
We could maybe fix this by redefining %x as "the current or most recent
xid", so that it'd still be valid for messages issued post-commit.
But I'm afraid that would add about as many bad behaviors as it would
remove. In your example above, that would result in a pretty misleading
xid attached to the "begin" statement, since at that point we have
started a new transaction but not assigned it any xid.
regards, tom lane
El 10/02/16 a las 20:11, Adrian Klaver escribió: >> >> So, my question is: Is this a bug, or a feature? I recall being able to >> log xids on DDLs but can't find the correct settings now. > > Maybe?: > > %v Virtual transaction ID (backendID/localXID) AFAICS that value won't help if I need the xid to do a PITR up to that xid not included. Regards, -- Martín Marqués http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
El 10/02/16 a las 21:46, Tom Lane escribió: > > Think you're outta luck on that. If we logged the duration before > commit, it would be entirely misleading for short commands, because > the time needed to commit wouldn't be included. So we log it after, > when there's no longer any active transaction. Any other way to log the DDL and DML statements (maybe delay writing the log until the xid is available)? Yes, I know the complexity of this, but I'm surprised this hasn't come up in the list before (maybe it did and i missed the mail). > We could maybe fix this by redefining %x as "the current or most recent > xid", so that it'd still be valid for messages issued post-commit. > But I'm afraid that would add about as many bad behaviors as it would > remove. In your example above, that would result in a pretty misleading > xid attached to the "begin" statement, since at that point we have > started a new transaction but not assigned it any xid. This really gives little use for recovery_target_xid. :( Regards, -- Martín Marqués http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
Martín Marqués wrote: > El 10/02/16 a las 21:46, Tom Lane escribió: > > We could maybe fix this by redefining %x as "the current or most recent > > xid", so that it'd still be valid for messages issued post-commit. > > But I'm afraid that would add about as many bad behaviors as it would > > remove. In your example above, that would result in a pretty misleading > > xid attached to the "begin" statement, since at that point we have > > started a new transaction but not assigned it any xid. > > This really gives little use for recovery_target_xid. :( Hmm, you can still use pg_xlogdump to figure it out from the actual WAL, which has the correct XIDs. It's obviously a worse solution though from the user's POV, because it's hard to figure out what WAL record corresponds to the change you care about ... -- Álvaro Herrera http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Alvaro Herrera <alvherre@2ndquadrant.com> writes:
> Mart�n Marqu�s wrote:
>> This really gives little use for recovery_target_xid. :(
> Hmm, you can still use pg_xlogdump to figure it out from the actual WAL,
> which has the correct XIDs. It's obviously a worse solution though from
> the user's POV, because it's hard to figure out what WAL record
> corresponds to the change you care about ...
To what extent does the commit_ts infrastructure fix this?
regards, tom lane
Tom Lane wrote: > Alvaro Herrera <alvherre@2ndquadrant.com> writes: > > Mart�n Marqu�s wrote: > >> This really gives little use for recovery_target_xid. :( > > > Hmm, you can still use pg_xlogdump to figure it out from the actual WAL, > > which has the correct XIDs. It's obviously a worse solution though from > > the user's POV, because it's hard to figure out what WAL record > > corresponds to the change you care about ... > > To what extent does the commit_ts infrastructure fix this? I don't think it does at all. You could try to find out the XID using a timestamp you obtain from the log file (knowing that the lookups are the opposite way, i.e. you give it an XID and it returns a timestamp); but if that's the scenario, I think it's simpler to use the timestamp in recovery_target_time directly. -- Álvaro Herrera http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services