본문 바로가기
Database/PostgreSQL

PostgreSQL Log 설정 - 2

갈색왜성 2019. 5. 10. 01:17
반응형

지난 PostgreSQL Log 설정 포스팅에 이은 다음편이다. 이래저래 정신이 없다 보니 무려 5개월 만에 같은 주제의 포스팅을 마무리하는 상황이다. 5월 들어 조금 짬이 나서 어떻게든 마무리를 짓겠다 마음 먹어서, 그나마 마무리 하는 상황이다. 

When to Log

'Where to Log' Sub-Section다음에 이어지는 Sub-Section이다. 여기서 말하는 'WHEN'은 현재 동작하는 PostgreSQL이 Log를 남기는 조건을 나타낸다. 설정 사항이 3가지 밖에 없고 그 중에서 log_min_duration_statement만 자주 설정을 변경할 여지가 있다.

  • log_min_messages, log_min_messages_statement ; log_min_messages는 어떤 Level의 Message를 남길까를 설정한다. Default값은 warning이고, 이 경우 warning, error, log, fatal, panic level의 message가 모두 남기 때문에 default값을 그대로 사용해도 괜찮다. (Log level의 message가 모두 남기 때문에 그렇다.) 혹시 cross-compile 작업 이상으로 Code를 건드릴 일이 있으면 Debug Level으로 설정해야할 것이다. log_min_messages_statement는 실행되는 Query를 어떤 Level에 Log에 남길 지를 설정한다. 역시 Default값인 'error'면 충분하다고 생각한다. 
  • log_min_duration_statement : 성능 및 Query Tuning 시에 가장 중요한 설정 중에 하나이다. 여기서 설정한 시간(단위는 milli-second)이상이 소요되는 Query들과 그 소요시간을 Log에 남긴다. -1로 설정하면 아무런 Log도 안남기게 되고 0일 경우에는 모든 Log를 남긴다.

log_min_duration_statement를 500으로 설정했을 때, 아래와 같이 500ms 이상 걸리는 Query에 대해 Query 내용과 소요 시간 정보를 보여준다.

...
< 2019-05-01 13:15:36.859 KST >LOG:  statement: SELECT * FROM timeTest;
< 2019-05-01 13:15:36.859 KST >LOG:  duration: 0.520 ms
...

 

What to Log

마지막 Sub-Section인 'What to Log'는 항목이 무척 많다. 그리고 이 Sub-Section에서는 log_line_prefix와 log_statement가 매우 중요한 설정이기 때문에 이 부분부터 먼저 설명하려고 한다. 이 값을 잘 설정해야 추후에 Log를 통해 Trouble Shooting이나 Tuning 작업을 수월하게 수행할 수 있다.

 

  • log_line_prefix : log_destination을 'stderr'로 설정했을 때, 발생하는 Log들의 접두어를 설정할 수 있다. Option이 매우 다양하기 때문에 공식 문서에서 Option을 확인해 보는 것을 권장하며 기본 값은 '<%m>'으로 millisecond를 포함한 Time Stamp를 Log 앞에 남긴다. (참고로, csvlog와 syslog의 경우에는 기본적으로 Time Stamp를 남긴다.) 필자는 사용하지 않았지만 Log 분석 Tool Project로 유명한 pgFouine에서는 다음 설정을 권장하고 있다.

log_line_prefix = '%t [%p]: [%l-1] '                                               // 시간, Process ID, Session Line Number
log_line_prefix = '%t [%p]: [%l-1] user=%u,db=%d'                    //      + 접근 유저, Database 명
log_line_prefix = '%t [%p]: [%l-1] user=%u,db=%d,remote=%r'  //              + 접속한 위치

 

아래는 log_line_prefix를 Default 값인 '<%m>'에서 권장 설정 중에 가장 마지막에 언급한 '%t [%p]: [%l-1] user=%u,db=%d, remote=%r'로 변경했을 때 Log가 어떻게 변경 되는 지 보여준다. ('log_destination'은 'stderr'인 상태임)

