db2 活動日志激增的原因分析處理

本文簡單地介紹了DB2中日志的使用、活動日志以及首個活動日志的概念、日志滿的原因、日志滿的診斷、臨時處理以及避免辦法

日志使用

下圖顯示了並發事務條件下，日志使用的示意

有3個並發的程序Process 1、Process 2、Process 3。每一個程序都有兩個事務。藍塊代表SQL語句，紅塊代表commit操作，綠塊代表rollback操作。每一個向下的箭頭都代表日志緩沖區的數據被刷新到日志磁盤上（默認是每一次提交操作都會導致日志緩沖被刷新到磁盤上）。

在T1時刻，事務A commit，日志緩沖區被刷新到磁盤上。
在T2時刻，事務B commit，日志緩沖區被刷新到磁盤上，此時日志X使用完，但由於X中的事務C還沒有提交，所以X此時還是活動日志。

在上圖中，如果事務C一直沒有提交操作，那么日志X將永遠是首個活動日志(oldest transaction log)，后續的日志也是活動日志，其他應用最終會導致日志滿。

活動日志

如果一個日志中包含有未提交的事務，那么這個日志就是活動日志(也有其他情況，比如雖然所有事務已經提交，但對應的更改還沒有持久化到磁盤上)。

首個活動日志(First Active Log)

第一個活動日志，首個活動日志之后的日志（也就是編號比首個活動日志大的日志）都是活動日志，可以通過數據庫的snapshot查看first active log, current active log, 以及 last active log.

$ db2 get snapshot for db on sample | grep -i "File number"
File number of first active log            = 0
File number of last active log             = 2
File number of current active log          = 0

File number of log being archived          = Not applicable

日志滿原因

DB2總的可用活動日志的最大空間是有限制的，當達到限制之后，就會發生日志滿的問題，限制為(LOGPRIMARY + LOGSECOND) * LOGFILSIZ * 4KB

日志滿的原因無非兩種:
1. 一個小事務hold住了首個活動日志，一直沒有提交，導致首個活動日志一直是活動狀態，不被釋放。這個跟堵車類似，一輛車因發動機故障（事務沒有提交）堵住路口（占用首個活動日志），即使后面的車都沒有問題（后續事務正常提交），也無法通過路口，且會越積越多，最終導致整個路都堵滿車（日志滿）。
2.  有個事務非常大，迅速用盡了所有的日志。

日志滿的表現:

首先應用會報出SQL0964C錯誤：

$ db2 "insert into test select * from test"
DB21034E  The command was processed as an SQL statement because it was not a
valid Command Line Processor command.  During SQL processing it returned:
SQL0964C  The transaction log for the database is full.  SQLSTATE=57011

其次，db2diag.log中會有以下報錯

2017-03-09-17.24.50.315000+480 E3234873F644         LEVEL: Error
PID     : 8532                 TID : 13028          PROC : db2syscs.exe
INSTANCE: DB2INST1             NODE : 000           DB   : SAMPLE
APPHDL  : 0-453                APPID: *LOCAL.DB2INST1.170309092321
AUTHID  : MIAOQINGSONG         HOSTNAME: ADMINIB-PR7US3I
EDUID   : 13028                EDUNAME: db2agent (SAMPLE)
FUNCTION: DB2 UDB, data protection services, sqlpgResSpace, probe:2860
MESSAGE : ADM1823E  The active log is full and is held by application handle
          "0-441".  Terminate this application by COMMIT, ROLLBACK or FORCE
          APPLICATION.

日志滿的臨時處理：

1. 可以通過增加LOGSECOND來臨時增加可用的日志大小（修改時需要加上immediate選項使之立即生效）；增加LOGPRIMARY並沒有用，因為需要重啟數據庫才能生效。
2. force掉hold住首個活動日志的的應用，在force之前，可以抓取snapshot，看一下這個應用的狀態：

$ db2 get snapshot for database on sample | grep -i oldest
Appl id holding the oldest transaction     = 441

$ db2 get snapshot for application agentid 441

Application Snapshot

Application handle                         = 441
Application status                         = UOW Waiting                 <<--應用狀態為UOW Waiting
Status change time                         = 2017-03-09 17:23:15.068895
Application code page                      = 1386
Application country/region code            = 86
DUOW correlation token                     = *LOCAL.DB2INST1.170309092244
Application name                           = db2bp.exe
Application ID                             = *LOCAL.DB2INST1.170309092244

..

Connection request start timestamp         = 2017-03-09 17:22:44.963163  <<--應用連庫時間
Connect request completion timestamp       = 2017-03-09 17:22:45.961157
Application idle time                      = 4 minutes  7 seconds



UOW log space used (Bytes)                 = 664
Previous UOW completion timestamp          = 2017-03-09 17:22:45.961157
Elapsed time of last completed uow (sec.ms)= 0.000000
UOW start timestamp                        = 2017-03-09 17:23:02.770477 <<--當前事務開始時間
UOW stop timestamp                         =                            <<--當前事務結束時間為空，說明還沒有commit
UOW completion status                      =

