Skip to content

📚 PostgreSQL auto explain enabled

🔍 Prepare：

## OS and Software environment：

Environment name Version
OS Rocky Linux 9.x
DB PostgreSQL 16.X

### 1. Install and Create auto explain extension(postgres)

  • 1.1 Check the auto_explain.so exists in your library folder or not
locate auto_explain.so

alt text

  • 1.2 Add auto_explain to the shared_preload_libraries in your postgresql.conf file, like so: shared_preload_libraries = 'auto_explain'
vi postgresql.conf
shared_preload_libraries = 'auto_explain'

alt text

Multiple items are required, please add them If configuring the parameter on the initial Cluster, please ignore them This parameter needs to reload DB to enable

  • 1.2.1 add two auto explain parameter (just need to reload the configuration file)
vi postgresql.conf
#auto_explain.log_analyze=true
#auto_explain.log_min_duration = 0

auto_explain.log_min_duration：the minimum statement execution time, in milliseconds; it depends on your demand auto_explain.log_analyze：explain analyze output, rather than just EXPLAIN output, to be printed when an execution plan is logged auto_explain.log_min_duration = 0 A large number of logs will be generated, it is recommended to enable them if necessary

  • 1.2.2 enable log function (need to reload DB), for more information refer to appendix.
vi postgresql.conf
log_destination = 'stderr'
logging_collector = on
log_directory = 'log'
log_filename = 'postgresql-%a%H.log'
log_truncate_on_rotation = on
log_rotation_age = 60
log_rotation_size = 1000000
log_min_messages = info
log_min_duration_statement = 10000
log_checkpoints = on
log_connections = on
log_disconnections = on
log_hostname = on
log_line_prefix = '%t [%p] : db = %d , user = %u , app = %a , Tag = %i , client = %h , session_id = %c , session_start = %s'
log_lock_waits = on
log_statement = 'mod'
  • 1.3 restart DB
pg_ctl restart -D /pgdata/SID

alt text

  • 1.4 We can use the Pgadmin tool to see the execution plan

  • 1.4.1 normal query with execute/fresh button(red-mark)

alt text

  • 1.4.2 query with explain button(red mark, simulate the execution plan time, no analysis)

alt text

Click the analysis tag alt text

Click the Statistics alt text

  • 1.4.3 query with explain analyze button (red mark)

alt text

Click the analysis tag alt text

Click the Statistics alt text

  • 1.5 We can check log on Server

  • 1.5.1 Check current logfile

cd /pgdata/SID
cat current_logfiles

alt text

  • 1.5.2 Do the query on psql
select * from wih_mo_bak;

alt text

  • 1.5.3 Then, check today’s log. You will find your query be recorded.

auto_explain.log_analyze=true & auto_explain.log_min_duration = 0 alt text

### 2. Appendix (log function)

https://www.postgresql.org/docs/16/runtime-config-logging.html

  • 2.1 Where to Log

  • 2.1.1 log_destination （2 ways to set log_destination to stderr or CSV-format. Here, we set it to ‘stderr’ ）

vi postgresql.conf
log_destination = 'stderr'
#log_destination = 'csvlog'
  • 2.1.2 logging_collector Enable capturing of stderr and csvlog into log files (change requires restart) 
vi postgresql.conf
logging_collector = on
  • 2.1.3 log_directory （When logging_collector is enabled, this parameter determines the directory in which log files will be created. The default is log）
vi postgresql.conf
log_directory = 'log'
  • 2.1.4 log_filename （log file name pattern, The default is postgresql-%a.log）
vi postgresql.conf
log_filename = 'postgresql-%a%H.log'

There are few parameters that you can use. Depends on your demand. %Y →year %m →month %d →day %H →hour %M →minute %S →second

  • 2.1.5 log_file_mode （creation mode for log files, The default permissions are 0600, meaning only the server owner can read or write the log files.）
