[go: up one dir, main page]
More Web Proxy on the site http://driver.im/

GA

ラベル ytkit の投稿を表示しています。 すべての投稿を表示
ラベル ytkit の投稿を表示しています。 すべての投稿を表示

2021/03/28

ぼくがかんがえたさいきょうのMySQL監視スクリプトのはなし

PHPerKaigi 2021 でトークしてきた話です。

これは yt-healthcheck の話で、ウチの環境ではこれを5分に1回、crondからキックしています。

喋っていた他にもいくつかひねりがあって、でも再集録の時間が取れなくて断念したネタもあります。


セッションのあと、Ask The Speakerで話しかけてくださったみなさまありがとうございました!
いつもこういう時ぼっちになるので助かりました!

Q. 「RDSではread_onlyの監視は要らない」って言ってたけどそれは何故?
A. RDSはRDSの基盤側で勝手にread_onlyを切り替えてユーザー側では指定できないので監視する必要はないのです

Q. SHOW ENGINE INNODB STATUS をもっと統一しようみたいな動きはないの?
A. アレは「InnoDBチームが自分たちのために出している出力」みたいなところがあるので、エンドユーザーが使っていることは知っていてもそういう流れにはならなさそう。一つの別解がMySQL 5.6から使える information_schema.innodb_metrics なんだと思う

Q. コネクション監視の閾値ってどれくらい?
A. デフォルトで70%がワーニングになってますけど、これ「そもそも平常状態のピーク * 2 = max_connection 」で普段設定していて、この前提の上で70%だと「想定していたピークの1.4倍くらいコネクションが来た」とか「オートスケールでコネクションプールが増えた」みたいなのが良い感じで引っ掛かります

【2021/03/29 11:31】

Q. AUTO_INCREMENTが40億行くってどういうケース?

A. 主にログ系。バッチで数か月分とか消し込みがかかっていてもAUTO_INCREMENTは巻き戻らないので、毎日100万とか1000万の単位で書き込まれると案外あふれる。あとはINSERT .. SELECT .. でバンバン連番を払い出すやつとか

2020/10/22

InnoDBのHistory list lengthの監視と原因スレッドの特定と

TL;DR
  • yt-healthckeckHistory list length ( trx_rseg_history_len ) の監視を追加した
    • --history-list-enable=1 すると有効になる(そのうちこっちをデフォルトにする…)
      • MySQL 5.6とそれ以降のみ対応、もう5.5は知らない…
    • デフォルトで10万がワーニング、50万をクリティカルにしてたんだけどあっさり食いちぎられた
      • その時の確認方法を主に

History list lengthとは(これは SHOW ENGINE INNODB STATUS の出力に載ってる用語、 information_schema.innodb_metrics 的には trx_rseg_history_len という名前で出てくる)「パージされずに残っているUNDOログレコードの数」らしく、主に「トランザクション開始したまま COMMITROLLBACKQUIT もせずに残ってるコネクション」があると増えていく。
これが伸びるのはデフォルトの REPEATABLE-READ を保証するためなので、ロックの有無には一切関係ない(ロックフリーな SELECT だけしか含まないトランザクションでも、残っている限り降り積もる)

で、まあコイツが伸びていくと無関係なテーブルでも重くなる(UNDOログがバッファプールに占める割合が増えて、バッファプールミスヒットが多くなるから?)ので、コイツを監視する機能をウチで使っている監視スクリプトである yt-healthckeck に搭載した。
SHOW ENGINE INNODB STATUS のパースとかはしたくなかったので、MySQL 5.6とそれ以降の information_schema.innodb_metrics に頼り切っている。

mysql80 15> SELECT name, subsystem, comment, count FROM information_schema.innodb_metrics WHERE name = 'trx_rseg_history_len';
+----------------------+-------------+-------------------------------------+---------+
| name                 | subsystem   | comment                             | count   |
+----------------------+-------------+-------------------------------------+---------+
| trx_rseg_history_len | transaction | Length of the TRX_RSEG_HISTORY list | 2695887 |
+----------------------+-------------+-------------------------------------+---------+
1 row in set (0.01 sec)

