Chào các bạn. Bài viết này mình xin giới thiệu thêm về một chức năng cơ bản mà rất cần thiết khi thiết kế sử dụng một cơ sở dữ liệu PostgreSQL cho người sử dụng. Như tiêu đề đã nêu, đó là quản lý log.
Log là một phần không thể thiếu trong việc giải quyết các vấn đề liên quan tới database như phát hiện lock wait, deadlock, tình trạng checkpoint, autovacuum, phát hiện slow query... Thiết kế sao cho log chứa những thông tin hữu ích để giải quyết những vấn đề xảy ra trong lúc hoạt động, và làm sao để việc xuất log không ảnh hưởng nhiều tới hệ thống là một phần không thể thiếu đối với một quản trị viên cơ sở dữ liệu.

Chức năng log của PostgreSQL

Log là chức năng có sẵn của PostgreSQL, ta có thể sử dụng mà không cần cài đặt thêm module nào cả. Chức năng log của PostgreSQL lưu trữ các thao tác, lỗi khi sử dụng, vận hành, ... dưới dạng text, cho phép người dùng có thể quan sát trực tiếp. PostgreSQL có thể thiết kế để xuất log tới syslog(linux) hay event log(windows), mặc định PostgreSQL xuất log bên dưới pg_log bên dưới thư mục cơ sở dữ liệu (nếu tham số logging_collector thiết lập là on). Để quản lý đơn giản hơn thường dữ liệu log được thiết lập để xuất bên dưới thư mục cơ sở dữ liệu. Bài viết này mình cũng đưa ra những ví dụ log từ pg_log bên dưới thư mục cơ sở dữ liệu.

Chú ý khi thiết kế log

Trạng thái xuất log mặc định

Giá trị khởi tạo của tham số logging_collector là off, tức là log messages không được lưu trữ. Nhưng nếu bạn tạo database cluster theo cách bên dưới đây thì giá trị mặc định đối với tham số logging_collector cho database cluster đó là on.

• Database được tạo ra lúc cài đặt PostgreSQL bằng (EDB) Installer trên môi trường Windows.
• Database được tạo ra bởi initdb được cài đặt từ rpm từ community.

Chú ý khác với initdb của rpm, database cluster được tạo ra bằng cách chạy trực tiếp lệnh initdb của EDB installer (ít nhất tại thời điểm hiện tại) lại có mặc định logging_collector = off.

Một số chú ý về log của PostgreSQL khi lưu trữ bên dưới thư mục dữ liệu

• Mặc định log của PostgreSQL tăng không có giới hạn
  Mặc định các tham số log_filename, log_truncate_on_rotation làm cho log không có cơ chế loại bỏ được log cũ nên dung lượng log sẽ tăng không ngừng theo thời gian. Ta phải thiết kế để tránh tình trạng trên và sao cho phù hợp với yêu cầu hệ thống.
• Không thể giới hạn được dung lượng xuất log của PostgreSQL
  Như giải thích về tham số log_rotate_size ở bên dưới. Chúng ta không thể giới hạn được dung lượng xuất log của PostgreSQL. Bởi vậy nên cần tính toán thiết kế sao cho lượng log không xuất ra quá nhiều so với mong đợi.

Các tham số liên quan tới log của PostgreSQL

PostgreSQL có rất nhiều paramters liên quan tới log, nội dung giải thích bên dưới mình chỉ tập chung vào các tham số thường được sử dụng trong vận hành và lúc tuning (tinh chỉnh). Cụ thể các tham số đó vui lòng tham khảo ở Document của PostgreSQL.

Các tham số liên quan tới PostgreSQL được chia ra 3 nhóm chính. Mình sẽ đi vào giải thích các tham số trong từng nhóm.

Trong các tham số liên quan tới log, duy có tham số logging_collector khi thay đổi cần restart server(pg_ctl restart) để có hiệu lực. Các paramter khác có thể reload server(pg_ctl reload), hoặc một vài paramter có thể thiết lập trong từng session(bằng cách sử dụng câu lệnh SET).

Nơi xuất log

$ ll $PGDATA/log/
total 16
-rw-------. 1 postgres postgres    0 May  4 00:00 postgresql-Fri.log
-rw-------. 1 postgres postgres    0 May  7 00:00 postgresql-Mon.log
-rw-------. 1 postgres postgres 1039 May  5 16:07 postgresql-Sat.log
-rw-------. 1 postgres postgres    0 May  6 00:00 postgresql-Sun.log
-rw-------. 1 postgres postgres  941 May  3 18:39 postgresql-Thu.log
-rw-------. 1 postgres postgres   74 May 11 23:55 postgresql-Tue.log
-rw-------. 1 postgres postgres  718 May 16 06:31 postgresql-Wed.log