vi postgresql.conf
#log_file_mode = 0600

means, use default value

  • 2.1.6 log_truncate_on_rotation （If on, an existing log file with the same name as the new log file will be truncated rather than appended to. truncation will occur only due to time-based rotation, not during server startup or size-based rotation. Default is on）
vi postgresql.conf
log_truncate_on_rotation = on

Example: To keep 7 days of logs, one log file per day named postgresql-Mon.log, postgresql-Tue.log, etc, and automatically overwrite last week's log with this week's log. Set the below setting: log_filename to postgresql-%a.log & log_truncate_on_rotation to on & and log_rotation_age to 1440 (24*60=1440=1d, without units, it is taken as minutes)

Example: To keep 24 hours of logs, one log file per hour, but also rotate sooner if the log file size exceeds 1GB, set log_filename to postgresql-%H%M.log & log_truncate_on_rotation to on & log_rotation_age to 60 & log_rotation_size to 1000000. Including %M in log_filename allows any size-driven rotations that might occur to select a file name different from the hour's initial file name.

  • 2.1.7 log_rotation_age （When logging_collector is enabled, Automatic rotation of logfiles will happen after that time. 0 disables; The default is 24 hours; If this value is specified without units, it is taken as minutes）
vi postgresql.conf
log_rotation_age = 60
  • 2.1.8 log_rotation_size （When logging_collector is enabled, Automatic rotation of logfiles will happen after that much log output. 0 disables; The default is 10 MB; If this value is specified without units, it is taken as kilobytes）
vi postgresql.conf
log_rotation_size = 1000000

  • 2.2 When to Log

  • 2.2.1 log_min_messages （Controls which message levels are written to the server log. Valid values are DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1, INFO, NOTICE, WARNING, ERROR, LOG, FATAL, and PANIC. The later the level, the fewer messages are sent to the log. The default is WARNING）

vi postgresql.conf
log_min_messages = info
  • 2.2.2 log_min_error_statement （Controls which SQL statements that cause an error condition are recorded in the server log. Valid values are DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1, INFO, NOTICE, WARNING, ERROR, LOG, FATAL, and PANIC. The default is ERROR, which means statements causing errors, log messages, fatal errors, or panics will be logged）
vi postgresql.conf
log_min_error_statement = error

Message Severity Levels Severity Usage DEBUG1..DEBUG5 ： Provides successively-more-detailed information for use by developers. INFO ： Provides information implicitly requested by the user, e.g., output from VACUUM VERBOSE. NOTICE ： Provides information that might be helpful to users, e.g., notice of truncation of long identifiers. WARNING ： Provides warnings of likely problems, e.g., COMMIT outside a transaction block. ERROR ： Reports an error that caused the current command to abort. LOG ： Reports information of interest to administrators, e.g., checkpoint activity. FATAL ： Reports an error that caused the current session to abort. PANIC ： Reports an error that caused all database sessions to abort.

  • 2.2.3 log_min_duration_statement （The duration of each completed statement to be logged if the statement ran for at least the specified amount of time.-1 is disabled, 0 logs all statements and their durations, > 0 logs only statements running at least this number of milliseconds; If this value is specified without units, it is taken as milliseconds）
vi postgresql.conf
log_min_duration_statement = 0

Ex. if you set it to 250ms then all SQL statements that run 250ms or longer will be logged

log_min_duration_statement = 250： alt text

  • 2.3 What to Log

  • 2.3.1 log_checkpoints （Causes checkpoints and restartpoints to be logged in the server log. Some statistics are included in the log messages, including the number of buffers written and the time spent writing them. The default is off）

vi postgresql.conf
log_checkpoints = on
  • 2.3.2 log_connections （Causes each attempted connection to the server to be logged, as well as successful completion of client authentication. The default is off）
vi postgresql.conf
log_connections = on
  • 2.3.3 log_disconnections （Causes session terminations to be logged. The log output provides information similar to log_connections, plus the duration of the session. The default is off）
