Re: Too frequent checkpoints ?

I was looking at the vacuum/visibility bug that Jeff Janes reported
and brought up the server with the data directory he has shared. With
his configuration,

# - Checkpoints -

checkpoint_segments = 1 # in logfile segments, min 1, 16MB each
checkpoint_timeout = 30s # range 30s-1h

# - Archiving -

archive_mode = on # allows archiving to be done
# (change requires restart)
archive_command = 'echo archive_command %p %f `date`' # command
to use to archive a logfile segment
# placeholders: %p = path of file to archive
# %f = file name only
# e.g. 'test ! -f /mnt/server/archivedir/%f && cp %p
/mnt/server/archivedir/%f'
archive_timeout = 30 # force a logfile segment switch after this
# number of seconds; 0 disables

I see the following messages coming on the console:

3092 2013-02-08 02:29:01.239 PST:LOG: checkpoints are occurring too
frequently (0 seconds apart)
3092 2013-02-08 02:29:01.239 PST:HINT: Consider increasing the
configuration parameter "checkpoint_segments".
3092 2013-02-08 02:29:01.239 PST:LOG: checkpoint starting: xlog
3092 2013-02-08 02:29:01.246 PST:LOG: checkpoint complete: wrote 0
buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1
recycled; write=0.000 s, sync=0.000 s, total=0.007 s; sync files=0,
longest=0.000 s, average=0.000 s
archive_command pg_xlog/0000000100000057000000F5
0000000100000057000000F5 Fri Feb 8 15:59:01 IST 2013
3092 2013-02-08 02:29:31.278 PST:LOG: checkpoints are occurring too
frequently (0 seconds apart)
3092 2013-02-08 02:29:31.278 PST:HINT: Consider increasing the
configuration parameter "checkpoint_segments".
3092 2013-02-08 02:29:31.278 PST:LOG: checkpoint starting: xlog
3092 2013-02-08 02:29:31.285 PST:LOG: checkpoint complete: wrote 0
buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1
recycled; write=0.000 s, sync=0.000 s, total=0.006 s; sync files=0,
longest=0.000 s, average=0.000 s
archive_command pg_xlog/0000000100000057000000F6
0000000100000057000000F6 Fri Feb 8 15:59:31 IST 2013
3092 2013-02-08 02:30:01.316 PST:LOG: checkpoints are occurring too
frequently (0 seconds apart)
3092 2013-02-08 02:30:01.316 PST:HINT: Consider increasing the
configuration parameter "checkpoint_segments".
3092 2013-02-08 02:30:01.316 PST:LOG: checkpoint starting: xlog
archive_command pg_xlog/0000000100000057000000F7
0000000100000057000000F7 Fri Feb 8 16:00:01 IST 2013
3092 2013-02-08 02:30:01.323 PST:LOG: checkpoint complete: wrote 0
buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1
recycled; write=0.000 s, sync=0.000 s, total=0.006 s; sync files=0,
longest=0.000 s, average=0.000 s
3092 2013-02-08 02:30:31.327 PST:LOG: checkpoints are occurring too
frequently (0 seconds apart)
3092 2013-02-08 02:30:31.327 PST:HINT: Consider increasing the
configuration parameter "checkpoint_segments".
3092 2013-02-08 02:30:31.327 PST:LOG: checkpoint starting: xlog
archive_command pg_xlog/0000000100000057000000F8
0000000100000057000000F8 Fri Feb 8 16:00:31 IST 2013
3092 2013-02-08 02:30:31.334 PST:LOG: checkpoint complete: wrote 0
buffers (0.0%); 0 transaction log file(s) added, 0 removed, 1
recycled; write=0.000 s, sync=0.000 s, total=0.007 s; sync files=0,
longest=0.000 s, average=0.000 s

I wonder if this is all expected. The database is getting ZERO
activity. There are no connections open at this time. The checkpoints
are happening at every 30 seconds and new WAL files are being created,
AFAIK because the old ones are getting archived. Can't we be smart
about not archiving new files if we did not generate any new WAL since
the last archive ?

Also, the log says "checkpoints are occurring too frequently (0
seconds apart)". But that looks wrong too. Checkpoints are really
happening at 30 seconds apart and not 0 as the log message claims.

Thanks,
Pavan

--
Pavan Deolasee
http://www.linkedin.com/in/pavandeolasee

On 02/08/2013 02:37 AM, Pavan Deolasee wrote:

> I wonder if this is all expected. The database is getting ZERO
> activity. There are no connections open at this time. The checkpoints
> are happening at every 30 seconds and new WAL files are being created,
> AFAIK because the old ones are getting archived. Can't we be smart
> about not archiving new files if we did not generate any new WAL since
> the last archive ?

It is because you have it set up so that the longest time you can go
without checkpoints is 30 seconds. So no matter what, if you have 1000
checkpoint segments you are still going to checkpoint ever 30 seconds.

JD

