Thread: Major Problems with PostgreSQL Logs (8.1.3)
I'm not sure what is going on, but this is the third try to get this to the list.
---I am having a major problem with the PostgreSQL log files. We have sql logging turned on for recovery purposes, and have discovered a problem. We have lines of sql being interrupted by the next log line before they complete. The interrupting log line is not starting at the beginning of a line, but rather cutting right into the middle of the previous log line. Eventually, the intrrupted log line is completed. This is causing serious issues for us, since we can not rely on the log files to be accurrate.
Attached is an example from my production logs showing a line from db2 interrupting a log line from db1. Sorry for the ugly queries, but this is an inherited db that was not properly normalized). The line showing the problem start with "db1,6432,x12,2006-06-05 15:47:07.355 EDT,44845f8d.1920,39256,2006-06-05 12:45:01 EDT,9301850,UPDATE,LOG: duration: 5.186 ms statement:"
---I am having a major problem with the PostgreSQL log files. We have sql logging turned on for recovery purposes, and have discovered a problem. We have lines of sql being interrupted by the next log line before they complete. The interrupting log line is not starting at the beginning of a line, but rather cutting right into the middle of the previous log line. Eventually, the intrrupted log line is completed. This is causing serious issues for us, since we can not rely on the log files to be accurrate.
Attached is an example from my production logs showing a line from db2 interrupting a log line from db1. Sorry for the ugly queries, but this is an inherited db that was not properly normalized). The line showing the problem start with "db1,6432,x12,2006-06-05 15:47:07.355 EDT,44845f8d.1920,39256,2006-06-05 12:45:01 EDT,9301850,UPDATE,LOG: duration: 5.186 ms statement:"
Is there a quick solution for this? We are starting to work on a PITR backup system, but it is just in the begining stages. We had this problem when we were running 7.3.4 (which we just upgraded from) and thought is was related to our log rotation problem, but now this leads me to believe this is a problem with PostgreSQL itself, since it is clearly happening in our 8.1.3 database. I know you don't recommend using the sql logs for recovery purposes, but for our application, they work just fine, and we have used them in the past. However, after discovering this issue in both 7.3.4 and now in 8.1.3, we are very concerned.
Here is my postgresql.conf active lines:
listen_addresses = '*' # what IP address(es) to listen on;
port = 50001
max_connections = 256
shared_buffers = 32768 # min 16 or max_connections*2, 8KB each
max_prepared_transactions = 256 # can be 0 or more
work_mem = 4096 # min 64, size in KB
maintenance_work_mem = 1048576 # min 1024, size in KB
max_fsm_pages = 8000000 # min max_fsm_relations*16, 6 bytes each
max_fsm_relations = 40000 # min 100, ~70 bytes each
wal_buffers = 64 # min 4, 8KB each
checkpoint_segments = 256 # in logfile segments, min 1, 16MB each
checkpoint_timeout = 1800 ### USE FOR DB LOADS ONLY
effective_cache_size = 755048 # typically 8KB each
random_page_cost = 2 # units are one sequential page fetch
default_statistics_target = 100 # range 1-1000
constraint_exclusion = on
redirect_stderr = on # Enable capturing of stderr into log
log_directory = 'pg_log' # Directory where log files are written
log_truncate_on_rotation = on # If on, any existing log file of the same
log_rotation_age = 1440 # Automatic rotation of logfiles will
log_rotation_size = 1048576 # Automatic rotation of logfiles will
log_min_duration_statement = 0 # -1 is disabled, 0 logs all statements
log_connections = on
log_disconnections = on
log_duration = on
log_line_prefix = '%d,%p,%u,%m,%c,%l,%s,%x,%i,' # Special values:
log_statement = 'all' # none, mod, ddl, all
stats_start_collector = on
stats_command_string = on
stats_block_level = on
stats_row_level = on
stats_reset_on_server_start = on
search_path = '$user,public,rcvd_trans,sent_trans,intelliview,eedi,cob_temp' # schema names
lc_messages = 'C' # locale for system error message
lc_monetary = 'C' # locale for monetary formatting
lc_numeric = 'C' # locale for number formatting
lc_time = 'C' # locale for time formatting
add_missing_from = on
Thanks,
Chris
RHAS 4.0
PostgreSQL 8.1.3
Here is my postgresql.conf active lines:
listen_addresses = '*' # what IP address(es) to listen on;
port = 50001
max_connections = 256
shared_buffers = 32768 # min 16 or max_connections*2, 8KB each
max_prepared_transactions = 256 # can be 0 or more
work_mem = 4096 # min 64, size in KB
maintenance_work_mem = 1048576 # min 1024, size in KB
max_fsm_pages = 8000000 # min max_fsm_relations*16, 6 bytes each
max_fsm_relations = 40000 # min 100, ~70 bytes each
wal_buffers = 64 # min 4, 8KB each
checkpoint_segments = 256 # in logfile segments, min 1, 16MB each
checkpoint_timeout = 1800 ### USE FOR DB LOADS ONLY
effective_cache_size = 755048 # typically 8KB each
random_page_cost = 2 # units are one sequential page fetch
default_statistics_target = 100 # range 1-1000
constraint_exclusion = on
redirect_stderr = on # Enable capturing of stderr into log
log_directory = 'pg_log' # Directory where log files are written
log_truncate_on_rotation = on # If on, any existing log file of the same
log_rotation_age = 1440 # Automatic rotation of logfiles will
log_rotation_size = 1048576 # Automatic rotation of logfiles will
log_min_duration_statement = 0 # -1 is disabled, 0 logs all statements
log_connections = on
log_disconnections = on
log_duration = on
log_line_prefix = '%d,%p,%u,%m,%c,%l,%s,%x,%i,' # Special values:
log_statement = 'all' # none, mod, ddl, all
stats_start_collector = on
stats_command_string = on
stats_block_level = on
stats_row_level = on
stats_reset_on_server_start = on
search_path = '$user,public,rcvd_trans,sent_trans,intelliview,eedi,cob_temp' # schema names
lc_messages = 'C' # locale for system error message
lc_monetary = 'C' # locale for monetary formatting
lc_numeric = 'C' # locale for number formatting
lc_time = 'C' # locale for time formatting
add_missing_from = on
Thanks,
Chris
RHAS 4.0
PostgreSQL 8.1.3
Attachment
"Chris Hoover" <revoohc@gmail.com> writes: > ---I am having a major problem with the PostgreSQL log files. We have sql > logging turned on for recovery purposes, and have discovered a problem. We > have lines of sql being interrupted by the next log line before they > complete. The interrupting log line is not starting at the beginning of a > line, but rather cutting right into the middle of the previous log line. > Eventually, the intrrupted log line is completed. This is causing serious > issues for us, since we can not rely on the log files to be accurrate. You might try using syslog logging, although I'm not sure whether it would really be much better. If your log messages exceed PIPEBUF (8K typically) then writes to the redirect_stderr process are not going to be atomic, and there's not all that much we can do about it. regards, tom lane
Is there an easy way to see if this is the problem? How can I verify the size of PIPEBUF, and additionally, how do you tell the exact size of the statement being logged?
On 6/9/06, Tom Lane <tgl@sss.pgh.pa.us> wrote:
"Chris Hoover" < revoohc@gmail.com> writes:
> ---I am having a major problem with the PostgreSQL log files. We have sql
> logging turned on for recovery purposes, and have discovered a problem. We
> have lines of sql being interrupted by the next log line before they
> complete. The interrupting log line is not starting at the beginning of a
> line, but rather cutting right into the middle of the previous log line.
> Eventually, the intrrupted log line is completed. This is causing serious
> issues for us, since we can not rely on the log files to be accurrate.
You might try using syslog logging, although I'm not sure whether it
would really be much better. If your log messages exceed PIPEBUF (8K
typically) then writes to the redirect_stderr process are not going to
be atomic, and there's not all that much we can do about it.
regards, tom lane