Expose checkpoint start/finish times into SQL.

Theo Schlossnagle wrote:

First whack at exposing the start and finish checkpoint times into SQL.

I suggest using GetCurrentTimestamp() directly instead of time_t and
converting.

--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

Theo Schlossnagle wrote:

First whack at exposing the start and finish checkpoint times into SQL.

Why is that useful?

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

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Thu, 03 Apr 2008 23:21:49 +0100
Heikki Linnakangas <heikki@enterprisedb.com> wrote:

Theo Schlossnagle wrote:

First whack at exposing the start and finish checkpoint times into
SQL.

Why is that useful?

For knowing how long checkpoints are taking. If they are taking too
long you may need to adjust your bgwriter settings, and it is a
serious drag to parse postgresql logs for this info.

Joshua D. Drake

- --
The PostgreSQL Company since 1997: http://www.commandprompt.com/
PostgreSQL Community Conference: http://www.postgresqlconference.org/
United States PostgreSQL Association: http://www.postgresql.us/
Donate to the PostgreSQL Project: http://www.postgresql.org/about/donate

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)

iD8DBQFH9VpcATb/zqfZUUQRAiFwAJ0W7uu4Xk4DgXph1JaL180XfsAKpQCghDRw
GYNE9ouPjlRhEqUmxwktDYc=
=DRsZ
-----END PGP SIGNATURE-----

Heikki Linnakangas <heikki@enterprisedb.com> writes:

Theo Schlossnagle wrote:

First whack at exposing the start and finish checkpoint times into SQL.

Why is that useful?

Does this implementation even work? It looks to me like the
globalStats.last_checkpoint_start/done fields will go back to zero the
very next time the bgwriter sends a stats message. I'm not sure what
a sane behavior would be, but it seems unlikely that that's it.

regards, tom lane

Joshua D. Drake wrote:

Theo Schlossnagle wrote:

First whack at exposing the start and finish checkpoint times into
SQL.

Why is that useful?

For knowing how long checkpoints are taking. If they are taking too
long you may need to adjust your bgwriter settings, and it is a
serious drag to parse postgresql logs for this info.

Even if this were true, surely the answer is to improve the logging.

Has this feature been discussed on -hackers? I don't recall it (and my
memory has plenty of holes in it), but I'm sure that after attending my
talk last Sunday Theo hasn't sent in a patch for an undiscussed feature ;-)

cheers

andrew

"Joshua D. Drake" <jd@commandprompt.com> writes:

Heikki Linnakangas <heikki@enterprisedb.com> wrote:

Why is that useful?

For knowing how long checkpoints are taking. If they are taking too
long you may need to adjust your bgwriter settings, and it is a
serious drag to parse postgresql logs for this info.

1. To do anything useful along those lines, you would need to look at a
lot of checkpoints over time, which is what log_checkpoints is good for.
This patch only tells you about the latest, which isn't very useful
for making any good decisions about parameters.

2. If I read the patch correctly, half of the time what you'd be seeing
is the start time of the currently-active checkpoint and the completion
time of the prior checkpoint. I don't know what those numbers are good
for at all.

3. As of PG 8.3, the bgwriter tries very hard to make the elapsed time
of a checkpoint be just about checkpoint_timeout *
checkpoint_completion_target, regardless of load factors. So unless
your settings are completely broken, measuring the actual time isn't
going to tell you much.

In short: Heikki's question is on point.

regards, tom lane

On Thursday 03 April 2008 19:08, Andrew Dunstan wrote:

Joshua D. Drake wrote:

Theo Schlossnagle wrote:

First whack at exposing the start and finish checkpoint times into
SQL.

Why is that useful?

For knowing how long checkpoints are taking. If they are taking too
long you may need to adjust your bgwriter settings, and it is a
serious drag to parse postgresql logs for this info.

Even if this were true, surely the answer is to improve the logging.

Exposing everything into the log files isn't always sufficient (says the guy
who maintains a remote admin tool)

--
Robert Treat
Build A Brighter LAMP :: Linux Apache {middleware} PostgreSQL

Robert Treat wrote:

On Thursday 03 April 2008 19:08, Andrew Dunstan wrote:

Joshua D. Drake wrote:

Theo Schlossnagle wrote:

First whack at exposing the start and finish checkpoint times into
SQL.

Why is that useful?

For knowing how long checkpoints are taking. If they are taking too
long you may need to adjust your bgwriter settings, and it is a
serious drag to parse postgresql logs for this info.

Even if this were true, surely the answer is to improve the logging.

