Thread: Why so many xlogs?
Hi
have strange situation - too many xlog files.
PostgreSQL 8.3.11 on i386-pc-solaris2.10, compiled by cc -Xa
config:
# select name, setting from pg_settings where name ~ 'checkpoint|wal' order by 1;
name | setting
------------------------------+---------------
checkpoint_completion_target | 0.9
checkpoint_segments | 100
checkpoint_timeout | 900
checkpoint_warning | 30
log_checkpoints | on
wal_buffers | 2048
wal_sync_method | open_datasync
wal_writer_delay | 200
(8 rows)
as I understand, max number of xlog files in pg_xlog should be ( 1 + 2 *
checkpoint_segments ).
And in our case - it's more.
Added cronjob to log data about number of segments, current segment
name, number of segments in pg_xlog that are before current, and after
current. script is:
------------------------------------------------------------
#!/usr/bin/bash
LOGFILE=/home/postgres/logs/check_pg_xlog.out
LS_OUTPUT=$( ls -l /pgdata/main/pg_xlog | egrep -v "xlogtemp|backup|status|total" | sort -k9 )
FIRST_SEGMENT_LINE=$( echo "$LS_OUTPUT" | head -1 )
LAST_SEGMENT_LINE=$( echo "$LS_OUTPUT" | tail -1 )
FIRST_SEGMENT=$( echo "$FIRST_SEGMENT_LINE" | awk '{print $NF}' )
LAST_SEGMENT=$( echo "$LAST_SEGMENT_LINE" | awk '{print $NF}' )
FIRST_SEGMENT_NUM=$( echo "$FIRST_SEGMENT" | awk '{print $NF}' | cut -b 9-16,23-24 )
LAST_SEGMENT_NUM=$( echo "$LAST_SEGMENT" | awk '{print $NF}' | cut -b 9-16,23-24 )
SEGMENT_COUNT=$( printf $'ibase=16\n1 + %s - %s\n' $LAST_SEGMENT_NUM $FIRST_SEGMENT_NUM | bc )
CURRENT_WAL_FILE=$( /opt/pgsql8311/bin/psql -U postgres -qAtX -c 'select file_name from pg_xlogfile_name_offset(
pg_current_xlog_location())')
CURRENT_WAL_FILE_NUM=$( echo "$CURRENT_WAL_FILE" | cut -b 9-16,23-24 )
SEGMENTS_BEFORE_CURRENT=$( printf $'ibase=16\n%s - %s\n' $CURRENT_WAL_FILE_NUM $FIRST_SEGMENT_NUM | bc )
SEGMENTS_AFTER_CURRENT=$( printf $'ibase=16\n%s - %s\n' $LAST_SEGMENT_NUM $CURRENT_WAL_FILE_NUM | bc )
CURRENT_SEGMENT_LINE=$( echo "$LS_OUTPUT" | grep "$CURRENT_WAL_FILE" )
(
date
printf $'First segment : %s\n' "$FIRST_SEGMENT_LINE"
printf $'Current segment : %s\n' "$CURRENT_SEGMENT_LINE"
printf $'Last segment : %s\n' "$LAST_SEGMENT_LINE"
printf $'Segment count : %s\n' "$SEGMENT_COUNT"
printf $'Current wal segment : %s\n' "$CURRENT_WAL_FILE"
printf $'Segments before current : %s\n' "$SEGMENTS_BEFORE_CURRENT"
printf $'Segments after current : %s\n' "$SEGMENTS_AFTER_CURRENT"
printf $'Last checkpoint time : %s\n' "$( /opt/pgsql8311/bin/pg_controldata /pgdata/main | egrep '^Time of
latestcheckpoint:' | sed 's/^[^:]*: *//' )"
/opt/pgsql8311/bin/psql -U postgres -c "select name, setting from pg_settings where name =
any('{checkpoint_timeout,checkpoint_segments,archive_mode,archive_command}')"
) >> $LOGFILE
------------------------------------------------------------
sample output looks like this:
| Mon Nov 1 13:46:00 EDT 2010
| First segment : -rw------- 1 postgres postgres 16777216 Nov 1 13:16 000000010000376700000053
| Current segment : -rw------- 1 postgres postgres 16777216 Nov 1 13:45 000000010000376700000064
| Last segment : -rw------- 1 postgres postgres 16777216 Nov 1 13:01 000000010000376800000029
| Segment count : 215
| Current wal segment : 000000010000376700000064
| Segments before current : 17
| Segments after current : 197
| Last checkpoint time : Mon Nov 01 13:31:29 2010
| name | setting
| ---------------------+---------------
| archive_command | /usr/bin/true
| archive_mode | on
| checkpoint_segments | 100
| checkpoint_timeout | 900
| (4 rows)
As you can see, now we have 215 segments, with 17 that represent wal before current location and 197 that are after
currentsegment!
Here - you can see graph which plots number of wal segments in the last week http://depesz.com/various/bad-wal.jpg
it virtually never goes below 215, and it spikes to 270-300.
In here: http://www.depesz.com/various/bad-wal.log.gz is log from my test script since 20th of october.
Any ideas why number of segments is higher than expected?
Just so that I am clear: I do not want to lower it by changing
checkpoint_segments. I'm looking for information/enlightenment about why
it works the way it works, and what could be possibly wrong.
Best regards,
depesz
--
Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/
jid/gtalk: depesz@depesz.com / aim:depeszhdl / skype:depesz_hdl / gg:6749007
2010/11/1 hubert depesz lubaczewski <depesz@depesz.com>: > as I understand, max number of xlog files in pg_xlog should be ( 1 + 2 * > checkpoint_segments ). why? for a server overloaded with R/W transactions, it's possible to go beyond this. checkpoints just do not keep up. right now I have an 8.3 with checkpoint_segments=3, constantly running pgbench and I see 8 WAL segments. cheers Filip
2010/11/1 hubert depesz lubaczewski <depesz@depesz.com>:
> Hi
> have strange situation - too many xlog files.
>
> PostgreSQL 8.3.11 on i386-pc-solaris2.10, compiled by cc -Xa
>
> config:
> # select name, setting from pg_settings where name ~ 'checkpoint|wal' order by 1;
> name | setting
> ------------------------------+---------------
> checkpoint_completion_target | 0.9
> checkpoint_segments | 100
> checkpoint_timeout | 900
> checkpoint_warning | 30
> log_checkpoints | on
> wal_buffers | 2048
> wal_sync_method | open_datasync
> wal_writer_delay | 200
> (8 rows)
>
> as I understand, max number of xlog files in pg_xlog should be ( 1 + 2 *
> checkpoint_segments ).
(2 + checkpoint_completion_target) * checkpoint_segments + 1
=> 291
> And in our case - it's more.
>
> Added cronjob to log data about number of segments, current segment
> name, number of segments in pg_xlog that are before current, and after
> current. script is:
>
> ------------------------------------------------------------
> #!/usr/bin/bash
> LOGFILE=/home/postgres/logs/check_pg_xlog.out
>
> LS_OUTPUT=$( ls -l /pgdata/main/pg_xlog | egrep -v "xlogtemp|backup|status|total" | sort -k9 )
> FIRST_SEGMENT_LINE=$( echo "$LS_OUTPUT" | head -1 )
> LAST_SEGMENT_LINE=$( echo "$LS_OUTPUT" | tail -1 )
>
> FIRST_SEGMENT=$( echo "$FIRST_SEGMENT_LINE" | awk '{print $NF}' )
> LAST_SEGMENT=$( echo "$LAST_SEGMENT_LINE" | awk '{print $NF}' )
> FIRST_SEGMENT_NUM=$( echo "$FIRST_SEGMENT" | awk '{print $NF}' | cut -b 9-16,23-24 )
> LAST_SEGMENT_NUM=$( echo "$LAST_SEGMENT" | awk '{print $NF}' | cut -b 9-16,23-24 )
>
> SEGMENT_COUNT=$( printf $'ibase=16\n1 + %s - %s\n' $LAST_SEGMENT_NUM $FIRST_SEGMENT_NUM | bc )
> CURRENT_WAL_FILE=$( /opt/pgsql8311/bin/psql -U postgres -qAtX -c 'select file_name from pg_xlogfile_name_offset(
pg_current_xlog_location())')
> CURRENT_WAL_FILE_NUM=$( echo "$CURRENT_WAL_FILE" | cut -b 9-16,23-24 )
>
> SEGMENTS_BEFORE_CURRENT=$( printf $'ibase=16\n%s - %s\n' $CURRENT_WAL_FILE_NUM $FIRST_SEGMENT_NUM | bc )
> SEGMENTS_AFTER_CURRENT=$( printf $'ibase=16\n%s - %s\n' $LAST_SEGMENT_NUM $CURRENT_WAL_FILE_NUM | bc )
>
> CURRENT_SEGMENT_LINE=$( echo "$LS_OUTPUT" | grep "$CURRENT_WAL_FILE" )
> (
> date
> printf $'First segment : %s\n' "$FIRST_SEGMENT_LINE"
> printf $'Current segment : %s\n' "$CURRENT_SEGMENT_LINE"
> printf $'Last segment : %s\n' "$LAST_SEGMENT_LINE"
> printf $'Segment count : %s\n' "$SEGMENT_COUNT"
> printf $'Current wal segment : %s\n' "$CURRENT_WAL_FILE"
> printf $'Segments before current : %s\n' "$SEGMENTS_BEFORE_CURRENT"
> printf $'Segments after current : %s\n' "$SEGMENTS_AFTER_CURRENT"
> printf $'Last checkpoint time : %s\n' "$( /opt/pgsql8311/bin/pg_controldata /pgdata/main | egrep '^Time of
latestcheckpoint:' | sed 's/^[^:]*: *//' )"
> /opt/pgsql8311/bin/psql -U postgres -c "select name, setting from pg_settings where name =
any('{checkpoint_timeout,checkpoint_segments,archive_mode,archive_command}')"
> ) >> $LOGFILE
> ------------------------------------------------------------
>
>
> sample output looks like this:
>
> | Mon Nov 1 13:46:00 EDT 2010
> | First segment : -rw------- 1 postgres postgres 16777216 Nov 1 13:16 000000010000376700000053
> | Current segment : -rw------- 1 postgres postgres 16777216 Nov 1 13:45 000000010000376700000064
> | Last segment : -rw------- 1 postgres postgres 16777216 Nov 1 13:01 000000010000376800000029
> | Segment count : 215
> | Current wal segment : 000000010000376700000064
> | Segments before current : 17
> | Segments after current : 197
> | Last checkpoint time : Mon Nov 01 13:31:29 2010
> | name | setting
> | ---------------------+---------------
> | archive_command | /usr/bin/true
> | archive_mode | on
> | checkpoint_segments | 100
> | checkpoint_timeout | 900
> | (4 rows)
>
> As you can see, now we have 215 segments, with 17 that represent wal before current location and 197 that are after
currentsegment!
>
> Here - you can see graph which plots number of wal segments in the last week http://depesz.com/various/bad-wal.jpg
>
> it virtually never goes below 215, and it spikes to 270-300.
>
> In here: http://www.depesz.com/various/bad-wal.log.gz is log from my test script since 20th of october.
>
> Any ideas why number of segments is higher than expected?
>
> Just so that I am clear: I do not want to lower it by changing
> checkpoint_segments. I'm looking for information/enlightenment about why
> it works the way it works, and what could be possibly wrong.
>
> Best regards,
>
> depesz
>
> --
> Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/
> jid/gtalk: depesz@depesz.com / aim:depeszhdl / skype:depesz_hdl / gg:6749007
>
> --
> Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-general
>
--
Cédric Villemain 2ndQuadrant
http://2ndQuadrant.fr/ PostgreSQL : Expertise, Formation et Support
On Mon, Nov 01, 2010 at 07:22:50PM +0100, Cédric Villemain wrote: > > as I understand, max number of xlog files in pg_xlog should be ( 1 + 2 * > > checkpoint_segments ). > (2 + checkpoint_completion_target) * checkpoint_segments + 1 > => 291 this is formula gave to me by rhodiumtoad on irc, but we tested with lower checkpoint_completion_target and it didn't change *anything*. Best regards, depesz -- Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/ jid/gtalk: depesz@depesz.com / aim:depeszhdl / skype:depesz_hdl / gg:6749007
On Mon, Nov 01, 2010 at 07:18:22PM +0100, Filip Rembiałkowski wrote: > 2010/11/1 hubert depesz lubaczewski <depesz@depesz.com>: > > > as I understand, max number of xlog files in pg_xlog should be ( 1 + 2 * > > checkpoint_segments ). > > why? > > for a server overloaded with R/W transactions, it's possible to go beyond this. > checkpoints just do not keep up. > right now I have an 8.3 with checkpoint_segments=3, constantly running > pgbench and I see 8 WAL segments. you will notice in the logs that the system doesn't look like very loaded. i mean - there is fair amount of work, but nothing even resembling "overloaded". Best regards, depesz -- Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/ jid/gtalk: depesz@depesz.com / aim:depeszhdl / skype:depesz_hdl / gg:6749007
2010/11/1 hubert depesz lubaczewski <depesz@depesz.com>: > On Mon, Nov 01, 2010 at 07:22:50PM +0100, Cédric Villemain wrote: >> > as I understand, max number of xlog files in pg_xlog should be ( 1 + 2 * >> > checkpoint_segments ). >> (2 + checkpoint_completion_target) * checkpoint_segments + 1 >> => 291 > > this is formula gave to me by rhodiumtoad on irc, but we tested with lower > checkpoint_completion_target and it didn't change *anything*. You'll have between 211 and 291 files for 0.1 to 0.9 checkpoint_completion_target. You'd have more than the number of files given by formula used during your tests ? > > Best regards, > > depesz > > -- > Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/ > jid/gtalk: depesz@depesz.com / aim:depeszhdl / skype:depesz_hdl / gg:6749007 > -- Cédric Villemain 2ndQuadrant http://2ndQuadrant.fr/ PostgreSQL : Expertise, Formation et Support
2010/11/1 hubert depesz lubaczewski <depesz@depesz.com>: > On Mon, Nov 01, 2010 at 07:18:22PM +0100, Filip Rembiałkowski wrote: >> 2010/11/1 hubert depesz lubaczewski <depesz@depesz.com>: >> >> > as I understand, max number of xlog files in pg_xlog should be ( 1 + 2 * >> > checkpoint_segments ). >> >> why? >> >> for a server overloaded with R/W transactions, it's possible to go beyond this. >> checkpoints just do not keep up. >> right now I have an 8.3 with checkpoint_segments=3, constantly running >> pgbench and I see 8 WAL segments. > > you will notice in the logs that the system doesn't look like very > loaded. > i mean - there is fair amount of work, but nothing even resembling > "overloaded". There exists some checkpoint which occur more frequently than perhaps expected. (less than 15 minutes)... The logline about checkpoint might be usefull. Still I wonder what your question is exactly ? > > Best regards, > > depesz > > -- > Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/ > jid/gtalk: depesz@depesz.com / aim:depeszhdl / skype:depesz_hdl / gg:6749007 > > -- > Sent via pgsql-general mailing list (pgsql-general@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-general > -- Cédric Villemain 2ndQuadrant http://2ndQuadrant.fr/ PostgreSQL : Expertise, Formation et Support
On Mon, Nov 01, 2010 at 08:13:49PM +0100, Cédric Villemain wrote: > 2010/11/1 hubert depesz lubaczewski <depesz@depesz.com>: > > On Mon, Nov 01, 2010 at 07:22:50PM +0100, Cédric Villemain wrote: > >> > as I understand, max number of xlog files in pg_xlog should be ( 1 + 2 * > >> > checkpoint_segments ). > >> (2 + checkpoint_completion_target) * checkpoint_segments + 1 > >> => 291 > > > > this is formula gave to me by rhodiumtoad on irc, but we tested with lower > > checkpoint_completion_target and it didn't change *anything*. > > You'll have between 211 and 291 files for 0.1 to 0.9 > checkpoint_completion_target. > You'd have more than the number of files given by formula used during > your tests ? yes. we decreased checkpoint_completion_target to 0.5, and the numbers of xlog segments *did not change*. also - can you explain why "fraction of total time" (time!) would directly relate to number of xlog files existing in pg_xlog? I mean - you're not the first person to suggest it, but I don't see any way that these two could be related. Best regards, depesz -- Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/ jid/gtalk: depesz@depesz.com / aim:depeszhdl / skype:depesz_hdl / gg:6749007
On Mon, Nov 01, 2010 at 08:18:24PM +0100, Cédric Villemain wrote: > 2010/11/1 hubert depesz lubaczewski <depesz@depesz.com>: > > On Mon, Nov 01, 2010 at 07:18:22PM +0100, Filip Rembiałkowski wrote: > >> 2010/11/1 hubert depesz lubaczewski <depesz@depesz.com>: > >> > >> > as I understand, max number of xlog files in pg_xlog should be ( 1 + 2 * > >> > checkpoint_segments ). > >> > >> why? > >> > >> for a server overloaded with R/W transactions, it's possible to go beyond this. > >> checkpoints just do not keep up. > >> right now I have an 8.3 with checkpoint_segments=3, constantly running > >> pgbench and I see 8 WAL segments. > > > > you will notice in the logs that the system doesn't look like very > > loaded. > > i mean - there is fair amount of work, but nothing even resembling > > "overloaded". > > There exists some checkpoint which occur more frequently than perhaps > expected. (less than 15 minutes)... > > The logline about checkpoint might be usefull. Still I wonder what > your question is exactly ? why the number of wal segments is larger than 2n + 1 Best regards, depesz -- Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/ jid/gtalk: depesz@depesz.com / aim:depeszhdl / skype:depesz_hdl / gg:6749007
2010/11/1 hubert depesz lubaczewski <depesz@depesz.com>: > On Mon, Nov 01, 2010 at 08:13:49PM +0100, Cédric Villemain wrote: >> 2010/11/1 hubert depesz lubaczewski <depesz@depesz.com>: >> > On Mon, Nov 01, 2010 at 07:22:50PM +0100, Cédric Villemain wrote: >> >> > as I understand, max number of xlog files in pg_xlog should be ( 1 + 2 * >> >> > checkpoint_segments ). >> >> (2 + checkpoint_completion_target) * checkpoint_segments + 1 >> >> => 291 >> > >> > this is formula gave to me by rhodiumtoad on irc, but we tested with lower >> > checkpoint_completion_target and it didn't change *anything*. >> >> You'll have between 211 and 291 files for 0.1 to 0.9 >> checkpoint_completion_target. >> You'd have more than the number of files given by formula used during >> your tests ? > > yes. we decreased checkpoint_completion_target to 0.5, and the numbers > of xlog segments *did not change*. It should stick at a maximum of 3 * checkpoint_segments + 1, if it exceed it will remove the extra files after. > also - can you explain why "fraction of total time" (time!) would > directly relate to number of xlog files existing in pg_xlog? I mean - > you're not the first person to suggest it, but I don't see any way that > these two could be related. It's guess that while your checkpoint is longer by this factor(X%), the number of wal files needed might be multiplied by the same ratio. (1+X%) To handle extra files created while the checklpoint is still running. > > Best regards, > > depesz > > -- > Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/ > jid/gtalk: depesz@depesz.com / aim:depeszhdl / skype:depesz_hdl / gg:6749007 > -- Cédric Villemain 2ndQuadrant http://2ndQuadrant.fr/ PostgreSQL : Expertise, Formation et Support
On Mon, Nov 01, 2010 at 08:31:10PM +0100, Cédric Villemain wrote: > It should stick at a maximum of 3 * checkpoint_segments + 1, if it > exceed it will remove the extra files after. if you'd look at the graph you'd notice that it never goes down to 2n+1. And really - so far I have not yet heard/seen/read any solid reasoning for 3n instead of 2n. > > also - can you explain why "fraction of total time" (time!) would > > directly relate to number of xlog files existing in pg_xlog? I mean - > > you're not the first person to suggest it, but I don't see any way that > > these two could be related. > It's guess that while your checkpoint is longer by this factor(X%), > the number of wal files needed might be multiplied by the same ratio. > (1+X%) To handle extra files created while the checklpoint is still > running. I'm not sure I understand. Will need to run some tests. Yet - even assuming (2 + checkpoint_completion_target ) * n - it doesn't explain why there was no difference in number of segments after decreasing from 0.9 to 0.5. Best regards, depesz -- Linkedin: http://www.linkedin.com/in/depesz / blog: http://www.depesz.com/ jid/gtalk: depesz@depesz.com / aim:depeszhdl / skype:depesz_hdl / gg:6749007
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Le 01/11/2010 20:54, hubert depesz lubaczewski a écrit : > On Mon, Nov 01, 2010 at 08:31:10PM +0100, Cédric Villemain wrote: >> It should stick at a maximum of 3 * checkpoint_segments + 1, if it >> exceed it will remove the extra files after. > > if you'd look at the graph you'd notice that it never goes down to 2n+1. > And really - so far I have not yet heard/seen/read any solid reasoning > for 3n instead of 2n. I understand this 3n this way: n "active" WAL files n "recycled-ready-to-use" WAL files checkpoint_completion_target*n WAL being write on disk > >>> also - can you explain why "fraction of total time" (time!) would >>> directly relate to number of xlog files existing in pg_xlog? I mean - >>> you're not the first person to suggest it, but I don't see any way that >>> these two could be related. >> It's guess that while your checkpoint is longer by this factor(X%), >> the number of wal files needed might be multiplied by the same ratio. >> (1+X%) To handle extra files created while the checklpoint is still >> running. > > I'm not sure I understand. Will need to run some tests. Yet - even > assuming (2 + checkpoint_completion_target ) * n - it doesn't explain > why there was no difference in number of segments after decreasing from > 0.9 to 0.5. Does your cluster have enough write ? I think you might have to wait a bit longer to see remaining files being recycled or deleted... > > Best regards, > > depesz > > -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.10 (GNU/Linux) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/ iEYEARECAAYFAkzPHZcACgkQxWGfaAgowiKQnQCgg7HIAI35mlfySbYY/VptqyjQ kIwAni9DtLqx4j7MFk//1cTf88Dul/4e =NfHT -----END PGP SIGNATURE-----