PostgreSQL Log로 DB 성능 분석 (feat. pgBadger)

PostgreSQL의 장점 중에 하나는 나름대로의 Open Source 생태계가 발달해 있기 때문에, 어떤 기능이 하나 아쉬울 떄 검색만 잘하면 원하던 기능을 찾을 수 있다는 점이다. 이 포스팅에서 소개하는 pgBadger도 그런 다양한 Tool중에 하나로 PostgreSQL에서 생성하는 Log를 분석해 Performance Report(html 형식)를 만들어주는 기능을 제공하고 있다.

공식 페이지에서 샘플로 제공한 결과물은 다음과 같으니 참고하시면 된다.

pgBadger

pgBadger와 관련된 주요 Site의 URL은 아래와 같으니 목적에 따라 방문하면 된다.

• http://pgbadger.darold.net : Official Page. 특징, License, Example 정보 등 제공
• https://github.com/darold/pgbadger : 설치 및 사용 방법 안내
• https://github.com/darold/pgbadger/releases : 설치 Package Download

pgBadger는 다음과 같은 특징을 가지고 있다.

• Perl Script만 지원되면 동작가능한 독립형 Tool
• PostgreSQL의 다양한 Log Format 지원 ; syslog, csvlog, stderr. (jsonlog도 지원한다 하는데 필자는 이 부분은 잘 모르겠다.)
• local에 있는 Log 파일 외에, HTTP/FTP/SSH등의 Protocol을 통해 원격 지원 가능
• crontab과의 조합으로 기간별로 Report를 제공할 수 있고, 특정 시점 이후 사항만 기록한 Incremental Report도 생성 가능
• 내부 그래프는 모두 확대/축소 가능하고, 별도의 Image File로 저장 가능
• 실시간 Monitoring 목적으로 사용은 불가하고, 특정 기간별로 성능 확인용일 때 사용
• 무료 (자발적인 Donation은 Option 사항)

개인적인 경험으로는 System 최종 성능 Test Phase, 초기 Production Phase, 또는 실제 서비스에서 문제가 있을 때에 Log를 모아서 분석하니 유용했었다.

설치 

pgBadger는 perl script로 만들어진 stand-alone형식의 프로그램이기 때문에 설치하려는 곳에 Perl Script가 설치되어 있어야 한다. (*) 위에 언급한 Release Site를 방문하면 pgBadger 최신 버전의 Source Code의 압축파일을 다운받을 수 있고, 압축을 푼 후에 compile&Install 하면 된다. (2019.06 현재 v11이다.)

 

아래의 과정은 Terminal에서 진행 했기 때문에 Browser를 통해 Download 받지 못하고, wget을 통해 down받아 설치하는 과정이다. (Browser에서 down 받을 경우 File명이 pgbadger-11.tar.gz 이다.)

...
[dohoon@localhost ~]$ mkdir pgbadger
[dohoon@localhost ~]$ cd pgbadger
[dohoon@localhost pgbadger]$ wget https://github.com/darold/pgbadger/archive/v11.tar.gz
--2019-06-11 09:12:40--  https://github.com/darold/pgbadger/archive/v11.tar.gz
Resolving github.com (github.com)... 52.78.231.108
...
HTTP request sent, awaiting response... 200 OK
...                                                                                                             ] 1,680,430   5.94MB/s   in 0.3s   
2019-06-11 09:12:41 (5.94 MB/s) - ‘v11.tar.gz’ saved [1680430]
...
[root@localhost pgbadger]# tar xzf v11.tar.gz 
[root@localhost pgbadger]# cd pgbadger-11/
[root@localhost pgbadger-11]# perl Makefile.PL 
Checking if your kit is complete...
Looks good
Writing Makefile for pgBadger
[root@localhost pgbadger-11]# make && make install
which: no pod2markdown in (/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/root/bin)
cp pgbadger blib/script/pgbadger
/usr/bin/perl -MExtUtils::MY -e 'MY->fixin(shift)' -- blib/script/pgbadger
...
[root@localhost pgbadger-11]# pgbadger -V
pgBadger version 11
...

(root 계정으로 작업했기 때문에 sudo 명령을 따로 쓰지 않았다는 점 주의)

사용방법

pgBadger는 PostgreSQL의 Log를 통해 성능 분석을 하는 Tool이기 때문에, 분석하고자 하는 DB의 Log 설정을 어떻게 하느냐가 매우 중요하다. (PosgreSQL LOG 설정에 대한 것은 다음 포스팅 참조 : [1], [2]) pgBadger를 사용하기 위해 중요한 Log 설정은 다음과 같다. 제일 중요한 설정 3개는 log_line_prefix, log_min_duration_time, lc_messages 이고, log_statement에 'none' 값이 강력하게 권장되는 사실을 주의해야 한다.