Exposing everything into the log files isn't always sufficient (says the guy
who maintains a remote admin tool)

It should be now that you can have machine readable logs (says the guy
who literally spent weeks making that happen) ;-)

cheers

andrew

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Thu, 03 Apr 2008 20:29:18 -0400
Tom Lane <tgl@sss.pgh.pa.us> wrote:

"Joshua D. Drake" <jd@commandprompt.com> writes:

Heikki Linnakangas <heikki@enterprisedb.com> wrote:

Why is that useful?

For knowing how long checkpoints are taking. If they are taking too
long you may need to adjust your bgwriter settings, and it is a
serious drag to parse postgresql logs for this info.

1. To do anything useful along those lines, you would need to look at
a lot of checkpoints over time, which is what log_checkpoints is good
for. This patch only tells you about the latest, which isn't very
useful for making any good decisions about parameters.

I would agree with this. We would need a history of checkpoints that
didn't reset until we told it to.

2. If I read the patch correctly, half of the time what you'd be
seeing is the start time of the currently-active checkpoint and the
completion time of the prior checkpoint. I don't know what those
numbers are good for at all.

IMO we should see start checkpoint, end checkpoint. As part of a single
record. Other possibly interesting info would be how many logs were
processed.

3. As of PG 8.3, the bgwriter tries very hard to make the elapsed time
of a checkpoint be just about checkpoint_timeout *
checkpoint_completion_target, regardless of load factors. So unless
your settings are completely broken, measuring the actual time isn't
going to tell you much.

You assume that people don't have broken settings. :)

In short: Heikki's question is on point.

I didn't say it wasn't. I was just stating why a patch that does what
was described is useful. I believe with changes it would still be
useful. Having to go to log for a lot of this stuff is painful.

Joshua D. Drake

- --
The PostgreSQL Company since 1997: http://www.commandprompt.com/
PostgreSQL Community Conference: http://www.postgresqlconference.org/
United States PostgreSQL Association: http://www.postgresql.us/
Donate to the PostgreSQL Project: http://www.postgresql.org/about/donate

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)

iD8DBQFH9YETATb/zqfZUUQRAmiTAJ0Shc4rSIKRG5nabAv9RwW1MVi/BQCfUIiK
Nb8qyBonAlNl/Agp/wCyvTU=
=H8TF
-----END PGP SIGNATURE-----

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Thu, 03 Apr 2008 20:45:37 -0400
Andrew Dunstan <andrew@dunslane.net> wrote:

Exposing everything into the log files isn't always sufficient
(says the guy who maintains a remote admin tool)

It should be now that you can have machine readable logs (says the
guy who literally spent weeks making that happen) ;-)

And how does the person get access to those? And what script do I need
to write to make it happen? Don't get me wrong, the feature you worked
entirely too hard on to get working is valuable but... being able to
say, "SELECT * FROM give_me_my_db_info;" is much more useful in this
context.

In short, I should never have to go to log for this class of
information. It should be available in the database.

Sincerely,

Joshua D. Drake

- --
The PostgreSQL Company since 1997: http://www.commandprompt.com/
PostgreSQL Community Conference: http://www.postgresqlconference.org/
United States PostgreSQL Association: http://www.postgresql.us/
Donate to the PostgreSQL Project: http://www.postgresql.org/about/donate

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)

iD8DBQFH9YF9ATb/zqfZUUQRAp+fAKCIOOKCKv5FaWiOF7hZjtLr8PzfGQCfRpq+
lY353B+9fmWwxWppAkhncMY=
=BwYD
-----END PGP SIGNATURE-----

"Joshua D. Drake" <jd@commandprompt.com> writes:

I would agree with this. We would need a history of checkpoints that
didn't reset until we told it to.

Indeed, but the submitted patch has nought whatsoever to do with that.
It exposes some instantaneous state.

You could perhaps *build* a log facility on top of that, at the SQL
level; but I don't see the point, and I definitely disagree that it
would be "easier than trolling the logs".

regards, tom lane

On Apr 3, 2008, at 7:08 PM, Andrew Dunstan wrote:

Joshua D. Drake wrote:

Theo Schlossnagle wrote:

First whack at exposing the start and finish checkpoint times into
SQL.

Why is that useful?

For knowing how long checkpoints are taking. If they are taking too
long you may need to adjust your bgwriter settings, and it is a
serious drag to parse postgresql logs for this info.

Even if this were true, surely the answer is to improve the logging.

