Thread: mysterious log output
I keep seeing the following log output around every 5 minutes:
2005-02-28 23:25:05 [8646] LOG: 00000: QUERY STATISTICS
DETAIL: ! system usage stats: ! 0.005023 elapsed 0.000000 user 0.000000 system sec !
[537.130000user 44.860000 sys total] ! 0/0 [0/0] filesystem blocks in/out ! 0/4
[848810/1849693]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 ! buffer usage stats: ! Shared blocks:
0 read, 0 written, buffer hit
rate = 100.00% ! Local blocks: 0 read, 0 written, buffer hit
rate = 0.00% ! Direct blocks: 0 read, 0 written
LOCATION: ShowUsage, postgres.c:3199
The server is postgresql 7.4, running on debian linux. According to
postgres.c, it should be outputting due to GUC, however I verified that all
of the log_*_stats lines in the postgresql.conf are turned off and also
verified those GUC's are off in the show all; output... here's the relevant
bits.
log_connections | offlog_duration | offlog_error_verbosity |
verboselog_executor_stats | offlog_hostname | offlog_min_duration_statement |
5000log_min_error_statement | infolog_min_messages | noticelog_parser_stats |
offlog_pid | onlog_planner_stats | offlog_source_port |
offlog_statement | offlog_statement_stats | offlog_timestamp | on
the only thing real sketchy about this is that it always seems to be on the
same pid (8646) and if I turn query logging on I see the following executed
right before this happens:
2005-03-01 00:25:08 [8646] LOG: 00000: statement: select
"_rv".cleanupEvent();
LOCATION: pg_parse_query, postgres.c:464
now according to the slony folks, there is nothing in slony that modifys the
logging output... so assuming that's true, anyone have any ideas on what
might be causing this logging?
--
Robert Treat
Build A Brighter Lamp :: Linux Apache {middleware} PostgreSQL
Robert Treat <xzilla@users.sourceforge.net> writes:
> I keep seeing the following log output around every 5 minutes:
> 2005-02-28 23:25:05 [8646] LOG: 00000: QUERY STATISTICS
This has to be coming from exec_simple_query():
if (save_log_statement_stats) ShowUsage("QUERY STATISTICS");
so *something* is turning on log_statement_stats.
regards, tom lane
Tom Lane wrote:
> Robert Treat <xzilla@users.sourceforge.net> writes:
> > I keep seeing the following log output around every 5 minutes:
> > 2005-02-28 23:25:05 [8646] LOG: 00000: QUERY STATISTICS
>
> This has to be coming from exec_simple_query():
>
> if (save_log_statement_stats)
> ShowUsage("QUERY STATISTICS");
>
> so *something* is turning on log_statement_stats.
I wonder if some statistics were turned on at postmaster start and even
though it was turned off and 'pg_ctl reload' was done the
checkpoint/bgwriter process isn't reloading for some reason.
-- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610)
359-1001+ If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square,
Pennsylvania19073
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> Tom Lane wrote:
>> This has to be coming from exec_simple_query():
> I wonder if some statistics were turned on at postmaster start and even
> though it was turned off and 'pg_ctl reload' was done the
> checkpoint/bgwriter process isn't reloading for some reason.
The checkpoint/bgwriter never executes exec_simple_query(). I think
the 5-minute cycle is driven by something in Robert's application,
rather than being tied to checkpoints.
regards, tom lane
On Tuesday 01 March 2005 12:46, Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > Tom Lane wrote:
> >> This has to be coming from exec_simple_query():
> >
> > I wonder if some statistics were turned on at postmaster start and even
> > though it was turned off and 'pg_ctl reload' was done the
> > checkpoint/bgwriter process isn't reloading for some reason.
>
> The checkpoint/bgwriter never executes exec_simple_query(). I think
> the 5-minute cycle is driven by something in Robert's application,
> rather than being tied to checkpoints.
>
Actually looking at it now, it happens every 10 minutes, so you're right in
that it doesn't coincide with the bgwriter. Actually I am pretty sure this
is slony related... the output is always on the same pid, and everything else
output on that pid is slony commands. Is there some way I could see what
that pid thinks the GUC variables are set to? I have a wild theory that
slony is preventing the modification of SUSET level variables, but haven't
really got anything solid to back that up.
--
Robert Treat
Build A Brighter Lamp :: Linux Apache {middleware} PostgreSQL