Thời điểm xuất log

postgres=# set client_min_messages to log;
SET
postgres=# set log_min_duration_statement to 0;
LOG:  duration: 0.103 ms  statement: set log_min_duration_statement to 0;
SET
postgres=# select pg_sleep(1);
LOG:  duration: 1003.193 ms  statement: select pg_sleep(1);
 pg_sleep 
----------
 
(1 row)

$ psql
psql (11devel)
Type "help" for help.

postgres=# set log_min_messages to debug5;
SET
postgres=# select count(*) from pg_class;
 count 
-------
   343
(1 row)

postgres=# \q
$ tail -2 $PGDATA/log/postgresql-Wed.log | grep DEBUG
2018-05-16 07:42:50.299 JST [22540] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2018-05-16 07:42:50.299 JST [22540] DEBUG:  proc_exit(-1): 0 callbacks to make
$ 

postgres=# show log_min_error_statement;
 log_min_error_statement 
-------------------------
 error
(1 row)

postgres=# select testerror;
ERROR:	column "testerror" does not exist
LINE 1: select testerror;
	       ^
postgres=# \q
$ tail -3 $PGDATA/log/postgresql-Wed.log | grep ERROR -A2
2018-05-16 07:45:51.324 JST [22591] ERROR:  column "testerror" does not exist at character 8
2018-05-16 07:45:51.324 JST [22591] STATEMENT:	select testerror;
$ 

postgres=# set client_min_messages to log;
SET
postgres=# set log_min_duration_statement to 100;
LOG:  duration: 0.103 ms  statement: set log_min_duration_statement to 100;
SET
postgres=# select pg_sleep(1);
LOG:  duration: 1003.193 ms  statement: select pg_sleep(1);
 pg_sleep 
----------
 
(1 row)

Nội dung log

$ psql -c "show log_connections"
 log_connections 
-----------------
 on
(1 row)

$ tail $PGDATA/log/postgresql-Wed.log | grep -A1 "connection received"
2018-05-16 07:51:12.137 JST [22714] LOG:  connection received: host=[local]
2018-05-16 07:51:12.138 JST [22714] LOG:  connection authorized: user=postgres database=postgres

$ psql -c "show log_disconnections"
 log_disconnections 
--------------------
 on
(1 row)

$ tail -1 $PGDATA/log/postgresql-Wed.log
2018-05-16 07:53:49.485 JST [22754] LOG:  disconnection: session time: 0:00:00.003 user=postgres database=postgres host=[local]

postgres=# set log_duration to on;
SET
postgres=# set client_min_messages to log;
LOG:  duration: 0.075 ms
SET
postgres=# select pg_sleep(1);
LOG:  duration: 1002.341 ms
 pg_sleep 
----------
 
(1 row)

postgres=# 

[postgres@localhost ~]$ psql -c "show log_line_prefix"
		     log_line_prefix			 
---------------------------------------------------------
 [%m host:%h database:%d user:%u PID:%p TransactionID:%x] 
(1 row)

[postgres@localhost ~]$ tail -1 $PGDATA/log/postgresql-Wed.log
[2018-05-16 07:57:33.815 JST host:[local] database:postgres user:postgres PID:22817 TransactionID:0] LOG:  disconnection: session time: 0:00:00.003 user=postgres database=postgres host=[local]
[postgres@localhost ~]$ 

postgres=# set log_statement to 'ddl';
SET
postgres=# set client_min_messages to log;
SET
postgres=# create table testtbl(id integer);
LOG:  statement: create table testtbl(id integer);
CREATE TABLE
postgres=# insert into testtbl values(1);
INSERT 0 1
postgres=# drop table testtbl ;
LOG:  statement: drop table testtbl ;
DROP TABLE
postgres=#

postgres=# set log_temp_files to 0;
SET
postgres=# set work_mem to 64;
SET
postgres=# show work_mem ;
 work_mem 
----------
 64kB
(1 row)

postgres=# explain analyze select * from pg_class order by relname desc;
						  QUERY PLAN					    
	   