...
# log_line_prefix가 Default Value인 '<%>'으로 적용되었을 때
< 2019-05-14 11:50:30.074 KST > LOG:  aborting any active transactions
< 2019-05-14 11:50:30.075 KST > LOG:  autovacuum launcher shutting down
< 2019-05-14 11:50:30.075 KST > LOG:  shutting down
< 2019-05-14 11:50:30.337 KST > LOG:  database system is shut down
...
# postgresql.conf 의 설정 변경
log_line_prefix = '%t [%p]: [%l-1] user=%u, db=%d, remote=%r '   
...
# 설정 변경 이후 PostgreSQL Service 시작 Log
2019-05-14 11:50:30 KST [6206]: [1-1] user=, db=, remote= LOG:  database system was shut down at 2019-05-14 11:50:30 KST
2019-05-14 11:50:30 KST [6206]: [2-1] user=, db=, remote= LOG:  MultiXact member wraparound protections are now enabled
2019-05-14 11:50:30 KST [6201]: [3-1] user=, db=, remote= LOG:  database system is ready to accept connections
2019-05-14 11:50:30 KST [6210]: [1-1] user=, db=, remote= LOG:  autovacuum launcher started
...
# psql 상에서 Database를 조회 후, 사용자 browndwarf의 testdb로 접속한 후 job table을 조회
postgres=\list
postgres=# \c testdb browndwarf
testdb=# SELECT * FROM job;
...
# 위의 Operation 을 수행중 발생하는 Log
2019-05-14 11:51:17 KST [6219]: [1-1] user=postgres, db=postgres, remote=::1(59068) LOG:  statement: SELECT d.datname as "Name",
	       pg_catalog.pg_get_userbyid(d.datdba) as "Owner",
	       pg_catalog.pg_encoding_to_char(d.encoding) as "Encoding",
	       d.datcollate as "Collate",
	       d.datctype as "Ctype",
	       pg_catalog.array_to_string(d.datacl, E'\n') AS "Access privileges"
	FROM pg_catalog.pg_database d
	ORDER BY 1;
2019-05-14 11:52:19 KST [6232]: [1-1] user=browndwarf, db=testdb, remote=::1(59098) LOG:  statement: SELECT * FROM job;
...

 

  • log_statement : Query 로그를 어느 수준으로 남길지 설정한다. none, ddl, mod, all 값이 들어갈 수 있고 Default는 'none'이다. none은 Query를 남기지 않는 것이며, ddl은 Table Create나 Drop과 같이 구조 변경을 하는 Query 이상을 Log 로 남기고, 'mod'는 Data Record 단위로 변경을 하는 Query 이상을 log로 남긴다. 'all'은 모든 Query가 Log로 남긴다고 생각하면 된다.

log_statement 값에 따라 Log가 어떻게 달라지는 지 알아보기 위해 아래 Query List를 실행하면서 남겨지는 Log가 어떻게 변하는 지 보자.

...
CREATE TABLE logTest (id integer NOT NULL, name character varying(255), CONSTRAINT logTest_pk PRIMARY KEY (id));
INSERT INTO logTest (id, name) VALUES (1, 'Teide1');
SELECT * FROM logTest WHERE id=1;
UPDATE logTest SET id=101 WHERE id=1;
DROP TABLE logTest;
...

 

log_statement를 'all'로 설정하면 아래와 같이 모든 Query에 대한 Log가 남는다.

...
<2019-05-03 10:34:03.300 KST>LOG:  statement: CREATE TABLE logTest (id integer NOT NULL, name character varying(255), CONSTRAINT logTest_pk PRIMARY KEY (id));
<2019-05-03 10:34:13.956 KST>LOG:  statement: INSERT INTO logTest (id, name) VALUES (1, 'Teide1');
<2019-05-03 10:34:22.236 KST>LOG:  statement: SELECT * FROM logTest WHERE id=1;
<2019-05-03 10:34:30.564 KST>LOG:  statement: UPDATE logTest SET id=101 WHERE id=1;
<2019-05-03 10:34:39.092 KST>LOG:  statement: DROP TABLE logTest;
 ...

 

