Re: log sql?

On Tue, Jul 30, 2002 at 11:06:54AM -0400, Bruce Momjian wrote:
>
> What we really need is something that prints the query, username, and
> times for admins who want to see which queries are slow.  That is on the
> TODO list.

That would indeed be cool.  In the meantime, here are some strategies
I have used for working around the deficiency.  Almost certainly not
news to anyone experienced, but I hope they're useful to someone.

I log the PID, connection, source port, and also the queries.  I keep
several hundred megabytes of logs, in order to be able to track
backwards & find trouble spots.

If I get a report of slow performance, it is frequently one of those
annoying "blahblah is slow" type reports.  But it usually includes
enough data that I can find the relevant query in my logs.  Logged
with the query is the PID.  PostgreSQL's one-process-per-connection
is a real advantage here, because I can track everything associated
with the transaction just by looking for the PID.  (If you are
inexperienced with grep, trying to whittle down your logs is a good
way to learn to use it.  On a busy system, you'll want to start with
something like

    grep "\[yourpid\]" yourlogfile

)

Sometimes, the problem is obvious: a query turns out _not_ to be the
action reported or some such (don't laugh.  I had someone complain
one time that queries were slow, to discover that the person in
question was actually reqesting a Cartesian product of several
million rows to several other million rows).  But usually, the
problem is obscure.  I sometimes find that a trigger is performing an
action which is causing the bottleneck -- they're a good thing to
watch for, because it's easy to forget about that extra insert or
update when you think about what the transaction "should" do.

You can turn on any of

    #show_parser_stats = false
    #show_planner_stats = false
    #show_executor_stats = false
    #show_query_stats = false

to see what the backend is doing.  You can do it in a single psql session,
if you like, by issuing (for example)

    set show_query_stats=on;

You can turn on those show_ parameters for the whole database by
editing the config gile and turning on the desired stat, and then
giving the postmaster SIGHUP.  If you want to see the stats for your
session on a busy system, use more than one regular expression with
grep (different versions of grep handle that differently, but the -e
option often works).  The stats all begin on a line with "!".  Just
like the [] characters, you have to escape ! in order to use it, or
your shell will probably grab it.  Note that the stats do not get the
PID on every line.  (You can write a regexp to catch the stats for
just your PID, but this is not a regexp tutirial, so you're on your
own.)

Sometimes the only answer is to begin a transaction, and then start
stepping through the queries until you run into the problem.  It's a
bad idea to do this on a production system (although if you have an
unreproducable problem, you sometimes have to.  Don't forget to roll
back your transactions.  This is a risky thing to do.  It is very
bad.  Be careful).

It has almost never happened to me that I had to undertake the
step-through approach, and not had an immediate head-slap moment when
I saw the actually slow query.  It's either something plain -- a
recently-analysed table suddenly has had a bunch of updates, for
instance -- or else a query written so badly that I can't believe I
didn't see it first.

Anyway, the one-PID-per connection provides a really nice selection
criterion for reading log files.  It would obviously be nice to be
able to turn on a feature and get a nice query-and-statistics line,
but the PostgreSQL logging is pretty flexible, and most of the
information one might want is actually available from the log
facility as it exists.

As I mentioned before, though, all this logging is _not_ free.  It
has a measurable effect on the speed of your system.

Hope this is useful to someone.

A

--
----
Andrew Sullivan                               87 Mowat Avenue
Liberty RMS                           Toronto, Ontario Canada
<andrew@libertyrms.info>                              M6K 3E3
                                         +1 416 646 3304 x110