• log_line_prefix : 분석하려는 목표에 따라 prefix에 찍힐 인자들을 정리하고, 이 값과 pgBadger Option을 동일하게 해야 한다. 주의해야할 사항 중 하나는 syslog를 사용할 경우에는 Process ID와 Timestamp 정보가 자동으로 생성되지만, stderr을 사용할 경우에는 반드시 %t 와 %p option이 설정되어야 한다.
• log_min_duration_time : 전체 Query를 대상으로 성능 분석이 필요할 경우 이 값을 0으로 해서 전체 Query Log가 출력되게 하고, Query 실행 시간을 확인해야 한다.
• lc_messages : 별다른 언어 지원이 없기 때문에 언어를 영어로 설정해야 한다. (그 외에는 'Not recommended' 한다고 적혀있다.)
• log_checkpoint : Check Point에 대한 통계 및 성능 분석이 필요할 때 'on'으로 설정한다.
• log_connections, log_disconnections : DB 접속 주체에 대한 통계가 필요할 때 'on'으로 설정한다.
• log_lock_waits : DB Operation중 lock 통계가 필요할 때 'on'으로 설정한다
• log_temp_files : temp file 통계를 작성하려 할 때 설정. 0으로 설정하면 전체 temp file에 대한 Log가 생성된다
• log_autovacuum_min_duration : Vaccuum Process 통계를 작성하려 할 때 설정. 0으로 설정하면 전체 Vaccume Process에 대한 Log가 생성된다
• log_statement : pgBadger가 log를 분석할 때, log_min_duration_time에 의해 Write되는 Log와 분간하지 못하기 때문에 'none'으로 설정해야 한다.

사용예

Case 1) log_line_prefix='%t [%p]: [%l-1] user=%u,db=%d,app=%a,client=%h' 로 생성된 log file 'postgresql-2019-05-31_133159.log'을 분석한 결과를 test.html으로 생성. 단, 생성되는 중간 과정을 표시하도록 -v Option을 적용.

...
[root@localhost temp]# pgbadger -v --prefix '%t [%p]: [%l-1] user=%u,db=%d,app=%a,client=%h' postgresql-2019-05-31_133159.log -o test.html
DEBUG: Output 'html' reports will be written to test.html
DEBUG: Starting progressbar writer process
DEBUG: Autodetected log format 'stderr' from postgresql-2019-05-31_133159.log
DEBUG: pgBadger will use log format stderr to parse postgresql-2019-05-31_133159.log.
DEBUG: Processing log file: postgresql-2019-05-31_133159.log
DEBUG: Starting reading file postgresql-2019-05-31_133159.log...
DEBUG: Start parsing postgresql log at offset 0 of file postgresql-2019-05-31_133159.log to 4448185
[========================>] Parsed 4448185 bytes of 4448185 (100.00%), queries: 3665, events: 94
DEBUG: the log statistics gathering took: 3 wallclock secs ( 0.04 usr  0.00 sys +  1.03 cusr  0.00 csys =  1.07 CPU)
DEBUG: Output 'html' reports will be written to test.html
LOG: Ok, generating html report...
DEBUG: building reports took: 10 wallclock secs ( 9.84 usr +  0.00 sys =  9.84 CPU)
DEBUG: the total execution time took: 13 wallclock secs ( 9.88 usr  0.00 sys +  1.03 cusr  0.00 csys = 10.91 CPU)
...

 

Case 2) 현재 폴더에 있는 모든 Log 파일을 log_line_prefix='%t [%p]: [%l-1] user=%u,db=%d,app=%a,client=%h' 로 가정해서 분석하되 2개의 CPU를 활용해서 Log 분석. (결과는 Default로 out.html으로 생성.)

...
[root@localhost temp]# pgbadger --prefix '%t [%p]: [%l-1] user=%u,db=%d,app=%a,client=%h' -j 2 ./*.log
[========================>] Parsed 8395066796 bytes of 8395066796 (100.00%), queries: 12845909, events: 7
LOG: Ok, generating html report...
[root@localhost temp]# ll
total 8200004
-rw-r--r--. 1 root root    1730280 Jun 28 13:59 out.html
-rw-r--r--. 1 root root 2238798022 Jun 28 12:18 postgresql-Mon-01.log
-rw-r--r--. 1 root root 6156268774 Jun 28 12:23 postgresql-Mon-02.log
[root@localhost temp]# 
...

case 2를 통해 나온 결과물인 out.html은 아래에 첨부했으니 필요하신 분들은 다운 받아서 내용 확인하시길 바랍니다.

out.html

1.65MB

결과물 설명

위에서 만든 out.html 파일은 아래와 같다.

몇몇 통계 분석은 빠지거나 의미가 없는 내용이기는 하지만 꽤 유용한 통계 분석 내용이 포함되어 있다는 것을 확인할 수 있으며, 각 Page 및 Tab들을 요약해서 설명하면 다음과 같다.

 

• Overview
  • Global Stats : Log에 포함된 전체 Query의 수, Session의 수, Connection의 수와 같은 기본 통계 정보.
  • SQL Traffic : 시간에 따른 SQL Request Graph와 최고 Peak치
  • SELECT Traffic : 시간에 따른 Select Query Graph와 최고 Peak치
  • INSERT/UPDATE/DELETE Traffic : 시간에 따른 Insert/Update/Delete Query Graph와 최고 Peak치
  • Qustion Duration : 시간에 따른 Query 수행 시간 Graph
  • Prepared queries ratio : 시간에 따른 Query 실행 시간과 준비 시간 Graph
  • General Activity : 주요 통계 Data를 시간대 별로 나타낸 Table
