search

darold / pgbadger

A fast PostgreSQL Log Analyzer
http://pgbadger.darold.net/
PostgreSQL License
3.51k stars 349 forks source link

DEBUG output interleaved with progress bar #722

Closed fluca1978 closed 2 years ago

fluca1978 commented 2 years ago

I'm running pgbadger 11.7 on FreeBSD, using both bash and zsh (if that matters). In debug output, -v, I see the following:

$ /usr/local/bin/pgbadger /postgres/13/data/log/*.log   -I -O /pgbadger/ -v -X --start-monday
DEBUG: pgBadger version 11.7.
DEBUG: Output 'html' reports will be written to out.html
DEBUG: Found log offset 373974062 in file /pgbadger//LAST_PARSED
DEBUG: Autodetected log format 'default' from /postgres/13/data/log/postgresql.log
DEBUG: Autodetected log format 'default' from /postgres/13/data/log/postgresql.log
DEBUG: Starting progressbar writer process
DEBUG: pgBadger will use log format default to parse /postgres/13/data/log/postgresql.log.
DEBUG: timezone not specified, using -3600 seconds
DEBUG: Processing log file: /postgres/13/data/log/postgresql.log
DEBUG: Starting offset 373974062 is greater than total size 8355613 for file /postgres/13/data/log/postgresql.log
DEBUG: Reverting start offset 373974062 to 0 for file /postgres/13/data/log/postgresql.log, stoppping offset is 8355613
DEBUG: Starting reading file "/postgres/13/data/log/postgresql.log"...
DEBUG: Start parsing postgresql log at offset 0 of file "/postgres/13/data/log/postgresql.log" to 8355613
DEBUG: setting current position in log to 8559349of 8355613 (92.01%), queries: 59998, events: 0
DEBUG: Saving last parsed line into /tmp/tmp_LAST_PARSED (2022-03-23 13:20:06s: 8559349)vents: 0

Looking carefully at the last line in the above output, you can see there's an s: after the timestamp and the vents after the closing bracket. Appears to me those are pieces of update_progress_bar (queries and events), and the thing go even wort if the number of queries (i.e., the size of the log) increases. I suspect before calling logmsg the output line should be cleared at all.

Invoking with the new option --no-progressbar removes the problem, so that I came to the conclusion it is something related to the line buffer filled with the progress bar:

$ /usr/local/bin/pgbadger /postgres/13/data/log/*.log   -I -O /pgbadger/ -v -X --start-monday --no-progressbar
DEBUG: pgBadger version 11.7.
DEBUG: Output 'html' reports will be written to out.html
DEBUG: Found log offset 8559349 in file /pgbadger//LAST_PARSED
DEBUG: Autodetected log format 'default' from /postgres/13/data/log/postgresql.log
DEBUG: Autodetected log format 'default' from /postgres/13/data/log/postgresql.log
DEBUG: pgBadger will use log format default to parse /postgres/13/data/log/postgresql.log.
DEBUG: timezone not specified, using -3600 seconds
DEBUG: Processing log file: /postgres/13/data/log/postgresql.log
DEBUG: This log might not be parsed: /postgres/13/data/log/postgresql.log, there no new lines in this file
DEBUG: Starting reading file "/postgres/13/data/log/postgresql.log"...
DEBUG: Start parsing postgresql log at offset 8559349 of file "/postgres/13/data/log/postgresql.log" to 29777255
DEBUG: setting current position in log to 29777255
DEBUG: Saving last parsed line into /tmp/tmp_LAST_PARSED (2022-03-23 13:20:42   29777255)
darold commented 2 years ago

Yes, the debug output is done by the running process whereas the progress bar output is done by a dedicated process and there is no control of the writing between them. The solution could be to send both messages to a single logger process that could serialize the writing but this is not a high priority.

darold commented 2 years ago

Won't be done.