Transaction ID not logged if no explicit transaction used

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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

=?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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general