log_statement를 'mod'로 설정하면 SELECT 문과 같이 단순 조회를 위한 Query는 제외시키게 된다.

...
< 2019-05-03 10:36:10.644 KST >LOG:  statement: CREATE TABLE logTest (id integer NOT NULL, name character varying(255), CONSTRAINT logTest_pk PRIMARY KEY (id));
< 2019-05-03 10:36:15.963 KST >LOG:  statement: INSERT INTO logTest (id, name) VALUES (1, 'Teide1');
< 2019-05-03 10:36:33.348 KST >LOG:  statement: UPDATE logTest SET id=101 WHERE id=1;
< 2019-05-03 10:36:39.484 KST >LOG:  statement: DROP TABLE logTest;
...

 

log_statement를 'ddl'로 설정하면 TABLE CREATE, DROP 과 같은 수준의 Log만 남게되고, 'none'으로 설정하면 아무런 Log도 남기지 않게 된다.

...
< 2019-05-03 10:37:18.476 KST >LOG:  statement: CREATE TABLE logTest (id integer NOT NULL, name character varying(255), CONSTRAINT logTest_pk PRIMARY KEY (id));
< 2019-05-03 10:37:51.068 KST >LOG:  statement: DROP TABLE logTest;
...

 

  • debug_print_parse, debug_print_rewritten, debug_print_plan : 이 3개의 옵션은 일반적인 경우에 사용하기 보다는 매우 느리게 동작하는 Query가 목격되었을 때 해당 Query가 어떻게 해석되고 어떤 Plan으로 동작하는 지 확인하려고 할 때 사용하는 설정값이다. 기본 값은 'off'로 되어 있고, on으로 설정할 경우 Log의 양이 폭증할 가능성이 높기 때문에 주의하여야 한다.
  • debug_pretty_print : 위 3개의 option이 매우 많은 Log를 발생시키기 때문에, 그 Log 양을 조금이나마 줄이고 싶을 때 사용하는 설정값이다. 기본 값은 'on'인데 'off'로 설정하면 Space와 New Line Character가 없어지면서 약간이나마 Log양이 줄게된다. (하지만 Readibility가 낮아지게 된다.) 아래는 debug_print_plan을 on으로 설정했을 때 (debug_pretty_print는 'ON') 발생하는 Log의 일부분이다.