Nagiosコンパチな作りになっているのでこんな風に検出できる。

$ bin/yt-healthcheck -S /usr/mysql/8.0.22/data/mysql.sock  -uroot --history-list-enable=1
CRITICAL on xxxxx: trx_rseg_history_len is 2776982 (master)

$ echo $?
2

と、まあ検出するところまではどうでも良くて、ここから「History listを伸ばしているスレッドを特定して、そいつが KILL しても良さそうなものかダメっぽいか」を確認する方法を考える。

まずは information_schema.innodb_trx から長そうなトランザクションを探す。具体的には trx_started が古そうなヤーツ。
History list lengthを何らかの方法でグラフ化しているのであれば、だいたい「増え始めた時間帯」に開始されたトランザクションが残っていることが多いのではないか。

mysql80 4532569> SELECT * FROM information_schema.innodb_trx ORDER BY trx_started ASC\G
*************************** 1. row ***************************
                    trx_id: 421499581279640
                 trx_state: RUNNING
               trx_started: 2020-10-22 15:40:04
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 0
       trx_mysql_thread_id: 15
                 trx_query: NULL
       trx_operation_state: NULL
         trx_tables_in_use: 0
         trx_tables_locked: 0
          trx_lock_structs: 0
     trx_lock_memory_bytes: 1136
           trx_rows_locked: 0
         trx_rows_modified: 0
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 0
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
       trx_schedule_weight: NULL
*************************** 2. row ***************************
                    trx_id: 5909317
                 trx_state: RUNNING
               trx_started: 2020-10-22 18:45:04
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 3
       trx_mysql_thread_id: 4558875
                 trx_query: COMMIT
       trx_operation_state: NULL
         trx_tables_in_use: 0
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1136
           trx_rows_locked: 1
         trx_rows_modified: 1
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 0
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
       trx_schedule_weight: NULL
2 rows in set (0.08 sec)

ここで手に入れた trx_mysql_thread_idSHOW PROCESSLISTID になる。

mysql80 4532569> SHOW PROCESSLIST;
+---------+-----------------+-----------+--------+---------+-------+----------------------------+------------------+
| Id      | User            | Host      | db     | Command | Time  | State                      | Info             |
+---------+-----------------+-----------+--------+---------+-------+----------------------------+------------------+
|       5 | event_scheduler | localhost | NULL   | Daemon  | 95512 | Waiting on empty queue     | NULL             |
|      15 | root            | localhost | d1     | Sleep   |   745 |                            | NULL             |
| 3300152 | root            | localhost | NULL   | Sleep   |     0 |                            | NULL             |
| 4233344 | root            | localhost | d1     | Sleep   |   630 |                            | NULL             |
| 4532569 | root            | localhost | NULL   | Query   |     0 | init                       | SHOW PROCESSLIST |
| 4626846 | root            | localhost | sbtest | Query   |     0 | waiting for handler commit | COMMIT           |
+---------+-----------------+-----------+--------+---------+-------+----------------------------+------------------+
6 rows in set (0.03 sec)

SHOW PROCESSLIST だと接続元IPとポートくらいはわかる(↑は root@localhost だけど…)ので、接続元にログインしてそのポートを使っているプロセスを特定すれば、「何をしていたのか、 KILL して良いのかどうか」はある程度判断が付く鴨。

バッチとかで掴んでいるようなわかりやすい場合はこれだけで何とかなるけど、「GUIなクライアントを開いている間ずっとトランザクションを掴みっぱなしになる」みたいな時は trx_mysql_thread_idperformance_schema.threadsthread_id に変換して performance_schema.events_statements_history から引くのが良い感じだった(バージョンによっては performance_schema.setup_consumers の設定が必要)
過去に発行したクエリーが何となくわかると特定はしやすかった。
ただし、 events_statements_history は直前の10件しか保持しないので、それより前に何をしていたのかはわからない。

