Percona 8.0.30中"show engine innodb status"導致coredump排查及分析

1. 異常崩潰

GreatSQL合併Percona-Server 8.0.30的Beta版測試中，QA報了一個crash的bug：

###########  bug list ##########
benchmarksql載入1000倉資料時，資料庫例項發生coredump。
core堆疊資訊如下：
#0  0x00007f51315a39d1 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000013258cd in handle_fatal_signal () at /src/sql/signal_handler.cc:228
#2  <signal handler called>
#3  0x0000000001339244 in mem_root_deque<Item*>::push_back () at /src/include/mem_root_deque.h:182
#4  0x0000000001364a16 in push_back () at /src/sql/parse_tree_helpers.h:126
#5  MYSQLparse(THD*, Parse_tree_root**) () at /src/sql/sql_yacc.yy:13506
#6  0x000000000103a595 in THD::sql_parser () at /src/sql/sql_class.cc:3287
#7  0x00000000010d0e37 in parse_sql () at /src/sql/sql_parse.cc:7353
#8  0x00000000010d61bd in dispatch_sql_command () at /src/sql/sql_parse.cc:5399
#9  0x00000000010d78d0 in dispatch_command () at /src/sql/sql_parse.cc:2052
#10 0x00000000010d9a12 in do_command () at /src/sql/sql_parse.cc:1424
#11 0x00000000013159f8 in handle_connection () at /src/sql/conn_handler/connection_handler_per_thread.cc:308
#12 0x00000000027db225 in pfs_spawn_thread () at /src/storage/perfschema/pfs.cc:2943
#13 0x00007f513159edd5 in start_thread () from /lib64/libpthread.so.0
#14 0x00007f512ffa9ead in clone () from /lib64/libc.so.6

core檔案在測試伺服器xxx.xxx.xxx.xxx的xxx目錄，能夠穩定復現crash。

2. 捕風捉影

2.1 資訊缺失

通常有core檔案的話定位bug不算太難。

第一時間使用GDB開啟core檔案，切到相應函式呼叫棧嘗試列印關鍵變數的資訊：

但無論嘗試任何變數，使用gdb列印時均會報：“gdb: No symbol "xxx" in current context”。

最初懷疑是GDB版本過低，安裝devtoolset-11並使用高版本GDB後問題依舊。檢查出包時的編譯記錄，發現cmake後，"CMAKE_CXX_FLAGS_RELWITHDEBINFO"後的編譯選項多了"-g1"。

CMAKE_CXX_FLAGS_RELWITHDEBINFO: -DNDEBUG -D_FORTIFY_SOURCE=2 -ffunction-sections -fdata-sections -O2 -g -DNDEBUG -g1

原因是新版本多了編譯選項“MINIMAL_RELWITHDEBINFO”，該選項在打包時自動開啟。

向打包指令碼新增"-DMINIMAL_RELWITHDEBINFO=OFF"後重新打包。經驗證，此時GDB能夠attach到新部署的資料庫例項並列印變數。

2.2 問題復現過程

• 本地編譯安裝。本地作業系統為ubuntu20.04，使用原始碼編譯安裝資料庫例項後匯入資料，未能復現crash。
• 使用新打的包在另一臺物理機部署例項並匯入資料測試，未復現crash。新部署的資料庫例項在一臺配置較高的物理機上，而出現問題的機器是一臺8 core，16G ram的虛擬機器。
• 重新在發生crash的虛擬機器上部署例項並匯入資料測試，依舊未復現crash。
• 為排除引數差異的影響：經比對修改後虛擬機器上兩例項的配置除basedir、datadir、log檔案位置、埠號等無法改為一致的外，其餘引數均相等。依舊未能復現crash。
• 在發生crash的資料庫例項上，使用新包替換可執行程式，執行匯入測試，能夠復現crash。

2.3 問題分析

經上述嘗試後，開始基於原始環境復現問題並分析core檔案中的異常記憶體資料。

• 經多次復現，每次crash的位置並不完全一致。
• 為縮小問題範圍，將benchmarksql匯入資料的woker改為1,驗證是否和多session併發寫入有關。併發度改為1後，經7-10分鐘，crash再次發生。說明問題和多執行緒併發匯入無關。

