# 关于PostgreSQL数据库日志、慢SQL、持续时间的测试

关于PostgreSQL数据库日志、慢SQL、持续时间的测试

官方文档：http://www.postgres.cn/docs/10/runtime-config-logging.html

1、结论

• A. log_duration = on #— 负责记录所有的日志+【持续时间】，否则不记录日志（单独一条记录）
• B. log_statement = ‘all’ #— 负责记录所有包含sql语句的日志+【sql语句】（单独一条记录）
• C. log_min_duration_statement = 100 #— 负责记录超时100ms的日志+【sql语句】+【持续时间】，这个是上面两个参数的交集，不应该和上面两个参数一起使用
• --------美丽分割线--------
• A、B 一起用时会产生两条日志
• A、B、C 一起用时，则3无效
• C 一般单独使用
• A、C 一起使用，产生叠加效果，会记录所有日志+【持续时间】，如果sql语句超过100ms，则会把【sql语句】也记录下来，【持续时间】、【sql语句】写在同一个字段中
• B、C 一起使用，产生叠加效果，会记录所有sql语句的日志，如果sql语句超过100ms，则会把【持续时间】也记录下来，【持续时间】、【sql语句】写在同一个字段中

2、测试过程

1

conf
log_duration = off
#log_statement = ‘all’
log_min_duration_statement = 100

#— SELECT pg_sleep(1); 记录日志，超过100ms记录sql语句文本，记录持续时间

2022-04-15 12:46:33.246 +07,"postgres","postgres",17441,"[local]",625906a1.4421,3,"SELECT",2022-04-15 12:46:09 +07,3/0,0,LOG,00000,"duration: 1057.883 ms  statement: SELECT pg_sleep(1);",,,,,,,,"exec_simple_query, postgres.c:1200","psql"

#— SELECT pg_sleep(0.001); 未超过100ms不记录日志

无

2

log_duration = on
#log_statement = ‘all’
log_min_duration_statement = 100

#— SELECT pg_sleep(1); 记录日志，超过100ms记录sql语句文本，记录持续时间

2022-04-15 12:56:06.435 +07,"postgres","postgres",17614,"[local]",625908f1.44ce,3,"SELECT",2022-04-15 12:56:01 +07,4/0,0,LOG,00000,"duration: 1001.958 ms  statement: SELECT pg_sleep(1);",,,,,,,,"exec_simple_query, postgres.c:1200","psql"

#— SELECT pg_sleep(0.001); 记录日志，未超过100ms不记录sql语句文本，记录持续时间

2022-04-15 12:56:32.695 +07,"postgres","postgres",17614,"[local]",625908f1.44ce,4,"SELECT",2022-04-15 12:56:01 +07,4/0,0,LOG,00000,"duration: 2.382 ms",,,,,,,,"exec_simple_query, postgres.c:1193","psql"

3

log_duration = on
#log_statement = ‘all’
log_min_duration_statement = -1

#— SELECT pg_sleep(1); 记录日志，无sql语句文本，记录持续时间

2022-04-15 13:42:00.946 +07,"postgres","postgres",18091,"[local]",625913a9.46ab,3,"SELECT",2022-04-15 13:41:45 +07,3/0,0,LOG,00000,"duration: 1001.928 ms",,,,,,,,"exec_simple_query, postgres.c:1193","psql"

#— SELECT pg_sleep(0.001); 记录日志，无sql语句文本，记录持续时间

2022-04-15 13:42:12.252 +07,"postgres","postgres",18091,"[local]",625913a9.46ab,4,"SELECT",2022-04-15 13:41:45 +07,3/0,0,LOG,00000,"duration: 1.358 ms",,,,,,,,"exec_simple_query, postgres.c:1193","psql"

4

log_duration = on
log_statement = ‘all’
log_min_duration_statement = 100

#— SELECT pg_sleep(1); 记录日志，超过100ms记录sql语句文本，记录持续时间，分两条记（一条记录语句，一条记录持续时间）

2022-04-15 13:10:29.602 +07,"postgres","postgres",17790,"[local]",62590c23.457e,3,"idle",2022-04-15 13:09:39 +07,3/6,0,LOG,00000,"statement: SELECT pg_sleep(1);",,,,,,,,"exec_simple_query, postgres.c:963","psql"
2022-04-15 13:10:30.603 +07,"postgres","postgres",17790,"[local]",62590c23.457e,4,"SELECT",2022-04-15 13:09:39 +07,3/0,0,LOG,00000,"duration: 1001.270 ms",,,,,,,,"exec_simple_query, postgres.c:1193","psql"

