MySQL 5.6ではprofilingが非推奨になってしまった件
Tweet
こんにちは、DBAのたなかです。
べんりなべんりなprofilingですが、5.6からは非推奨になってしまいました。
mysql56> SET profiling= 1; Query OK, 0 rows affected, 1 warning (0.03 sec)mysql56> SHOW WARNINGS; +———+——+———————————————————————-+ | Level | Code | Message | +———+——+———————————————————————-+ | Warning | 1287 | ‘@@profiling’ is deprecated and will be removed in a future release. | +———+——+———————————————————————-+ 1 row in set (0.04 sec)
mysql56> SELECT .. ..
mysql56> SHOW PROFILE; +——————————–+———-+ | Status | Duration | +——————————–+———-+ | starting | 0.031259 | | Waiting for query cache lock | 0.000007 | | init | 0.000005 | | checking query cache for query | 0.000075 | | checking permissions | 0.000015 | | Opening tables | 0.000019 | | init | 0.000018 | | System lock | 0.000009 | | optimizing | 0.000008 | | statistics | 0.000019 | | preparing | 0.000016 | | executing | 0.000004 | | Sending data | 0.000036 | | end | 0.000005 | | query end | 0.000005 | | closing tables | 0.000008 | | freeing items | 0.000033 | | cleaning up | 0.000016 | +——————————–+———-+ 18 rows in set, 1 warning (0.07 sec)
mysql56> SHOW WARNINGS; +———+——+————————————————————————————————————-+ | Level | Code | Message | +———+——+————————————————————————————————————-+ | Warning | 1287 | ‘SHOW PROFILE’ is deprecated and will be removed in a future release. Please use Performance Schema instead | +———+——+————————————————————————————————————-+ 1 row in set (0.00 sec)
代わりにPerformance Schemaを使えといわれます(´･ω･｀)
とはいえアレです。performance_schemaといえば
$ bin/mysqld_safe –no-defaults –performance-schema=0 &$ ps auxww | grep mysqld mysql 9052 12.7 4.2 844868 43628 pts/26 Sl 13:00 0:00 /usr/mysql/5.6.16/bin/mysqld –no-defaults –basedir=/usr/mysql/5.6.16 –datadir=/usr/mysql/5.6.16/data –plugin-dir=/usr/mysql/5.6.16/lib/plugin –performance-schema=0 –log-error=/usr/mysql/5.6.16/data/dev-personal-04.err –pid-file=/usr/mysql/5.6.16/data/dev-personal-04.pid
$ bin/mysqld_safe –no-defaults –performance-schema=1 &
$ ps aux | grep mysqld mysql 9177 10.7 44.7 1257600 456460 pts/26 Sl 13:01 0:01 /usr/mysql/5.6.16/bin/mysqld –no-defaults –basedir=/usr/mysql/5.6.16 –datadir=/usr/mysql/5.6.16/data –plugin-dir=/usr/mysql/5.6.16/lib/plugin –performance-schema=1 –log-error=/usr/mysql/5.6.16/data/dev-personal-04.err –pid-file=/usr/mysql/5.6.16/data/dev-personal-04.pid
メモリー使います。時代の流れなのか、仕方がないのか。なくなってしまうなら仕方ないので使い方を覚えないといけませんね。
mysql56> SELECT * FROM performance_schema.events_stages_current LIMIT 3; Empty set (0.00 sec)mysql56> SELECT * FROM performance_schema.events_stages_history LIMIT 3; Empty set (0.00 sec)
mysql56> SELECT * FROM performance_schema.events_stages_history_long LIMIT 3; Empty set (0.00 sec)
あれ、出てこない。
Performance Schemaがどの類の情報を蓄積していくかは performance_schema.setup_consumers で管理されているはずなので、そこをチェック。
mysql56> SELECT * FROM performance_schema.setup_consumers; +——————————–+———+ | NAME | ENABLED | +——————————–+———+ | events_stages_current | NO | | events_stages_history | NO | | events_stages_history_long | NO | | events_statements_current | YES | | events_statements_history | NO | | events_statements_history_long | NO | | events_waits_current | NO | | events_waits_history | NO | | events_waits_history_long | NO | | global_instrumentation | YES | | thread_instrumentation | YES | | statements_digest | YES | +——————————–+———+ 12 rows in set (0.00 sec)
eventsstages* が軒並みNOになっているので、とりあえず全部YESにしてみます。
mysql56> UPDATE performance_schema.setup_consumers SET enabled= ‘YES’ WHERE name LIKE ‘events_stages_%‘; Query OK, 3 rows affected (0.08 sec) Rows matched: 3 Changed: 3 Warnings: 0mysql56> SELECT * FROM performance_schema.setup_consumers; +——————————–+———+ | NAME | ENABLED | +——————————–+———+ | events_stages_current | YES | | events_stages_history | YES | | events_stages_history_long | YES | | events_statements_current | YES | | events_statements_history | NO | | events_statements_history_long | NO | | events_waits_current | NO | | events_waits_history | NO | | events_waits_history_long | NO | | global_instrumentation | YES | | thread_instrumentation | YES | | statements_digest | YES | +——————————–+———+ 12 rows in set (0.00 sec)
これでどうだ…！
mysql56> SELECT * FROM performance_schema.events_stages_current LIMIT 3; Empty set (0.00 sec)mysql56> SELECT * FROM performance_schema.events_stages_history LIMIT 3; Empty set (0.00 sec)
mysql56> SELECT * FROM performance_schema.events_stages_history_long LIMIT 3;
あれまだでない(´･ω･｀)
もうひとつ performance_schema.setup_instruments にもそれっぽいものを見つけたので見てみる。
mysql56> SELECT * FROM performance_schema.setup_instruments; +—————————————————————————————+———+——-+ | NAME | ENABLED | TIMED | +—————————————————————————————+———+——-+ | wait/synch/mutex/sql/PAGE::lock | NO | NO | | wait/synch/mutex/sql/TC_LOG_MMAP::LOCK_sync | NO | NO | | wait/synch/mutex/sql/TC_LOG_MMAP::LOCK_active | NO | NO | .. 555 rows in set (0.01 sec)
こっちもstage/sql関連が軒並みNOになっているのでYESに変える。
mysql56> UPDATE performance_schema.setup_instruments SET enabled= ‘Yes’ WHERE name LIKE ‘stage/sql/%’; Query OK, 107 rows affected (0.02 sec) Rows matched: 107 Changed: 107 Warnings: 0mysql56> mysql56> SELECT * FROM performance_schema.setup_instruments WHERE name LIKE ‘stage/sql/%’; +—————————————————————————————+———+——-+ | NAME | ENABLED | TIMED | +—————————————————————————————+———+——-+ | stage/sql/After create | YES | NO | | stage/sql/allocating local table | YES | NO | | stage/sql/preparing for alter table | YES | NO | .. 107 rows in set (0.03 sec)
こんどこそどうよ。
mysql56> SELECT * FROM performance_schema.events_stages_current LIMIT 3; +———–+———-+————–+————————–+——————-+————-+———–+————+——————+——————–+ | THREAD_ID | EVENT_ID | END_EVENT_ID | EVENT_NAME | SOURCE | TIMER_START | TIMER_END | TIMER_WAIT | NESTING_EVENT_ID | NESTING_EVENT_TYPE | +———–+———-+————–+————————–+——————-+————-+———–+————+——————+——————–+ | 1229 | 1332190 | NULL | stage/sql/updating | sql_update.cc:715 | NULL | NULL | NULL | 1332184 | STATEMENT | | 1230 | 1337659 | NULL | stage/sql/Opening tables | sql_base.cc:4911 | NULL | NULL | NULL | 1337656 | STATEMENT | | 1231 | 1262314 | NULL | stage/sql/updating | sql_update.cc:715 | NULL | NULL | NULL | 1262308 | STATEMENT | +———–+———-+————–+————————–+——————-+————-+———–+————+——————+——————–+ 3 rows in set (0.07 sec)mysql56> SELECT * FROM performance_schema.events_stages_history LIMIT 3; +———–+———-+————–+————————–+——————-+————-+———–+————+——————+——————–+ | THREAD_ID | EVENT_ID | END_EVENT_ID | EVENT_NAME | SOURCE | TIMER_START | TIMER_END | TIMER_WAIT | NESTING_EVENT_ID | NESTING_EVENT_TYPE | +———–+———-+————–+————————–+——————-+————-+———–+————+——————+——————–+ | 1229 | 1370525 | 1370525 | stage/sql/cleaning up | sql_parse.cc:1774 | NULL | NULL | NULL | 1370513 | STATEMENT | | 1229 | 1370516 | 1370516 | stage/sql/Opening tables | sql_base.cc:4911 | NULL | NULL | NULL | 1370513 | STATEMENT | | 1229 | 1370517 | 1370517 | stage/sql/init | sql_update.cc:262 | NULL | NULL | NULL | 1370513 | STATEMENT | +———–+———-+————–+————————–+——————-+————-+———–+————+——————+——————–+ 3 rows in set (0.00 sec)
mysql56> SELECT * FROM performance_schema.events_stages_history_long LIMIT 3; +———–+———-+————–+——————————————+——————-+————-+———–+————+——————+——————–+ | THREAD_ID | EVENT_ID | END_EVENT_ID | EVENT_NAME | SOURCE | TIMER_START | TIMER_END | TIMER_WAIT | NESTING_EVENT_ID | NESTING_EVENT_TYPE | +———–+———-+————–+——————————————+——————-+————-+———–+————+——————+——————–+ | 1235 | 1421345 | 1421345 | stage/sql/checking query cache for query | sql_cache.cc:1594 | NULL | NULL | NULL | 1421341 | STATEMENT | | 1235 | 1421346 | 1421346 | stage/sql/checking permissions | sql_parse.cc:5256 | NULL | NULL | NULL | 1421341 | STATEMENT | | 1235 | 1421347 | 1421347 | stage/sql/Opening tables | sql_base.cc:4911 | NULL | NULL | NULL | 1421341 | STATEMENT | +———–+———-+————–+——————————————+——————-+————-+———–+————+——————+——————–+ 3 rows in set (0.00 sec)
なんか取れてるっぽい。けど、TIMER_START, TIMER_ENDとかがNULLになってて、profilingの時のようなdurationがわからない(´･ω･｀)
setup_instrumentsのTIMEDもYesにするべきだったかしら。
mysql56> SELECT * FROM performance_schema.events_stages_history_long LIMIT 3; +———–+———-+————–+———————–+———————-+——————+——————+————+——————+——————–+ | THREAD_ID | EVENT_ID | END_EVENT_ID | EVENT_NAME | SOURCE | TIMER_START | TIMER_END | TIMER_WAIT | NESTING_EVENT_ID | NESTING_EVENT_TYPE | +———–+———-+————–+———————–+———————-+——————+——————+————+——————+——————–+ | 1233 | 2887094 | 2887094 | stage/sql/cleaning up | sql_parse.cc:1774 | 2972718805216000 | 2972718807784000 | 2568000 | 2887077 | STATEMENT | | 1229 | 2874037 | 2874037 | stage/sql/System lock | lock.cc:304 | 2972870398683000 | 2972870402912000 | 4229000 | 2874029 | STATEMENT | | 1229 | 2874038 | 2874038 | stage/sql/optimizing | sql_optimizer.cc:138 | 2972870402912000 | 2972870408938000 | 6026000 | 2874029 | STATEMENT | +———–+———-+————–+———————–+———————-+——————+——————+————+——————+——————–+ 3 rows in set (0.01 sec)
ｷﾀ!!
しかしこれセッション変数だったprofiling= 1と違って全部のスレッドのプロファイル取ってるんですよねー。調べてみると、 performance_schema.threads が個々のスレッドでp_sに情報を蓄積するかどうかのフラグを持っている模様。
mysql56> SELECT * FROM performance_schema.threads\G
*************************** 1. row ***************************
THREAD_ID: 1
NAME: thread/sql/main
TYPE: BACKGROUND
PROCESSLIST_ID: NULL
PROCESSLIST_USER: NULL
PROCESSLIST_HOST: NULL
PROCESSLIST_DB: NULL
PROCESSLIST_COMMAND: NULL
PROCESSLIST_TIME: 3098
PROCESSLIST_STATE: System lock
PROCESSLIST_INFO: INTERNAL DDL LOG RECOVER IN PROGRESS
PARENT_THREAD_ID: NULL
ROLE: NULL
INSTRUMENTED: YES
..
*************************** 27. row ***************************
THREAD_ID: 1517
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 1498
PROCESSLIST_USER: root
PROCESSLIST_HOST: localhost
PROCESSLIST_DB: performance_schema
PROCESSLIST_COMMAND: Query
PROCESSLIST_TIME: 0
PROCESSLIST_STATE: Sending data
PROCESSLIST_INFO: SELECT * FROM threads
PARENT_THREAD_ID: NULL
ROLE: NULL
INSTRUMENTED: YES
27 rows in set (0.00 sec)
mysql56> UPDATE performance_schema.threads SET instrumented= ‘NO’ WHERE thread_id<> 1517;
Query OK, 26 rows affected (0.21 sec)
Rows matched: 26 Changed: 26 Warnings: 0
mysql56> SELECT * FROM performance_schema.events_stages_history ORDER BY TIMER_START DESC LIMIT 3;
+———–+———-+————–+————————–+———————+——————+——————+————+——————+——————–+
| THREAD_ID | EVENT_ID | END_EVENT_ID | EVENT_NAME | SOURCE | TIMER_START | TIMER_END | TIMER_WAIT | NESTING_EVENT_ID | NESTING_EVENT_TYPE |
+———–+———-+————–+————————–+———————+——————+——————+————+——————+——————–+
| 1517 | 359 | 359 | stage/sql/Sending data | sql_executor.cc:190 | 3189672716680000 | 3189672731169000 | 14489000 | 345 | STATEMENT |
| 1517 | 358 | 358 | stage/sql/executing | sql_executor.cc:110 | 3189672712663000 | 3189672716680000 | 4017000 | 345 | STATEMENT |
| 1517 | 357 | 357 | stage/sql/Sorting result | sql_select.cc:5248 | 3189672707694000 | 3189672712663000 | 4969000 | 345 | STATEMENT |
+———–+———-+————–+————————–+———————+——————+——————+————+——————+——————–+
3 rows in set (0.05 sec)
よさげ…かな？；
本番に適用するとしたら、
- performance_schema= 1 はしておく
- setup_consumers, setup_instruments は設定しておく
- threads.instrumented= ‘NO’ を全スレッドに設定しておく
- 必要な時にps_helperのenable_current_threadプロシージャを使って有効化する
とか思いましたが、これ新しく入ってきたスレッドはthreads.instrumented= ‘YES’で入ってきちゃいますね(´･ω･｀)
引き続き調べるとして、今日はこのへんで。
つづき
