* events_stages_summary_by_account_by_event_name
* events_stages_summary_by_host_by_event_name
* events_stages_summary_by_thread_by_event_name
* events_stages_summary_by_user_by_event_name
* events_stages_summary_global_by_event_name
mysql> SELECT * FROM events_stages_summary_by_account_by_event_name WHERE count_star <> 0 ORDER BY sum_timer_wait DESC LIMIT 3; +------------+-----------+-------------------------+------------+----------------+----------------+----------------+----------------+ | USER | HOST | EVENT_NAME | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | +------------+-----------+-------------------------+------------+----------------+----------------+----------------+----------------+ | isucon2app | localhost | stage/sql/Sending data | 2509 | 39308705666000 | 0 | 15667080000 | 178525262000 | | isucon2app | localhost | stage/sql/freeing items | 3000 | 7854180396000 | 0 | 2618060000 | 25104133000 | | isucon2app | localhost | stage/sql/System lock | 2743 | 2691080812000 | 0 | 981072000 | 244085523000 | +------------+-----------+-------------------------+------------+----------------+----------------+----------------+----------------+ 3 rows in set (0.00 sec)
デフォルトではOFFになっていたステージの情報(5.5まででいうprofiling)の情報が見られるようになる。
はかどりそうだけど、event_stageの情報をdigest(つまりクエリー単位)でサマライズして見られたらもっと良かったのになぁ。。
profileと同じようにピンポイントで有効にすれば本来いいはず。
* events_waits_summary_by_account_by_event_name
* events_waits_summary_by_host_by_event_name
* events_waits_summary_by_instance
* events_waits_summary_by_thread_by_event_name
* events_waits_summary_by_user_by_event_name
* events_waits_summary_global_by_event_name
mysql> SELECT * FROM events_waits_summary_by_account_by_event_name WHERE count_star <> 0 and event_name <> 'idle' and user = 'isucon2app' ORDER BY sum_timer_wait DESC; +------------+-----------+------------------------------------------+------------+----------------+----------------+----------------+----------------+ | USER | HOST | EVENT_NAME | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | +------------+-----------+------------------------------------------+------------+----------------+----------------+----------------+----------------+ | isucon2app | localhost | wait/io/table/sql/handler | 32424969 | 41901091208900 | 49280 | 1292060 | 107226966770 | | isucon2app | localhost | wait/io/socket/sql/client_connection | 6455 | 8661436551845 | 510125 | 1341818170 | 25122662950 | | isucon2app | localhost | wait/io/file/innodb/innodb_log_file | 364 | 1616073950645 | 8077685 | 4439763405 | 418325359760 | | isucon2app | localhost | wait/io/file/innodb/innodb_data_file | 657 | 1146723865595 | 1064525 | 1745393650 | 209724324810 | | isucon2app | localhost | wait/synch/mutex/innodb/trx_mutex | 699706 | 41160329980 | 20790 | 58520 | 3020631845 | | isucon2app | localhost | wait/synch/mutex/mysys/THR_LOCK::mutex | 9634 | 11706377760 | 26950 | 1215060 | 10035856215 | | isucon2app | localhost | wait/lock/table/sql/handler | 11344 | 6277293330 | 26950 | 553245 | 126401660 | | isucon2app | localhost | wait/synch/mutex/innodb/trx_undo_mutex | 82384 | 4336347400 | 24640 | 52360 | 41428695 | | isucon2app | localhost | wait/synch/mutex/sql/THD::LOCK_thd_data | 18669 | 2553290740 | 25410 | 136675 | 45770340 | | isucon2app | localhost | wait/io/file/sql/FRM | 225 | 605735515 | 199045 | 2691920 | 43222025 | | isucon2app | localhost | wait/synch/rwlock/innodb/fil_space_latch | 675 | 66989230 | 24640 | 98945 | 846615 | | isucon2app | localhost | wait/io/file/sql/dbopt | 4 | 31597335 | 232925 | 7899045 | 27579475 | | isucon2app | localhost | wait/synch/rwlock/sql/MDL_lock::rwlock | 20 | 2514050 | 81235 | 125510 | 405405 | +------------+-----------+------------------------------------------+------------+----------------+----------------+----------------+----------------+ 13 rows in set (0.00 sec)
さっきとそんなに塩梅は変わらないものの、mutexの情報とか増えてる。
↓吊るしで同じクエリーを叩くとこれだけしか情報は出ない。
mysql> SELECT * FROM events_waits_summary_by_account_by_event_name WHERE count_star <> 0 and event_name <> 'idle' and user = 'isucon2app' ORDER BY sum_timer_wait DESC; +------------+-----------+--------------------------------------+------------+----------------+----------------+----------------+----------------+ | USER | HOST | EVENT_NAME | COUNT_STAR | SUM_TIMER_WAIT | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT | +------------+-----------+--------------------------------------+------------+----------------+----------------+----------------+----------------+ | isucon2app | localhost | wait/io/table/sql/handler | 30563374 | 30001032268130 | 48125 | 981365 | 65554244140 | | isucon2app | localhost | wait/io/file/innodb/innodb_log_file | 362 | 941252670050 | 7715785 | 2600145240 | 61855393600 | | isucon2app | localhost | wait/io/file/innodb/innodb_data_file | 386 | 769021622600 | 872795 | 1992283755 | 110223802535 | | isucon2app | localhost | wait/lock/table/sql/handler | 10640 | 3912227935 | 25410 | 367675 | 136991855 | | isucon2app | localhost | wait/io/file/sql/FRM | 160 | 453758305 | 201355 | 2835910 | 42650685 | | isucon2app | localhost | wait/io/file/sql/dbopt | 4 | 24409000 | 222530 | 6102250 | 21301280 | +------------+-----------+--------------------------------------+------------+----------------+----------------+----------------+----------------+ 6 rows in set (0.00 sec)
* mutex_instances
mysql> SELECT * FROM mutex_instances; +-------------------------------------------------+-----------------------+---------------------+ | NAME | OBJECT_INSTANCE_BEGIN | LOCKED_BY_THREAD_ID | +-------------------------------------------------+-----------------------+---------------------+ | wait/synch/mutex/mysys/my_thread_var::mutex | 140714335799552 | NULL | | wait/synch/mutex/mysys/my_thread_var::mutex | 140714402908416 | NULL | | wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data | 140714805632408 | NULL | | wait/synch/mutex/mysys/THR_LOCK::mutex | 140714805616856 | NULL | | wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data | 140714805660792 | NULL | | wait/synch/mutex/mysys/THR_LOCK::mutex | 140714805657816 | NULL | | wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data | 140714805659576 | NULL | | wait/synch/mutex/mysys/THR_LOCK::mutex | 140714805645720 | NULL | | wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data | 140714805679048 | NULL | | wait/synch/mutex/mysys/THR_LOCK::mutex | 140714805586648 | NULL | | wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data | 140714805601848 | NULL | | wait/synch/mutex/mysys/THR_LOCK::mutex | 140714805602632 | NULL | | wait/synch/mutex/mysys/my_thread_var::mutex | 140714201581952 | NULL | | wait/synch/mutex/sql/MDL_wait::LOCK_wait_status | 36850088 | NULL | | wait/synch/mutex/sql/THD::LOCK_thd_data | 36853576 | NULL | | wait/synch/mutex/sql/MDL_wait::LOCK_wait_status | 42562344 | NULL | | wait/synch/mutex/sql/THD::LOCK_thd_data | 42565832 | NULL | | wait/synch/mutex/sql/MDL_wait::LOCK_wait_status | 42577160 | NULL | | wait/synch/mutex/sql/THD::LOCK_thd_data | 42580648 | NULL | | wait/synch/mutex/sql/MDL_wait::LOCK_wait_status | 42740984 | NULL | | wait/synch/mutex/sql/THD::LOCK_thd_data | 42744472 | NULL | | wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data | 140714604308568 | NULL | | wait/synch/mutex/sql/TABLE_SHARE::LOCK_ha_data | 140714604309576 | NULL | | wait/synch/mutex/sql/MDL_wait::LOCK_wait_status | 42529224 | NULL | | wait/synch/mutex/sql/THD::LOCK_thd_data | 42532712 | NULL | | wait/synch/mutex/sql/MDL_wait::LOCK_wait_status | 42595464 | NULL | | wait/synch/mutex/sql/THD::LOCK_thd_data | 42598952 | NULL | +-------------------------------------------------+-----------------------+---------------------+ 27 rows in set (0.00 sec)
これはむしろクエリー流している最中に見て、locked_by_thread_idが埋まりがちだったらインスタンスを分けるとかしたほうがいいのかしら。
パッと見これくらいなので、普段は吊るしのまま(バックグラウンドスレッドはOFFにしてもいい)か、setup_instrumentsのWHERE name LIKE 'stage%'を有効にだけしておいて、実際に計測したいときにsetup_consumersのevents_stages_currentをYesにしてやればいいですかね。
前にそんなことちょっと書いたなぁと思いつつ。
performance_schema_instrumentの設定方法 | GMOメディア エンジニアブログ
performance_schema_instrumentの設定方法 | GMOメディア エンジニアブログ
0 件のコメント :
コメントを投稿