Thread: Re: [COMMITTERS] pgsql: Write a WAL record whenever we perform an operation without

I'm seeing these messages in the standby server log:

WARNING:  unlogged operation performed, data may be missing
HINT:  This can happen if you temporarily disable archive_mode without
taking a new base backup.
CONTEXT:  xlog redo unlogged operation: heap inserts on "pg_temp_65646"

which connected with operations on temp tables, probably as a result of
VACUUM FULL and CLUSTER.

I don't think those messages should be there.


On Wed, 2010-01-20 at 19:43 +0000, Heikki Linnakangas wrote:
> Log Message:
> -----------
> Write a WAL record whenever we perform an operation without WAL-logging
> that would've been WAL-logged if archiving was enabled. If we encounter
> such records in archive recovery anyway, we know that some data is
> missing from the log. A WARNING is emitted in that case.
> 
> Original patch by Fujii Masao, with changes by me.
> 
> Modified Files:
> --------------
>     pgsql/src/backend/access/heap:
>         heapam.c (r1.282 -> r1.283)
>         (http://anoncvs.postgresql.org/cvsweb.cgi/pgsql/src/backend/access/heap/heapam.c?r1=1.282&r2=1.283)
>     pgsql/src/backend/access/nbtree:
>         nbtsort.c (r1.122 -> r1.123)
>         (http://anoncvs.postgresql.org/cvsweb.cgi/pgsql/src/backend/access/nbtree/nbtsort.c?r1=1.122&r2=1.123)
>     pgsql/src/backend/access/transam:
>         xlog.c (r1.358 -> r1.359)
>         (http://anoncvs.postgresql.org/cvsweb.cgi/pgsql/src/backend/access/transam/xlog.c?r1=1.358&r2=1.359)
>     pgsql/src/backend/commands:
>         cluster.c (r1.193 -> r1.194)
>         (http://anoncvs.postgresql.org/cvsweb.cgi/pgsql/src/backend/commands/cluster.c?r1=1.193&r2=1.194)
>         tablecmds.c (r1.316 -> r1.317)
>         (http://anoncvs.postgresql.org/cvsweb.cgi/pgsql/src/backend/commands/tablecmds.c?r1=1.316&r2=1.317)
>     pgsql/src/include/access:
>         xlog.h (r1.97 -> r1.98)
>         (http://anoncvs.postgresql.org/cvsweb.cgi/pgsql/src/include/access/xlog.h?r1=1.97&r2=1.98)
>     pgsql/src/include/catalog:
>         pg_control.h (r1.48 -> r1.49)
>         (http://anoncvs.postgresql.org/cvsweb.cgi/pgsql/src/include/catalog/pg_control.h?r1=1.48&r2=1.49)
> 
-- Simon Riggs           www.2ndQuadrant.com

Simon Riggs wrote:
> I'm seeing these messages in the standby server log:
> 
> WARNING:  unlogged operation performed, data may be missing
> HINT:  This can happen if you temporarily disable archive_mode without
> taking a new base backup.
> CONTEXT:  xlog redo unlogged operation: heap inserts on "pg_temp_65646"
> 
> which connected with operations on temp tables, probably as a result of
> VACUUM FULL and CLUSTER.
> 
> I don't think those messages should be there.

Hmm. The "unlogged" record is written here:

...
void
heap_sync(Relation rel)
{char reason[NAMEDATALEN + 30];
/* temp tables never need fsync */if (rel->rd_istemp)    return;
snprintf(reason, sizeof(reason), "heap inserts on \"%s\"",
RelationGetRelationName(rel));XLogReportUnloggedStatement(reason);
...


So it clearly shouldn't be written for temp relations. Apparently the
rd_istemp flag not set correctly after CLUSTER / VACUUM FULL.

Can you reproduce that?

--  Heikki Linnakangas EnterpriseDB   http://www.enterprisedb.com

On Mon, 2010-02-01 at 11:33 +0200, Heikki Linnakangas wrote:
> Can you reproduce that?

Every time

-- Simon Riggs           www.2ndQuadrant.com

On Mon, Feb 1, 2010 at 6:33 PM, Heikki Linnakangas
<heikki.linnakangas@enterprisedb.com> wrote:
> Hmm. The "unlogged" record is written here:
>
> ...
> void
> heap_sync(Relation rel)
> {
>        char reason[NAMEDATALEN + 30];
>
>        /* temp tables never need fsync */
>        if (rel->rd_istemp)
>                return;
>
>        snprintf(reason, sizeof(reason), "heap inserts on \"%s\"",
>                         RelationGetRelationName(rel));
>        XLogReportUnloggedStatement(reason);
> ...
>
>
> So it clearly shouldn't be written for temp relations. Apparently the
> rd_istemp flag not set correctly after CLUSTER / VACUUM FULL.

The cause of the problem seems to be the new heap created by
rebuild_relation() and copy_heap_data(), i.e., new VACUUM FULL.
Since it's not a temporary heap, its rd_istemp is off. OTOH
it needs to be synced after physical copy from old heap. So
XLogReportUnloggedStatement() is called in heap_sync().

The easy fix is to change the code as below.
   if (XLogIsNeeded())   {       snprintf(reason, sizeof(reason), "heap inserts on \"%s\"",
RelationGetRelationName(rel));      XLogReportUnloggedStatement(reason);   } 

But I'm not sure this fix is right, so I need to investigate
the code more.

Regards,

--
Fujii Masao
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

Simon Riggs wrote:
> On Mon, 2010-02-01 at 11:33 +0200, Heikki Linnakangas wrote:
>> Can you reproduce that?
> 
> Every time

Ok, good :-). What I really meant was: How?

--  Heikki Linnakangas EnterpriseDB   http://www.enterprisedb.com

On Mon, 2010-02-01 at 12:11 +0200, Heikki Linnakangas wrote:
> Simon Riggs wrote:
> > On Mon, 2010-02-01 at 11:33 +0200, Heikki Linnakangas wrote:
> >> Can you reproduce that?
> > 
> > Every time
> 
> Ok, good :-). What I really meant was: How?

As mentioned in first post: VACUUM FULL and CLUSTER.

Coffee is recommended.

-- Simon Riggs           www.2ndQuadrant.com

On Mon, Feb 1, 2010 at 6:58 PM, Fujii Masao <masao.fujii@gmail.com> wrote:
>    if (XLogIsNeeded())
>    {
>        snprintf(reason, sizeof(reason), "heap inserts on \"%s\"",
>                         RelationGetRelationName(rel));
>        XLogReportUnloggedStatement(reason);
>    }

Oops!
Typo: XLogIsNeeded() --> !XLogIsNeeded()

Regards,

--
Fujii Masao
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

Fujii Masao wrote:
> The cause of the problem seems to be the new heap created by
> rebuild_relation() and copy_heap_data(), i.e., new VACUUM FULL.
> Since it's not a temporary heap, its rd_istemp is off. OTOH
> it needs to be synced after physical copy from old heap.

Why does it need to be synced?

ISTM the bug is that rd_istemp is off at that point.

--  Heikki Linnakangas EnterpriseDB   http://www.enterprisedb.com

Simon Riggs wrote:
> On Mon, 2010-02-01 at 12:11 +0200, Heikki Linnakangas wrote:
>> Simon Riggs wrote:
>>> On Mon, 2010-02-01 at 11:33 +0200, Heikki Linnakangas wrote:
>>>> Can you reproduce that?
>>> Every time
>> Ok, good :-). What I really meant was: How?
> 
> As mentioned in first post: VACUUM FULL and CLUSTER.

I'm asking because I couldn't reproduce it. I added an elog(LOG) to
XLogReportUnloggedStatement() so that I can see when an unlogged-record
is written. Then I ran:

CREATE TEMPORARY TABLE foo (id int4);
VACUUM FULL foo;

But XLogReportUnloggedStatement() was not executed. When I removed the
"TEMPORARY" and tried again, it was executed.

--  Heikki Linnakangas EnterpriseDB   http://www.enterprisedb.com

On Mon, Feb 1, 2010 at 7:27 PM, Heikki Linnakangas
<heikki.linnakangas@enterprisedb.com> wrote:
> Fujii Masao wrote:
>> The cause of the problem seems to be the new heap created by
>> rebuild_relation() and copy_heap_data(), i.e., new VACUUM FULL.
>> Since it's not a temporary heap, its rd_istemp is off. OTOH
>> it needs to be synced after physical copy from old heap.
>
> Why does it need to be synced?
>
> ISTM the bug is that rd_istemp is off at that point.

Umm... ISTM that new heap needs to be synced before calling
swap_relation_files(), but, in the now, I'm not sure whether
it's really required or not. Sorry.

Regards,

-- 
Fujii Masao
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

On Mon, Feb 1, 2010 at 7:30 PM, Heikki Linnakangas
<heikki.linnakangas@enterprisedb.com> wrote:
> CREATE TEMPORARY TABLE foo (id int4);
> VACUUM FULL foo;

How about issuing just "VACUUM FULL" after creating log-shipping environment?

Regards,

-- 
Fujii Masao
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

Heikki Linnakangas wrote:
> Simon Riggs wrote:
>> On Mon, 2010-02-01 at 12:11 +0200, Heikki Linnakangas wrote:
>>> Simon Riggs wrote:
>>>> On Mon, 2010-02-01 at 11:33 +0200, Heikki Linnakangas wrote:
>>>>> Can you reproduce that?
>>>> Every time
>>> Ok, good :-). What I really meant was: How?
>> As mentioned in first post: VACUUM FULL and CLUSTER.
> 
> I'm asking because I couldn't reproduce it. I added an elog(LOG) to
> XLogReportUnloggedStatement() so that I can see when an unlogged-record
> is written. Then I ran:
> 
> CREATE TEMPORARY TABLE foo (id int4);
> VACUUM FULL foo;
> 
> But XLogReportUnloggedStatement() was not executed. When I removed the
> "TEMPORARY" and tried again, it was executed.

No, hang on. When I run this:

postgres=# CREATE TABLE foo (id int4);
CREATE TABLE
postgres=# vacuum full foo;
VACUUM

I get this in the log:

LOG:  Writing record: CLUSTER on "pg_temp_24677"
STATEMENT:  vacuum full foo;
LOG:  Writing record: heap inserts on "pg_temp_24677"
STATEMENT:  vacuum full foo;

So you get those messages when the table is *not* a temporary table. I
can see now what Fujii was trying to say. His patch seems Ok, though
perhaps it would be better to move the responsibility of calling
XLogReportUnloggedStatement() to the callers of heap_sync(). When I put
it in heap_sync(), I didn't take into account that it's sometimes called
just to flush buffers from buffer cache, not to fsync() non-WAL-logged
operations.

--  Heikki Linnakangas EnterpriseDB   http://www.enterprisedb.com

On Mon, 2010-02-01 at 12:30 +0200, Heikki Linnakangas wrote:
> Simon Riggs wrote:
> > On Mon, 2010-02-01 at 12:11 +0200, Heikki Linnakangas wrote:
> >> Simon Riggs wrote:
> >>> On Mon, 2010-02-01 at 11:33 +0200, Heikki Linnakangas wrote:
> >>>> Can you reproduce that?
> >>> Every time
> >> Ok, good :-). What I really meant was: How?
> > 
> > As mentioned in first post: VACUUM FULL and CLUSTER.
> 
> I'm asking because I couldn't reproduce it. I added an elog(LOG) to
> XLogReportUnloggedStatement() so that I can see when an unlogged-record
> is written. Then I ran:
> 
> CREATE TEMPORARY TABLE foo (id int4);
> VACUUM FULL foo;
> 
> But XLogReportUnloggedStatement() was not executed. When I removed the
> "TEMPORARY" and tried again, it was executed.

drop table if exists foo;
create table foo (col1 serial, col2 text);
insert into foo (col2) 
select repeat('a', 5000) from generate_series(1,1000);
create index on foo (col1);
cluster foo using foo_col1_idx;

So it appears this relates to toast tables.

-- Simon Riggs           www.2ndQuadrant.com

Fujii Masao <masao.fujii@gmail.com> writes:
> On Mon, Feb 1, 2010 at 7:27 PM, Heikki Linnakangas
> <heikki.linnakangas@enterprisedb.com> wrote:
>> Fujii Masao wrote:
>>> The cause of the problem seems to be the new heap created by
>>> rebuild_relation() and copy_heap_data(), i.e., new VACUUM FULL.
>>> Since it's not a temporary heap, its rd_istemp is off. OTOH
>>> it needs to be synced after physical copy from old heap.
>> 
>> Why does it need to be synced?
>> 
>> ISTM the bug is that rd_istemp is off at that point.

> Umm... ISTM that new heap needs to be synced before calling
> swap_relation_files(), but, in the now, I'm not sure whether
> it's really required or not. Sorry.

If the original table is temp, then none of this work needs to be
fsync'd.  Ever.  So ISTM that CLUSTER ought to be copying the istemp
bit.  Another reason to do that is to make sure that the new instance
of the table goes into the temp tablespace and not the regular one.
        regards, tom lane

On Mon, Feb 1, 2010 at 7:40 PM, Heikki Linnakangas
<heikki.linnakangas@enterprisedb.com> wrote:
> So you get those messages when the table is *not* a temporary table. I
> can see now what Fujii was trying to say. His patch seems Ok, though
> perhaps it would be better to move the responsibility of calling
> XLogReportUnloggedStatement() to the callers of heap_sync(). When I put
> it in heap_sync(), I didn't take into account that it's sometimes called
> just to flush buffers from buffer cache, not to fsync() non-WAL-logged
> operations.

As you said, I moved the responsibility of calling XLogReportUnloggedStatement()
to the callers of heap_sync(). Here is the patch.

Regards,

--
Fujii Masao
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

Fujii Masao wrote:
> On Mon, Feb 1, 2010 at 7:40 PM, Heikki Linnakangas
> <heikki.linnakangas@enterprisedb.com> wrote:
>> So you get those messages when the table is *not* a temporary table. I
>> can see now what Fujii was trying to say. His patch seems Ok, though
>> perhaps it would be better to move the responsibility of calling
>> XLogReportUnloggedStatement() to the callers of heap_sync(). When I put
>> it in heap_sync(), I didn't take into account that it's sometimes called
>> just to flush buffers from buffer cache, not to fsync() non-WAL-logged
>> operations.
> 
> As you said, I moved the responsibility of calling XLogReportUnloggedStatement()
> to the callers of heap_sync(). Here is the patch.

Committed. The use_wal parameter to end_heap_rewrite() was not
necessary, that information is already in RewriteState, so I took that out.

--  Heikki Linnakangas EnterpriseDB   http://www.enterprisedb.com

> Fujii Masao wrote:
> > On Mon, Feb 1, 2010 at 7:40 PM, Heikki Linnakangas
> > <heikki.linnakangas@enterprisedb.com> wrote:
> >> So you get those messages when the table is *not* a temporary table. I
> >> can see now what Fujii was trying to say. His patch seems Ok, though
> >> perhaps it would be better to move the responsibility of calling
> >> XLogReportUnloggedStatement() to the callers of heap_sync(). When I put
> >> it in heap_sync(), I didn't take into account that it's sometimes called
> >> just to flush buffers from buffer cache, not to fsync() non-WAL-logged
> >> operations.
> > 
> > As you said, I moved the responsibility of calling XLogReportUnloggedStatement()
> > to the callers of heap_sync(). Here is the patch.
> 
> Committed. The use_wal parameter to end_heap_rewrite() was not
> necessary, that information is already in RewriteState, so I took that out.

Are we going to bump up frontend/backend protocol version 3.0 to 3.x
or some such?
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese: http://www.sraoss.co.jp

Tatsuo Ishii wrote:
>> Fujii Masao wrote:
>>> On Mon, Feb 1, 2010 at 7:40 PM, Heikki Linnakangas
>>> <heikki.linnakangas@enterprisedb.com> wrote:
>>>> So you get those messages when the table is *not* a temporary table. I
>>>> can see now what Fujii was trying to say. His patch seems Ok, though
>>>> perhaps it would be better to move the responsibility of calling
>>>> XLogReportUnloggedStatement() to the callers of heap_sync(). When I put
>>>> it in heap_sync(), I didn't take into account that it's sometimes called
>>>> just to flush buffers from buffer cache, not to fsync() non-WAL-logged
>>>> operations.
>>> As you said, I moved the responsibility of calling XLogReportUnloggedStatement()
>>> to the callers of heap_sync(). Here is the patch.
>> Committed. The use_wal parameter to end_heap_rewrite() was not
>> necessary, that information is already in RewriteState, so I took that out.
> 
> Are we going to bump up frontend/backend protocol version 3.0 to 3.x
> or some such?

No, this doesn't affect the normal FE/BE protocol. The message header
was added to the streaming replication messages that are sent within
CopyData messages.

--  Heikki Linnakangas EnterpriseDB   http://www.enterprisedb.com