#— SELECT pg_sleep(0.001); 记录日志，未超过100ms也记录sql语句文本，记录持续时间，分两条记（一条记录语句，一条记录持续时间）

2022-04-15 13:10:10.153 +07,"postgres","postgres",17790,"[local]",62590c23.457e,5,"idle",2022-04-15 13:09:39 +07,3/5,0,LOG,00000,"statement: SELECT pg_sleep(0.001);",,,,,,,,"exec_simple_query, postgres.c:963","psql"
2022-04-15 13:10:10.156 +07,"postgres","postgres",17790,"[local]",62590c23.457e,6,"SELECT",2022-04-15 13:09:39 +07,3/0,0,LOG,00000,"duration: 2.469 ms",,,,,,,,"exec_simple_query, postgres.c:1193","psql"

5

log_duration = off
log_statement = ‘all’
log_min_duration_statement = 100

#— SELECT pg_sleep(1); 记录日志，超过100ms记录sql语句文本，记录持续时间，分两条记（一条记录语句，一条记录持续时间）

2022-04-15 14:20:37.745 +07,"postgres","postgres",18385,"[local]",62591cbd.47d1,3,"idle",2022-04-15 14:20:29 +07,3/4,0,LOG,00000,"statement: SELECT pg_sleep(1);",,,,,,,,"exec_simple_query, postgres.c:963","psql"
2022-04-15 14:20:38.747 +07,"postgres","postgres",18385,"[local]",62591cbd.47d1,4,"SELECT",2022-04-15 14:20:29 +07,3/0,0,LOG,00000,"duration: 1001.841 ms",,,,,,,,"exec_simple_query, postgres.c:1193","psql"

#— SELECT pg_sleep(0.001); 记录日志，未超过100ms也记录sql语句文本，但未记录持续时间

2022-04-15 14:20:46.685 +07,"postgres","postgres",18385,"[local]",62591cbd.47d1,5,"idle",2022-04-15 14:20:29 +07,3/5,0,LOG,00000,"statement: SELECT pg_sleep(0.001);",,,,,,,,"exec_simple_query, postgres.c:963","psql"

3、日志字段解析

PostgreSQL csvlog日志格式记录了非常多的信息，共二十三列，各字段翻译参考PostgreSQL中文文档

• 字段说明

CREATE TABLE postgres_log
(
  log_time timestamp(3) with time zone,#日志时间，带毫秒的时间戳
  user_name text,# 当前登录数据库的用户名
  database_name text,# 数据库名
  process_id integer,# 进程ID
  connection_from text,# 客户端主机:端口号
  session_id text,# 会话ID 由后台进程启动时间和PID组成
  session_line_num bigint,#每个会话的行号，类似history命令
  command_tag text,# 命令标签
  session_start_time timestamp with time zone,# 会话开始时间
  virtual_transaction_id text,# 虚拟事务ID
  transaction_id bigint,# 事务ID
  error_severity text,# 错误等级
  sql_state_code text,# SQLSTATE 代码
  message text,# 消息
  detail text,# 错误消息详情
  hint text,# 提示
  internal_query text,# 导致错误的内部查询（如果有）
  internal_query_pos integer,# 错误位置所在的字符计数
  context text,#  错误上下文
  query text,# 导致错误的用户查询（如果有且被log_min_error_statement启用）
  query_pos integer,# 错误位置所在的字符计数
  location text,# 在 PostgreSQL 源代码中错误的位置（如果log_error_verbosity被设置为verbose）
  application_name text,# 应用名
  PRIMARY KEY (session_id, session_line_num)
);

# 导入日志到数据库
COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;

• 日志示例：

2022-04-15 12:56:06.435 +07,
"postgres",
"postgres",
17614,
"[local]",
625908f1.44ce,
3,
"SELECT",
2022-04-15 12:56:01 +07,
4/0,
0,
LOG,
00000,
"duration: 1001.958 ms  statement: SELECT pg_sleep(1);",
,,,,,,,
"exec_simple_query, postgres.c:1200",
"psql"

最后

爱你！