mysql80 4532569> SELECT * FROM performance_schema.threads WHERE processlist_id = 15\G
*************************** 1. row ***************************
          THREAD_ID: 49
               NAME: thread/sql/one_connection
               TYPE: FOREGROUND
     PROCESSLIST_ID: 15
   PROCESSLIST_USER: root
   PROCESSLIST_HOST: localhost
     PROCESSLIST_DB: d1
PROCESSLIST_COMMAND: Sleep
   PROCESSLIST_TIME: 888
  PROCESSLIST_STATE: NULL
   PROCESSLIST_INFO: NULL
   PARENT_THREAD_ID: NULL
               ROLE: NULL
       INSTRUMENTED: YES
            HISTORY: YES
    CONNECTION_TYPE: Socket
       THREAD_OS_ID: 29875
     RESOURCE_GROUP: USR_default
1 row in set (0.10 sec)

mysql80 4532569> SELECT sql_text FROM performance_schema.events_statements_history WHERE thread_id = 49 ORDER BY timer_start ASC;
+-------------------------------------------------------------------------------------------------------------------+
| sql_text                                                                                                          |
+-------------------------------------------------------------------------------------------------------------------+
| SELECT * FROM sbtest.sbtest1 WHERE id = 2                                                                         |
| SELECT * FROM sbtest.sbtest1 WHERE id = 2                                                                         |
| SELECT * FROM information_schema.innodb_buffer_page LIMIT 1                                                       |
| SELECT table_name, index_name, COUNT(*) FROM information_schema.innodb_buffer_page GROUP BY 1, 2                  |
| SELECT table_name, index_name, page_state, COUNT(*) FROM information_schema.innodb_buffer_page GROUP BY 1, 2, 3   |
| SELECT space, COUNT(*) FROM information_schema.innodb_buffer_page GROUP BY 1                                      |
| SELECT page_type, COUNT(*) FROM information_schema.innodb_buffer_page GROUP BY 1                                  |
| SELECT * FROM information_scheam.innodb_metrics WHERE name = 'trx_rseg_history_len'                               |
| SELECT * FROM information_schema.innodb_metrics WHERE name = 'trx_rseg_history_len'                               |
| SELECT name, subsystem, comment, count FROM information_schema.innodb_metrics WHERE name = 'trx_rseg_history_len' |
+-------------------------------------------------------------------------------------------------------------------+
10 rows in set (0.04 sec)

「そのトランザクションが一度でも UPDATEINSERT をしたかどうか」というだけなら、 SHOW ENGINE INNODB STATUSTRANSACTIONS セクションに undo log entries と一緒に現れるかどうかで判断できる。行を更新してコミットしていないなら、必ずUNDOログを抱えているから。

------------
TRANSACTIONS
------------
Trx id counter 6437808
Purge done for trx's n:o < 43475 undo n:o < 0 state: running but idle
History list length 3153058
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421499581282208, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421499581281352, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421499581278784, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421499581277928, not started flushing log
mysql tables in use 1, locked 1
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 6437806, ACTIVE (PREPARED) 0 sec
2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 4819118, OS thread handle 140024457672448, query id 14114909 localhost root waiting for handler commit
COMMIT

おまけ。
トランザクションを生かしたまま、他のスレッドからひたすら UPDATE sbtest.sbtest1 SET k = k + 1 WHERE id = 1 だけを突っ込み続けてHistory list lengthを270万くらいまで伸ばした時のバッファプールの様子。

mysql80 15> SELECT page_type, COUNT(*) FROM information_schema.innodb_buffer_page GROUP BY 1;
+-------------------+----------+
| page_type         | COUNT(*) |
+-------------------+----------+
| UNDO_LOG          |     5200 |
| UNKNOWN           |     1024 |
| INDEX             |     1513 |
| SYSTEM            |      384 |
| INODE             |       57 |
| EXTENT_DESCRIPTOR |        4 |
| IBUF_BITMAP       |        4 |
| FILE_SPACE_HEADER |        5 |
| TRX_SYSTEM        |        1 |
+-------------------+----------+
9 rows in set (0.12 sec)

半分以上UNDO_LOGに持っていかれてしまった…。
道理でよくミスヒットするわけだ(空っぽのテーブルに対するSELECTでも散発的に10msくらいかかる)

