Re: log_duration

On top of a confusing day, I now have this:

I set log_duration = true in a postgresql.conf file.
I startup and test, local users connected via psql: working, no problem.

Users connecting remotely, same user, same database: no log of query
statement durations.

There is nothing in the code that sets this value independently for sets
of users (is there?)

I'm also having similar problems with log_min_statement_duration not
working at all.

Any ideas? Thanks,

Best Regards, Simon Riggs

"Simon Riggs" <simon(at)2ndquadrant(dot)com> writes:
> On top of a confusing day, I now have this:
> I set log_duration = true in a postgresql.conf file.
> I startup and test, local users connected via psql: working, no problem.
> Users connecting remotely, same user, same database: no log of query
> statement durations.
> There is nothing in the code that sets this value independently for sets
> of users (is there?)

No. How sure are you that the remote users are really connecting to the
same postmaster?

regards, tom lane

> From: Tom Lane
> "Simon Riggs" <simon(at)2ndquadrant(dot)com> writes:
> > On top of a confusing day, I now have this:
> > I set log_duration = true in a postgresql.conf file.
> > I startup and test, local users connected via psql:
> working, no problem.
> > Users connecting remotely, same user, same database: no log of query
> > statement durations.
> > There is nothing in the code that sets this value
> independently for sets
> > of users (is there?)
>
> No. How sure are you that the remote users are really
> connecting to the
> same postmaster?

Yes, very definitely.

I'm sitting here watching the Statement: lines scroll up the screen for
the remotely connected users.
Local sessions show both Statement: and Duration:

Can't see anything in the code that gives any kind of conditional on
that.

The code is straight 8.0.1, no code editing, but compiled on SUSE.

I wouldn't care, but I'm trying to tune the database, so the missing
data matters,

Best Regards, Simon Riggs

>Simon Riggs
> > From: Tom Lane
> > "Simon Riggs" <simon(at)2ndquadrant(dot)com> writes:
> > > On top of a confusing day, I now have this:
> > > I set log_duration = true in a postgresql.conf file.
> > > I startup and test, local users connected via psql:
> > working, no problem.
> > > Users connecting remotely, same user, same database: no
> log of query
> > > statement durations.
> > > There is nothing in the code that sets this value
> > independently for sets
> > > of users (is there?)
> >
> > No. How sure are you that the remote users are really
> > connecting to the
> > same postmaster?
>
> Yes, very definitely.
>
> I'm sitting here watching the Statement: lines scroll up the
> screen for
> the remotely connected users.
> Local sessions show both Statement: and Duration:
>
> Can't see anything in the code that gives any kind of conditional on
> that.
>
> The code is straight 8.0.1, no code editing, but compiled on SUSE.
>
> I wouldn't care, but I'm trying to tune the database, so the missing
> data matters,

Further update on this:

We've isolated this issue to JDBC client access.
When connecting using the latest JDBC driver, we do not get "Duration:"
LOG messages when using log_duration = true.
[driver 8.0-310.jdbc2.jar]

We've tested both localhost connections and remotely connected users
with libpq clients and these do produce the log records for the
"Duration:" as we would expect.

Is this a V2/V3 protocol issue? Or a bug? (If so, where)

Thanks for any help.

Best Regards, Simon Riggs

"Simon Riggs" <simon(at)2ndquadrant(dot)com> writes:
> Further update on this:

> We've isolated this issue to JDBC client access.

Ah-hah, now it makes sense. I believe the JDBC driver always uses
extended query protocol (parse/bind/execute messages). We know that
that code path is a bit shy of a load with respect to statement logging,
mainly because no one has worked out exactly what it ought to log and
when. When you consider the possibilities for re-use of parsed
statements and partial execution of portals, it's not clear what a
"statement" is, let alone what its "duration" is. Maybe the real
problem is that the GUC variables are defined in terms of a too
simplistic view of the world.

As a quick workaround until someone thinks of a better idea, it might be
sufficient to attach logging code to the execute phase, and ignore the
partial-execution issue.

regards, tom lane

>Tom Lane
> "Simon Riggs" <simon(at)2ndquadrant(dot)com> writes:
> > Further update on this:
>
> > We've isolated this issue to JDBC client access.
>
> Ah-hah, now it makes sense. I believe the JDBC driver always uses
> extended query protocol (parse/bind/execute messages).

Thanks for the *solution.

I had a D'Oh moment about 2 hours after I posted...

> As a quick workaround until someone thinks of a better idea,
> it might be
> sufficient to attach logging code to the execute phase, and ignore the
> partial-execution issue.

Done... we're getting results out now.

I'm logging both duration of execution and the statement text, as would
be displayed in pg_stat_activity.

Thanks,

Best Regards, Simon Riggs