I am a little concerned about a log_* setting that is INFO. I understand
why you used INFO (for log_min_error_messages), but INFO is inconsistent
with the log* prefix, and by default INFO doesn't appear in the log
file.

So, by default, the INFO is going to go to the user terminal, and not to
the logfile.

Ideas?

---------------------------------------------------------------------------

Simon Riggs wrote:
> On Mon, 2007-02-19 at 19:38 +0000, Simon Riggs wrote:
> > On Tue, 2007-02-13 at 22:19 -0500, Bruce Momjian wrote:
> > > Simon Riggs wrote:
> > > > On Thu, 2006-10-26 at 18:45 -0400, Tom Lane wrote:
> > > > > Chris Campbell <chris@bignerdranch.com> writes:
> > > > > > Is there additional logging information I can turn on to get more
> > > > > > details? I guess I need to see exactly what locks both processes
> > > > > > hold, and what queries they were running when the deadlock occurred?
> > > > > > Is that easily done, without turning on logging for *all* statements?
> > > > >
> > > > > log_min_error_statement = error would at least get you the statements
> > > > > reporting the deadlocks, though not what they're conflicting against.
> > > >
> > > > Yeh, we need a much better locking logger for performance analysis.
> > > >
> > > > We really need to dump the whole wait-for graph for deadlocks, since
> > > > this might be more complex than just two statements involved. Deadlocks
> > > > ought to be so infrequent that we can afford the log space to do this -
> > > > plus if we did this it would likely lead to fewer deadlocks.
> > > >
> > > > For 8.3 I'd like to have a log_min_duration_lockwait (secs) parameter
> > > > that would allow you to dump the wait-for graph for any data-level locks
> > > > that wait too long, rather than just those that deadlock. Many
> > > > applications experience heavy locking because of lack of holistic
> > > > design. That will also show up the need for other utilities to act
> > > > CONCURRENTLY, if possible.
> > >
> > > Old email, but I don't see how our current output is not good enough?
> > >
> > > test=> lock a;
> > > ERROR: deadlock detected
> > > DETAIL: Process 6855 waits for AccessExclusiveLock on relation 16394 of
> > > database 16384; blocked by process 6795.
> > > Process 6795 waits for AccessExclusiveLock on relation 16396 of database
> > > 16384; blocked by process 6855.
> >
> > This detects deadlocks, but it doesn't detect lock waits.
> >
> > When I wrote that it was previous experience driving me. Recent client
> > experience has highlighted the clear need for this. We had a lock wait
> > of 50 hours because of an RI check; thats the kind of thing I'd like to
> > show up in the logs somewhere.
> >
> > Lock wait detection can be used to show up synchronisation points that
> > have been inadvertently designed into an application, so its a useful
> > tool in investigating performance issues.
> >
> > I have a patch implementing the logging as agreed with Tom, will post to
> > patches later tonight.
>
> Patch for discussion, includes doc entries at top of patch, so its
> fairly clear how it works.
>
> Output is an INFO message, to allow this to trigger
> log_min_error_statement when it generates a message, to allow us to see
> the SQL statement that is waiting. This allows it to generate a message
> prior to the statement completing, which is important because it may not
> ever complete, in some cases, so simply logging a list of pids won't
> always tell you what the SQL was that was waiting.
>
> Other approaches are possible...
>
> Comments?
>
> --
> Simon Riggs
> EnterpriseDB http://www.enterprisedb.com
>

[ Attachment, skipping... ]

--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://www.enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +

---------------------------(end of broadcast)---------------------------
TIP 7: You can help support the PostgreSQL project by donating at

http://www.postgresql.org/about/donate

On Mon, 2007-02-26 at 13:34 -0500, Bruce Momjian wrote:

> I am a little concerned about a log_* setting that is INFO. I understand
> why you used INFO (for log_min_error_messages), but INFO is inconsistent
> with the log* prefix, and by default INFO doesn't appear in the log
> file.

Yeh, LOG would be most appropriate, but thats not possible.

log_min_messages allows only DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1,
INFO, NOTICE and WARNING for non-error states.

Possibly DEBUG1?

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com



---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

"Simon Riggs" <simon@2ndquadrant.com> writes:
> Yeh, LOG would be most appropriate, but thats not possible.

You have not given any good reason for that.

> log_min_messages allows only DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1,
> INFO, NOTICE and WARNING for non-error states.

I don't think you understand quite how the log message priority works...

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

On Mon, 2007-02-26 at 14:11 -0500, Tom Lane wrote:
> "Simon Riggs" <simon@2ndquadrant.com> writes:
> > Yeh, LOG would be most appropriate, but thats not possible.
>
> You have not given any good reason for that.

The idea of the patch is that it generates a log message which then
invokes log_min_error_statement so that the SQL statement is displayed.
LOG is not on the list of options there, otherwise I would use it.

The reason for behaving like this is so that a message is generated
while the statement is still waiting, rather than at the end. As I
mentioned in the submission, you may not like that behaviour; I'm in two
minds myself, but I'm trying to get to the stage of having useful
information come out of the server when we have long lock waits.

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com



---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

"Simon Riggs" <simon@2ndquadrant.com> writes:
> The idea of the patch is that it generates a log message which then
> invokes log_min_error_statement so that the SQL statement is displayed.
> LOG is not on the list of options there, otherwise I would use it.

