概述
概述statement_history用于記錄當(dāng)前節(jié)點(diǎn)的SQL執(zhí)行信息，用于替代日志方式記錄Slow SQL。用于性能問題定位、SQL性能問題分析。會根據(jù)配置，記錄兩類SQL。
- 全量SQL記錄
- 慢SQL
對于此系統(tǒng)表查詢有如下約束：
- 必須在postgres庫內(nèi)查詢，其它庫中不存數(shù)據(jù)。
- 此系統(tǒng)表受track_stmt_stat_level控制，默認(rèn)為"OFF,L0"，第一部分控制Full SQL，第二部分控制Slow SQL，具體字段記錄級別見下表。
- 對于Slow SQL，當(dāng)track_stmt_stat_level的值為非OFF時，且SQL執(zhí)行時間超過log_min_duration_statement，會記錄為慢SQL。
- 查詢系統(tǒng)表必須具有sysadmin權(quán)限。
相關(guān)參數(shù)
- log_min_duration_statement
參數(shù)說明：設(shè)置記錄慢SQL的閥值。默認(rèn)值1800000ms
-1 is disabled, 0 logs all statements and their durations, > 0 logs only statements running at least this number of milliseconds
- track_stmt_details_size
參數(shù)說明：設(shè)置單語句可以收集的最大的執(zhí)行事件的大小(byte)。
該參數(shù)屬于USERSET類型參數(shù)，請參考重設(shè)參數(shù)中對應(yīng)設(shè)置方法進(jìn)行設(shè)置。
取值范圍：整型，0 ~ 576460752303423487
默認(rèn)值：4096
- track_stmt_retention_time
參數(shù)說明：組合參數(shù)，控制全量/慢SQL記錄的保留時間。以60秒為周期讀取該參數(shù)，并執(zhí)行清理超過保留時間的記錄，僅sysadmin用戶可以訪問。
該參數(shù)屬于SIGHUP類型參數(shù)，請參考重設(shè)參數(shù)中對應(yīng)設(shè)置方法進(jìn)行設(shè)置。
取值范圍：字符型
該參數(shù)分為兩部分，形式為’full sql retention time, slow sql retention time’：
full sql retention time為全量SQL保留時間，取值范圍為0 ~ 86400。
slow sql retention time為慢SQL的保留時間，取值范圍為0 ~ 604800。
默認(rèn)值：3600,604800
- track_stmt_stat_level
參數(shù)說明：控制語句執(zhí)行跟蹤的級別。
該參數(shù)屬于USERSET類型參數(shù)，請參考重設(shè)參數(shù)中對應(yīng)設(shè)置方法進(jìn)行設(shè)置，不區(qū)分英文字母大小寫，如果打開full sql功能會影響性能，并可能會占用大量的磁盤空間。
取值范圍：字符型
該參數(shù)分為兩部分，形式為’full sql stat level, slow sql stat level’：
第一部分為全量SQL跟蹤級別，取值范圍為OFF、L0、L1、L2。
第二部分為慢SQL的跟蹤級別，取值范圍為OFF、L0、L1、L2。
說明：
若全量SQL跟蹤級別值為非OFF時，當(dāng)前SQL跟蹤級別值為全量SQL和慢SQL的較高級別（L2 > L1 >L0），級別說明請參見表1。
默認(rèn)值：OFF,L0
- track_stmt_parameter
Enable to track the parameter of statements，默認(rèn)值OFF
相關(guān)函數(shù)
- statement_detail_decode(detail text, format text, pretty boolean)
描述：解析全量/慢SQL語句中的details字段的信息。
返回值類型：text
參數(shù)
detail: SQL語句產(chǎn)生的事件的集合（不可讀）。
format: 解析輸出格式，取值為plaintext。
pretty: 當(dāng)format為plaintext時，是否以優(yōu)雅的格式展示：
true表示通過“\n”分隔事件。
false表示通過“，”分隔事件。
示例，查看SQL執(zhí)行過程中鎖申請、釋放信息
select unique_query_id,statement_detail_decode(details,'plaintext',true) from statement_history where details is not null;
unique_query_id | statement_detail_decode
-----------------+----------------------------------------------------------------------------------------------------------------
3809144128 | '1' 'LOCK_START' '2022-05-18 10:16:03.309549+08' '3e44:a37:0:0:0:0' 'AccessShareLock' +
| '2' 'LOCK_END' '2022-05-18 10:16:03.309557+08' +
| '3' 'LOCK_START' '2022-05-18 10:16:03.309565+08' '3e44:a7c:0:0:0:0' 'AccessShareLock' +
| '4' 'LOCK_END' '2022-05-18 10:16:03.309566+08' +
| '5' 'LOCK_RELEASE' '2022-05-18 10:16:03.309581+08' '3e44:a7c:0:0:0:0' 'AccessShareLock' +
| '6' 'LOCK_RELEASE' '2022-05-18 10:16:03.309581+08' '3e44:a37:0:0:0:0' 'AccessShareLock' +
| '7' 'LOCK_START' '2022-05-18 10:16:03.309588+08' '3e44:30c8:0:0:0:0' 'AccessShareLock' +
| '8' 'LOCK_END' '2022-05-18 10:16:03.309589+08' +
| '9' 'LOCK_START' '2022-05-18 10:16:03.309625+08' '3e44:21c3:0:0:0:0' 'AccessShareLock' +
| '10' 'LOCK_END' '2022-05-18 10:16:03.309625+08' +
| '11' 'LOCK_START' '2022-05-18 10:16:03.309629+08' '3e44:21cc:0:0:0:0' 'AccessShareLock' +
| '12' 'LOCK_END' '2022-05-18 10:16:03.309629+08' +
| '13' 'LOCK_RELEASE' '2022-05-18 10:16:03.309637+08' '3e44:21cc:0:0:0:0' 'AccessShareLock' +
| '14' 'LOCK_RELEASE' '2022-05-18 10:16:03.309638+08' '3e44:21c3:0:0:0:0' 'AccessShareLock' +
| '15' 'LOCK_START' '2022-05-18 10:16:03.309676+08' '0:2337:0:0:0:0' 'AccessShareLock' +
| '16' 'LOCK_END' '2022-05-18 10:16:03.309676+08' +
| '17' 'LOCK_START' '2022-05-18 10:16:03.30968+08' '0:2340:0:0:0:0' 'AccessShareLock' +
| '18' 'LOCK_END' '2022-05-18 10:16:03.30968+08' +
| '19' 'LOCK_RELEASE' '2022-05-18 10:16:03.309691+08' '0:2340:0:0:0:0' 'AccessShareLock' +
| '20' 'LOCK_RELEASE' '2022-05-18 10:16:03.309691+08' '0:2337:0:0:0:0' 'AccessShareLock' +
| '21' 'LOCK_START' '2022-05-18 10:16:03.309707+08' '3e44:30c8:0:0:0:0' 'AccessShareLock' +
| '22' 'LOCK_END' '2022-05-18 10:16:03.309708+08' +
| '23' 'LOCK_START' '2022-05-18 10:16:03.309708+08' '3e44:30c8:0:0:0:0' 'AccessShareLock' +
| '24' 'LOCK_END' '2022-05-18 10:16:03.309708+08' +
| '25' 'LOCK_RELEASE' '2022-05-18 10:16:03.311669+08' '3e44:30c8:0:0:0:0' 'AccessShareLock'
2893388431 | '1' 'LOCK_START' '2022-05-18 10:16:13.312375+08' '0:4ec:0:0:0:0' 'AccessShareLock' +
| '2' 'LOCK_END' '2022-05-18 10:16:13.31239+08' +
| '3' 'LOCK_RELEASE' '2022-05-18 10:16:13.312412+08' '0:4ec:0:0:0:0' 'AccessShareLock'
2490934982 | '1' 'LOCK_START' '2022-05-18 10:16:26.869224+08' '0:4ec:0:0:0:0' 'AccessShareLock'
常見問題
1、占用多少內(nèi)存
跑一下benchmarksql，測一下能會記錄多少SQL，及內(nèi)存占用情況
參數(shù)
track_stmt_stat_level | L0,L2
MogDB=# select is_slow_sql,count(*),min(start_time),min(finish_time),max(now()) now from statement_history group by is_slow_sql;
is_slow_sql | count | min | min | now
-------------+--------+-------------------------------+-------------------------------+-------------------------------
t | 5 | 2022-05-18 09:54:21.865765+08 | 2022-05-18 09:54:22.871032+08 | 2022-05-18 11:24:51.791587+08
f | 363794 | 2022-05-18 10:24:48.128899+08 | 2022-05-18 10:24:48.132055+08 | 2022-05-18 11:24:51.791587+08
(2 rows)
Time: 13947.234 ms
MogDB=# select * from global_shared_memory_detail where contextname like '%statement_history%';
node_name | contextname | level | parent | totalsize | freesize | usedsize
-----------+----------------------------+-------+-----------------------------------+-----------+----------+----------
test | statement_history_time_idx | 4 | GlobalSysDBCacheEntryMemCxt_15940 | 4096 | 272 | 3824
test | statement_history | 4 | GlobalSysDBCacheEntryMemCxt_15940 | 8432 | 112 | 8320
test | statement_history | 4 | GlobalSysDBCacheEntryMemCxt_16385 | 8432 | 112 | 8320
test | statement_history_time_idx | 4 | GlobalSysDBCacheEntryMemCxt_16385 | 4096 | 272 | 3824
(4 rows)
Time: 23.284 ms
記錄的SQL 36萬，相應(yīng)的SQL內(nèi)存區(qū)大小并沒有變化，占用的內(nèi)存很小，數(shù)據(jù)會記錄到postgres.statement_history表中
MogDB=# \dS+ statement_history
Unlogged table "pg_catalog.statement_history"
Column | Type | Modifiers | Storage | Stats target | Description
----------------------+--------------------------+-----------+----------+--------------+-------------
db_name | name | | plain | |
schema_name | name | | plain | |
origin_node | integer | | plain | |
user_name | name | | plain | |
application_name | text | | extended | |
client_addr | text | | extended | |
client_port | integer | | plain | |
unique_query_id | bigint | | plain | |
debug_query_id | bigint | | plain | |
query | text | | extended | |
start_time | timestamp with time zone | | plain | |
finish_time | timestamp with time zone | | plain | |
slow_sql_threshold | bigint | | plain | |
transaction_id | bigint | | plain | |
thread_id | bigint | | plain | |
session_id | bigint | | plain | |
n_soft_parse | bigint | | plain | |
n_hard_parse | bigint | | plain | |
query_plan | text | | extended | |
n_returned_rows | bigint | | plain | |
n_tuples_fetched | bigint | | plain | |
n_tuples_returned | bigint | | plain | |
n_tuples_inserted | bigint | | plain | |
n_tuples_updated | bigint | | plain | |
n_tuples_deleted | bigint | | plain | |
n_blocks_fetched | bigint | | plain | |
n_blocks_hit | bigint | | plain | |
db_time | bigint | | plain | |
cpu_time | bigint | | plain | |
execution_time | bigint | | plain | |
parse_time | bigint | | plain | |
plan_time | bigint | | plain | |
rewrite_time | bigint | | plain | |
pl_execution_time | bigint | | plain | |
pl_compilation_time | bigint | | plain | |
data_io_time | bigint | | plain | |
net_send_info | text | | extended | |
net_recv_info | text | | extended | |
net_stream_send_info | text | | extended | |
net_stream_recv_info | text | | extended | |
lock_count | bigint | | plain | |
lock_time | bigint | | plain | |
lock_wait_count | bigint | | plain | |
lock_wait_time | bigint | | plain | |
lock_max_count | bigint | | plain | |
lwlock_count | bigint | | plain | |
lwlock_wait_count | bigint | | plain | |
lwlock_time | bigint | | plain | |
lwlock_wait_time | bigint | | plain | |
details | bytea | | extended | |
is_slow_sql | boolean | | plain | |
trace_id | text | | extended | |
Indexes:
"statement_history_time_idx" btree (start_time, is_slow_sql) TABLESPACE pg_default
Replica Identity: NOTHING
Has OIDs: no
Options: orientation=row, compression=no
2、性能損耗
track_stmt_stat_level | L0,L2
五月 18, 2022 4:03:1Term-00, Running Average tpmTOTAL: 4663.81 Current tpmTOTAL: 153804 Memory Usage: 20MB / 35MB 16:08:14,743 [Thread-3] INFO jTPCC : Term-00, 16:08:14,744 [Thread-3] INFO jTPCC : Term-00,
16:08:14,744 [Thread-3] INFO jTPCC : Term-00, Measured tpmC (NewOrders) = 2105.31
16:08:14,744 [Thread-3] INFO jTPCC : Term-00, Measured tpmTOTAL = 4663.47
16:08:14,744 [Thread-3] INFO jTPCC : Term-00, Session Start = 2022-05-18 16:03:14
16:08:14,745 [Thread-3] INFO jTPCC : Term-00, Session End = 2022-05-18 16:08:14
16:08:14,745 [Thread-3] INFO jTPCC : Term-00, Transaction Count = 23324
track_stmt_stat_level | off,l2
五月 18, 2022 5:37:0Term-00, Running Average tpmTOTAL: 5475.29 Current tpmTOTAL: 180480 Memory Usage: 17MB / 35MB 17:42:05,837 [Thread-5] INFO jTPCC : Term-00, 17:42:05,837 [Thread-5] INFO jTPCC : Term-00,
17:42:05,838 [Thread-5] INFO jTPCC : Term-00, Measured tpmC (NewOrders) = 2476.3
17:42:05,838 [Thread-5] INFO jTPCC : Term-00, Measured tpmTOTAL = 5474.86
17:42:05,838 [Thread-5] INFO jTPCC : Term-00, Session Start = 2022-05-18 17:37:05
17:42:05,838 [Thread-5] INFO jTPCC : Term-00, Session End = 2022-05-18 17:42:05
17:42:05,838 [Thread-5] INFO jTPCC : Term-00, Transaction Count = 27381
關(guān)掉全量SQL記錄后，Running Average tpmTOTAL從4663.81提高到5475.29，tpmTOTAL提升811,性能提升17%。通過測試看到當(dāng)記錄的SQL量很大時，對性能影響較大。建議不要開啟FULL SQL，合適設(shè)置Slow SQL閥值。
3、保留多久，清理機(jī)制
保留時間受參數(shù)track_stmt_retention_time控制，經(jīng)測試，超過設(shè)置的保留時間后，舊的記錄會陸續(xù)被清理。
omm2=# show track_stmt_stat_level;
track_stmt_stat_level
-----------------------
L0,L2
(1 row)
omm2=# show track_stmt_retention_time;
track_stmt_retention_time
---------------------------
3600,604800
(1 row)
select is_slow_sql,count(*),min(start_time),min(finish_time),max(now()) now from statement_history group by is_slow_sql;
is_slow_sql | count | min | min | now
-------------+-------+-------------------------------+-------------------------------+-------------------------------
t | 1 | 2022-05-18 09:54:21.865765+08 | 2022-05-18 09:54:22.871032+08 | 2022-05-18 11:19:23.002656+08
f | 99 | 2022-05-18 10:18:40.599727+08 | 2022-05-18 10:18:40.600507+08 | 2022-05-18 11:19:23.002656+08
(2 rows)
表1 STATEMENT_HISTORY字段
參考
https://docs.mogdb.io/zh/mogdb/v2.1/STATEMENT_HISTORY
| 名稱 | 類型 | 描述 | 記錄級別 |
|---|---|---|---|
| db_name | name | 數(shù)據(jù)庫名稱。 | L0 |
| schema_name | name | schema名稱。 | L0 |
| origin_node | integer | 節(jié)點(diǎn)名稱。 | L0 |
| user_name | name | 用戶名。 | L0 |
| application_name | text | 用戶發(fā)起的請求的應(yīng)用程序名稱。 | L0 |
| client_addr | text | 用戶發(fā)起的請求的客戶端地址。 | L0 |
| client_port | integer | 用戶發(fā)起的請求的客戶端端口。 | L0 |
| unique_query_id | bigint | 歸一化SQL ID。 | L0 |
| debug_query_id | bigint | 唯一SQL ID。 | L0 |
| query | text | 歸一化SQL。 | L0 |
| start_time | timestamp with time zone | 語句啟動的時間。 | L0 |
| finish_time | timestamp with time zone | 語句結(jié)束的時間。 | L0 |
| slow_sql_threshold | bigint | 語句執(zhí)行時慢SQL的標(biāo)準(zhǔn)。 | L0 |
| transaction_id | bigint | 事務(wù)ID。 | L0 |
| thread_id | bigint | 執(zhí)行線程ID。 | L0 |
| session_id | bigint | 用戶session id。 | L0 |
| n_soft_parse | bigint | 軟解析次數(shù)，n_soft_parse + n_hard_parse可能大于n_calls，因?yàn)樽硬樵兾从嬋雗_calls。 | L0 |
| n_hard_parse | bigint | 硬解析次數(shù)，n_soft_parse + n_hard_parse可能大于n_calls，因?yàn)樽硬樵兾从嬋雗_calls。 | L0 |
| query_plan | text | 語句執(zhí)行計劃。 | L1 |
| n_returned_rows | bigint | SELECT返回的結(jié)果集行數(shù)。 | L0 |
| n_tuples_fetched | bigint | 隨機(jī)掃描行。 | L0 |
| n_tuples_returned | bigint | 順序掃描行。 | L0 |
| n_tuples_inserted | bigint | 插入行。 | L0 |
| n_tuples_updated | bigint | 更新行。 | L0 |
| n_tuples_deleted | bigint | 刪除行。 | L0 |
| n_blocks_fetched | bigint | buffer的塊訪問次數(shù)。 | L0 |
| n_blocks_hit | bigint | buffer的塊命中次數(shù)。 | L0 |
| db_time | bigint | 有效的DB時間花費(fèi)，多線程將累加（單位：微秒）。 | L0 |
| cpu_time | bigint | CPU時間（單位：微秒）。 | L0 |
| execution_time | bigint | 執(zhí)行器內(nèi)執(zhí)行時間（單位：微秒）。 | L0 |
| parse_time | bigint | SQL解析時間（單位：微秒）。 | L0 |
| plan_time | bigint | SQL生成計劃時間（單位：微秒）。 | L0 |
| rewrite_time | bigint | SQL重寫時間（單位：微秒）。 | L0 |
| pl_execution_time | bigint | plpgsql上的執(zhí)行時間（單位：微秒）。 | L0 |
| pl_compilation_time | bigint | plpgsql上的編譯時間（單位：微秒）。 | L0 |
| data_io_time | bigint | IO上的時間花費(fèi)（單位：微秒）。 | L0 |
| net_send_info | text | 通過物理連接發(fā)送消息的網(wǎng)絡(luò)狀態(tài)，包含時間（微秒）、調(diào)用次數(shù)、吞吐量（字節(jié)）。通過該字段可以分析SQL在分布式系統(tǒng)下的網(wǎng)絡(luò)開銷，單機(jī)模式下不支持該字段。例如：{“time”:xxx, “n_calls”:xxx, “size”:xxx}。 | L0 |
| net_recv_info | text | 通過物理連接接收消息的網(wǎng)絡(luò)狀態(tài)，包含時間（微秒）、調(diào)用次數(shù)、吞吐量（字節(jié)）。通過該字段可以分析SQL在分布式系統(tǒng)下的網(wǎng)絡(luò)開銷，單機(jī)模式下不支持該字段。例如：{“time”:xxx, “n_calls”:xxx, “size”:xxx}。 | L0 |
| net_stream_send_info | text | 通過邏輯連接發(fā)送消息的網(wǎng)絡(luò)狀態(tài)，包含時間（微秒）、調(diào)用次數(shù)、吞吐量（字節(jié)）。通過該字段可以分析SQL在分布式系統(tǒng)下的網(wǎng)絡(luò)開銷，單機(jī)模式下不支持該字段。例如：{“time”:xxx, “n_calls”:xxx, “size”:xxx}。 | L0 |
| net_stream_recv_info | text | 通過邏輯連接接收消息的網(wǎng)絡(luò)狀態(tài)，包含時間（微秒）、調(diào)用次數(shù)、吞吐量（字節(jié)）。通過該字段可以分析SQL在分布式系統(tǒng)下的網(wǎng)絡(luò)開銷，單機(jī)模式下不支持該字段。例如：{“time”:xxx, “n_calls”:xxx, “size”:xxx}。 | L0 |
| lock_count | bigint | 加鎖次數(shù)。 | L0 |
| lock_time | bigint | 加鎖耗時。 | L1 |
| lock_wait_count | bigint | 加鎖等待次數(shù)。 | L0 |
| lock_wait_time | bigint | 加鎖等待耗時。 | L1 |
| lock_max_count | bigint | 最大持鎖數(shù)量。 | L0 |
| lwlock_count | bigint | 輕量級加鎖次數(shù)（預(yù)留）。 | L0 |
| lwlock_wait_count | bigint | 輕量級等鎖次數(shù)。 | L0 |
| lwlock_time | bigint | 輕量級加鎖時間（預(yù)留）。 | L1 |
| lwlock_wait_time | bigint | 輕量級等鎖時間。 | L1 |
| details | bytea | 語句鎖事件的列表，該列表按時間書序記錄事件，記錄的數(shù)量受參數(shù)track_stmt_details_size的影響。 | L2 |
| 事件包括： | |||
| - 加鎖開始 | |||
| - 加鎖結(jié)束 | |||
| - 等鎖開始 | |||
| - 等鎖結(jié)束 | |||
| - 放鎖開始 | |||
| - 放鎖結(jié)束 | |||
| - 輕量級等鎖開始 | |||
| - 輕量級等鎖結(jié)束 | |||
| is_slow_sql | boolean | 該SQL是否為slow SQL。 | L0 |
「喜歡這篇文章，您的關(guān)注和贊賞是給作者最好的鼓勵」
關(guān)注作者
【版權(quán)聲明】本文為墨天輪用戶原創(chuàng)內(nèi)容，轉(zhuǎn)載時必須標(biāo)注文章的來源（墨天輪），文章鏈接，文章作者等基本信息，否則作者和墨天輪有權(quán)追究責(zé)任。如果您發(fā)現(xiàn)墨天輪中有涉嫌抄襲或者侵權(quán)的內(nèi)容，歡迎發(fā)送郵件至：contact@modb.pro進(jìn)行舉報，并提供相關(guān)證據(jù)，一經(jīng)查實(shí)，墨天輪將立刻刪除相關(guān)內(nèi)容。