Statement type                             = Dynamic SQL Statement
Statement                                  = Close
Section number                             = 201
Application creator                        = NULLID
Package name                               = SQLC2K26
Consistency Token                          =
Package Version ID                         =
Cursor name                                = SQLCUR201
Statement member number                    = 0
Statement start timestamp                  = 2017-03-09 17:23:15.067789
Statement stop timestamp                   = 2017-03-09 17:23:15.068893 
Elapsed time of last completed stmt(sec.ms)= 0.000024
Total Statement user CPU time              = 0.000000
Total Statement system CPU time            = 0.000000
..
Dynamic SQL statement text:      

select * from t1

 

<<--一個事務中可能有多條SQL，這個只表示當前正在執行或者最后執行過的SQL，並不能表示就是這條SQL導致了日志滿，這里抓取到的是一條SELECT語句，SELECT語句不占用日志。

$ db2 "force application (441)"
DB20000I  The FORCE APPLICATION command completed successfully.
DB21024I  This command is asynchronous and may not be effective immediately.

日志滿的避免：

1.）根據抓取到的應用的snapshot，找應用開發人員查看為何不肯提交，這才是避免問題再次出現的根本辦法。
2.）從DB2管理層面，可以設置數據庫配置參數max_log和num_log_span
3.）可以寫腳本，以固定的間隔抓取database snapshot中的Appl id holding the oldest transaction, 如果長時間不發生變化（比如2天），就Force掉。

 

補充案例1：

活動日志激增排查：

DB2總的可用活動日志的最大空間是有限制的，當達到限制之后，就會發生日志滿的問題，限制為(LOGPRIMARY + LOGSECOND) * LOGFILSIZ * 4KB

日志滿的原因無非兩種:

1. 一個小事務hold住了首個活動日志，一直沒有提交，導致首個活動日志一直是活動狀態，不被釋放。這個跟堵車類似，一輛車因發動機故障（事務沒有提交）堵住路口（占用首個活動日志），即使后面的車都沒有問題（后續事務正常提交），也無法通過路口，且會越積越多，最終導致整個路都堵滿車（日志滿）。

2. 有個事務非常大，迅速用盡了所有的日志。

 日志滿的臨時處理：

1. 可以通過增加LOGSECOND來臨時增加可用的日志大小（修改時需要加上immediate選項使之立即生效）；增加LOGPRIMARY並沒有用，因為需要重啟數據庫才能生效。

2. force掉hold住首個活動日志的的應用，在force之前，可以抓取snapshot，看一下這個應用的狀態：

db2 get snapshot for database on sample | grep -i oldest

 首個活動日志(First Active Log)

第一個活動日志，首個活動日志之后的日志（也就是編號比首個活動日志大的日志）都是活動日志，可以通過數據庫的snapshot查看first active log, current active log, 以及 last active log.

db2 get snapshot for db on fxyjdb|grep -i "File number"

日志有無報錯

db2diag -l "Error,Severe" -H 1d

查看事務占用日志情況

db2 "select application_handle,UOW_LOG_SPACE_USED,UOW_START_TIME FROM TABLE(MON_GET_UNIT_OF_WORK(NULL,-1)) order by UOW_LOG_SPACE_USED" 

快照查看最老事務

db2 get snapshot for db on fxyjdb|grep -i oldest

查詢 App Handle 49379 具體事務信息

db2 get snapshot for application agentid 49379

查看當前事務

db2top -db fxyjdb

-h參數說明

輸入參數a 寫入App Handle 49379回車

取得相關信息包括sql語句

確認sql drop掉相關事務

db2 "force application(49379)"

再次查看事務占用日志情況

此外可以用db2pd -db dbname -logs檢查

 

解釋說明

 

在線日志使用率為啥會激增？正常使用率在5%以下，一般select不會產生日志。

 

原因在於App Handle 49379是最老且有尚未提交事務，因為會造成事務使用率持續增高。一直到提交或回滾。您可參考下列技術文檔

Appl id holding the oldest transaction     = 49379
 

IBM How to get immediate relief when log space get full
http://www-01.ibm.com/support/docview.wss?uid=swg21664899

 

關鍵詞：

 

The database snapshot will show the oldest transaction.
Collect following output,
db2 get snapshot for database on <db-name>

And, look for following in the database snapshot output,
"Appl id holding the oldest transaction "
The application handle showing up against the above field have to be forced off to get the transaction log space back against that.

db2 "force application (appl-handle)"

If there are more than one application which might be causing the issue then the same step might have to be repeated multiple times forcing the current oldest transaction from that moment, until the log full situation is taken care.

Following could be run during the time of the problem to get a full picture of all the transactions,
db2pd –db <db-name> -transactions

There are some rare situations when the transaction log files might be held by indoubt transaction.

Indoubt transaction can be caused by anything using two phase commit.

The way to check indoubt transaction is to run,

db2 list indoubt transactions with prompting

and, then take necessary step to rollback or, forget the transaction.

As a permanent solution, fix the queries which might not be committing frequently enough or, increase the total log space if it's not large enough by increasing any of LOGPRIMARY, LOGSECOND or, LOGFILSZ as necessary.