2020/06/16

information_schema.tables を定期的に貯めてASCIIグラフにしている

最近(でもないけど) information_schema.tables の中身を1日1回程度取得してMySQLに突っ込んでいる。

/*!80013 SET SESSION information_schema_stats_expiry = 0; */

SELECT
  table_schema AS table_schema,
  table_name AS table_name,
  table_rows AS table_rows,
  data_length AS data_length,
  index_length AS index_length,
  data_free AS data_free,
  engine AS engine,
  NOW() AS last_update
FROM
  information_schema.tables
WHERE
  table_schema NOT IN ('mysql', 'information_schema', 'performance_schema', 'sys') AND
  table_type = 'BASE TABLE'
ORDER BY
  data_length + index_length DESC;

CREATE TABLE `table_status_info` (
  `seq` bigint unsigned NOT NULL AUTO_INCREMENT,
  `ipaddr` varchar(15) NOT NULL,
  `port` smallint unsigned NOT NULL,
  `table_schema` varchar(255) NOT NULL,
  `table_name` varchar(255) NOT NULL,
  `table_rows` bigint unsigned NOT NULL,
  `data_length` bigint unsigned NOT NULL,
  `index_length` bigint unsigned NOT NULL,
  `data_free` bigint unsigned NOT NULL,
  `engine` varchar(32) NOT NULL,
  `last_update` datetime NOT NULL,
  PRIMARY KEY (`seq`),
  KEY `idx_lastupdate` (`last_update`),
  KEY `table_status_info_ibfk_1` (`ipaddr`,`port`),
  CONSTRAINT `table_status_info_ibfk_1` FOREIGN KEY (`ipaddr`, `port`) REFERENCES `instance_info` (`ipaddr`, `port`) ON DELETE CASCADE ON UPDATE CASCADE
) ENGINE=InnoDB AUTO_INCREMENT=211 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci;

INSERT INTO table_status_info 
  (ipaddr, port, data_free, data_length, engine, index_length, last_update, table_name, table_rows, table_schema) 
VALUES 
  ('localhost', '3306', '0', '143310848', 'InnoDB', '9977856', '2020-06-16 10:47:08', 'stock', '391992', 'tpcc'), 
.. 
ON DUPLICATE KEY UPDATE 
  data_free = VALUES(data_free), /* この書き方は8.0.19でdeprecated.. */
  data_length = VALUES(data_length), 
  engine = VALUES(engine), 
  index_length = VALUES(index_length), 
  last_update = VALUES(last_update), 
  table_name = VALUES(table_name), 
  table_rows = VALUES(table_rows), 
  table_schema = VALUES(table_schema);

採取自体は yt-collect を使ってやってる(というよりは、これをやるためにyt-collectを作ったのだから)

$ yt-collect -h${ipaddr} -P${port} -u${watch_user} -p${watch_password} --output=sql --sql-update | mysql -u${local_user} -S${local_socket} -p${local_password} admintool

これに いくつかのView を噛ませて、こんなSQLで対象を引っ張り出す。

WITH maybe_maintained AS (
  SELECT DISTINCT hostname, datadir, table_schema, table_name
  FROM adminview.table_status_list_analyze_90
  WHERE _diff < 0) -- 差分がマイナスになるタイミングがあるってことはたぶんお掃除バッチが仕事してる
SELECT DISTINCT
  hostname, datadir, table_schema, table_name, CAST(_first AS UNSIGNED) AS _fist, CAST(_last AS UNSIGNED) AS _last
FROM
  adminview.table_status_list_analyze_90
WHERE
  _first > 100000 AND       -- 90日くらい前の時点で10万行を超えていて
  _last > _first * 1.05 AND -- 90日くらい経って5%以上増えてる
  (hostname, datadir, table_schema, table_name) NOT IN (SELECT hostname, datadir, table_schema, table_name FROM maybe_maintained)
AND
  (ipaddr, port) NOT IN (SELECT ipaddr, port FROM admintool.slave_info) -- スレーブを除外してマスターだけチェック