由於crash時的位置不同，選擇較早crash時的core檔案進行分析，堆疊如下（發生在parser階段）：

#0  0x00007f51315a39d1 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000013258cd in handle_fatal_signal () at /src/sql/signal_handler.cc:228
#2  <signal handler called>
#3  0x0000000001339244 in mem_root_deque<Item*>::push_back () at /src/include/mem_root_deque.h:182
#4  0x0000000001364a16 in push_back () at /src/sql/parse_tree_helpers.h:126
#5  MYSQLparse(THD*, Parse_tree_root**) () at /src/sql/sql_yacc.yy:13506
#6  0x000000000103a595 in THD::sql_parser () at /src/sql/sql_class.cc:3287
#7  0x00000000010d0e37 in parse_sql () at /src/sql/sql_parse.cc:7353
#8  0x00000000010d61bd in dispatch_sql_command () at /src/sql/sql_parse.cc:5399
#9  0x00000000010d78d0 in dispatch_command () at /src/sql/sql_parse.cc:2052
#10 0x00000000010d9a12 in do_command () at /src/sql/sql_parse.cc:1424
#11 0x00000000013159f8 in handle_connection () at /src/sql/conn_handler/connection_handler_per_thread.cc:308
#12 0x00000000027db225 in pfs_spawn_thread () at /src/storage/perfschema/pfs.cc:2943
#13 0x00007f513159edd5 in start_thread () from /lib64/libpthread.so.0
#14 0x00007f512ffa9ead in clone () from /lib64/libc.so.6

切到"#3"，列印mem_root_deque<Item*>物件的內容：

• 發現其頭部內容存在非法地址。
• 按字串格式輸出記憶體內容時，發現其尾部內容被填充了一小段"INSERT INTO bmsql_xxxx ..."。

切到"#7"，“p parser_state->m_lip->m_buf_length”輸出原始sql語句的長度，將gdb定向到log檔案，調整print element足夠大後執行“p parser_state->m_lip->m_buf”，匯出原始sql語句到log檔案。 此時可發現異常記憶體的內容為當前語句的頭部。

由於“mem_root_deque”使用的記憶體是從當前THD->mem_root分配的，基本可判斷是當前session的"thd->mem_root"分配異常。即已分配出去的記憶體被重新分配給其它物件，最終造成coredump。

3. 誤打誤撞

以上資訊還不夠準確定位問題。為進一步縮小排查範圍，嘗試將benchmarksql在load資料期間傳送的語句記錄到general_log，將general_log中的語句匯出到文字，使用文字中固定的語句嘗試觸發crash並驗證crash時間點是否一致。

重啟資料庫例項、清理並重建database、開啟general_log、啟動benchmarksql匯入。一段時間後資料庫crash，一切按預期進行。

開啟general_log，找benchmarksql對應的session時發現general_log多了部分內容，每隔幾秒執行一次。