Has this feature been discussed on -hackers? I don't recall it (and
my memory has plenty of holes in it), but I'm sure that after
attending my talk last Sunday Theo hasn't sent in a patch for an
undiscussed feature ;-)

Andrew: I don't think this feature has been discussed on hackers. The
patch took about 15 minutes to author, so it sounds like the most
concise way to start a conversation. Seems silly to start the
conversation on hackers with a patch. :-)

Alvaro: Thanks, I flip that to GetCurrentTimestamp()

Heikki: It it useful for knowing when the last checkpoint occurred.
Like Robert, we have situations where reading the log file is a PITA
-- so this provides that information. I originally planned on only
adding the start time, but figured adding the end would make sense too.

Tom: It worked for me in my testing, though I did not extensively
tested. I didn't see anywhere the stats are zero'd out, so I believe
the timestamp is zero at start and then only ever set to the starttime
during a checkpoint invocation. I admittedly don't have a thorough
understanding of that code -- but that segment (before my patch)
looked pretty concise.

--
Theo Schlossnagle
Esoteric Curio -- http://lethargy.org/
OmniTI Computer Consulting, Inc. -- http://omniti.com/

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Thu, 03 Apr 2008 21:26:46 -0400
Tom Lane <tgl@sss.pgh.pa.us> wrote:

"Joshua D. Drake" <jd@commandprompt.com> writes:

I would agree with this. We would need a history of checkpoints that
didn't reset until we told it to.

Indeed, but the submitted patch has nought whatsoever to do with that.
It exposes some instantaneous state.

You could perhaps *build* a log facility on top of that, at the SQL
level; but I don't see the point, and I definitely disagree that it
would be "easier than trolling the logs".

Having the ability to do this:

SELECT * FROM pg_stat_bgwriter
WHERE last_checkpoint
BETWEEN (current_time - '1 Day'::interval) AND current_time;

Would be very useful. Which I can do with logs currently. You are
correct. However from a usability, remote reporting and manageability
perspective it certainly is not the same as something as I describe
above.

Note I am perfectly willing to table this until we have a full todo and
specification for a feature.

Sincerely,

Joshua D. Drake

- --
The PostgreSQL Company since 1997: http://www.commandprompt.com/
PostgreSQL Community Conference: http://www.postgresqlconference.org/
United States PostgreSQL Association: http://www.postgresql.us/
Donate to the PostgreSQL Project: http://www.postgresql.org/about/donate

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)

iD8DBQFH9YVlATb/zqfZUUQRAnRxAKCab3O4dmBXctXTptDFwkRx+1zUQQCdFmsN
E3GWNoC90jS7ooFgArR8Nv0=
=CvMx
-----END PGP SIGNATURE-----

Joshua D. Drake wrote:

Exposing everything into the log files isn't always sufficient
(says the guy who maintains a remote admin tool)

It should be now that you can have machine readable logs (says the
guy who literally spent weeks making that happen) ;-)

And how does the person get access to those? And what script do I need
to write to make it happen? Don't get me wrong, the feature you worked
entirely too hard on to get working is valuable but... being able to
say, "SELECT * FROM give_me_my_db_info;" is much more useful in this
context.

How to load the CSV logs is very clearly documented. It's really *very*
easy, so easy it's mostly C&P. See
http://www.postgresql.org/docs/current/static/runtime-config-logging.html#RUNTIME-CONFIG-LOGGING-CSVLOG

If you are trying to tell me that that's too hard for a DBA, then I have
to say you need better DBAs.

In short, I should never have to go to log for this class of
information. It should be available in the database.

What you haven't explained is why this information needs to be kept in
the db on a historical basis, as opposed to all the other possible
diagnostics where history might be useful (and, as Tom has pointed out,
this patch doesn keep it historically any way).

I think there is quite possibly a good case for keeping some diagnostics
in a table or tables, on a rolling basis, maybe. But then that's a
facility that needs to be properly designed.

cheers

andrew

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Thu, 03 Apr 2008 21:44:00 -0400
Andrew Dunstan <andrew@dunslane.net> wrote:

I think there is quite possibly a good case for keeping some
diagnostics in a table or tables, on a rolling basis, maybe. But then
that's a facility that needs to be properly designed.

Please see my later email on the thread.

Joshua D. Drake

- --
The PostgreSQL Company since 1997: http://www.commandprompt.com/
PostgreSQL Community Conference: http://www.postgresqlconference.org/
United States PostgreSQL Association: http://www.postgresql.us/
Donate to the PostgreSQL Project: http://www.postgresql.org/about/donate

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)