...
<2019-05-15 16:37:13.961 KST> LOG:  plan:
<2019-05-15 16:37:13.961 KST> DETAIL:     {PLANNEDSTMT 
	   :commandType 1 
	   :queryId 0 
	   :hasReturning false 
	   :hasModifyingCTE false 
	   :canSetTag true 
	   :transientPlan false 
	   :dependsOnRole false 
	   :parallelModeNeeded false 
	   :planTree 
	      {SEQSCAN 
	      :startup_cost 0.00 
	      :total_cost 10.90 
	      :plan_rows 90 
	      :plan_width 868 
	      :parallel_aware false 
	      :plan_node_id 0 
	      :targetlist (
	         {TARGETENTRY 
...

 

  • log_checkpoints ; PostgreSQL은 Checkpoint라고 하는 Shared Buffer와 WAL에 저장되어 있는 모든 변경 내용을 Data Disk에 쓰는 Process가 있다. log_checkpoint는 이 Process에 관련된 Log를 남길지를 설정하는 값이자('on'으로 설정하면 Log를 남긴다. 기본값은 'off') 기본 설정에 의하면 5분마다(checkpoint_timeout=5min), 또는 WAL log가 1G 쌓였을 때(max_wal_size=1GB) Checkpoint Process가 실행되고, 또는 'CHECKPOINT' Command를 실행할 때 Checkpoint Process가 동작하게 된다. 경우에 따라서 Checkpoint로 인해 DB 성능이 저하될 수 있기 때문에 DB Tuning 과정에서 이 값을 'on'으로 해서 성능에 영향을 미치는 지 알아보기도 한다. 아래는 시간에 의해 Checkpoint이 실행될 때의 Log이다.
...
< 2019-05-01 11:55:45.654 KST > LOG:  checkpoint starting: time
< 2019-05-01 11:55:46.162 KST > LOG:  checkpoint complete: wrote 5 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.501 s, sync=0.001 s, total=0.507 s; sync files=4, longest=0.001 s, average=0.000 s; distance=0 kB, estimate=0 kB
...

 

  • log_connections, log_disconnections ; DB에 오는 Connection/Disconnection Request와 그 결과를 Log에 남긴다. 기본 값은 Off 이며 이 때는 관련 Log를 남기지 않는다.
...
# 정상적인 연결 요청과 그 때 발생한 Log
[root@localhost ~]psql -h localhost -U postgres
...
< 2019-05-01 12:40:53.648 KST > LOG:  connection received: host=::1 port=54498
< 2019-05-01 12:40:53.649 KST > LOG:  connection authorized: user=postgres database=postgres
...
# 잘못된 연결 요청과 그 때 발생한 Log
[root@localhost ~]psql -h localhost -U browndwarf
psql: FATAL:  database "browndwarf" does not exist
...
< 2019-05-01 12:43:41.882 KST > LOG:  connection received: host=::1 port=54502
< 2019-05-01 12:43:41.883 KST > LOG:  connection authorized: user=browndwarf database=browndwarf
< 2019-05-01 12:43:41.883 KST > FATAL:  database "browndwarf" does not exist
...
# 정상적인 연결 해제 요청과 그 때 발생한 Log
...
postgres=# \q
...
< 2019-05-01 12:41:05.705 KST > LOG:  disconnection: session time: 0:00:12.056 user=postgres database=postgres host=::1 port=54498
...

 

  • log_duration ; 실행되는 Query들의 실행시간을 Log로 남긴다. 기본값은 'off'이다. 일반적으로 모든 Query에 실행 시간을 남기기 보다는 일정 시간 이상 소요되는 Query를 분석하려 하기 때문에, log_duration 설정 보다는  log_min_duration_statement 설정을 사용한다.
......
postgres=# SELECT 1;
...
postgres=# SELECT * FROM job
...

< 2019-05-01 10:01:38.690 KST >LOG:  statement: SELECT 1;
< 2019-05-01 10:01:38.691 KST >LOG:  duration: 0.148 ms
< 2019-05-01 10:01:53.642 KST >LOG:  statement: SELECT * FROM job;
< 2019-05-01 10:01:25.660 KST >LOG:  duration: 0.480 ms
...

 

  • log_hostname ; 위에 나타난 Connection 관련 Log를 보면 접속하려는 대상이 IP로 표기되어 있다. (::1) log_hostname field가 활성화 되면 IP대신 Hostname이 Log에 남게된다. 기본값은 Off 이다.
...
# log_hostname을 'ON'으로 설정 후 연결 요청과 관련된 Log
[root@localhost ~]psql -h localhost -U postgres
...
< 2019-05-01 13:01:53.648 KST > LOG:  connection received: host=localhost port=54504
< 2019-05-01 13:01:53.649 KST > LOG:  connection authorized: user=postgres database=postgres
...

 

  • log_error_verbosity ; 에러 발생시에 Log 관련 정보 노출 수준을 설정한다. 가능한 값은 terse, default, verbose이며 기본값은 default이다. 개인적인 경험으로는 설정을 바꿀 일이 없었다.
  • log_replication_commands ; PostgreSQL의 Replication을 실행할 때, Replication 과 관련된 Command 들을 Log에 기록하게 한다. 기본값은 off이다. 이 Log를 이용해서 Replication Status를 Monitoring 할 수 있다.
  • log_temp_files : PostgreSQL은 Query를 실행할 때 미리 정해진 Memory('work_mem' 으로 설정되며 기본 값은 4MB)이상을 사용할 때 일부를 temp_file에 저장하게 된다. 이 설정값은 그 temp_file 사용에 관련된 Log를 남길 것인 지 여부를 설정할 때 사용된다. 기본값인 -1일 때는 기능을 사용하지 않게 되고, 0일 때는 모든 temp_file에 대한 log를 남기게 되고, 0 이상의 값은 그 크기를 넘는 temp_file(단위는 KB이며 'MB'와 같은 상위 단위를 사용할 수 없는 것 같다.)이 사용될 때만 Log를 남기게 된다. 너무 큰 Size의 결과값을 가져오는 Query를 파악해서 Tuning하거나 'work_mem' 설정을 Tuning할 필요가 있는 지 확인할 때 이 값을 사용하면 된다.
  • log_timezone : log_line_prefix에 %t, %m, %n과 같이 시간 정보를 남길 때 기준이 되는 Timezone을 설정한다.  'timezone' 설정값과 동일한 값을 사용하지 않으면 Log의 시간 정보와 실제 DB에 Timestamp로 남겨진 시간 정보가 다를 수 있으니 주의해야 한다.
  • log_lock_waits : Lock으로 인해 일정 시간 이상 지연되는 경우 Log를 남기게 한다. 기준이 되는 시간은 deadlock_timeout에 의해 설정되며 기본값은 1 초 이다. DB 성능 Tuning시에 유용한 설정값으로 lock에 의해 지연되는 Query의 빈도를 파악하는데 필요하다.


기타

그리고 'ERROR REPORTING AND LOGGING' section에 포함되는 설정 항목은 아니지만 Log File에 중요 정보를 남기거나 Log에 영향을 미치는 항목들이 더 있으니 참고 삼아 아래 내용도 알아두면 좋을 것 같다.

 

  • log_parser_stats, log_planner_stats, log_executor_stats, log_statement_stats : Runtime 시에 Query를 실행하는 과정에서 사용하는 CPU와 소요 시간, I/O 정보, Memory 사용 정보 등을 보여줄 지 여부를 설정한다. (기본값은 'off'이다) log_parser_stats, log_planner_stats, log_executor_stats은 Query 실행 시 각 단계의 통계치를 나누어서 Log로 남기고, log_statement_stats은 종합해서 Log를 남긴다. log_parser_stats, log_planner_stats, log_executor_stats들은 log_statement_stats와 동시에 사용하는 것으로 설정할 수 없다.

log_parser_stats, log_planner_stats, log_executor_stats를 모두 'on'으로 설정했을 때 아래과 같이 Query 실행의 각 단계(Parsing 단계, Planning 단계, 실행 단계)에서 소요되는 System Resource에 대한 정보를 보여준다.

...
< 2019-05-01 13:33:42.171 KST >LOG:  PARSER STATISTICS
< 2019-05-01 13:33:42.171 KST >DETAIL:  ! system usage stats:
	!	0.000050 elapsed 0.000016 user 0.000033 system sec
	!	[0.000830 user 0.001661 sys total]
	!	0/0 [0/264] filesystem blocks in/out
	!	0/10 [0/501] page faults/reclaims, 0 [0] swaps
	!	0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
	!	0/0 [2/0] voluntary/involuntary context switches
< 2019-05-01 13:33:42.171 KST >STATEMENT:  SELECT * FROM timeTest;
< 2019-05-01 13:33:42.171 KST >LOG:  statement: SELECT * FROM timeTest;
< 2019-05-01 13:33:42.171 KST >LOG:  PARSE ANALYSIS STATISTICS
< 2019-05-01 13:33:42.171 KST >DETAIL:  ! system usage stats:
	!	0.000217 elapsed 0.000073 user 0.000146 system sec
	!	[0.000918 user 0.001837 sys total]
	!	0/0 [0/264] filesystem blocks in/out
	!	0/22 [0/523] page faults/reclaims, 0 [0] swaps
	!	0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
	!	0/0 [2/0] voluntary/involuntary context switches
< 2019-05-01 13:33:42.171 KST >STATEMENT:  SELECT * FROM timeTest;
< 2019-05-01 13:33:42.171 KST >LOG:  REWRITER STATISTICS
< 2019-05-01 13:33:42.171 KST >DETAIL:  ! system usage stats:
	!	0.000033 elapsed 0.000011 user 0.000022 system sec
	!	[0.000933 user 0.001866 sys total]
	!	0/0 [0/264] filesystem blocks in/out
	!	0/3 [0/526] page faults/reclaims, 0 [0] swaps
	!	0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
	!	0/0 [2/0] voluntary/involuntary context switches
< 2019-05-01 13:33:42.171 KST >STATEMENT:  SELECT * FROM timeTest;
< 2019-05-01 13:33:42.172 KST >LOG:  PLANNER STATISTICS
< 2019-05-01 13:33:42.172 KST >DETAIL:  ! system usage stats:
	!	0.000283 elapsed 0.000000 user 0.000282 system sec
	!	[0.000936 user 0.002155 sys total]
	!	0/0 [0/264] filesystem blocks in/out
	!	0/32 [0/558] page faults/reclaims, 0 [0] swaps
	!	0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
	!	0/0 [2/0] voluntary/involuntary context switches
< 2019-05-01 13:33:42.172 KST >STATEMENT:  SELECT * FROM timeTest;
< 2019-05-01 13:33:42.172 KST >LOG:  EXECUTOR STATISTICS
< 2019-05-01 13:33:42.172 KST >DETAIL:  ! system usage stats:
	!	0.000054 elapsed 0.000000 user 0.000054 system sec
	!	[0.000936 user 0.002233 sys total]
	!	0/0 [0/264] filesystem blocks in/out
	!	0/5 [0/566] page faults/reclaims, 0 [0] swaps
	!	0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
	!	0/0 [2/0] voluntary/involuntary context switches
< 2019-05-28 13:33:42.172 KST >STATEMENT:  SELECT * FROM timeTest;
...

 

아래는 log_statement_stats를 'on'으로 설정했을 때 나오는 Log이다. 똑같은 Query를 실행했을 때 설정에 따라 어떤 내용을 보여주는 지 위와 비교할 수 있다.

...
< 2019-05-01 13:35:00.924 KST >LOG:  QUERY STATISTICS
< 2019-05-01 13:35:00.924 KST >DETAIL:  ! system usage stats:
	!	0.000616 elapsed 0.000000 user 0.000617 system sec
	!	[0.000000 user 0.003829 sys total]
	!	0/0 [0/264] filesystem blocks in/out
	!	0/76 [0/567] page faults/reclaims, 0 [0] swaps
	!	0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
	!	0/0 [2/0] voluntary/involuntary context switches
< 2019-05-01 13:35:00.924 KST >STATEMENT:  SELECT * FROM timeTest;
...

 

  • lc_message : System Error Message를 어떤 언어로 출력할 것인지에 대한 설정이고, 한국어 OS에 설치했을 경우 'ko_KR.UTF-8'로 기본 설정 되어 있는데, Error에 대한 자료를 검색하기 위해서 'en_US.UTF-8'로 변경 하는 것이 좋다.

맺음말

5개월 만에 Log 설정 관련 포스팅을 마무리 했다. 눈물 난다.

'Database > PostgreSQL' 카테고리의 다른 글

PostgreSQL Table Partition 성능 비교 v9.6 vs v11 (+ 10)  (0) 2019.07.17
PostgreSQL Log로 DB 성능 분석 (feat. pgBadger)  (2) 2019.06.03
PostgreSQL DB Backup 및 Restore  (3) 2018.12.31
PostgreSQL Log 설정 - 1  (2) 2018.12.04
PostgreSQL HA 구성 - 3. PGPool을 활용한 FailOver 구현  (7) 2018.10.12

'Database/PostgreSQL' Related Articles

티스토리툴바