vi postgresql.conf
log_disconnections = on
  • 2.3.4 log_hostname （By default, connection log messages only show the IP address of the connecting host. Turning this parameter on causes logging of the host name as well）
vi postgresql.conf
log_hostname = on
  • 2.3.5 log_line_prefix （This is a printf-style string that is output at the beginning of each log line. % characters begin “escape sequences” that are replaced with status information as outlined below. The default is '%m [%p] 'which logs a time stamp and the process ID）
vi postgresql.conf
log_line_prefix = '#PostGreSQL: %i^^%t^^%u^^%d^^%r^^%c^^%s'

Escape Effect Session only %a Application name yes %u User name yes %d Database name yes %r Remote host name or IP address, and remote port yes %h Remote host name or IP address yes %p Process ID no %t Time stamp without milliseconds no %m Time stamp with milliseconds no %n Time stamp with milliseconds (as a Unix epoch) no %i Command tag: type of session's current command yes %e SQLSTATE error code no %c Session ID: see below no %l Number of the log line for each session or process, starting at 1 no %s Process start time stamp no %v Virtual transaction ID (backendID/localXID) no %x Transaction ID (0 if none is assigned) no %q Produces no output, but tells non-session processes to stop at this point in the string; ignored by session processes no %% Literal % no

Tip: The %q escape is useful when including information that is only available in session (backend) context like user or database name. For example: log_line_prefix = '%m [%p] %q%u@%d/%a'

  • 2.3.6 log_lock_waits Controls whether a log message is produced when a session waits longer than deadlock_timeout to acquire a lock. This is useful in determining if lock waits are causing poor performance. The default is off. (log lock waits >= deadlock_timeout)
vi postgresql.conf
log_lock_waits = on
  • 2.3.7 log_statement Controls which SQL statements are logged. Valid values are none (off), ddl, mod, and all (all statements). ddl logs all data definition statements, such as CREATE, ALTER, and DROP statements. mod logs all ddl statements, plus data-modifying statements such as INSERT, UPDATE, DELETE, TRUNCATE, and COPY FROM. PREPARE, EXECUTE, and EXPLAIN ANALYZE statements are also logged if their contained command is of an appropriate type. The default is none
vi postgresql.conf
log_statement = 'mod'
  • 2.3.8 log_timezone Sets the time zone used for timestamps written in the server log. The built-in default is GMT, but that is typically overridden in postgresql.conf; initdb will install a setting there corresponding to its system environment

vi postgresql.conf
log_timezone = 'Asia/Taipei'
### 3. Our current DB setting for log function

Log parameter in postgresql.conf(WIH) 

log_destination = 'stderr'
logging_collector = on
#log_directory = 'log'
log_filename = 'postgresql-%a%H.log'
#log_file_mode = 0600
log_truncate_on_rotation = on
log_rotation_age = 60
log_rotation_size = 1000000
log_min_messages = info
#log_min_error_statement = error
log_min_duration_statement = 0
log_checkpoints = on
log_connections = on
log_disconnections = on
log_hostname = on
log_line_prefix = '#PostGreSQL: %i^^%t^^%u^^%d^^%r^^%c^^%s'
log_lock_waits = on
log_statement = 'mod'

Log parameter in postgresql.conf(WZS) 

log_destination = 'stderr'
logging_collector = on
log_directory = 'log'
log_filename = 'postgresql-%a%H.log'
log_truncate_on_rotation = on
log_rotation_age = 60
log_rotation_size = 1000000
log_min_messages = info
log_min_duration_statement = 10000
log_checkpoints = on
log_connections = on
log_disconnections = on
log_hostname = on
log_line_prefix = '%t [%p] : db = %d , user = %u , app = %a , Tag = %i , clinet = %h , session_id = %c , session_start = %s'
log_lock_waits = on
log_statement = 'mod'