2023-02-12T09:08:43.665421+08:00          243 Connect   greatsql@***.**.***.*** on  using TCP/IP
2023-02-12T09:08:43.666014+08:00          243 Query     SET AUTOCOMMIT = 0
2023-02-12T09:08:43.666791+08:00          243 Query     SHOW GLOBAL STATUS
2023-02-12T09:08:43.698693+08:00          243 Query     show variables
2023-02-12T09:08:43.739684+08:00          243 Query     select count(*) from information_schema.innodb_trx where now()-trx_started>10
2023-02-12T09:08:43.740640+08:00          243 Query     select count(*) from information_schema.innodb_trx where now()-trx_started>60
2023-02-12T09:08:43.741376+08:00          243 Query     select count(*) from information_schema.innodb_trx where now()-trx_started>180
2023-02-12T09:08:43.742095+08:00          243 Query     select count(*) from information_schema.innodb_trx where now()-trx_started>600
2023-02-12T09:08:43.742751+08:00          243 Query     show engine innodb status
2023-02-12T09:08:43.744324+08:00          243 Query     select round(innodb_buffer_pool_read_requests / (innodb_buffer_pool_read_requests + innodb_buffer_pool_reads) * 100,2) FROM   (SELECT max(CASE VARIABLE_NAME WHEN 'innodb_buffer_pool_read_requests' THEN VARIABLE_VALUE ELSE 0 END) AS innodb_buffer_pool_read_requests,           max(CASE VARIABLE_NAME WHEN 'innodb_buffer_pool_reads' THEN VARIABLE_VALUE ELSE 0 END) AS innodb_buffer_pool_reads    FROM performance_schema.global_status) t
2023-02-12T09:08:43.747029+08:00          243 Query     SHOW SLAVE STATUS
2023-02-12T09:08:43.758254+08:00          243 Query     SHOW WARNINGS
2023-02-12T09:08:43.759621+08:00          243 Query     show binary logs
2023-02-12T09:08:43.760013+08:00          243 Query     select count(1) from information_schema.INNODB_TRX
2023-02-12T09:08:43.760676+08:00          243 Query     select count(1) from performance_schema.DATA_LOCK_WAITS
2023-02-12T09:08:43.761246+08:00          243 Query     select count(1) from performance_schema.DATA_LOCKS
2023-02-12T09:08:43.761829+08:00          243 Query     select count(1) from information_schema.tables where engine='MEMORY'
2023-02-12T09:08:43.765503+08:00          243 Query     select count(1) from information_schema.tables where engine='InnoDB'
2023-02-12T09:08:43.770064+08:00          243 Query     select count(1) from information_schema.tables where engine='MyISAM'
2023-02-12T09:08:43.770126+08:00          244 Quit
2023-02-12T09:08:43.772994+08:00          243 Query     select count(1) from information_schema.tables where engine='CSV'
2023-02-12T09:08:43.775934+08:00          243 Query     select count(1) from information_schema.tables where engine='PERFORMANCE_SCHEMA'
2023-02-12T09:08:43.783303+08:00          243 Query     show variables like '%semi%'
2023-02-12T09:08:43.787773+08:00          243 Query     show status like '%semi%'
2023-02-12T09:08:43.790204+08:00          243 Query     select rgms.COUNT_TRANSACTIONS_IN_QUEUE  from performance_schema.replication_group_members rgm ,performance_schema.replication_group_member_stats rgms where rgm.CHANNEL_NAME=rgms.CHANNEL_NAME and rgm.MEMBER_ID=rgms.MEMBER_ID and rgm.MEMBER_HOST='***.**.***.***' and rgm.MEMBER_PORT='1957'
2023-02-12T09:08:43.790947+08:00          243 Query     select MEMBER_STATE,MEMBER_ROLE from performance_schema.replication_group_members where MEMBER_HOST='***.**.***.***' and MEMBER_PORT='1957'
2023-02-12T09:08:43.794132+08:00          243 Query     select max( if(LAST_APPLIED_TRANSACTION <>'', timestampdiff(MICROSECOND,LAST_APPLIED_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP,LAST_APPLIED_TRANSACTION_END_APPLY_TIMESTAMP) div 1000,0)) 'max_worker_latency' from performance_schema.replication_applier_status_by_worker where SERVICE_STATE='ON' and CHANNEL_NAME='group_replication_applier'
2023-02-12T09:08:43.794800+08:00          243 Query     select max(count_transactions_remote_in_applier_queue) from performance_schema.replication_group_member_stats
2023-02-12T09:08:43.795266+08:00          243 Quit

看到多的這部分內容，心裡一震，原來QA部署的資料庫例項會被平臺納管。 莫非是這些語句導致benchmarksql匯入資料時crash？

4. 真相大白

寫了個簡單指令碼，迴圈向資料庫例項傳送指定檔案中的sql語句

file repeat_sql_file.sh:

#!/bin/bash
for ((i=1;i<=1000000000;i++)) ;
do
  usleep 100
  greatsql -h***.**.***.*** -ugreatsql -p123456 -P1957 < $1
done

再將general log中的語句取出到檔案monit.sql，執行命令"file repeat_sql_file.sh  monit.sql"。然後啟動benchmarksql匯入資料。

僅僅過了15秒，資料庫例項crash。

接下來要找到肇事sql。採用二分查詢法先註釋一半內容逐步驗證，重複幾次後將肇事語句鎖定到了DBA最常用的一條語句：