iD8DBQFH9YjfATb/zqfZUUQRAnrwAKCUW76EI+lnz+qGJXFPyp9QqWJ9DgCgpnmP
eiGM+P4P79O20VgBm6ew1u4=
=/abt
-----END PGP SIGNATURE-----

Theo Schlossnagle <jesus@omniti.com> writes:

Heikki: It it useful for knowing when the last checkpoint occurred.

I guess I'm wondering why that's important. In the current bgwriter
design, the system spends half its time checkpointing (or in general
checkpoint_completion_target % of the time). So this seems fairly close
to wanting to know when the bgwriter last wrote a dirty buffer --- yeah,
I can imagine scenarios for wanting to know that, but they probably
require a whole pile of other knowledge as well.

JD seems to have gone off into the weeds imagining that this patch would
provide tracking of the last N checkpoints; which might start to
approach the level of an interesting feature, except that it's still not
clear *why* those numbers are interesting, given the bgwriter's
propensity to try to hold the checkpoint duration constant.

regards, tom lane

Theo Schlossnagle wrote:

Has this feature been discussed on -hackers? I don't recall it (and
my memory has plenty of holes in it), but I'm sure that after
attending my talk last Sunday Theo hasn't sent in a patch for an
undiscussed feature ;-)

Andrew: I don't think this feature has been discussed on hackers. The
patch took about 15 minutes to author, so it sounds like the most
concise way to start a conversation. Seems silly to start the
conversation on hackers with a patch. :-)

Well, not really. I believe -hackers has a much larger readership than
-patches, so even for small features we generally want them discussed
there.

cheers

andrew

On Thursday 03 April 2008 21:14, Joshua D. Drake wrote:

On Thu, 03 Apr 2008 20:29:18 -0400

Tom Lane <tgl@sss.pgh.pa.us> wrote:

"Joshua D. Drake" <jd@commandprompt.com> writes:

Heikki Linnakangas <heikki@enterprisedb.com> wrote:

Why is that useful?

For knowing how long checkpoints are taking. If they are taking too
long you may need to adjust your bgwriter settings, and it is a
serious drag to parse postgresql logs for this info.

1. To do anything useful along those lines, you would need to look at
a lot of checkpoints over time, which is what log_checkpoints is good
for. This patch only tells you about the latest, which isn't very
useful for making any good decisions about parameters.

I would agree with this. We would need a history of checkpoints that
didn't reset until we told it to.

You can plug a single item graphed over time into things like rrdtool to get
good trending information. And it's often easier to do this using sql
interfaces to get the data than pulling it out of log files (almost like the
db was designed for that :-)

2. If I read the patch correctly, half of the time what you'd be
seeing is the start time of the currently-active checkpoint and the
completion time of the prior checkpoint. I don't know what those
numbers are good for at all.

Knowing when the last checkpoint occured is certainly useful for monitoring
purposes (wrt pitr and as a general item for cuasing alerts if checkpoints
stop occuring frequently enough, or if they start taking too long.)

3. As of PG 8.3, the bgwriter tries very hard to make the elapsed time
of a checkpoint be just about checkpoint_timeout *
checkpoint_completion_target, regardless of load factors. So unless
your settings are completely broken, measuring the actual time isn't
going to tell you much.

How does one measure when the bgwriter is failing at this effort?

--
Robert Treat
Build A Brighter LAMP :: Linux Apache {middleware} PostgreSQL

Robert Treat <xzilla@users.sourceforge.net> writes:

Tom Lane <tgl@sss.pgh.pa.us> wrote:

3. As of PG 8.3, the bgwriter tries very hard to make the elapsed time
of a checkpoint be just about checkpoint_timeout *
checkpoint_completion_target, regardless of load factors. So unless
your settings are completely broken, measuring the actual time isn't
going to tell you much.

How does one measure when the bgwriter is failing at this effort?

Well, not with *this* patch. At least not without adding a lot of
infrastructure on top of it, and I'm failing to see why you'd build
such infrastructure in order to track just two numbers that are of
uncertain value.

JD seems to be on record that the existing logging mechanism sucks
and he needs something else. That's fine, but I think it means that
we need to improve logging in general, not invent a single-purpose
mechanism for logging checkpoint times.

Theo claimed he had a reason for wanting to know the latest checkpoint
time, *without* any intention of time-extended tracking of that; but
he didn't say what it was. If there is a credible reason for that
then it might justify a patch of this nature, but I don't see that
the reasons that have been stated so far in the thread hold any water.

regards, tom lane