SHOW INNODB STATUSのソースコード
提供：MySQL Practice Wiki
目次 |
概要
SHOW INNODB STATUSはINNODBに関する統計情報を出力するコマンドである。また、デッドロックや外部キーに関するエラー情報も含んでいるので、パフォーマンスチューニングやトラブルシューティングに非常に役立つ。マニュアルは次の通りである。
しかしマニュアルにはあまり詳しい記載がないので、各セクションの意味は、MySQL Performance Blogの以下の記事を見ると分かりやすい。
- SHOW INNODB STATUS walk through
- http://www.mysqlperformanceblog.com/2006/07/17/show-innodb-status-walk-through/
SHOW INNODB STATUSは統計情報にアクセスするためにmutex lockをとらなければいけないので、運が悪ければ高負荷時などには時間がかかってしまう。
SHOW INNODB STATUSの構造
SHOW INNODB STATUSのソースコードを参照すること。
各セクションの意味
以下、DBT-2で負荷をかけたときの値を元に解説する・・・予定。
SEMAPHORES
<highlightSyntax language="mysql">---------- SEMAPHORES
OS WAIT ARRAY INFO: reservation count 79443, signal count 33500 --Thread 1101830480 has waited at ../../storage/innobase/include/log0log.ic line 311 for 0.00 seconds the semaphore: Mutex at 0x7faa8409c910 created file log/log0log.c line 738, lock var 1 waiters flag 1 --Thread 1101027664 has waited at ../../storage/innobase/include/log0log.ic line 311 for 0.00 seconds the semaphore: Mutex at 0x7faa8409c910 created file log/log0log.c line 738, lock var 1 waiters flag 1 --Thread 1101228368 has waited at ../../storage/innobase/include/log0log.ic line 311 for 0.00 seconds the semaphore: Mutex at 0x7faa8409c910 created file log/log0log.c line 738, lock var 1 waiters flag 1 --Thread 1099823440 has waited at ../../storage/innobase/include/log0log.ic line 311 for 0.00 seconds the semaphore: Mutex at 0x7faa8409c910 created file log/log0log.c line 738, lock var 1 waiters flag 1 --Thread 1081821520 has waited at ../../storage/innobase/include/log0log.ic line 311 for 0.00 seconds the semaphore: Mutex at 0x7faa8409c910 created file log/log0log.c line 738, lock var 1 waiters flag 1 --Thread 1100224848 has waited at ../../storage/innobase/include/log0log.ic line 311 for 0.00 seconds the semaphore: Mutex at 0x7faa8409c910 created file log/log0log.c line 738, lock var 1 waiters flag 1 --Thread 1195628880 has waited at ../../storage/innobase/include/log0log.ic line 311 for 0.00 seconds the semaphore: Mutex at 0x7faa8409c910 created file log/log0log.c line 738, lock var 1 waiters flag 1 --Thread 1195227472 has waited at ../../storage/innobase/include/log0log.ic line 311 for 0.00 seconds the semaphore: Mutex at 0x7faa8409c910 created file log/log0log.c line 738, lock var 1 waiters flag 1 Mutex spin waits 0, rounds 2498609, OS waits 61942 RW-shared spins 20574, OS waits 8720; RW-excl spins 17618, OS waits 8037 </highlightSyntax>
TRANSACTIONS
<highlightSyntax language="mysql">------------ TRANSACTIONS
Trx id counter 0 3638489 Purge done for trx's n:o < 0 3637621 undo n:o < 0 0 History list length 417 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 0 0, not started, process no 5387, OS thread id 1195026768 MySQL thread id 2, query id 1083823 localhost 127.0.0.1 mikiya show innodb status ---TRANSACTION 0 0, not started, process no 5387, OS thread id 1099622736 MySQL thread id 1, query id 931536 localhost 127.0.0.1 mikiya ---TRANSACTION 0 3638487, ACTIVE 0 sec, process no 5387, OS thread id 1101830480 mysql tables in use 1, locked 1 2 lock struct(s), heap size 368, 1 row lock(s), undo log entries 1 MySQL thread id 17, query id 1083777 localhost 127.0.0.1 mikiya freeing items UPDATE warehouse SET w_ytd = w_ytd + 3942.110107 WHERE w_id = 4 Trx read view will not see trx with id >= 0 3638488, sees < 0 3638365 ---TRANSACTION 0 3638485, ACTIVE 0 sec, process no 5387, OS thread id 1195428176 waiting in InnoDB queue mysql tables in use 1, locked 1 MySQL thread id 11, query id 1083819 localhost 127.0.0.1 mikiya updating DELETE FROM new_order WHERE no_o_id = 3085
AND no_w_id = 3 AND no_d_id = 1
Trx read view will not see trx with id >= 0 3638486, sees < 0 3638365 ---TRANSACTION 0 3638483, COMMITTED IN MEMORY, process no 5387, OS thread id 1100826960 committing , undo log entries 4 MySQL thread id 9, query id 1083794 localhost 127.0.0.1 mikiya COMMIT ---TRANSACTION 0 3638481, ACTIVE 0 sec, process no 5387, OS thread id 1100024144 starting index read mysql tables in use 1, locked 1 LOCK WAIT 4 lock struct(s), heap size 1216, 2 row lock(s), undo log entries 1 MySQL thread id 4, query id 1083717 localhost 127.0.0.1 mikiya Updating UPDATE district SET d_ytd = d_ytd + 1305.660034 WHERE d_id = 9
AND d_w_id = 5
Trx read view will not see trx with id >= 0 3638482, sees < 0 3638365
TRX HAS BEEN WAITING 0 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 294931 n bits 120 index `PRIMARY` of table `dbt2`.`district` trx id 0 3638481 lock_mode X locks rec but not gap waiting Record lock, heap no 50 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
0: len 4; hex 80000005; asc ;; 1: len 4; hex 80000009; asc ;; 2: len 6; hex 0000003784c2; asc 7 ;; 3: len 7; hex 00000100250bfb; asc % ;; 4: len 8; hex ebdf40ee5467f263; asc @ Tg c;; 5: len 14; hex 77ed5e766f55ee60e25a4d7ee5f7; asc w ^voU ` ZM~ ;; 6: len 12; hex 68355cdcea35f471e92d603e; asc h5\ 5 q -`>;; 7: len 17; hex 4b77f1fc65516b297b5a675ee7ee3370de; asc Kw eQk){Zg^ 3p ;; 8: len 2; hex 5a5a; asc ZZ;; 9: len 9; hex 313839313131313131; asc 189111111;; 10: len 8; hex d42b6519e258973f; asc +e X ?;; 11: len 12; hex 8000003760d60697a7100000; asc 7` ;; 12: len 4; hex 80001189; asc ;;
---TRANSACTION 0 3638480, ACTIVE 0 sec, process no 5387, OS thread id 1101027664 inserting, thread declared inside InnoDB 500 mysql tables in use 1, locked 1 8 lock struct(s), heap size 1216, 3 row lock(s), undo log entries 6 MySQL thread id 10, query id 1083814 localhost 127.0.0.1 mikiya update INSERT INTO order_line (ol_o_id, ol_d_id, ol_w_id, ol_number,
ol_i_id, ol_supply_w_id, ol_delivery_d,
ol_quantity, ol_amount, ol_dist_info)
VALUES (4444, 4, 2, 2, 49072, 2, NULL, 4, 250.559998, 'lkfUNMWmNAWWbqjTDMZIWiXm') Trx read view will not see trx with id >= 0 3638481, sees < 0 3638365 ---TRANSACTION 0 3638478, ACTIVE 0 sec, process no 5387, OS thread id 1101228368 updating or deleting, thread declared inside InnoDB 499 mysql tables in use 1, locked 1 9 lock struct(s), heap size 1216, 4 row lock(s), undo log entries 7 MySQL thread id 14, query id 1083812 localhost 127.0.0.1 mikiya Updating UPDATE stock SET s_quantity = s_quantity - 10 WHERE s_i_id = 46592
AND s_w_id = 4
Trx read view will not see trx with id >= 0 3638479, sees < 0 3638365 ---TRANSACTION 0 3638477, ACTIVE 0 sec, process no 5387, OS thread id 1076418896 waiting in InnoDB queue mysql tables in use 1, locked 0 9 lock struct(s), heap size 1216, 4 row lock(s), undo log entries 9 MySQL thread id 18, query id 1083821 localhost 127.0.0.1 mikiya statistics SELECT s_quantity, s_dist_08, s_data FROM stock WHERE s_i_id = 40816
AND s_w_id = 3
Trx read view will not see trx with id >= 0 3638478, sees < 0 3638365 ---TRANSACTION 0 3638468, ACTIVE 0 sec, process no 5387, OS thread id 1100224848 inserting, thread declared inside InnoDB 500 mysql tables in use 1, locked 1 14 lock struct(s), heap size 3024, 9 row lock(s), undo log entries 18 MySQL thread id 5, query id 1083813 localhost 127.0.0.1 mikiya update INSERT INTO order_line (ol_o_id, ol_d_id, ol_w_id, ol_number,
ol_i_id, ol_supply_w_id, ol_delivery_d,
ol_quantity, ol_amount, ol_dist_info)
VALUES (4458, 1, 4, 8, 53166, 4, NULL, 1, 17.480000, 'pwjkTDogRabTQAaUZpEjwCUw') Trx read view will not see trx with id >= 0 3638469, sees < 0 3638365 ---TRANSACTION 0 3638466, ACTIVE 0 sec, process no 5387, OS thread id 1099823440 updating or deleting, thread declared inside InnoDB 499 mysql tables in use 1, locked 1 15 lock struct(s), heap size 3024, 10 row lock(s), undo log entries 19 MySQL thread id 3, query id 1083810 localhost 127.0.0.1 mikiya Updating UPDATE stock SET s_quantity = s_quantity - 2 WHERE s_i_id = 30512
AND s_w_id = 5
Trx read view will not see trx with id >= 0 3638467, sees < 0 3638365 ---TRANSACTION 0 3638464, ACTIVE 0 sec, process no 5387, OS thread id 1081821520 updating or deleting, thread declared inside InnoDB 499 mysql tables in use 1, locked 1 9 lock struct(s), heap size 1216, 4 row lock(s), undo log entries 7 MySQL thread id 12, query id 1083811 localhost 127.0.0.1 mikiya Updating UPDATE stock SET s_quantity = s_quantity - 1 WHERE s_i_id = 7928
AND s_w_id = 1
Trx read view will not see trx with id >= 0 3638465, sees < 0 3638365 ---TRANSACTION 0 3638458, ACTIVE 0 sec, process no 5387, OS thread id 1101629776 waiting in InnoDB queue mysql tables in use 1, locked 0 13 lock struct(s), heap size 3024, 8 row lock(s), undo log entries 17 MySQL thread id 16, query id 1083816 localhost 127.0.0.1 mikiya statistics SELECT s_quantity, s_dist_07, s_data FROM stock WHERE s_i_id = 3455
AND s_w_id = 3
Trx read view will not see trx with id >= 0 3638459, sees < 0 3638365 ---TRANSACTION 0 3638455, ACTIVE 0 sec, process no 5387, OS thread id 1101429072 starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s) MySQL thread id 15, query id 1083221 localhost 127.0.0.1 mikiya statistics SELECT d_tax, d_next_o_id FROM district WHERE d_w_id = 3
AND d_id = 7
FOR UPDATE Trx read view will not see trx with id >= 0 3638456, sees < 0 3638365
TRX HAS BEEN WAITING 0 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 294931 n bits 120 index `PRIMARY` of table `dbt2`.`district` trx id 0 3638455 lock_mode X locks rec but not gap waiting Record lock, heap no 28 PHYSICAL RECORD: n_fields 13; compact format; info bits 0
0: len 4; hex 80000003; asc ;; 1: len 4; hex 80000007; asc ;; 2: len 6; hex 0000003784ba; asc 7 ;; 3: len 7; hex 00000100280d24; asc ( $;; 4: len 9; hex 7b5c39f144e4e87e6c; asc {\9 D ~l;; 5: len 17; hex 2162e5ea473b33e7ea2757f42ee05625de; asc !b G;3 'W . V% ;; 6: len 19; hex e8e65d5d3b6b4755483031ef34314af6f16e32; asc ]];kGUH01 41J n2;; 7: len 10; hex 4efa297aef355c3e313b; asc N )z 5\>1;;; 8: len 2; hex 4c51; asc LQ;; 9: len 9; hex 303933303131313131; asc 093011111;; 10: len 8; hex 174850fc1873c73f; asc HP s ?;; 11: len 12; hex 8000003af79a0ad3fce80000; asc : ;; 12: len 4; hex 800011b2; asc ;;
---TRANSACTION 0 3638417, ACTIVE 0 sec, process no 5387, OS thread id 1195227472 updating or deleting, thread declared inside InnoDB 499 mysql tables in use 1, locked 1 39 lock struct(s), heap size 6752, 111 row lock(s), undo log entries 103 MySQL thread id 6, query id 1083817 localhost 127.0.0.1 mikiya Updating UPDATE customer SET c_delivery_cnt = c_delivery_cnt + 1,
c_balance = c_balance + 6863.970039
WHERE c_id = 591
AND c_w_id = 5 AND c_d_id = 7
Trx read view will not see trx with id >= 0 3638418, sees < 0 3638327 ---TRANSACTION 0 3638408, ACTIVE 0 sec, process no 5387, OS thread id 1195628880 updating or deleting, thread declared inside InnoDB 499 mysql tables in use 1, locked 1 41 lock struct(s), heap size 6752, 101 row lock(s), undo log entries 93 MySQL thread id 13, query id 1083818 localhost 127.0.0.1 mikiya Updating UPDATE orders SET o_carrier_id = 5 WHERE o_id = 3117
AND o_w_id = 1 AND o_d_id = 8
Trx read view will not see trx with id >= 0 3638409, sees < 0 3638327 ---TRANSACTION 0 3638386, ACTIVE 1 sec, process no 5387, OS thread id 1100626256 waiting in InnoDB queue mysql tables in use 1, locked 1 48 lock struct(s), heap size 6752, 125 row lock(s), undo log entries 116 MySQL thread id 8, query id 1083822 localhost 127.0.0.1 mikiya Updating UPDATE customer SET c_delivery_cnt = c_delivery_cnt + 1,
c_balance = c_balance + 19234.820174
WHERE c_id = 2016
AND c_w_id = 2 AND c_d_id = 9
Trx read view will not see trx with id >= 0 3638387, sees < 0 3638325 ---TRANSACTION 0 3638365, ACTIVE 1 sec, process no 5387, OS thread id 1100425552 waiting in InnoDB queue mysql tables in use 1, locked 0 25 lock struct(s), heap size 3024, 61 row lock(s), undo log entries 52 MySQL thread id 7, query id 1083820 localhost 127.0.0.1 mikiya Sending data SELECT no_o_id FROM new_order WHERE no_w_id = 4
AND no_d_id = 5
Trx read view will not see trx with id >= 0 3638366, sees < 0 3638325 </highlightSyntax>
FILE I/O
<highlightSyntax language="mysql">-------- FILE I/O
I/O thread 0 state: waiting for i/o request (insert buffer thread) I/O thread 1 state: waiting for i/o request (log thread) I/O thread 2 state: waiting for i/o request (read thread) I/O thread 3 state: waiting for i/o request (write thread) Pending normal aio reads: 0, aio writes: 0,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 1; buffer pool: 0 18735 OS file reads, 69904 OS file writes, 69622 OS fsyncs 6.49 reads/s, 20259 avg bytes/read, 229.16 writes/s, 228.67 fsyncs/s </highlightSyntax>
INSERT BUFFER AND ADAPTIVE HASH INDEX
<highlightSyntax language="mysql">------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX
Ibuf: size 1, free list len 12, seg size 14, 1817 inserts, 1817 merged recs, 313 merges Hash table size 8850487, node heap has 769 buffer(s) 3184.23 hash searches/s, 2269.71 non-hash searches/s </highlightSyntax>
LOG
<highlightSyntax language="mysql">--- LOG --- Log sequence number 3 2915926002 Log flushed up to 3 2915924694 Last checkpoint at 3 2811099332 1 pending log writes, 0 pending chkp writes 69569 log i/o's done, 228.48 log i/o's/second </highlightSyntax>
BUFFER POOL AND MEMORY
<highlightSyntax language="mysql">---------------------- BUFFER POOL AND MEMORY
Total memory allocated 4736740512; in additional pool allocated 1031424 Dictionary memory allocated 72520 Buffer pool size 262144 Free buffers 237193 Database pages 24182 Modified db pages 19142 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages read 22717, created 1465, written 1621 8.02 reads/s, 3.98 creates/s, 4.23 writes/s Buffer pool hit rate 1000 / 1000 </highlightSyntax>
ROW OPERATIONS
<highlightSyntax language="mysql">-------------- ROW OPERATIONS
8 queries inside InnoDB, 4 queries in queue 16 read views open inside InnoDB Main thread process no. 5387, id 1152862544, state: sleeping Number of rows inserted 226953, updated 420516, deleted 10784, read 21325433 747.19 inserts/s, 1389.57 updates/s, 32.95 deletes/s, 70644.05 reads/s </highlightSyntax>
ソースコードの箇所
SHOW INNODB STATUSが実行されると・・・
sql/sql_parse.cc
まず、mysql_execute_command()においてからinnodb_show_status()が呼び出される。（SHOW INNODB STATUSはSQLCOM_SHOW_INNODB_STATUSに該当する）
sql/ha_innodb.cc
innodb_show_status()は種々の処理をするが、出力する情報を作成している実体はsrv_printf_innodb_monitor()関数である。
innobase/srv/srv0srv.c
srv_printf_innodb_monitor()がレポート作成のエントリポイントである。そこからさらに種々の関数が呼び出される。
実際にレポートの内容を出力する関数たち
| セクション名 | 関数 | 定義されているファイル |
|---|---|---|
| SEMAPHORES | sync_print() | sync/sync0sync.c |
| LATEST FOREIGN KEY ERROR | srv_printf_innodb_monitor()内部でベタ書き | N/A |
| LATEST DETECTED DEADLOCK | lock_print_info_summary() | lock/lock0lock.c |
| FILE I/O | os_aio_print() | os/os0file.c: |
| INSERT BUFFER AND ADAPTIVE HASH INDEX | ibuf_print()他 | ibuf/ibuf0ibuf.c他 |
| LOG | log_print() | log/log0log.c |
| BUFFER POOL AND MEMORY | buf_print_io()他 | buf/buf0buf.c |
| ROW OPERATIONS | srv_printf_innodb_monitor()内部でベタ書き | N/A |
統計情報のリフレッシュ
各種統計情報は毎秒リフレッシュ（ゼロクリア）される。これを行っているのはsrv/srv0srv.c - srv_refresh_innodb_monitor_stats()である。
ソースコード抜粋
void
srv_printf_innodb_monitor(
/*======================*/
FILE* file, /* in: output stream */
ulint* trx_start, /* out: file position of the start of
the list of active transactions */
ulint* trx_end) /* out: file position of the end of
the list of active transactions */
{
double time_elapsed;
time_t current_time;
ulint n_reserved;
mutex_enter(&srv_innodb_monitor_mutex);
current_time = time(NULL);
/* We add 0.001 seconds to time_elapsed to prevent division
by zero if two users happen to call SHOW INNODB STATUS at the same
time */
time_elapsed = difftime(current_time, srv_last_monitor_time)
+ 0.001;
srv_last_monitor_time = time(NULL);
fputs("\n=====================================\n", file);
ut_print_timestamp(file);
fprintf(file,
" INNODB MONITOR OUTPUT\n"
"=====================================\n"
"Per second averages calculated from the last %lu seconds\n",
(ulong)time_elapsed);
fputs("----------\n"
"SEMAPHORES\n"
"----------\n", file);
sync_print(file);
/* Conceptually, srv_innodb_monitor_mutex has a very high latching
order level in sync0sync.h, while dict_foreign_err_mutex has a very
low level 135. Therefore we can reserve the latter mutex here without
a danger of a deadlock of threads. */
mutex_enter(&dict_foreign_err_mutex);
if (ftell(dict_foreign_err_file) != 0L) {
fputs("------------------------\n"
"LATEST FOREIGN KEY ERROR\n"
"------------------------\n", file);
ut_copy_file(file, dict_foreign_err_file);
}
mutex_exit(&dict_foreign_err_mutex);
lock_print_info_summary(file);
if (trx_start) {
long t = ftell(file);
if (t < 0) {
*trx_start = ULINT_UNDEFINED;
} else {
*trx_start = (ulint) t;
}
}
lock_print_info_all_transactions(file);
if (trx_end) {
long t = ftell(file);
if (t < 0) {
*trx_end = ULINT_UNDEFINED;
} else {
*trx_end = (ulint) t;
}
}
fputs("--------\n"
"FILE I/O\n"
"--------\n", file);
os_aio_print(file);
fputs("-------------------------------------\n"
"INSERT BUFFER AND ADAPTIVE HASH INDEX\n"
"-------------------------------------\n", file);
ibuf_print(file);
ha_print_info(file, btr_search_sys->hash_index);
fprintf(file,
"%.2f hash searches/s, %.2f non-hash searches/s\n",
(btr_cur_n_sea - btr_cur_n_sea_old)
/ time_elapsed,
(btr_cur_n_non_sea - btr_cur_n_non_sea_old)
/ time_elapsed);
btr_cur_n_sea_old = btr_cur_n_sea;
btr_cur_n_non_sea_old = btr_cur_n_non_sea;
fputs("---\n"
"LOG\n"
"---\n", file);
log_print(file);
fputs("----------------------\n"
"BUFFER POOL AND MEMORY\n"
"----------------------\n", file);
fprintf(file,
"Total memory allocated " ULINTPF
"; in additional pool allocated " ULINTPF "\n",
ut_total_allocated_memory,
mem_pool_get_reserved(mem_comm_pool));
if (srv_use_awe) {
fprintf(file,
"In addition to that %lu MB of AWE memory allocated\n",
(ulong) (srv_pool_size / ((1024 * 1024) / UNIV_PAGE_SIZE)));
}
buf_print_io(file);
fputs("--------------\n"
"ROW OPERATIONS\n"
"--------------\n", file);
fprintf(file, "%ld queries inside InnoDB, %lu queries in queue\n",
(long) srv_conc_n_threads,
(ulong) srv_conc_n_waiting_threads);
fprintf(file, "%lu read views open inside InnoDB\n",
UT_LIST_GET_LEN(trx_sys->view_list));
n_reserved = fil_space_get_n_reserved_extents(0);
if (n_reserved > 0) {
fprintf(file,
"%lu tablespace extents now reserved for B-tree split operations\n",
(ulong) n_reserved);
}
#ifdef UNIV_LINUX
fprintf(file, "Main thread process no. %lu, id %lu, state: %s\n",
(ulong) srv_main_thread_process_no,
(ulong) srv_main_thread_id,
srv_main_thread_op_info);
#else
fprintf(file, "Main thread id %lu, state: %s\n",
(ulong) srv_main_thread_id,
srv_main_thread_op_info);
#endif
fprintf(file,
"Number of rows inserted " ULINTPF
", updated " ULINTPF ", deleted " ULINTPF ", read " ULINTPF "\n",
srv_n_rows_inserted,
srv_n_rows_updated,
srv_n_rows_deleted,
srv_n_rows_read);
fprintf(file,
"%.2f inserts/s, %.2f updates/s, %.2f deletes/s, %.2f reads/s\n",
(srv_n_rows_inserted - srv_n_rows_inserted_old)
/ time_elapsed,
(srv_n_rows_updated - srv_n_rows_updated_old)
/ time_elapsed,
(srv_n_rows_deleted - srv_n_rows_deleted_old)
/ time_elapsed,
(srv_n_rows_read - srv_n_rows_read_old)
/ time_elapsed);
srv_n_rows_inserted_old = srv_n_rows_inserted;
srv_n_rows_updated_old = srv_n_rows_updated;
srv_n_rows_deleted_old = srv_n_rows_deleted;
srv_n_rows_read_old = srv_n_rows_read;
fputs("----------------------------\n"
"END OF INNODB MONITOR OUTPUT\n"
"============================\n", file);
mutex_exit(&srv_innodb_monitor_mutex);
fflush(file);
}