show engine innodb status;

下載Percona-8.0.30官方原始碼並按上述步驟編譯安裝部署後，重現了crash！

繼續驗證MySQL官方的8.0.30，發現該crash沒有觸發。

5. Release notes review

既然已明確是Percona-Server的bug，那就先到MySQL和Percona官網看新版本release note有沒有和"show engine innodb status"相關的bugfix。

首先是Percona-8.0.31，未看到相關bugfix說明，只看到一個從庫crash的bugfix。

（）

但release notes list中看到多了一個8.0.30-update：其中有一個bugfix涉及到"show engine innodb status"

（）

6. 原始碼分析

定位Percona 8.0.30 PS-8351相關patch，可看到Percona修改了一些程式碼，而這部分程式碼在MySQL 8.0.30上是未被修改的：

430 char *thd_security_context(MYSQL_THD thd, char *buffer, size_t length,
431                            size_t max_query_len) {


487     LEX_STRING truncated_query = {nullptr, 0};  // 這裡是Percona引入的
488     if (len < thd->query().length &&
489         !thd->convert_string(&truncated_query, thd->charset(), thd->query().str,
490                              len, thd->charset())) {
491       str.append(truncated_query.str, truncated_query.length);
492     } else {
493       // In case of error or not trimming, fall back to the original behavior
494       str.append(thd->query().str, len);

........

其呼叫邏輯為：

| > innodb_show_status
| | > srv_printf_innodb_monitor
| | | > srv_printf_locks_and_transactions
| | | | > lock_print_info_all_transactions
| | | | | > lock_trx_print_wait_and_mvcc_state
| | | | | | > trx_print_latched
| | | | | | | > trx_print_low
| | | | | | | | > innobase_mysql_print_thd
| | | | | | | | | > thd_security_context  // MySQL原始程式碼不會呼叫convert_string
| | | | | | | | | | > THD::convert_string

而在trx_print_low中：很明顯作為引數傳遞下去的"trx->mysql_thd"歸屬於例項中其它活躍的session，而不是歸屬於當前執行"show engine innodb status"的session

void trx_print_low() {
  .....
  if (trx_state != TRX_STATE_NOT_STARTED && trx->mysql_thd != nullptr) {
    innobase_mysql_print_thd(f, trx->mysql_thd,
                             static_cast<uint>(max_query_len));
  }
}

繼續看convert_string：執行"show engine innodb status"的session使用了其它session的mem_root開闢了記憶體空間。

bool THD::convert_string(）{
  size_t new_length = to_cs->mbmaxlen * from_length;
  if (!(to->str = (char *)alloc(new_length + 1))) {
    to->length = 0;  // Safety fix
    return true;     // EOM
  }
  ......
}

// alloc實際呼叫的是THD的父類成員函式Query_arena::alloc(),程式碼為
class Query_arena {
  ....
    void *alloc(size_t size) { return mem_root->Alloc(size); }
  ....
};

因此，一旦“thd->convert_string()”使用thd->memroot申請記憶體，就會出現兩個執行緒併發操作thd->memroot。由於對同一mem_root的操作不是執行緒安全的，兩個執行緒分配的記憶體空間可能存在重疊。

隨著"show engine innodb status"執行緒的執行，重疊記憶體區域的內容可能會被填上部分原始sql語句。回顧上文中列印mem_root_deque<Item*>物件的記憶體內容，其尾部也確實包含了原始sql語句的開頭。

7. 總結

• 排查問題時儘量規避外界的影響。
• 如果生產系統使用了Percona-8.0.30，請慎用"show engine innodb status"。

目前MySQL-8.0.32版本的release note中已有相關的patch：

（）

從commit資訊看，該commit來自Percona。

Truncating a message at a fixed length might leave
a partial UTF-8 character at the end of a truncated message.
This patch makes sure, that a truncation doesn't result
in such a "garbled" character.

Patch is based on contribution from Iwo Panowicz <iwo.panowicz@percona.com>
Thanks to Iwo and Percona for this patch.

Change-Id: I5f8e6dce28608f432fbb4b77220e1a21049f510f

解決了show engine innodb status亂碼問題的同時，不再使用“convert_string()”。