set terminal dumb をおぼえて gnuplot のグラフをASCIIで出せるようになってからめっきり gnuplot 派になった(was. redashでグラフだけ作る、グラフだけExcel)

sql=$(cat << EOF
SELECT _date, table_rows
FROM adminview.table_status_list_analyze_90
WHERE (hostname, datadir, table_schema, table_name) = ('$hostname', '$datadir', '$table_schema', '$table_name')
ORDER BY _date

EOF
)

mysql -u${local_user} -S${local_socket} -p${local_password} -e "${sql}" | gnuplot -e "set terminal dumb; set xdata time; set timefmt '%Y-%m-%d'; set format y '%10.0f'; plot '< cat -' using 1:2 with lines title ''"

多少なりともお掃除がされているもの ( WITH maybe_maintained で指定してる _diff < 0 になるタイミングがあるやつ ) はこんな感じになる。

   12300000 ++---+---+----+---+----+---+----+---+----+---+----+---+----+--++
            +        *****    +        +        +        +        +        +
   12200000 ++    ***     *                                               ++
            |              **                                              |
   12100000 ++               **                                           ++
            |                  *                      *                    |
   12000000 ++                                       **                   ++
            |                   *                    * *                   |
   11900000 ++                   *                  *  *       *          ++
            |                     *                *   *       **          |
            |                     *                *    *     *  *         |
   11800000 ++                     *             **     *     *   *       ++
            |                       ***        **        *    *   *        |
   11700000 ++                         **    **          *   *     *      ++
            |                              **            *   *      *****  |
   11600000 ++                           **               * *             ++
            |                                             * *              |
   11500000 ++                                            * *             ++
            +        +        +        +        +        + *      +        +
   11400000 ++---+---+----+---+----+---+----+---+----+---+-*--+---+----+--++
          03/14    03/28    04/11    04/25    05/09    05/23    06/06    06/20

増えているにしても「消し込まれている上で増えてる」ので、必要な容量なのであろう。ということで対象からは除外。

クエリー全体で引っ掛かるのはこんな線形に増えているやつか(要らないレコードは消してね!)

   12800000 ++---+---+----+---+----+---+----+---+----+---+----+---+----**-++
            +        +        +        +        +        +        +  ***   +
   12700000 ++                                                   ****     ++
            |                                                 ***          |
   12600000 ++                                              **            ++
            |                                            ***               |
   12500000 ++                                      *****                 ++
            |                                    ***                       |
   12400000 ++                                ***                         ++
            |                              ***                             |
            |                          ****                                |
   12300000 ++                     ****                                   ++
            |                    **                                        |
   12200000 ++                ***                                         ++
            |              ***                                             |
   12100000 ++           **                                               ++
            |           *                                                  |
   12000000 ++       ***                                                  ++
            +     ***+        +        +        +        +        +        +
   11900000 ++---+---+----+---+----+---+----+---+----+---+----+---+----+--++
          03/14    03/28    04/11    04/25    05/09    05/23    06/06    06/20

何か良いことでもあったのかな、みたいなグラフ。

   45500000 ++---+---+----+---+----+---+----+---+----+---+----+---+----+--++
            +        +        +        +        +        +        +        +
   45000000 ++                                             ************** ++
            |                                              *               |
   44500000 ++                                            *               ++
            |                                             *                |
   44000000 ++                                           *                ++
            |                                            *                 |
   43500000 ++                                           *                ++
   43000000 ++                                          *                 ++
            |                                           *                  |
   42500000 ++                                          *                 ++
            |                                          *                   |
   42000000 ++                                         *                  ++
            |                                         *                    |
   41500000 ++                                *********                   ++
            |                     ************                             |
   41000000 ++    ****************                                        ++
            +        +        +        +        +        +        +        +
   40500000 ++---+---+----+---+----+---+----+---+----+---+----+---+----+--++
          03/14    03/28    04/11    04/25    05/09    05/23    06/06    06/20

Window関数とWITH句と gnuplot だけで案外楽しんでいる毎日でした。