---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
db1,6432,x12,2006-06-05 15:47:07.350 EDT,44845f8d.1920,39253,2006-06-05 12:45:01 EDT,9301850,idle in transaction,LOG: statement: UPDATE DETPRO1 SET PROC_CD_QFR = 'HC', PROC_CD = '93325', PROC_MOD_1 = '26', PROC_MOD_2 = ' ', PROC_MOD_3 = ' ', PROC_MOD_4 = ' ', CHG_AMT = '000000209.00', UOM_CD = 'UN', UNITS = '000000001.0000', PLACE_OF_SVC = ' ', DIAG_CD_POINTER_1 = 1, DIAG_CD_POINTER_2 = 0, DIAG_CD_POINTER_3 = 0, DIAG_CD_POINTER_4 = 0, EMERGENCY_IND = ' ', EPSDT_IND = ' ', FAMILY_PLANNING_IND = ' ', COPAY_STATUS_CD = ' ', PRESCRIPT_NBR = '', DME_PROC_CD = '', DME_LENGTH_OF_MED_NECESSITY = '000000000.0000', DME_RENTAL_PRICE = '000000000.00', DME_PUR_PRICE = '000000000.00', DME_RENTAL_UNIT_IND = ' ', DMERC_ATCH_XMIT_CD = ' ', PAT_WEIGHT = '00000.0000', AMB_TRANSPORT_CD = ' ', AMB_TRANSPORT_RSN_CD = ' ', AMB_TRANSPORT_DISTANCE = '000000.0', AMB_ROUND_TRIP_PURPOSE = '', AMB_STRETCHER_PURPOSE = '', SPINAL_1_PAT_COND_CD = ' ', SPINAL_1_PAT_COND_DESC_1 = '', SPINAL_1_PAT_COND_DESC_2 = '', SPINAL_1_XRAY_AVAIL_IND = ' ', SPINAL_2_PAT_COND_CD = ' ', SPINAL_2_PAT_COND_DESC_1 = '', SPINAL_2_PAT_COND_DESC_2 = '', SPINAL_2_XRAY_AVAIL_IND = ' ', SPINAL_3_PAT_COND_CD = ' ', SPINAL_3_PAT_COND_DESC_1 = '', SPINAL_3_PAT_COND_DESC_2 = '', SPINAL_3_XRAY_AVAIL_IND = ' ', SPINAL_4_PAT_COND_CD = ' ', SPINAL_4_PAT_COND_DESC_1 = '', SPINAL_4_PAT_COND_DESC_2 = '', SPINAL_4_XRAY_AVAIL_IND = ' ', SPINAL_5_PAT_COND_CD = ' ', SPINAL_5_PAT_COND_DESC_1 = '', SPINAL_5_PAT_COND_DESC_2 = '', SPINAL_5_XRAY_AVAIL_IND = ' ', DME_CERT_TYPE_CD = ' ', DME_CERT_DURATION = '000000000.0000', OXY_CERT_TYPE_CD = ' ', OXY_TRMT_PERIOD_CNT = '000000000.0000', OXY_BLOOD_GAS_QTY = '000000000.0000', OXY_SATURATION_QTY = '000000000.0000', OXY_TEST_COND_CD = ' ', OXY_TEST_FINDINGS_CD_1 = ' ', OXY_TEST_FINDINGS_CD_2 = ' ', OXY_TEST_FINDINGS_CD_3 = ' ', AMB_1_CERT_COND_IND = ' ', AMB_1_COND_CD_1 = ' ', AMB_1_COND_CD_2 = ' ', AMB_1_COND_CD_3 = ' ', AMB_1_COND_CD_4 = ' ', AMB_1_COND_CD_5 = ' ', AMB_2_CERT_COND_IND = ' ', AMB_2_COND_CD_1 = ' ', AMB_2_COND_CD_2 = ' ', AMB_2_COND_CD_3 = ' ', AMB_2_COND_CD_4 = ' ', AMB_2_COND_CD_5 = ' ', AMB_3_CERT_COND_IND = ' ', AMB_3_COND_CD_1 = ' ', AMB_3_COND_CD_2 = ' ', AMB_3_COND_CD_3 = ' ', AMB_3_COND_CD_4 = ' ', AMB_3_COND_CD_5 = ' ', HOSPICE_EMPEE_IND = ' ', DMERC_1_CD_CAT = ' ', DMERC_1_CERT_COND_IND = ' ', DMERC_1_COND_IND_1 = ' ', DMERC_1_COND_IND_2 = ' ', DMERC_1_COND_IND_3 = ' ', DMERC_1_COND_IND_4 = ' ', DMERC_1_COND_IND_5 = ' ', DMERC_2_CD_CAT = ' ', DMERC_2_CERT_COND_IND = ' ', DMERC_2_COND_IND_1 = ' ', DMERC_2_COND_IND_2 = ' ', DMERC_2_COND_IND_3 = ' ', DMERC_2_COND_IND_4 = ' ', DMERC_2_COND_IND_5 = ' ', SVC_BEG_DT = '20060331', SVC_END_DT = '20060331', CERT_REVISION_DT = ' ', REFER_DT = ' ', BEG_THERAPY_DT = ' ', LAST_CERT_DT = ' ', ORDER_DT = ' ', LAST_SEEN_DT = ' ', TEST_1_DT_QFR = ' ', TEST_1_DT = ' ', TEST_2_DT_QFR = ' ', TEST_2_DT = ' ', OXY_TEST_1_DT_QFR = ' ', OXY_TEST_1_DT = ' ', OXY_TEST_2_DT_QFR = ' ', OXY_TEST_2_DT = ' ', OXY_TEST_3_DT_QFR = ' ', OXY_TEST_3_DT = ' ', SHIPPED_DT = ' ', ONSET_DT = ' ', LAST_XRAY_DT = ' ', ACUTE_MANIFEST_DT = ' ', INIT_TRMT_DT = ' ', SIMILAR_ONSET_DT = ' ', ANESTH_MOD_UNITS_1_QFR = ' ', ANESTH_MOD_UNITS_1 = '000000000.0000', ANESTH_MOD_UNITS_2_QFR = ' ', ANESTH_MOD_UNITS_2 = '000000000.0000', ANESTH_MOD_UNITS_3_QFR = ' ', ANESTH_MOD_UNITS_3 = '000000000.0000', ANESTH_MOD_UNITS_4_QFR = ' ', ANESTH_MOD_UNITS_4 = '000000000.0000', ANESTH_MOD_UNITS_5_QFR = ' ', ANESTH_MOD_UNITS_5 = '000000000.0000', CONTRACT_TYPE_CD = ' ', CONTRACT_AMT = '000000000.00', CONTRACT_PCT = '0000000.000000', CONTRACT_CD = '', CONTRACT_TERMS_DISC_PCT = '0000000.000000', CONTRACT_VER_ID = '', REPRICED_LINE_REF_NBR = '', ADJ_REPRICED_LINE_REF_NBR = '', LINE_CNTL_NBR = '012345678A000000003', MAMMO_CERT_NBR = '', CLIA_FAC_ID = '', REFER_CLIA_NBR = '', IMMUN_BATCH_NBR = '', AMBUL_PAT_GRP_1_NBR = '', AMBUL_PAT_GRP_2_NBR = '', AMBUL_PAT_GRP_3_NBR = '', AMBUL_PAT_GRP_4_NBR = '', OXY_FLOW_RATE = '', UPN_ID_QFR = ' ', UPN = '', SALES_TAX_AMT = '000000000.00', APPR_AMT = '000000000.00', POSTAGE_CLAIMED_AMT = '000000000.00', FIXED_FORMAT_INFO_1 = '', FIXED_FORMAT_INFO_2 = '', FIXED_FORMAT_INFO_3 = '', FIXED_FORMAT_INFO_4 = '', FIXED_FORMAT_INFO_5 = '', FIXED_FORMAT_INFO_6 = '', FIXED_FORMAT_INFO_7 = '', FIXED_FORMAT_INFO_8 = '', FIXED_FORMAT_INFO_9 = '', FIXED_FORMAT_INFO_10 = '', LINE_NOTE_REF_CD = ' ', LINE_NOTE_TEXT = '', PUR_SVC_PROV_ID = '', PUR_SVC_CHG_AMT = '000000000.00', HC_SVC_NBR_VISITS = '00000.0000', HC_SVC_FREQ_PERIOD = ' ', HC_SVC_FREQ_CNT = '00000.0000', HC_SVC_TM_QFR = ' ', HC_SVC_NBR_PERIODS = 0, HC_SVC_DEL_PATTERN_CD = ' ', HC_SVC_DEL_PATTERN_TM_CD = ' ', USER_ID = 'user', LIVE_REC = '1' WHERE INV_NBR = 12345678 AND INV_QFR = 'A' AND LINE_NBR = 3 db1,6432,x12,2006-06-05 15:47:07.352 EDT,44845f8d.1920,39254,2006-06-05 12:45:01 EDT,9301850,UPDATE,NOTICE: in update segment db1,6432,x12,2006-06-05 15:47:07.355 EDT,44845f8d.1920,39255,2006-06-05 12:45:01 EDT,9301850,UPDATE,LOG: duration: 5.186 ms db2,9162,x12,2006-06-05 15:47:07.355 EDT,44848910.23ca,4540,2006-06-05 15:42:08 EDT,9301868,idle in transaction,LOG: statement: SELECT C0_OVRIDE_CD_1, C0_OVRIDE_CD_2, C0_OVRIDE_CD_3, C0_OVRIDE_CD_4, C0_OVRIDE_CD_5, C0_WARN_OVRIDE_CD_2 FROM COMPTECH1 WHERE INV_NBR = 98765432 AND INV_QFR = 'A' 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: UPDATE DETPRO1 SET PROC_CD_QFR = 'HC', PROC_CD = '93325', PROC_MOD_1 = '26', PROC_MOD_2 = ' ', PROC_MOD_3 = ' ', PROC_MOD_4 = ' ', CHG_AMT = '000000209.00', UOM_CD = 'UN', UNITS = '000000001.0000', PLACE_OF_SVC = ' ', DIAG_CD_POINTER_1 = 1, DIAG_CD_POINTER_2 = 0, DIAG_CD_POINTER_3 = 0, DIAG_CD_POINTER_4 = 0, EMERGENCY_IND = ' ', EPSDT_IND = ' ', FAMILY_PLANNING_IND = ' ', COPAY_STATUS_CD = ' ', PRESCRIPT_NBR = '', DME_PROC_CD = '', DME_LENGTH_OF_MED_NECESSITY = '000000000.0000', DME_RENTAL_PRICE = '000000000.00', DME_PUR_PRICE = '000000000.00', DME_RENTAL_UNIT_IND = ' ', DMERC_ATCH_XMIT_CD = ' ', PAT_WEIGHT = '00000.0000', AMB_TRANSPORT_CD = ' ', AMB_TRANSPORT_RSN_CD = ' ', AMB_TRANSPORT_DISTANCE = '000000.0', AMB_ROUND_TRIP_PURPOSE = '', AMB_STRETCHER_PURPOSE = '', SPINAL_1_PAT_COND_CD = ' ', SPINAL_1_PAT_COND_DESC_1 = '', SPINAL_1_PAT_COND_DESC_2 = '', SPINAL_1_XRAY_AVAIL_IND = ' ', SPINAL_2_PAT_COND_CD = ' ', SPINAL_2_PAT_COND_DESC_1 = '', SPINAL_2_PAT_COND_DESC_2 = '', SPINAL_2_XRAY_AVAIL_IND = ' ', SPINAL_3_PAT_COND_CD = ' ', SPINAL_3_PAT_COND_DESC_1 = '', SPINAL_3_PAT_COND_DESC_2 = '', SPINAL_3_XRAY_AVAIL_IND = ' ', SPINAL_4_PAT_COND_CD = ' ', SPINAL_4_PAT_COND_DESC_1 = '', SPINAL_4_PAT_COND_DESC_2 = '', SPINAL_4_XRAY_AVAIL_IND = ' ', SPINAL_5_PAT_COND_CD = ' ', SPINAL_5_PAT_COND_DESC_1 = '', SPINAL_5_PAT_COND_DESC_2 = '', SPINAL_5_XRAY_AVAIL_IND = ' ', DME_CERT_TYPE_CD = ' ', DME_CERT_DURATION = '000000000.0000', OXY_CERT_TYPE_CD = ' ', OXY_TRMT_PERIOD_CNT = '000000000.0000', OXY_BLOOD_GAS_QTY = '000000000.0000', OXY_SATURATION_QTY = '000000000.0000', OXY_TEST_COND_CD = ' ', OXY_TEST_FINDINGS_CD_1 = ' ', OXY_TEST_FINDINGS_CD_2 = ' ', OXY_TEST_FINDINGS_CD_3 = ' ', AMB_1_CERT_COND_IND = ' ', AMB_1_COND_CD_1 = ' ', AMB_1_COND_CD_2 = ' ', AMB_1_COND_CD_3 = ' ', AMB_1_COND_CD_4 = ' ', AMB_1_COND_CD_5 = ' ', AMB_2_CERT_COND_IND = ' ', AMB_2_COND_CD_1 = ' ', AMB_2_COND_CD_2 = ' ', AMB_2_COND_CD_3 = ' ', AMB_2_COND_CD_4 = ' ', AMB_2_COND_CD_5 = ' ', AMB_3_CERT_COND_IND = ' ', AMB_3_COND_CD_1 = ' ', AMB_3_COND_CD_2 = ' ', AMB_3_COND_CD_3 = ' ', AMB_3_COND_CD_4 = ' ', AMB_3_COND_CD_5 = ' ', HOSPICE_EMPEE_IND = ' ', DMERC_1_CD_CAT = ' ', DMERC_1_CERT_COND_IND = ' ', DMERC_1_COND_IND_1 = ' ', DMERC_1_COND_IND_2 = ' ', DMERC_1_COND_IND_3 = ' ', DMERC_1_COND_IND_4 = ' ', DMERC_1_COND_IND_5 = ' ', DMERC_2_CD_CAT = ' ', DMERC_2_CERT_COND_IND = ' ', DMERC_2_COND_IND_1 = ' ', DMERC_2_COND_IND_2 = ' ', DMERC_2_COND_IND_3 = ' ', DMERC_2_COND_IND_4 = ' ', DMERC_2_COND_IND_5 = ' ', SVC_BEG_DT = '20060331', SVC_END_DT = '20060331', CERT_REVISION_DT = ' ', REFER_DT = ' ', BEG_THERAPY_DT = ' ', LAST_CERT_DT = ' ', ORDER_DT = ' ', LAST_SEEN_DT = ' ', TEST_1_DT_QFR = ' ', TEST_1_DT = ' ', TEST_2_DT_QFR = ' ', TEST_2_DT = ' ', OXY_TEST_1_DT_QFR = ' ', OXY_TEST_1_DT = ' ', OXY_TEST_2_DT_QFR = ' ', OXY_TEST_2_DT = ' ', OXY_TEST_3_DT_QFR = ' ', OXY_TEST_3_DT = ' ', SHIPPED_DT = ' ', ONSET_DT = ' ', LAST_XRAY_DT = ' ', ACUTE_MANIFEST_DT = ' ', INIT_TRMT_DT = ' ', SIMILAR_ONSET_DT = ' ', ANESTH_MOD_UNITS_1_QFR = ' ', ANESTH_MOD_UNITS_1 = '000000000.0000', ANESTH_MOD_UNITS_2_QFR = ' ', ANESTH_MOD_UNITS_2 = '000000000.0000', ANESTH_MOD_UNITS_3_QFR = ' ', ANESTH_MOD_UNITS_3 = '000000000.0000', ANESTH_MOD_UNITS_4_QFR = ' ', ANESTH_MOD_UNITS_4 = '000000000.0000', ANESTH_MOD_UNITS_5_QFR = ' ', ANESTH_MOD_UNITS_5 = '000000000.0000', CONTRACT_TYdb2,9162,x12,2006-06-05 15:47:07.355 EDT,44848910.23ca,4541,2006-06-05 15:42:08 EDT,9301868,SELECT,LOG: duration: 0.531 ms db2,9162,x12,2006-06-05 15:47:07.356 EDT,44848910.23ca,4542,2006-06-05 15:42:08 EDT,9301868,SELECT,LOG: duration: 0.531 ms statement: SELECT C0_OVRIDE_CD_1, C0_OVRIDE_CD_2, C0_OVRIDE_CD_3, C0_OVRIDE_CD_4, C0_OVRIDE_CD_5, C0_WARN_OVRIDE_CD_2 FROM COMPTECH1 WHERE INV_NBR = 98765432 AND INV_QFR = 'A' PE_CD = ' ', CONTRACT_AMT = '000000000.00', CONTRACT_PCT = '0000000.000000', CONTRACT_CD = '', CONTRACT_TERMS_DISC_PCT = '0000000.000000', CONTRACT_VER_ID = '', REPRICED_LINE_REF_NBR = '', ADJ_REPRICED_LINE_REF_NBR = '', LINE_CNTL_NBR = '012345678A000000003', MAMMO_CERT_NBR = '', CLIA_FAC_ID = '', REFER_CLIA_NBR = '', IMMUN_BATCH_NBR = '', AMBUL_PAT_GRP_1_NBR = '', AMBUL_PAT_GRP_2_NBR = '', AMBUL_PAT_GRP_3_NBR = '', AMBUL_PAT_GRP_4_NBR = '', OXY_FLOW_RATE = '', UPN_ID_QFR = ' ', UPN = '', SALES_TAX_AMT = '000000000.00', APPR_AMT = '000000000.00', POSTAGE_CLAIMED_AMT = '000000000.00', FIXED_FORMAT_INFO_1 = '', FIXED_FORMAT_INFO_2 = '', FIXED_FORMAT_INFO_3 = '', FIXED_FORMAT_INFO_4 = '', FIXED_FORMAT_INFO_5 = '', FIXED_FORMAT_INFO_6 = '', FIXED_FORMAT_INFO_7 = '', FIXED_FORMAT_INFO_8 = '', FIXED_FORMAT_INFO_9 = '', FIXED_FORMAT_INFO_10 = '', LINE_NOTE_REF_CD = ' ', LINE_NOTE_TEXT = '', PUR_SVC_PROV_ID = '', PUR_SVC_CHG_AMT = '000000000.00', HC_SVC_NBR_VISITS = '00000.0000', HC_SVC_FREQ_PERIOD = ' ', HC_SVC_FREQ_CNT = '00000.0000', HC_SVC_TM_QFR = ' ', HC_SVC_NBR_PERIODS = 0, HC_SVC_DEL_PATTERN_CD = ' ', HC_SVC_DEL_PATTERN_TM_CD = ' ', USER_ID = 'user', LIVE_REC = '1' WHERE INV_NBR = 12345678 AND INV_QFR = 'A' AND LINE_NBR = 3