• Connection
  • Established Connections : 시간에 따른 DB에 연결된 Connection 수 Graph
  • Connections per database : Connection 수를 DB 별로 표시한 Pie Chart
  • Connections per user : Connection 수를 User 별로 표시한 Pie Chart
  • Connections per host : Connection 수를 Source Host 별로 표시한 Pie Chart
• Sessions
  • Simultaneous sessions : 시간에 따른 Simultaneous session Graph(정확한 의미를 모르겠음)
  • Histogram of sessions times : Session 시간 분포 Histogram
  • Sessions per database : Session 수를 DB 별로 표시한 Pie Chart
  • Sessions per user : Session 수를 User 별로 표시한 Pie Chart
  • Sessionse per host : Session 수를 Source Host 별로 표시한 Pie Chart
  • Sessions per application : Session 수를 Source Application 별로 표시한 Pie Chart
• Checkpoints
  • Checkpoints buffers : 시간대 별로 Checkpoint Process에 따라 Wirte된 Buffer의 수를 나타낸 Graph
  • Checkpoints Wal files : 시간대 별로 Checkpoint Process에 의해 생성/삭제/재사용된 WAL file의 수를 나타낸 Graph
  • Checkpoints distance : ??? (정확한 의미를 모르겠음)
  • Checkpoint activity : 위에 언급된 통계 정보를 나타낸 Table
• Temp Files(DB의 work memory가 쿼리 결과를 저장하기에 부족할 때 Temp File이 생성되는데 이 Temp File에 대한 통계를 표시)
  • Size of temporary files : 시간대 별로 Temp File의 Size를 표시한 Graph
  • Number of temporary files : 시간대 별로 Temp File의 수를 표시한 Graph
  • Temporary files activity : 시간대 별로 Temp File 통계치를 나타낸 Table
  • Queries generating the most files : Temp File 생성을 야기한 Query
  • Queries generating the largest files : 가장 큰 Temp File 생성을 야기한 Query
• Vacuums : VACUUM과 ANALYZE process에 대한 통계 정보 표시
  • Vacuums distribution : 시간대 별로 Vacuum/Analyze Process 수를 표시한 Graph(+ CPU를 가장 많이 사용한 Table)
  • Vacuums activity : 시간대 별로 Vacuum/Analyze Process 통계 정보를 표시한 Table
  • Analyzes per Tables : Analyze Process의 Target Table 비율을 표시한 Pie Chart
  • Vacuums per Tables : Vacuum Process의 Target Table 비율을 표시한 Pie Chart
  • Tuples removed : 삭제된 Tuple을 포함했던 Table 비율을 표시한 Pie Chart
  • Page removed : 삭제된 Page를 포함했던 Table 비율을 표시한 Pie Chart
• Locks : Lock에 대한 통계정보 표시
  • Lockes by type : 발생한 Lock을 Type 별로 표시한 Pie Chart
  • Most frequent waiting queries : Lock을 가장 자주 발생시키는 Query List
  • Queries that waited the most : Lcok으로 인해 가장 많이 대기하는 Query List
• Queries : 개별 Query 실행 관련한 통계.(Query를 직접 작성하는 경우에 매우 유용하다.)
  • Queries by type :실행한 Query를 Type(SELECT/INSERT/UPDATE/DELETE)별로 표시한 Pie Chart
  • Queries by database : Query가 실행된 Database에 따라 표시한 Pie Chart
  • Queries by user : Query를 실행한 User에 따라 표시한 Pie Chart
  • Duration by user : Query 실행 시간을 User에 따라 표시한 Pie Chart
  • Queries by host : Query 요청 Source Host에 따라 표시한 Pie Chart
  • Queries by application : Query 요청 Source Application에 따라 표시한 Pie Chart
  • Number of cancelled queries : 취소 Query 수를 시간에 따라 표시한 그래프
• Top : 각종 통계상에서 상위 항목 표시
  • Histogram of query times : Query들을 실행 시간에 따라 분류한 Histogram
  • Slowest individual queries : 실행 시간을 많이 소요된 개별 Query List
  • Time Consuming queries (N) : 총 실행 시간을 많이 소요한 Query List
  • Most frequent queries : 가장 자주 보이는 Query
  • Normalized slowest queries : 평균 실행 시간이 오래 걸리는 Query List

그리고 필자가 만든 예제 결과물에는 포함되어 있지 않지만, pgBouncer라는 Connection Pool을 관리하는 Plugin의 로그도 같이 분석할 수 있다. 이 내용은 pgBadger Home Page에서 제공하는 Sample을 참조하면 될 것 같다.

 

(*) CSV 형식으로 된 Log 파일을 분석하거나 결과를 JSON형식으로 만들 경우에는 perl module이 추가로 필요하다 

 

 

ps) 이런 유용한 툴을 무료로 제공하는 분에게 행운이 가득하길 빈다.