Thread: logs of postgresql and pid-stamping. possible improvement?
hi, is there any way, one could spent some time to allow *full* pid-stamping in logs? right now logs look like: [5703] LOG: query: select * from pg_class WHERE relname='pg_class'; [5703] LOG: QUERY STATISTICS ! system usage stats: ! 0.028300 elapsed 0.000000 user 0.000000 system sec ! [0.020000 user 0.010000 sys total] ! 0/0 [0/0] filesystem blocks in/out ! 9/7 [305/148] page faults/reclaims, 0 [0] swaps ! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent ! 0/0 [0/0] voluntary/involuntary context switches ! postgres usage stats: ! Shared blocks: 3 read, 0 written, buffer hit rate = 96,55% ! Local blocks: 0 read, 0 written, buffer hit rate = 0,00% ! Direct blocks: 0 read, 0 written and what i'd like to see is something like: [5703] LOG: query: select * [5703] from [5703] pg_class [5703] WHERE [5703] relname='pg_class'; [5703] LOG: QUERY STATISTICS [5703] ! system usage stats: [5703] ! 0.028300 elapsed 0.000000 user 0.000000 system sec [5703] ! [0.020000 user 0.010000 sys total] [5703] ! 0/0 [0/0] filesystem blocks in/out [5703] ! 9/7 [305/148] page faults/reclaims, 0 [0] swaps [5703] ! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent [5703] ! 0/0 [0/0] voluntary/involuntary context switches [5703] ! postgres usage stats: [5703] ! Shared blocks: 3 read, 0 written, buffer hit rate = 96,55% [5703] ! Local blocks: 0 read, 0 written, buffer hit rate = 0,00% [5703] ! Direct blocks: 0 read, 0 written this is very imporant if you want to make tuning of existing system, written by someone else, and you have (by looking at pgsql logs) to check what queries are being run most often, and which of them use most of time. the problem is that with heavily loaded systems, queries overlap, and one cannot know which statistics are for which query, and even which line is for which query!!! unfortunatelly my c-knowledge is too limited to try to do it by myself. depesz -- hubert depesz lubaczewski http://www.depesz.pl/ ------------------------------------------------------------------------ Mój Boże, spraw abym milczał, dopóki się nie upewnię, że naprawdę mam coś do powiedzenia. (c) 1998 depesz
Attachment
On Thu, Aug 15, 2002 at 11:48:40AM +0200, Hubert depesz Lubaczewski wrote:
> hi,
> is there any way, one could spent some time to allow *full* pid-stamping
> in logs?
> right now logs look like:
> [5703] LOG: query: select *
> from
> pg_class
> WHERE
> relname='pg_class';
> [5703] LOG: QUERY STATISTICS
> ! system usage stats:
> ! 0.028300 elapsed 0.000000 user 0.000000 system sec
> ! [0.020000 user 0.010000 sys total]
> ! 0/0 [0/0] filesystem blocks in/out
> ! 9/7 [305/148] page faults/reclaims, 0 [0] swaps
> ! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
> ! 0/0 [0/0] voluntary/involuntary context switches
> ! postgres usage stats:
> ! Shared blocks: 3 read, 0 written, buffer hit rate = 96,55%
> ! Local blocks: 0 read, 0 written, buffer hit rate = 0,00%
> ! Direct blocks: 0 read, 0 written
Yes, but all that stuff with the ! at the beginning is associated
with the LOG: QUERY STATISTICS ahead of it, no? Isn't that enough of
a separator to make it clear? Or am I missing something (likely)?
A
--
----
Andrew Sullivan 87 Mowat Avenue
Liberty RMS Toronto, Ontario Canada
<andrew@libertyrms.info> M6K 3E3
+1 416 646 3304 x110
Andrew Sullivan <andrew@libertyrms.info> writes:
> Yes, but all that stuff with the ! at the beginning is associated
> with the LOG: QUERY STATISTICS ahead of it, no? Isn't that enough of
> a separator to make it clear? Or am I missing something (likely)?
He's concerned about query stats printed by concurrent backends becoming
interleaved in the log file. A fair concern, but I don't think it's
real, at least not since 7.2.
As of 7.2, the whole multiline stats message will be written in a
single write() call, so I'd be pretty surprised if it got interleaved
with other processes' messages. At least on HPUX, this is guaranteed
not to happen when stderr is a pipe, so if you're piping the postmaster
log to some kind of log rotation script then it ought to be quite safe.
Possibly if the log is a plain disk file there might be trouble on some
kernels.
If you're logging via syslog() then it's a different story: each line is
sent to syslog individually, I believe. But syslog already marks each
line with PID.
regards, tom lane
On Thu, 2002-08-15 at 13:13, Tom Lane wrote: > Andrew Sullivan <andrew@libertyrms.info> writes: > > Yes, but all that stuff with the ! at the beginning is associated > > with the LOG: QUERY STATISTICS ahead of it, no? Isn't that enough of > > a separator to make it clear? Or am I missing something (likely)? > > He's concerned about query stats printed by concurrent backends becoming > interleaved in the log file. A fair concern, but I don't think it's > real, at least not since 7.2. > > As of 7.2, the whole multiline stats message will be written in a > single write() call, so I'd be pretty surprised if it got interleaved > with other processes' messages. At least on HPUX, this is guaranteed > not to happen when stderr is a pipe, so if you're piping the postmaster > log to some kind of log rotation script then it ought to be quite safe. > Possibly if the log is a plain disk file there might be trouble on some > kernels. > > If you're logging via syslog() then it's a different story: each line is > sent to syslog individually, I believe. But syslog already marks each > line with PID. and with multi-line messages, it gives a message number-line number tag as well. (I remember putting in the smarter breakup code in 7.1 (IIRC)). LER -- Larry Rosenman http://www.lerctr.org/~ler Phone: +1 972-414-9812 E-Mail: ler@lerctr.org US Mail: 1905 Steamboat Springs Drive, Garland, TX 75044-6749