开始
首先log 相关的内容如下：
#------------------------------------------------------------------------------ # ERROR REPORTING AND LOGGING #------------------------------------------------------------------------------ # - Where to Log - log_destination = 'csvlog' # Valid values are combinations of # stderr, csvlog, syslog, and eventlog, # depending on platform. csvlog # requires logging_collector to be on. # This is used when logging to stderr: logging_collector = on # Enable capturing of stderr and csvlog # into log files. Required to be on for # csvlogs. # (change requires restart) # These are only used if logging_collector is on: log_directory = 'pg_log' # directory where log files are written, # can be absolute or relative to PGDATA log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log' # log file name pattern, # can include strftime() escapes log_file_mode = 0600 # creation mode for log files, # begin with 0 to use octal notation log_truncate_on_rotation = off # If on, an existing log file with the # same name as the new log file will be # truncated rather than appended to. # But such truncation only occurs on # time-driven rotation, not on restarts # or size-driven rotation. Default is # off, meaning append to existing files # in all cases. log_rotation_age = 1d # Automatic rotation of logfiles will # happen after that time. 0 disables. log_rotation_size = 10MB # Automatic rotation of logfiles will # happen after that much log output. # 0 disables. # These are relevant when logging to syslog: #syslog_facility = 'LOCAL0' #syslog_ident = 'postgres' # This is only relevant when logging to eventlog (win32): #event_source = 'PostgreSQL' # - When to Log - #client_min_messages = notice # values in order of decreasing detail: # debug5 # debug4 # debug3 # debug2 # debug1 # log # notice # warning # error log_min_messages = info # values in order of decreasing detail: # debug5 # debug4 # debug3 # debug2 # debug1 # info # notice # warning # error # log # fatal # panic log_min_error_statement = info # values in order of decreasing detail: # debug5 # debug4 # debug3 # debug2 # debug1 # info # notice # warning # error # log # fatal # panic (effectively off) #log_min_duration_statement = -1 # -1 is disabled, 0 logs all statements # and their durations, > 0 logs only # statements running at least this number # of milliseconds # - What to Log - #debug_print_parse = off #debug_print_rewritten = off #debug_print_plan = off #debug_pretty_print = on #log_checkpoints = off #log_connections = off #log_disconnections = off #log_duration = off #log_error_verbosity = default # terse, default, or verbose messages #log_hostname = off #log_line_prefix = '%m' # special values: # %a = application name # %u = user name # %d = database name # %r = remote host and port # %h = remote host # %p = process ID # %t = timestamp without milliseconds # %m = timestamp with milliseconds # %i = command tag # %e = SQL state # %c = session ID # %l = session line number # %s = session start timestamp # %v = virtual transaction ID # %x = transaction ID (0 if none) # %q = stop here in non-session # processes # %% = '%' # e.g. '<%u%%%d> ' #log_lock_waits = off # log lock waits >= deadlock_timeout #log_statement = 'none' # none, ddl, mod, all #log_temp_files = -1 # log temporary files equal or larger # than the specified size in kilobytes; # -1 disables, 0 logs all temp files log_timezone = 'PRC'
为了了解 bufmgr 中对 BgBufferSync 的运作原理，对其进行 log 处理：
static void BufferSync(int flags) { …… while (num_to_scan-- > 0) { volatile BufferDesc *bufHdr = &BufferDescriptors[buf_id]; …… if (bufHdr->flags & BM_CHECKPOINT_NEEDED) { //added by gaojian elog(LOG,"In BufferSync, Calling SyncOneBuffer for all dirty\n"); if (SyncOneBuffer(buf_id, false) & BUF_WRITTEN) { TRACE_POSTGRESQL_BUFFER_SYNC_WRITTEN(buf_id); BgWriterStats.m_buf_written_checkpoints++; num_written++; …… if (num_written >= num_to_write) break; /* * Sleep to throttle our I/O rate. */ CheckpointWriteDelay(flags, (double) num_written / num_to_write); } } if (++buf_id >= NBuffers) buf_id = 0; } …… } bool BgBufferSync(void) { …… if (saved_info_valid) { //added by gaojian elog(LOG,"strategy_passes is:%u ",strategy_passes); elog(LOG,"....next_passes is:%u \n",next_passes); int32 passes_delta = strategy_passes - prev_strategy_passes; strategy_delta = strategy_buf_id - prev_strategy_buf_id; strategy_delta += (long) passes_delta *NBuffers; Assert(strategy_delta >= 0); …… } else { …… } //added by gaojian elog(LOG,"bgwriter ahead:bgw %u-%u strategy %u-%u delta=%ld lap=%d\n",next_passes, next_to_clean,strategy_passes, strategy_buf_id,strategy_delta, bufs_to_lap); …… /* Execute the LRU scan */ while (num_to_scan > 0 && reusable_buffers < upcoming_alloc_est) { //added by gaojian elog(LOG,"In BgBufferSync,Calling SyncOneBuffer.\n"); int buffer_state = SyncOneBuffer(next_to_clean, true); if (++next_to_clean >= NBuffers) { next_to_clean = 0; elog(INFO,"------------------next_passes++.\n"); next_passes++; } …… } …… }
运行后的 log 是如下的样子，我只选取了一小段，可以发现，SyncOneBuffer是被频繁调用的：
2012-11-01 15:56:46.061 CST,,,2987,,50922b3e.bab,1,,2012-11-01 15:56:46 CST,,0,LOG,00000,"database system was shut down at 2012-11-01 14:39:25 CST",,,,,,,,,"" 2012-11-01 15:56:46.146 CST,,,2989,,50922b3e.bad,1,,2012-11-01 15:56:46 CST,,0,LOG,00000,"bgwriter ahead:bgw 0-0 strategy 0-0 delta=0 lap=4096 ",,,,,,,,,"" 2012-11-01 15:56:46.146 CST,,,2989,,50922b3e.bad,2,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.146 CST,,,2989,,50922b3e.bad,3,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.146 CST,,,2989,,50922b3e.bad,4,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.146 CST,,,2989,,50922b3e.bad,5,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.146 CST,,,2989,,50922b3e.bad,6,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.146 CST,,,2989,,50922b3e.bad,7,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.147 CST,,,2991,,50922b3e.baf,1,,2012-11-01 15:56:46 CST,,0,LOG,00000,"autovacuum launcher started",,,,,,,,,"" 2012-11-01 15:56:46.148 CST,,,2985,,50922b3d.ba9,1,,2012-11-01 15:56:45 CST,,0,LOG,00000,"database system is ready to accept connections",,,,,,,,,"" 2012-11-01 15:56:46.346 CST,,,2989,,50922b3e.bad,8,,2012-11-01 15:56:46 CST,,0,LOG,00000,"strategy_passes is:0 ",,,,,,,,,"" 2012-11-01 15:56:46.346 CST,,,2989,,50922b3e.bad,9,,2012-11-01 15:56:46 CST,,0,LOG,00000,"....next_passes is:0 ",,,,,,,,,"" 2012-11-01 15:56:46.346 CST,,,2989,,50922b3e.bad,10,,2012-11-01 15:56:46 CST,,0,LOG,00000,"bgwriter ahead:bgw 0-6 strategy 0-0 delta=0 lap=4090 ",,,,,,,,,"" 2012-11-01 15:56:46.346 CST,,,2989,,50922b3e.bad,11,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.346 CST,,,2989,,50922b3e.bad,12,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.346 CST,,,2989,,50922b3e.bad,13,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.346 CST,,,2989,,50922b3e.bad,14,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.346 CST,,,2989,,50922b3e.bad,15,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.346 CST,,,2989,,50922b3e.bad,16,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.546 CST,,,2989,,50922b3e.bad,17,,2012-11-01 15:56:46 CST,,0,LOG,00000,"strategy_passes is:0 ",,,,,,,,,"" 2012-11-01 15:56:46.546 CST,,,2989,,50922b3e.bad,18,,2012-11-01 15:56:46 CST,,0,LOG,00000,"....next_passes is:0 ",,,,,,,,,"" 2012-11-01 15:56:46.546 CST,,,2989,,50922b3e.bad,19,,2012-11-01 15:56:46 CST,,0,LOG,00000,"bgwriter ahead:bgw 0-12 strategy 0-0 delta=0 lap=4084 ",,,,,,,,,"" 2012-11-01 15:56:46.546 CST,,,2989,,50922b3e.bad,20,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.546 CST,,,2989,,50922b3e.bad,21,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.546 CST,,,2989,,50922b3e.bad,22,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.546 CST,,,2989,,50922b3e.bad,23,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.546 CST,,,2989,,50922b3e.bad,24,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.546 CST,,,2989,,50922b3e.bad,25,,2012-11-01 15:56:46 CST,,0,LOG,00000,"In BgBufferSync,Calling SyncOneBuffer. ",,,,,,,,,"" 2012-11-01 15:56:46.746 CST,,,2989,,50922b3e.bad,26,,2012-11-01 15:56:46 CST,,0,LOG,00000,"strategy_passes is:0 ",,,,,,,,,"" 2012-11-01 15:56:46.746 CST,,,2989,,50922b3e.bad,27,,2012-11-01 15:56:46 CST,,0,LOG,00000,"....next_passes is:0 ",,,,,,,,,"" 2012-11-01 15:56:46.746 CST,,,2989,,50922b3e.bad,28,,2012-11-01 15:56:46 CST,,0,LOG,00000,"bgwriter ahead:bgw 0-18 strategy 0-0 delta=0 lap=4078
这里需要明确的是：BgBufferSync 与 BufferSync 是两回事。
BufferSync 被 checkpoint 所调用。 BgBufferSync 被 bgwriter 所调用。它们被调用的频率是不一样的。
BgBufferSync 和 BufferSync 都需要调用 SyncOneBuffer。
结束