----------------------------------------------------------------------------------------------------
-----------
 Sort  (cost=75.31..76.17 rows=342 width=262) (actual time=0.636..0.720 rows=343 loops=1)
   Sort Key: relname DESC
   Sort Method: external merge	Disk: 64kB
   ->  Seq Scan on pg_class  (cost=0.00..15.42 rows=342 width=262) (actual time=0.010..0.067 rows=34
3 loops=1)
 Planning Time: 0.862 ms
 Execution Time: 1.025 ms
(6 rows)

postgres=# \! tail -2 $PGDATA/log/postgresql-Wed.log
2018-05-16 08:10:36.530 JST [23134] LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp23134.0", size 65536
2018-05-16 08:10:36.530 JST [23134] STATEMENT:	explain analyze select * from pg_class order by relname desc;
postgres=# 

Cấu trúc processes của PostgreSQL

Khác với một số RDBMS khác sử dụng thread để xử lý, PostgreSQL sử dụng mỗi process cho những chức năng riêng biệt. Sau khi khởi tạo database và khởi động server, PostgreSQL sẽ có những processes như bên dưới.

[postgres@ip-172-31-31-242 ~]$ ps -ef | grep `head -1 $PGDATA/postmaster.pid    
postgres 17397     1  0 Apr11 pts/3    00:06:44 /usr/pgsql-9.6/bin/postgres    
postgres 17398 17397  0 Apr11 ?        00:00:33 postgres: logger process     
postgres 17400 17397  0 Apr11 ?        00:00:18 postgres: checkpointer process    
postgres 17401 17397  0 Apr11 ?        00:01:24 postgres: writer process     
postgres 17402 17397  0 Apr11 ?        00:01:31 postgres: wal writer process    
postgres 17403 17397  0 Apr11 ?        00:06:13 postgres: autovacuum launcher process    
postgres 17404 17397  0 Apr11 ?        00:11:30 postgres: stats collector process    
postgres  7205 17397  0 03:23 ?        00:00:00 postgres: postgres postgres [local] idle    

Cấu trúc tổng quan của các Processes có thể hiểu như bên dưới.

Postmaster Process

postgres 17397     1  0 Apr11 pts/3    00:06:44 /usr/pgsql-9.6/bin/postgres    

Là process khởi tạo đầu tiên sau khi server khởi động. Process này đảm nhiệm việc khởi động hoặc dừng các process khác nếu cần hoặc có yêu cầu. Sau khi khởi động Postmaster sẽ khởi động các processes thường trực như bên dưới để PostgreSQL server có thể hoạt động.

• logger process
• checkpointer process
• writer process
• wal writer process
• autovacuum launcher process (process này không khởi động khi parameter autovacuum = off)
• stats collector process

 Tiếp đó Postmaster sẽ thực hiện vòng lặp của mình, nếu có yêu cầu kết nối thoả mãn yêu cầu authenticate, hoặc khởi động các tiến trình thường trực khi bị lỗi. Khi có yêu cầu shutdown từ người dùng (pg_ctl stop), Postmaster sẽ gửi các signal tương ứng tới từng server processes.

logger process

postgres 17400 17397  0 Apr11 ?        00:00:18 postgres: logger process    

Process này đảm nhiệm việc ghi log của PostgreSQL.

checkpointer process

postgres 17400 17397  0 Apr11 ?        00:00:18 postgres: checkpointer process    

Process này chủ yếu giữ vai trò thực hiện checkpoint (đồng bộ dữ liệu từ bộ nhớ đệm xuống vùng lưu trữ) khi cần thiết.

writer process

postgres 17401 17397  0 Apr11 ?        00:01:24 postgres: writer process     

Hay còn gọi là background writer process, process này kết hợp với checkpointer process để đảm bảo việc ghi dữ liệu từ bộ đệm xuống vùng lưu trữ. Thông thường khi checkpoint không hoạt động, process này sẽ ghi từng chút một dữ liệu xuống vùng lưu trữ. Để hiểu thêm về background writer process xin vui lòng tham khảo ở manual tại đây.

wal writer process

postgres 17402 17397  0 Apr11 ?        00:01:31 postgres: wal writer process    

Đảm nhiệm việc đồng bộ WAL từ bộ nhớ đệm xuống vùng lưu trữ. Thông thường WAL sẽ được ghi từ bộ đệm xuống vùng lưu trữ khi transaction được commit. Nếu dữ liệu đệm của WAL trên bộ nhớ đệm vượt quá parameter wal_buffers dữ liệu WAL trên vùng nhớ đệm sẽ tự động ghi xuống vùng lưu trữ dữ liệu thông qua process này.

autovacuum launcher process

postgres 17403 17397  0 Apr11 ?        00:06:13 postgres: autovacuum launcher process    

Process này thường trú khi paramter autovacuum = on. Proccess này thực hiện chức năng tự động lấy vùng dữ liệu dư thừa sau khi DELETE hoặc UPDATE dữ liệu. Vui lòng thảo khảo bài viết về VACUUM để biết thêm về VACUUM. Process này khởi động các VACUUM worker processes sau mỗi autovacuum_naptime. Các VACUUM worker processes sẽ thực hiện việc VACUUM dữ liệu trên các database.

stats collector process

postgres 17404 17397  0 Apr11 ?        00:11:30 postgres: stats collector process    

Process này thực hiện vai trò lưu trữ các thông tin thống kê hoạt động của PostgreSQL và cập nhật vào các system catalog (thông tin nội bộ của PostgreSQL hiện diện bởi các bảng hoặc view pg_stat_*).

Server Process

postgres  7205 17397  0 03:23 ?        00:00:00 postgres: postgres postgres [local] idle    

Là các processes được sinh ra khi có yêu cầu từ phía client (aplication). Client gửi yêu cầu (bằng cách chạy các connection API) tới server, phía server sẽ sử dụng thông tin authentication (user, password, database, host) từ client để xem user này có được truy cập vào database không. Nếu được, Postmaster sẽ tạo một server process (bằng API fork()) cho client, từ đó client có thể chạy được các câu truy vấn, ... thông qua server process được tạo.

Một số processes không thường trực

Cơ chế lưu dữ liệu trên PostgreSQL

PostgreSQL cũng như một số RDBMS khác. Khi bạn chạy một câu lệnh cập nhật dữ liệu (UPDATE/INSERT/DELETE), dữ liệu vật lý trên đĩa cứng chưa thay đổi mà chỉ thay đổi trên bộ đệm (bộ nhớ dùng chung: PostgreSQL = shared_buffers). Khi bạn tham chiếu dữ liệu (SELECT), trước hết PostgreSQL xem dữ liệu tồn tại trên bộ đệm không, nếu tồn tại dữ liệu sẽ trả về người dùng. Nếu dữ liệu không tồn tại trên bộ đệm, PostgreSQL sẽ truy cập xuống vùng vật lý (ổ đĩa cứng) để lấy dữ liệu, sau đó trước khi trả về cho người dùng dữ liệu đó sẽ được đưa lên bộ đệm.
Cơ chế nêu trên làm tăng tốc độ xử lý nhờ vào việc giảm thiểu I/O trên đĩa cứng.

Độ lớn bộ đệm?

Độ lớn vùng nhớ đệm của PostgreSQL được chỉ định qua parameter shared_buffers (giá trị mặc định của parameter này tuỳ thuộc vào phiên bản PostgreSQL và bộ nhớ hệ thống).

Xem qua ở trên bạn chắc sẽ băn khoăn nếu dữ liệu vừa cập nhật trên bộ đệm, nếu máy tính bị tắt nguồn hoặc OS panic, thì dữ liệu này sẽ bị mất? Bạn yên tâm vì PostgreSQL cũng như các RDBMS khác PostgreSQL có cơ chế roll forward (phục hồi dữ liệu từ transaction log: WAL). Bạn có thể xem qua hình vẽ bên dưới để hiểu thêm.

CHECKPOINT

Khi buffer bị đầy PostgreSQL sẽ ghi những dirty buffers xuống đĩa để chỗ trống cho dữ liệu mới, quá trình này diễn ra liên tục làm tăng cách thao tác thừa sẽ ảnh hưởng tới người dùng. Vì vậy PostgreSQL cần có chức năng CHECKPOINT. CHECKPOINT là cơ chế đồng bộ dữ liệu cập nhật (đã commit) từ bộ nhớ đệm xuống dưới đĩa cứng.

Bạn có thể hình dung đơn giản chức năng CHECKPOINT thực hiện thông qua cơ chế ghi dữ liệu của PostgreSQL như bên dưới.

PostgreSQL thực hiện tự động xử lý checkpoint thông qua process checkpointer (phiên bản trước 9.2 thông qua background process). 

[postgres@ip-172-31-31-242 ~]$ pg_ctl status
pg_ctl: server is running (PID: 17397)
/usr/pgsql-9.6/bin/postgres
[postgres@ip-172-31-31-242 ~]$ ps -ef | grep 17397
postgres 14946 14348  0 13:11 pts/2    00:00:00 grep --color=auto 17397
postgres 17397     1  0 Apr11 pts/3    00:04:48 /usr/pgsql-9.6/bin/postgres
postgres 17398 17397  0 Apr11 ?        00:00:08 postgres: logger process   
postgres 17400 17397  0 Apr11 ?        00:00:10 **postgres: checkpointer process**  
postgres 17401 17397  0 Apr11 ?        00:01:08 postgres: writer process   
postgres 17402 17397  0 Apr11 ?        00:01:12 postgres: wal writer process  
postgres 17403 17397  0 Apr11 ?        00:04:31 postgres: autovacuum launcher process  
postgres 17404 17397  0 Apr11 ?        00:08:14 postgres: stats collector process  
[postgres@ip-172-31-31-242 ~]$   

CHECKPOINT diễn ra khi nào

Thông thường trong vận hành CHECKPOINT xảy ra khi có các điều kiện sau.

• Khi thời gian từ lần CHECKPOINT trước vượt quá tham số checkpoint_timeout Mặc định parameter này là 5 phút. Như vậy chắc chắn trong vòng 5 phút sẽ có 1 CHECKPOINT xảy ra. Lưu ý: CHECKPOINT xử lý theo cơ chế này, để giảm thiểu disk I/O PostgreSQL làm thao tác này chậm hơn các cơ chế CHECKPOINT khác (sự trì hoãn này phụ thuộc vào giá trị của parameter checkpoint_completion_target).

  Khi CHECKPOINT theo cơ chế này xảy ra, PostgreSQL log sẽ có messages như bên dưới(lưu ý set log_checkpoints = on để xuất log khi có CHECKPOINT xảy ra)

  
  [2017-07-08 12:57:05.993 EDT ] LOG: checkpoint starting: time
  [2017-07-08 12:57:12.020 EDT ] LOG: checkpoint complete: wrote 64 buffers (0.4%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=6.017 s, sync=0.002 s, total=6.026 s; sync files=17, longest=0.001 s, average=0.000 s; distance=730 kB, estimate=970 kB
  
  

• Khi lượng dữ liệu transaction log (WAL) lớn hơn max_wal_size (phiên bản trước 9.5 là tham số checkpoint_segments) Khi dung lượng của WAL (transaction log, được lưu trữ trong <thư mục database>/pg_xlog (PostgreSQL 10 -> pg_wal)) vượt quá max_wal_size, CHECKPOINT sẽ tự động diễn ra.

  lưu ý: tương quan giữa max_wal_size và checkpoint_segments bạn có thể hiểu là (max_wal_size = checkpoint_segments*3 + 1)

  CHECKPOINT theo cơ chế này xảy ra sẽ có messages như bên dưới trong PostgreSQL's log.

  
  [2017-07-08 13:02:42.620 EDT ] LOG:  checkpoint starting: xlog
  [2017-07-08 13:02:43.921 EDT ] LOG:  checkpoint complete: wrote 2312 buffers (14.1%); 0 transaction log file(s) added, 1 removed, 1 recycled; write=1.011 s, sync=0.139 s, total=1.311 s; sync files=2, longest=0.139 s, average=0.069 s; distance=32759 kB, estimate=34561 kB
  
  

• Ngoài ra CHECKPOINT còn xảy ra trong các trường hợp sau

1. Chạy câu lệnh CHECKPOINT từ người dùng (quyền super user)
2. Khi Shutdown server PostgreSQL
3. Khi khởi động PostgreSQL trong chế độ recovery (roll forward)
4. Khi tạo dữ liệu backup từ câu lệnh pg_basebackup

Tinh chỉnh CHECKPOINT sao cho hợp lý để hệ thống chạy tốt cũng là một việc quan trọng. Nếu tăng thời gian tự động CHECKPOINT, thì dữ liệu WAL sẽ nhiều, crash recovery, và CHECKPOINT sẽ mất nhiều thời gian ảnh hưởng tới người dùng. Nếu giảm thời gian này đi thì số lượng CHECKPOINT sẽ tăng lên, làm disk I/O tăng ảnh hưởng tới người dùng. Lưu ý là sau mỗi lần CHECKPOINT, lần cập nhật dữ liệu đầu tiên sẽ lưu cả block dữ liệu (full-page writes) lên WAL điều này làm ảnh hưởng tới disk I/O đáng kể. Vì vậy bạn nên thao khảo sát work-load của người dùng để quyết định tinh chỉnh như thế nào cho PostgreSQL chạy hiệu quả nhé.

Xin vui lòng đặt câu hỏi hoặc thảo luận bằng comments box bên dưới.