--
Command Prompt, Inc. - http://www.commandprompt.com/
PostgreSQL Support, Training, Professional Services and Development
High Availability, Oracle Conversion, Postgres-XC
@cmdpromptinc - 509-416-6579

On Fri, Feb 8, 2013 at 7:37 PM, Pavan Deolasee <pavan(dot)deolasee(at)gmail(dot)com> wrote:
> I wonder if this is all expected. The database is getting ZERO
> activity. There are no connections open at this time. The checkpoints
> are happening at every 30 seconds and new WAL files are being created,
> AFAIK because the old ones are getting archived. Can't we be smart
> about not archiving new files if we did not generate any new WAL since
> the last archive ?

AFAIR this problem has been discussed several times before, but has not
been fixed yet.

BTW, the cause of the problem is that the following sequences happens.

1. archive_timeout switches WAL file because checkpoint WAL record has
has been written since last switch
2. Checkpoint occurs and writes its WAL record because new WAL file was
generated since last checkpoint, i.e., checkpoint thinks that
there is at least
some activity since last checkpoint.
3. Back to #1 after archive_timeout passed through.

Regards,

--
Fujii Masao

On Fri, Feb 8, 2013 at 2:37 AM, Pavan Deolasee <pavan(dot)deolasee(at)gmail(dot)com> wrote:
> I was looking at the vacuum/visibility bug that Jeff Janes reported
> and brought up the server with the data directory he has shared. With
> his configuration,
>
....
> 3092 2013-02-08 02:30:31.327 PST:LOG: checkpoints are occurring too
> frequently (0 seconds apart)
> 3092 2013-02-08 02:30:31.327 PST:HINT: Consider increasing the
> configuration parameter "checkpoint_segments".
...
>
> I wonder if this is all expected. The database is getting ZERO
> activity. There are no connections open at this time. The checkpoints
> are happening at every 30 seconds and new WAL files are being created,
> AFAIK because the old ones are getting archived. Can't we be smart
> about not archiving new files if we did not generate any new WAL since
> the last archive ?

Yeah, this is a known issue. We skip two consecutive checkpoints
(forced by checkpoint_timeout) with no intervening activity, and we
skip two consecutive log switches (forced by archive_timeout) with no
intervening activity, but when you put them both together neither one
gets skipped because each one counts as "intervening activity" from
the other ones perspective. I think that at one point this was
considered desirable, as the arrival of log files in the archive, even
if they had no real content, was viewed as proof of life. You can set
up archive_command to send you an email if an archive fails, but the
same thing that prevents the archive might prevent the email from
arriving.

> Also, the log says "checkpoints are occurring too frequently (0
> seconds apart)". But that looks wrong too. Checkpoints are really
> happening at 30 seconds apart and not 0 as the log message claims.

I noticed that as well, and I think it might be a regression. I'll
run a bisection on it if I get a chance.

Cheers,

Jeff

>
>
>> Also, the log says "checkpoints are occurring too frequently (0
>> seconds apart)". But that looks wrong too. Checkpoints are really
>> happening at 30 seconds apart and not 0 as the log message claims.
>
> I noticed that as well, and I think it might be a regression. I'll
> run a bisection on it if I get a chance.
>

Looking further into it, seems there are two checkpoints happening almost immediately. The first happens because of timeout and the second happens immediately because of checkpoint segments (set to 1 in this case)

Given that no one has bothered to fix these issues, may be they are non issues after all.

Thanks,
Pavan

> Cheers,
>
> Jeff

On Fri, Feb 8, 2013 at 10:25 PM, Fujii Masao <masao(dot)fujii(at)gmail(dot)com> wrote:
.>
> BTW, the cause of the problem is that the following sequences happens.
>
> 1. archive_timeout switches WAL file because checkpoint WAL record has
> has been written since last switch

Thank you for explaining that. I also noticed that the WAL file switch
happens after archive_timeout seconds irrespective of whether
archive_mode is turned ON or not. This happens because we don't check
if XLogArchivingActive() in CheckArchiveTimeout() function. It looks
wrong to me. But if it's that way for a good reason, shouldn't we at
least document this behaviour ?

Thanks,
Pavan

--
Pavan Deolasee
http://www.linkedin.com/in/pavandeolasee

On Mon, Feb 11, 2013 at 5:46 PM, Pavan Deolasee
<pavan(dot)deolasee(at)gmail(dot)com> wrote:
> On Fri, Feb 8, 2013 at 10:25 PM, Fujii Masao <masao(dot)fujii(at)gmail(dot)com> wrote:
> .>
>> BTW, the cause of the problem is that the following sequences happens.
>>
>> 1. archive_timeout switches WAL file because checkpoint WAL record has
>> has been written since last switch
>
> Thank you for explaining that. I also noticed that the WAL file switch
> happens after archive_timeout seconds irrespective of whether
> archive_mode is turned ON or not. This happens because we don't check
> if XLogArchivingActive() in CheckArchiveTimeout() function. It looks
> wrong to me.

+1 to fix this. I've not heard the use case where archive_timeout needs to
be used even in not archive mode...

Regards,

--
Fujii Masao