As I said, you don't understand how the logging priority control works.
LOG *is* the appropriate level for stuff intended to go to the server log.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

On Mon, 2007-02-26 at 14:28 -0500, Tom Lane wrote:
> "Simon Riggs" <simon@2ndquadrant.com> writes:
> > The idea of the patch is that it generates a log message which then
> > invokes log_min_error_statement so that the SQL statement is displayed.
> > LOG is not on the list of options there, otherwise I would use it.
>
> As I said, you don't understand how the logging priority control works.
> LOG *is* the appropriate level for stuff intended to go to the server log.

Please look at the definition of log_min_error_statement, so you
understand where I'm coming from.

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com



---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

"Simon Riggs" <simon@2ndquadrant.com> writes:
> On Mon, 2007-02-26 at 14:28 -0500, Tom Lane wrote:
>> "Simon Riggs" <simon@2ndquadrant.com> writes:
>>> The idea of the patch is that it generates a log message which then
>>> invokes log_min_error_statement so that the SQL statement is displayed.
>>> LOG is not on the list of options there, otherwise I would use it.
>>
>> As I said, you don't understand how the logging priority control works.
>> LOG *is* the appropriate level for stuff intended to go to the server log.

> Please look at the definition of log_min_error_statement, so you
> understand where I'm coming from.

I *have* read the definition of log_min_error_statement. (The SGML docs
are wrong btw, as a quick look at the code shows that LOG is an accepted
value.)

The real issue here is that send_message_to_server_log just does

if (edata->elevel >= log_min_error_statement && debug_query_string != NULL)

to determine whether to log the statement, whereas arguably it should be
using a test like is_log_level_output --- that is, the priority ordering
for log_min_error_statement should be like log_min_messages not like
client_min_messages. We've discussed that before in another thread, but
it looks like nothing's been done yet. In any case, if you're unhappy
with the code's choice of whether to emit the STATEMENT part of a log
message, some changes here are what's indicated, not bizarre choices of
elevel for individual messages.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

On Mon, 2007-02-26 at 14:52 -0500, Tom Lane wrote:
> "Simon Riggs" <simon@2ndquadrant.com> writes:
> > On Mon, 2007-02-26 at 14:28 -0500, Tom Lane wrote:
> >> "Simon Riggs" <simon@2ndquadrant.com> writes:
> >>> The idea of the patch is that it generates a log message which then
> >>> invokes log_min_error_statement so that the SQL statement is displayed.
> >>> LOG is not on the list of options there, otherwise I would use it.
> >>
> >> As I said, you don't understand how the logging priority control works.
> >> LOG *is* the appropriate level for stuff intended to go to the server log.
>
> > Please look at the definition of log_min_error_statement, so you
> > understand where I'm coming from.
>
> I *have* read the definition of log_min_error_statement. (The SGML docs
> are wrong btw, as a quick look at the code shows that LOG is an accepted
> value.)

OK, I should have looked passed the manual.

> The real issue here is that send_message_to_server_log just does
>
> if (edata->elevel >= log_min_error_statement && debug_query_string != NULL)
>
> to determine whether to log the statement, whereas arguably it should be
> using a test like is_log_level_output --- that is, the priority ordering
> for log_min_error_statement should be like log_min_messages not like
> client_min_messages. We've discussed that before in another thread, but
> it looks like nothing's been done yet.

Hopefully not with me? Don't remember that.

> In any case, if you're unhappy
> with the code's choice of whether to emit the STATEMENT part of a log
> message, some changes here are what's indicated, not bizarre choices of
> elevel for individual messages.

Well, I would have chosen LOG if I thought it was available.

I'll do some more to the patch.

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com



---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

Simon Riggs wrote:
> On Mon, 2007-02-26 at 13:34 -0500, Bruce Momjian wrote:
>
> > I am a little concerned about a log_* setting that is INFO. I understand
> > why you used INFO (for log_min_error_messages), but INFO is inconsistent
> > with the log* prefix, and by default INFO doesn't appear in the log
> > file.
>
> Yeh, LOG would be most appropriate, but thats not possible.
>
> log_min_messages allows only DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1,
> INFO, NOTICE and WARNING for non-error states.
>
> Possibly DEBUG1?

This highlights a problem we have often had with LOG output where we
also want the query.

I think there are two possible approaches. First, we could add a new
bitmap value like LOG_STATEMENT to ereport when we want the statement
with the log line:

ereport (LOG | LOG_STATEMENT, ...)

(or a new LOG_WITH_STATEMENT log level) and a new GUC like
"log_include_statement" that would control the output of statements for
certain GUC parameters, and we document with GUC values it controls.

A simpler idea would be to unconditionally include the query in the
errdetail() of the actual LOG ereport.

This is not the first GUC that has needed this. We had this issue with
"log_temp_files", which we just added, and the only suggested solution
was to use log_statement = 'all'. Either of these ideas above would be
useful for this as well.

--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://www.enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

Bruce Momjian <bruce@momjian.us> writes:
> This is not the first GUC that has needed this.

Exactly. I think that we simply made a mistake in the initial
implementation of log_min_error_statement: we failed to think about
whether it should use client or server priority ordering, and the
easy-to-code behavior was the wrong one.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 7: You can help support the PostgreSQL project by donating at

http://www.postgresql.org/about/donate