================================================================= This is my notes/braindump/links outputs for the FOSDEM 2017 talk on applying profilers to MySQL ================================================================= P_S query, just in case: SELECT thread_id, CONCAT( CASE WHEN event_name LIKE 'stage%' THEN CONCAT(' ', event_name) WHEN event_name LIKE 'wait%' AND nesting_event_id IS NOT NULL THEN CONCAT(' ', event_name) ELSE IF(digest_text IS NOT NULL, SUBSTR(digest_text, 1, 64), event_name) END, ' (',ROUND(timer_wait/1000000000, 2),'ms) ') event FROM ( (SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, digest_text FROM events_statements_history_long) UNION (SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, NULL FROM events_stages_history_long) UNION (SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, NULL FROM events_waits_history_long) ) events ORDER BY thread_id, event_id; [openxs@fc23 maria10.1]$ cat /tmp/my.cnf [mysqld] performance-schema=1 performance_schema_instrument='wait/%=on' [openxs@fc23 maria10.1]$ ps aux | grep mysqld openxs 1283 0.0 0.0 119296 3288 pts/0 S 10:41 0:00 /bin/sh bin/mysqld_safe --defaults-file=/tmp/my.cnf openxs 1365 2.6 2.4 896032 196340 pts/0 Sl 10:41 0:00 /home/openxs/dbs/maria10.1/bin/mysqld --defaults-file=/tmp/my.cnf --basedir=/home/openxs/dbs/maria10.1 --datadir=/home/openxs/dbs/maria10.1/data --plugin-dir=/home/openxs/dbs/maria10.1/lib/plugin --log-error=/home/openxs/dbs/maria10.1/data/fc23.err --pid-file=fc23.pid openxs 1478 0.0 0.0 118520 948 pts/0 S+ 10:41 0:00 grep --color=auto mysqld MariaDB [performance_schema]> update setup_instruments set enabled='YES', timed='YES'; Query OK, 135 rows affected (0.00 sec) Rows matched: 679 Changed: 135 Warnings: 0 MariaDB [performance_schema]> update setup_consumers set enabled='YES'; Query OK, 8 rows affected (0.00 sec) Rows matched: 12 Changed: 8 Warnings: 0 MariaDB [performance_schema]> set global innodb_thread_concurrency=4; Query OK, 0 rows affected (0.00 sec) [openxs@fc23 maria10.1]$ bin/mysql -uroot test Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Welcome to the MariaDB monitor. Commands end with ; or \g. Your MariaDB connection id is 16 Server version: 10.1.22-MariaDB Source distribution Copyright (c) 2000, 2016, Oracle, MariaDB Corporation Ab and others. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. MariaDB [test]> select * from t0 where id=14; +----+------+---------------------+ | id | c1 | c2 | +----+------+---------------------+ | 14 | 630 | 0.23608397248767687 | +----+------+---------------------+ 1 row in set (4 min 58.28 sec) MariaDB [test]> exit Bye [openxs@fc23 maria10.1]$ pkill mysqlslap [2] Terminated bin/mysqlslap -uroot --no-drop --create-schema=test --number-of-queries=1000 iternations=10 --concurrency=1 --query="update t$i set c2 = rand() where id between 2000 and 300000;" [3] Terminated bin/mysqlslap -uroot --no-drop --create-schema=test --number-of-queries=1000 iternations=10 --concurrency=1 --query="update t$i set c2 = rand() where id between 2000 and 300000;" [4] Terminated bin/mysqlslap -uroot --no-drop --create-schema=test --number-of-queries=1000 iternations=10 --concurrency=1 --query="update t$i set c2 = rand() where id between 2000 and 300000;" [5] Terminated bin/mysqlslap -uroot --no-drop --create-schema=test --number-of-queries=1000 iternations=10 --concurrency=1 --query="update t$i set c2 = rand() where id between 2000 and 300000;" [openxs@fc23 maria10.1]$ pkill mysqlslap [6]- Terminated bin/mysqlslap -uroot --no-drop --create-schema=test --number-of-queries=1000 iternations=10 --concurrency=1 --query="update t$i set c2 = rand() where id between 2000 and 300000;" [7]+ Terminated bin/mysqlslap -uroot --no-drop --create-schema=test --number-of-queries=1000 iternations=10 --concurrency=1 --query="update t$i set c2 = rand() where id between 2000 and 300000;" [openxs@fc23 maria10.1]$ pkill mysqlslap [openxs@fc23 maria10.1]$ bin/mysql -uroot performance_schema -e " SELECT thread_id, CONCAT( CASE WHEN event_name LIKE 'stage%' THEN CONCAT(' ', event_name) WHEN event_name LIKE 'wait%' AND nesting_event_id IS NOT NULL THEN CONCAT(' ', event_name) ELSE IF(digest_text IS NOT NULL, SUBSTR(digest_text, 1, 64), event_name) END, ' (',ROUND(timer_wait/1000000000, 2),'ms) ') event FROM ( (SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, digest_text FROM events_statements_history_long) UNION (SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, NULL FROM events_stages_history_long) UNION (SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, NULL FROM events_waits_history_long) ) events ORDER BY thread_id, event_id" >/tmp/p_s.txt In /tmp/p_s.txt: 38 SELECT * FROM `t0` WHERE ID = ? (298281.28ms) 38 stage/sql/init (0.05ms) 38 stage/sql/checking permissions (0.00ms) 38 stage/sql/Opening tables (0.02ms) 38 stage/sql/After opening tables (0.00ms) 38 stage/sql/System lock (0.00ms) 38 stage/sql/Table lock (0.00ms) 38 stage/sql/init (0.02ms) 38 stage/sql/optimizing (0.01ms) 38 stage/sql/statistics (298281.08ms) 38 stage/sql/preparing (0.00ms) 38 stage/sql/Unlocking tables (0.02ms) 38 stage/sql/executing (0.00ms) 38 stage/sql/Sending data (0.01ms) 38 stage/sql/end (0.00ms) 38 stage/sql/query end (0.00ms) 38 stage/sql/closing tables (0.00ms) 38 stage/sql/Unlocking tables (0.01ms) 38 stage/sql/freeing items (0.00ms) 38 stage/sql/cleaning up (0.00ms) [openxs@fc23 maria10.1]$ bin/mysql -uroot performance_schema -e " SELECT thread_id, event_id, nesting_event_id, CONCAT( CASE WHEN event_name LIKE 'stage%' THEN CONCAT(' ', event_name) WHEN event_name LIKE 'wait%' AND nesting_event_id IS NOT NULL THEN CONCAT(' ', event_name) ELSE IF(digest_text IS NOT NULL, SUBSTR(digest_text, 1, 64), event_name) END, ' (',ROUND(timer_wait/1000000000, 2),'ms) ') event FROM ( (SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, digest_text FROM events_statements_history_long) UNION (SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, NULL FROM events_stages_history_long) UNION (SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, NULL FROM events_waits_history_long) ) events ORDER BY thread_id, event_id" >/tmp/p_s.txt 38 536 NULL SELECT * FROM `t0` WHERE ID = ? (298281.28ms) 38 537 536 stage/sql/init (0.05ms) 38 540 536 stage/sql/checking permissions (0.00ms) 38 541 536 stage/sql/Opening tables (0.02ms) 38 545 536 stage/sql/After opening tables (0.00ms) 38 546 536 stage/sql/System lock (0.00ms) 38 548 536 stage/sql/Table lock (0.00ms) 38 551 536 stage/sql/init (0.02ms) 38 552 536 stage/sql/optimizing (0.01ms) 38 553 536 stage/sql/statistics (298281.08ms) 38 614 536 stage/sql/preparing (0.00ms) 38 615 536 stage/sql/Unlocking tables (0.02ms) 38 617 536 stage/sql/executing (0.00ms) 38 618 536 stage/sql/Sending data (0.01ms) 38 619 536 stage/sql/end (0.00ms) 38 620 536 stage/sql/query end (0.00ms) 38 621 536 stage/sql/closing tables (0.00ms) 38 622 536 stage/sql/Unlocking tables (0.01ms) 38 626 536 stage/sql/freeing items (0.00ms) 38 629 536 stage/sql/cleaning up (0.00ms) 28 953263 NULL UPDATE `t1` SET `c2` = `rand` ( ) WHERE ID BETWEEN ? AND ? (26209.03ms) 28 953264 953263 stage/sql/init (0.08ms) 28 953268 953263 stage/sql/checking permissions (0.00ms) 28 953269 953263 stage/sql/Opening tables (0.02ms) 28 953274 953263 stage/sql/After opening tables (0.00ms) 28 953275 953263 stage/sql/System lock (0.00ms) 28 953277 953263 stage/sql/Table lock (0.00ms) 28 953280 953263 stage/sql/init (0.10ms) 28 953313 953263 stage/sql/updating (26049.30ms) 28 1930749 953263 stage/sql/end (0.01ms) 28 1930750 953263 stage/sql/query end (159.47ms) 28 1930802 953263 stage/sql/closing tables (0.00ms) 28 1930803 953263 stage/sql/Unlocking tables (0.02ms) 28 1930809 953263 stage/sql/freeing items (0.01ms) 28 1930812 953263 stage/sql/cleaning up (0.01ms) SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, digest_text FROM events_statements_history_long; SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, NULL FROM events_stages_history_long SELECT thread_id, event_id, event_name, timer_wait, timer_start, nesting_event_id, NULL FROM events_waits_history_long; Top 10 waits: SELECT event_name, ROUND(timer_wait/1000000000,2) wait_ms FROM events_waits_history_long ORDER BY 2 DESC LIMIT 10; MariaDB [performance_schema]> SELECT event_name, ROUND(timer_wait/1000000000,2) wait_ms FROM events_waits_history_long ORDER BY 2 DESC LIMIT 10; +----------------------------------------------------+---------+ | event_name | wait_ms | +----------------------------------------------------+---------+ | idle | 1550.04 | | wait/synch/mutex/innodb/buf_pool_flush_state_mutex | 57.41 | | wait/io/file/innodb/innodb_data_file | 32.64 | | wait/io/file/innodb/innodb_data_file | 24.73 | | wait/io/file/innodb/innodb_data_file | 0.72 | | wait/io/file/innodb/innodb_data_file | 0.72 | | wait/io/file/innodb/innodb_data_file | 0.69 | | wait/io/file/innodb/innodb_data_file | 0.69 | | wait/io/table/sql/handler | 0.01 | | wait/io/table/sql/handler | 0.01 | +----------------------------------------------------+---------+ 10 rows in set (0.00 sec) Other session in the process: MariaDB [test]> show processlist; +----+------+-----------+------+---------+------+------------+------------------------------------------------------------+----------+ | Id | User | Host | db | Command | Time | State | Info | Progress | +----+------+-----------+------+---------+------+------------+------------------------------------------------------------+----------+ | 2 | root | localhost | test | Query | 0 | init | show processlist | 0.000 | | 4 | root | localhost | NULL | Sleep | 138 | | NULL | 0.000 | | 5 | root | localhost | NULL | Sleep | 138 | | NULL | 0.000 | | 6 | root | localhost | test | Query | 12 | updating | update t1 set c2 = rand() where id between 2000 and 300000 | 0.000 | | 7 | root | localhost | NULL | Sleep | 138 | | NULL | 0.000 | | 8 | root | localhost | NULL | Sleep | 138 | | NULL | 0.000 | | 9 | root | localhost | NULL | Sleep | 138 | | NULL | 0.000 | | 10 | root | localhost | NULL | Sleep | 138 | | NULL | 0.000 | | 11 | root | localhost | test | Query | 120 | updating | update t5 set c2 = rand() where id between 2000 and 300000 | 0.000 | | 12 | root | localhost | test | Query | 15 | updating | update t3 set c2 = rand() where id between 2000 and 300000 | 0.000 | | 13 | root | localhost | test | Query | 69 | updating | update t4 set c2 = rand() where id between 2000 and 300000 | 0.000 | | 14 | root | localhost | test | Query | 13 | updating | update t6 set c2 = rand() where id between 2000 and 300000 | 0.000 | | 15 | root | localhost | test | Query | 12 | updating | update t2 set c2 = rand() where id between 2000 and 300000 | 0.000 | | 16 | root | localhost | test | Query | 125 | statistics | select * from t0 where id=14 | 0.000 | +----+------+-----------+------+---------+------+------------+------------------------------------------------------------+----------+ 14 rows in set (0.00 sec) All we can wait for in InnoDB: MariaDB [performance_schema]> select * from setup_instruments where name like '%innodb%'; +-------------------------------------------------------+---------+-------+ | NAME | ENABLED | TIMED | +-------------------------------------------------------+---------+-------+ | wait/synch/mutex/innodb/commit_cond_mutex | YES | YES | | wait/synch/mutex/innodb/innobase_share_mutex | YES | YES | | wait/synch/mutex/innodb/pending_checkpoint_mutex | YES | YES | | wait/synch/mutex/innodb/autoinc_mutex | YES | YES | | wait/synch/mutex/innodb/buf_pool_zip_mutex | YES | YES | | wait/synch/mutex/innodb/buf_pool_LRU_list_mutex | YES | YES | | wait/synch/mutex/innodb/buf_pool_free_list_mutex | YES | YES | | wait/synch/mutex/innodb/buf_pool_zip_free_mutex | YES | YES | | wait/synch/mutex/innodb/buf_pool_zip_hash_mutex | YES | YES | | wait/synch/mutex/innodb/buf_pool_flush_state_mutex | YES | YES | | wait/synch/mutex/innodb/cache_last_read_mutex | YES | YES | | wait/synch/mutex/innodb/dict_foreign_err_mutex | YES | YES | | wait/synch/mutex/innodb/dict_sys_mutex | YES | YES | | wait/synch/mutex/innodb/file_format_max_mutex | YES | YES | | wait/synch/mutex/innodb/fil_system_mutex | YES | YES | | wait/synch/mutex/innodb/flush_list_mutex | YES | YES | | wait/synch/mutex/innodb/fts_bg_threads_mutex | YES | YES | | wait/synch/mutex/innodb/fts_delete_mutex | YES | YES | | wait/synch/mutex/innodb/fts_optimize_mutex | YES | YES | | wait/synch/mutex/innodb/fts_doc_id_mutex | YES | YES | | wait/synch/mutex/innodb/fts_pll_tokenize_mutex | YES | YES | | wait/synch/mutex/innodb/log_flush_order_mutex | YES | YES | | wait/synch/mutex/innodb/hash_table_mutex | YES | YES | | wait/synch/mutex/innodb/ibuf_bitmap_mutex | YES | YES | | wait/synch/mutex/innodb/ibuf_mutex | YES | YES | | wait/synch/mutex/innodb/ibuf_pessimistic_insert_mutex | YES | YES | | wait/synch/mutex/innodb/log_bmp_sys_mutex | YES | YES | | wait/synch/mutex/innodb/log_sys_mutex | YES | YES | | wait/synch/mutex/innodb/mem_pool_mutex | YES | YES | | wait/synch/mutex/innodb/mutex_list_mutex | YES | YES | | wait/synch/mutex/innodb/page_zip_stat_per_index_mutex | YES | YES | | wait/synch/mutex/innodb/purge_sys_bh_mutex | YES | YES | | wait/synch/mutex/innodb/recv_sys_mutex | YES | YES | | wait/synch/mutex/innodb/recv_writer_mutex | YES | YES | | wait/synch/mutex/innodb/rseg_mutex | YES | YES | | wait/synch/mutex/innodb/rw_lock_list_mutex | YES | YES | | wait/synch/mutex/innodb/rw_lock_mutex | YES | YES | | wait/synch/mutex/innodb/srv_dict_tmpfile_mutex | YES | YES | | wait/synch/rwlock/innodb/archive_lock | YES | YES | | wait/synch/rwlock/innodb/btr_search_latch | YES | YES | | wait/synch/rwlock/innodb/dict_operation_lock | YES | YES | | wait/synch/rwlock/innodb/fil_space_latch | YES | YES | | wait/synch/rwlock/innodb/checkpoint_lock | YES | YES | | wait/synch/rwlock/innodb/fts_cache_rw_lock | YES | YES | | wait/synch/rwlock/innodb/fts_cache_init_rw_lock | YES | YES | | wait/synch/rwlock/innodb/trx_i_s_cache_lock | YES | YES | | wait/synch/rwlock/innodb/trx_purge_latch | YES | YES | | wait/synch/rwlock/innodb/index_tree_rw_lock | YES | YES | | wait/synch/rwlock/innodb/index_online_log | YES | YES | | wait/synch/rwlock/innodb/dict_table_stats | YES | YES | | wait/synch/rwlock/innodb/hash_table_locks | YES | YES | | wait/io/file/innodb/innodb_data_file | YES | YES | | wait/io/file/innodb/innodb_log_file | YES | YES | | wait/io/file/innodb/innodb_temp_file | YES | YES | | wait/io/file/innodb/innodb_bmp_file | YES | YES | +-------------------------------------------------------+---------+-------+ 55 rows in set (0.01 sec) Now in 8.0.0: [openxs@fc23 8.0]$ bin/mysql -uroot performance_schema Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 3 Server version: 8.0.0-dmr MySQL Community Server (GPL) Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> select * from setup_instruments where name like '%innodb%'; +---------------------------------------------------------+---------+-------+ | NAME | ENABLED | TIMED | +---------------------------------------------------------+---------+-------+ | wait/synch/mutex/innodb/commit_cond_mutex | NO | NO | | wait/synch/mutex/innodb/innobase_share_mutex | NO | NO | | wait/synch/mutex/innodb/autoinc_mutex | NO | NO | | wait/synch/mutex/innodb/autoinc_persisted_mutex | NO | NO | | wait/synch/mutex/innodb/buf_pool_flush_state_mutex | NO | NO | | wait/synch/mutex/innodb/buf_pool_LRU_list_mutex | NO | NO | | wait/synch/mutex/innodb/buf_pool_free_list_mutex | NO | NO | | wait/synch/mutex/innodb/buf_pool_zip_free_mutex | NO | NO | | wait/synch/mutex/innodb/buf_pool_zip_hash_mutex | NO | NO | | wait/synch/mutex/innodb/buf_pool_zip_mutex | NO | NO | | wait/synch/mutex/innodb/cache_last_read_mutex | NO | NO | | wait/synch/mutex/innodb/dict_foreign_err_mutex | NO | NO | | wait/synch/mutex/innodb/dict_persist_dirty_tables_mutex | NO | NO | | wait/synch/mutex/innodb/dict_sys_mutex | NO | NO | | wait/synch/mutex/innodb/recalc_pool_mutex | NO | NO | | wait/synch/mutex/innodb/fil_system_mutex | NO | NO | | wait/synch/mutex/innodb/flush_list_mutex | NO | NO | | wait/synch/mutex/innodb/fts_bg_threads_mutex | NO | NO | | wait/synch/mutex/innodb/fts_delete_mutex | NO | NO | | wait/synch/mutex/innodb/fts_optimize_mutex | NO | NO | | wait/synch/mutex/innodb/fts_doc_id_mutex | NO | NO | | wait/synch/mutex/innodb/log_flush_order_mutex | NO | NO | | wait/synch/mutex/innodb/hash_table_mutex | NO | NO | | wait/synch/mutex/innodb/ibuf_bitmap_mutex | NO | NO | | wait/synch/mutex/innodb/ibuf_mutex | NO | NO | | wait/synch/mutex/innodb/ibuf_pessimistic_insert_mutex | NO | NO | | wait/synch/mutex/innodb/log_sys_mutex | NO | NO | | wait/synch/mutex/innodb/log_sys_write_mutex | NO | NO | | wait/synch/mutex/innodb/mutex_list_mutex | NO | NO | | wait/synch/mutex/innodb/page_zip_stat_per_index_mutex | NO | NO | | wait/synch/mutex/innodb/purge_sys_pq_mutex | NO | NO | | wait/synch/mutex/innodb/recv_sys_mutex | NO | NO | | wait/synch/mutex/innodb/recv_writer_mutex | NO | NO | | wait/synch/mutex/innodb/redo_rseg_mutex | NO | NO | | wait/synch/mutex/innodb/noredo_rseg_mutex | NO | NO | | wait/synch/mutex/innodb/rw_lock_list_mutex | NO | NO | | wait/synch/mutex/innodb/rw_lock_mutex | NO | NO | | wait/synch/mutex/innodb/srv_dict_tmpfile_mutex | NO | NO | | wait/synch/mutex/innodb/srv_innodb_monitor_mutex | NO | NO | | wait/synch/mutex/innodb/srv_misc_tmpfile_mutex | NO | NO | | wait/synch/mutex/innodb/srv_monitor_file_mutex | NO | NO | | wait/synch/mutex/innodb/buf_dblwr_mutex | NO | NO | | wait/synch/mutex/innodb/trx_undo_mutex | NO | NO | | wait/synch/mutex/innodb/trx_pool_mutex | NO | NO | | wait/synch/mutex/innodb/trx_pool_manager_mutex | NO | NO | | wait/synch/mutex/innodb/srv_sys_mutex | NO | NO | | wait/synch/mutex/innodb/lock_mutex | NO | NO | | wait/synch/mutex/innodb/lock_wait_mutex | NO | NO | | wait/synch/mutex/innodb/trx_mutex | NO | NO | | wait/synch/mutex/innodb/srv_threads_mutex | NO | NO | | wait/synch/mutex/innodb/rtr_active_mutex | NO | NO | | wait/synch/mutex/innodb/rtr_match_mutex | NO | NO | | wait/synch/mutex/innodb/rtr_path_mutex | NO | NO | | wait/synch/mutex/innodb/rtr_ssn_mutex | NO | NO | | wait/synch/mutex/innodb/trx_sys_mutex | NO | NO | | wait/synch/mutex/innodb/zip_pad_mutex | NO | NO | | wait/synch/mutex/innodb/master_key_id_mutex | NO | NO | | wait/synch/sxlock/innodb/btr_search_latch | NO | NO | | wait/synch/sxlock/innodb/dict_operation_lock | NO | NO | | wait/synch/sxlock/innodb/fil_space_latch | NO | NO | | wait/synch/sxlock/innodb/checkpoint_lock | NO | NO | | wait/synch/sxlock/innodb/fts_cache_rw_lock | NO | NO | | wait/synch/sxlock/innodb/fts_cache_init_rw_lock | NO | NO | | wait/synch/sxlock/innodb/trx_i_s_cache_lock | NO | NO | | wait/synch/sxlock/innodb/trx_purge_latch | NO | NO | | wait/synch/sxlock/innodb/index_tree_rw_lock | NO | NO | | wait/synch/sxlock/innodb/index_online_log | NO | NO | | wait/synch/sxlock/innodb/dict_table_stats | NO | NO | | wait/synch/sxlock/innodb/hash_table_locks | NO | NO | | wait/synch/cond/innodb/commit_cond | NO | NO | | wait/io/file/innodb/innodb_data_file | YES | YES | | wait/io/file/innodb/innodb_log_file | YES | YES | | wait/io/file/innodb/innodb_temp_file | YES | YES | | stage/innodb/alter table (end) | YES | YES | | stage/innodb/alter table (flush) | YES | YES | | stage/innodb/alter table (insert) | YES | YES | | stage/innodb/alter table (log apply index) | YES | YES | | stage/innodb/alter table (log apply table) | YES | YES | | stage/innodb/alter table (merge sort) | YES | YES | | stage/innodb/alter table (read PK and internal sort) | YES | YES | | stage/innodb/buffer pool load | YES | YES | | memory/innodb/adaptive hash index | NO | NO | | memory/innodb/buf_buf_pool | NO | NO | | memory/innodb/buf_stat_per_index_t | NO | NO | | memory/innodb/dict_stats_bg_recalc_pool_t | NO | NO | | memory/innodb/dict_stats_index_map_t | NO | NO | | memory/innodb/dict_stats_n_diff_on_level | NO | NO | | memory/innodb/other | NO | NO | | memory/innodb/partitioning | NO | NO | | memory/innodb/row_log_buf | NO | NO | | memory/innodb/row_merge_sort | NO | NO | | memory/innodb/std | NO | NO | | memory/innodb/trx_sys_t::rw_trx_ids | NO | NO | | memory/innodb/ut_lock_free_hash_t | NO | NO | | memory/innodb/api0api | NO | NO | | memory/innodb/btr0btr | NO | NO | | memory/innodb/btr0bulk | NO | NO | | memory/innodb/btr0cur | NO | NO | | memory/innodb/btr0pcur | NO | NO | | memory/innodb/btr0sea | NO | NO | | memory/innodb/buf0buf | NO | NO | | memory/innodb/buf0dblwr | NO | NO | | memory/innodb/buf0dump | NO | NO | | memory/innodb/buf0flu | NO | NO | | memory/innodb/buf0lru | NO | NO | | memory/innodb/buf0stats | NO | NO | | memory/innodb/dict0boot | NO | NO | | memory/innodb/dict0dict | NO | NO | | memory/innodb/dict0load | NO | NO | | memory/innodb/dict0mem | NO | NO | | memory/innodb/dict0stats | NO | NO | | memory/innodb/dict0stats_bg | NO | NO | | memory/innodb/eval0eval | NO | NO | | memory/innodb/fil0fil | NO | NO | | memory/innodb/file | NO | NO | | memory/innodb/fsp0file | NO | NO | | memory/innodb/fsp0space | NO | NO | | memory/innodb/fsp0sysspace | NO | NO | | memory/innodb/fts0ast | NO | NO | | memory/innodb/fts0config | NO | NO | | memory/innodb/fts0fts | NO | NO | | memory/innodb/fts0opt | NO | NO | | memory/innodb/fts0pars | NO | NO | | memory/innodb/fts0que | NO | NO | | memory/innodb/fts0sql | NO | NO | | memory/innodb/fts0types | NO | NO | | memory/innodb/gis0sea | NO | NO | | memory/innodb/gis0type | NO | NO | | memory/innodb/ha0ha | NO | NO | | memory/innodb/ha_innodb | NO | NO | | memory/innodb/ha_innopart | NO | NO | | memory/innodb/handler0alter | NO | NO | | memory/innodb/hash0hash | NO | NO | | memory/innodb/i_s | NO | NO | | memory/innodb/ibuf0ibuf | NO | NO | | memory/innodb/lexyy | NO | NO | | memory/innodb/lock0lock | NO | NO | | memory/innodb/log0log | NO | NO | | memory/innodb/log0recv | NO | NO | | memory/innodb/mem | NO | NO | | memory/innodb/mem0mem | NO | NO | | memory/innodb/memory | NO | NO | | memory/innodb/os0event | NO | NO | | memory/innodb/os0file | NO | NO | | memory/innodb/page0cur | NO | NO | | memory/innodb/page0types | NO | NO | | memory/innodb/page0zip | NO | NO | | memory/innodb/pars0lex | NO | NO | | memory/innodb/read0read | NO | NO | | memory/innodb/rem0rec | NO | NO | | memory/innodb/row0ftsort | NO | NO | | memory/innodb/row0import | NO | NO | | memory/innodb/row0log | NO | NO | | memory/innodb/row0merge | NO | NO | | memory/innodb/row0mysql | NO | NO | | memory/innodb/row0sel | NO | NO | | memory/innodb/row0trunc | NO | NO | | memory/innodb/sess0sess | NO | NO | | memory/innodb/srv0conc | NO | NO | | memory/innodb/srv0srv | NO | NO | | memory/innodb/srv0start | NO | NO | | memory/innodb/sync0arr | NO | NO | | memory/innodb/sync0debug | NO | NO | | memory/innodb/sync0rw | NO | NO | | memory/innodb/sync0types | NO | NO | | memory/innodb/trx0i_s | NO | NO | | memory/innodb/trx0purge | NO | NO | | memory/innodb/trx0roll | NO | NO | | memory/innodb/trx0rseg | NO | NO | | memory/innodb/trx0sys | NO | NO | | memory/innodb/trx0trx | NO | NO | | memory/innodb/trx0types | NO | NO | | memory/innodb/trx0undo | NO | NO | | memory/innodb/usr0sess | NO | NO | | memory/innodb/ut0list | NO | NO | | memory/innodb/ut0lock_free_hash | NO | NO | | memory/innodb/ut0mem | NO | NO | | memory/innodb/ut0mutex | NO | NO | | memory/innodb/ut0new | NO | NO | | memory/innodb/ut0pool | NO | NO | | memory/innodb/ut0rbt | NO | NO | | memory/innodb/ut0vec | NO | NO | | memory/innodb/ut0wqueue | NO | NO | +---------------------------------------------------------+---------+-------+ 183 rows in set (0.01 sec) mysql> select * from setup_instruments where name like '%innodb%' and name not like '%memory%'; +---------------------------------------------------------+---------+-------+ | NAME | ENABLED | TIMED | +---------------------------------------------------------+---------+-------+ | wait/synch/mutex/innodb/commit_cond_mutex | NO | NO | | wait/synch/mutex/innodb/innobase_share_mutex | NO | NO | | wait/synch/mutex/innodb/autoinc_mutex | NO | NO | | wait/synch/mutex/innodb/autoinc_persisted_mutex | NO | NO | | wait/synch/mutex/innodb/buf_pool_flush_state_mutex | NO | NO | | wait/synch/mutex/innodb/buf_pool_LRU_list_mutex | NO | NO | | wait/synch/mutex/innodb/buf_pool_free_list_mutex | NO | NO | | wait/synch/mutex/innodb/buf_pool_zip_free_mutex | NO | NO | | wait/synch/mutex/innodb/buf_pool_zip_hash_mutex | NO | NO | | wait/synch/mutex/innodb/buf_pool_zip_mutex | NO | NO | | wait/synch/mutex/innodb/cache_last_read_mutex | NO | NO | | wait/synch/mutex/innodb/dict_foreign_err_mutex | NO | NO | | wait/synch/mutex/innodb/dict_persist_dirty_tables_mutex | NO | NO | | wait/synch/mutex/innodb/dict_sys_mutex | NO | NO | | wait/synch/mutex/innodb/recalc_pool_mutex | NO | NO | | wait/synch/mutex/innodb/fil_system_mutex | NO | NO | | wait/synch/mutex/innodb/flush_list_mutex | NO | NO | | wait/synch/mutex/innodb/fts_bg_threads_mutex | NO | NO | | wait/synch/mutex/innodb/fts_delete_mutex | NO | NO | | wait/synch/mutex/innodb/fts_optimize_mutex | NO | NO | | wait/synch/mutex/innodb/fts_doc_id_mutex | NO | NO | | wait/synch/mutex/innodb/log_flush_order_mutex | NO | NO | | wait/synch/mutex/innodb/hash_table_mutex | NO | NO | | wait/synch/mutex/innodb/ibuf_bitmap_mutex | NO | NO | | wait/synch/mutex/innodb/ibuf_mutex | NO | NO | | wait/synch/mutex/innodb/ibuf_pessimistic_insert_mutex | NO | NO | | wait/synch/mutex/innodb/log_sys_mutex | NO | NO | | wait/synch/mutex/innodb/log_sys_write_mutex | NO | NO | | wait/synch/mutex/innodb/mutex_list_mutex | NO | NO | | wait/synch/mutex/innodb/page_zip_stat_per_index_mutex | NO | NO | | wait/synch/mutex/innodb/purge_sys_pq_mutex | NO | NO | | wait/synch/mutex/innodb/recv_sys_mutex | NO | NO | | wait/synch/mutex/innodb/recv_writer_mutex | NO | NO | | wait/synch/mutex/innodb/redo_rseg_mutex | NO | NO | | wait/synch/mutex/innodb/noredo_rseg_mutex | NO | NO | | wait/synch/mutex/innodb/rw_lock_list_mutex | NO | NO | | wait/synch/mutex/innodb/rw_lock_mutex | NO | NO | | wait/synch/mutex/innodb/srv_dict_tmpfile_mutex | NO | NO | | wait/synch/mutex/innodb/srv_innodb_monitor_mutex | NO | NO | | wait/synch/mutex/innodb/srv_misc_tmpfile_mutex | NO | NO | | wait/synch/mutex/innodb/srv_monitor_file_mutex | NO | NO | | wait/synch/mutex/innodb/buf_dblwr_mutex | NO | NO | | wait/synch/mutex/innodb/trx_undo_mutex | NO | NO | | wait/synch/mutex/innodb/trx_pool_mutex | NO | NO | | wait/synch/mutex/innodb/trx_pool_manager_mutex | NO | NO | | wait/synch/mutex/innodb/srv_sys_mutex | NO | NO | | wait/synch/mutex/innodb/lock_mutex | NO | NO | | wait/synch/mutex/innodb/lock_wait_mutex | NO | NO | | wait/synch/mutex/innodb/trx_mutex | NO | NO | | wait/synch/mutex/innodb/srv_threads_mutex | NO | NO | | wait/synch/mutex/innodb/rtr_active_mutex | NO | NO | | wait/synch/mutex/innodb/rtr_match_mutex | NO | NO | | wait/synch/mutex/innodb/rtr_path_mutex | NO | NO | | wait/synch/mutex/innodb/rtr_ssn_mutex | NO | NO | | wait/synch/mutex/innodb/trx_sys_mutex | NO | NO | | wait/synch/mutex/innodb/zip_pad_mutex | NO | NO | | wait/synch/mutex/innodb/master_key_id_mutex | NO | NO | | wait/synch/sxlock/innodb/btr_search_latch | NO | NO | | wait/synch/sxlock/innodb/dict_operation_lock | NO | NO | | wait/synch/sxlock/innodb/fil_space_latch | NO | NO | | wait/synch/sxlock/innodb/checkpoint_lock | NO | NO | | wait/synch/sxlock/innodb/fts_cache_rw_lock | NO | NO | | wait/synch/sxlock/innodb/fts_cache_init_rw_lock | NO | NO | | wait/synch/sxlock/innodb/trx_i_s_cache_lock | NO | NO | | wait/synch/sxlock/innodb/trx_purge_latch | NO | NO | | wait/synch/sxlock/innodb/index_tree_rw_lock | NO | NO | | wait/synch/sxlock/innodb/index_online_log | NO | NO | | wait/synch/sxlock/innodb/dict_table_stats | NO | NO | | wait/synch/sxlock/innodb/hash_table_locks | NO | NO | | wait/synch/cond/innodb/commit_cond | NO | NO | | wait/io/file/innodb/innodb_data_file | YES | YES | | wait/io/file/innodb/innodb_log_file | YES | YES | | wait/io/file/innodb/innodb_temp_file | YES | YES | | stage/innodb/alter table (end) | YES | YES | | stage/innodb/alter table (flush) | YES | YES | | stage/innodb/alter table (insert) | YES | YES | | stage/innodb/alter table (log apply index) | YES | YES | | stage/innodb/alter table (log apply table) | YES | YES | | stage/innodb/alter table (merge sort) | YES | YES | | stage/innodb/alter table (read PK and internal sort) | YES | YES | | stage/innodb/buffer pool load | YES | YES | +---------------------------------------------------------+---------+-------+ 81 rows in set (0.00 sec) All we can wait for in Galera: MariaDB [performance_schema]> select * from setup_instruments where name like '%wsrep%'; +-----------------------------------------------+---------+-------+ | NAME | ENABLED | TIMED | +-----------------------------------------------+---------+-------+ | wait/synch/mutex/sql/LOCK_wsrep_ready | YES | YES | | wait/synch/mutex/sql/LOCK_wsrep_sst | YES | YES | | wait/synch/mutex/sql/wsrep_sst_thread | YES | YES | | wait/synch/mutex/sql/LOCK_wsrep_sst_init | YES | YES | | wait/synch/mutex/sql/LOCK_wsrep_rollback | YES | YES | | wait/synch/mutex/sql/THD::LOCK_wsrep_thd | YES | YES | | wait/synch/mutex/sql/LOCK_wsrep_replaying | YES | YES | | wait/synch/mutex/sql/LOCK_wsrep_slave_threads | YES | YES | | wait/synch/mutex/sql/LOCK_wsrep_desync | YES | YES | | wait/synch/mutex/sql/LOCK_wsrep_config_state | YES | YES | | wait/synch/cond/sql/COND_wsrep_ready | YES | YES | | wait/synch/cond/sql/COND_wsrep_sst | YES | YES | | wait/synch/cond/sql/COND_wsrep_sst_init | YES | YES | | wait/synch/cond/sql/wsrep_sst_thread | YES | YES | | wait/synch/cond/sql/COND_wsrep_rollback | YES | YES | | wait/synch/cond/sql/COND_wsrep_replaying | YES | YES | | wait/io/file/sql/wsrep_gra_log | YES | YES | +-----------------------------------------------+---------+-------+ 17 rows in set (0.00 sec) perf top (filer for "inno"): 5.52% mysqld [.] log_block_calc_checksum_innodb 0.05% mysqld [.] ha_innobase::update_row 0.02% mysqld [.] row_mysql_store_col_in_innobase_format 0.00% mysqld [.] ha_innobase::general_fetch 0.00% mysqld [.] ha_innobase::was_semi_consistent_read 0.00% mysqld [.] innobase_get_slow_log 0.00% mysqld [.] ha_innobase::index_next Á¦-0.00% mysqld [.] ha_innobase::multi_range_read_next 0.00% mysqld [.] srv_conc_enter_innodb ------ perf record -p `pidof mysqld` sleep 20 perf report perf record -a -g -F99 -p 7196 -- sleep 60 perf report >/tmp/perf.txt /proc/sys/kernel/perf_event_paranoid http://www.fromdual.ch/mysql-oprofile sudo operf -p `pidof mysqld` operf: Press Ctl-c or 'kill -SIGINT 2569' to stop profiling operf: Profiler started ... opreport --demangle=smart --symbols --long-filenames --merge tgid $(which mysqld) | head -n 20 http://oprofile.sourceforge.net/news/ oprofile-related/based bug reports: [root@centos ~]# operf --version Your kernel's Performance Events Subsystem does not support your processor type. Please use the opcontrol command instead of operf. operf - for non-root https://bugs.mysql.com/bug.php?id=29921 https://bugs.mysql.com/bug.php?id=31551 - still Verified https://bugs.mysql.com/bug.php?id=33948 https://bugs.mysql.com/bug.php?id=43161 https://bugs.mysql.com/bug.php?id=44723 https://bugs.mysql.com/bug.php?id=49047 https://bugs.mysql.com/bug.php?id=49169 https://bugs.mysql.com/bug.php?id=49177 - fixed only in 5.7.9+ and 8.0 https://bugs.mysql.com/bug.php?id=53825 - InnoDB locks removing from queue, still "Verified" https://bugs.mysql.com/bug.php?id=56332 https://bugs.mysql.com/bug.php?id=58037 - fixed in 5.5+ by MDL https://bugs.mysql.com/bug.php?id=61401 - MDL https://bugs.mysql.com/bug.php?id=64304 - still Verified, ping Marko about it https://bugs.mysql.com/bug.php?id=68818 - optimizer bug https://bugs.mysql.com/bug.php?id=72115 - partititoning, perf-related/based bug reports by Mark Callaghan: https://bugs.mysql.com/bug.php?id=69236 https://bugs.mysql.com/bug.php?id=74325 https://bugs.mysql.com/bug.php?id=68588 -- https://bugs.mysql.com/bug.php?id=45892 http://bugs.mysql.com/bug.php?id=74280 - P_S does NOT instrument this http://bugs.mysql.com/bug.php?id=74283 - see above http://smalldatum.blogspot.com/2014/10/details-on-range-scan-performance.html - on 2 bugs above, perf allows to see the difference - flat vs hierarchical perf output pmp: https://bugs.mysql.com/bug.php?id=78277 https://bugs.mysql.com/bug.php?id=62018 https://bugs.mysql.com/bug.php?id=68069 - impact of inlined functions on profiling https://bugs.mysql.com/bug.php?id=62425 - tell Marko about it perf-related/based bug reports by Mark Callaghan: https://bugs.mysql.com/bug.php?id=69236 https://bugs.mysql.com/bug.php?id=74325 https://bugs.mysql.com/bug.php?id=68588 -- https://bugs.mysql.com/bug.php?id=45892 http://bugs.mysql.com/bug.php?id=74280 - P_S does NOT instrument this http://bugs.mysql.com/bug.php?id=74283 - see above http://smalldatum.blogspot.com/2014/10/details-on-range-scan-performance.html - on 2 bugs above, perf allows to see the difference - flat vs hierarchical perf output pmp: https://bugs.mysql.com/bug.php?id=78277 https://bugs.mysql.com/bug.php?id=62018 https://bugs.mysql.com/bug.php?id=68069 - impact of inlined functions on profiling https://bugs.mysql.com/bug.php?id=62425 - tell Marko about it http://www.brendangregg.com/perf.html sudo perf report -g -n --stdio Ubuntu 16:04: oprofile, 1.1.0-0ubuntu1.1 --> 0.9.9 openxs@ubuntu:~$ operf --version Your kernel's Performance Events Subsystem does not support your processor type. sudo apt-get remove oprofile sudo apt-cache showpkg oprofile perf --> linux-tools-common linux-tools-generic https://bugs.mysql.com/bug.php?id=39630 - benchmark() bug pt-stalk: local have_oprofile="" if [ "$CMD_OPCONTROL" -a "$OPT_COLLECT_OPROFILE" ]; then if $CMD_OPCONTROL --init; then $CMD_OPCONTROL --start --no-vmlinux have_oprofile="yes" fi ... if [ "$have_oprofile" ]; then $CMD_OPCONTROL --stop $CMD_OPCONTROL --dump local oprofiled_pid=$(_pidof oprofiled | awk '{print $1; exit;}') if [ "$oprofiled_pid" ]; then kill $oprofiled_pid else warn "Cannot kill oprofiled because its PID cannot be determined" fi $CMD_OPCONTROL --save=pt_collect_$p local mysqld_path=$(_which mysqld); if [ "$mysqld_path" -a -f "$mysqld_path" ]; then $CMD_OPREPORT \ --demangle=smart \ --symbols \ --merge tgid \ session:pt_collect_$p \ "$mysqld_path" \ > "$d/$p-opreport" https://bugs.launchpad.net/percona-toolkit/+bug/1152571 - oprofile does not work for Galera in PXC ToDo: report a bug about oprofile in pt-stalk and new oprofile 10.x.y http://stackoverflow.com/questions/8319126/using-o-profile-with-linux-redhat-os-conflict-with-nmi-watchdog http://stackoverflow.com/questions/22071808/oprofile-error-failed-to-open-profile-device-device-or-resource-busy echo "0" | sudo tee /proc/sys/kernel/watchdog [root@centos ~]# opcontrol --start-daemon Count 100000 for event CPU_CLK_UNHALTED is below the minimum 750000 Using default event: CPU_CLK_UNHALTED:100000:0:1:1 Count 100000 for event CPU_CLK_UNHALTED is below the minimum 750000 [root@centos ~]# opcontrol --start-daemon --event=CPU_CLK_UNHALTED:750000:0:1:1 http://oprofile.sourceforge.net/faq/ https://sourceforge.net/p/oprofile/mailman/message/34174881/ - oprofile vs perf vs gperf http://rhaas.blogspot.com/2012/06/perf-good-bad-ugly.html http://oprofile-list.sf.narkive.com/rVbJlHdX/oprofile-vs-perf https://en.wikipedia.org/wiki/OProfile 2001 https://en.wikipedia.org/wiki/Perf_(Linux), PCL, 2.6.31+, 2010 P_S in Galera: MariaDB [test]> select name from performance_schema.setup_instruments where name like '%wsrep%'; +-----------------------------------------------+ | name | +-----------------------------------------------+ | wait/synch/mutex/sql/LOCK_wsrep_ready | | wait/synch/mutex/sql/LOCK_wsrep_sst | | wait/synch/mutex/sql/wsrep_sst_thread | | wait/synch/mutex/sql/LOCK_wsrep_sst_init | | wait/synch/mutex/sql/LOCK_wsrep_rollback | | wait/synch/mutex/sql/THD::LOCK_wsrep_thd | | wait/synch/mutex/sql/LOCK_wsrep_replaying | | wait/synch/mutex/sql/LOCK_wsrep_slave_threads | | wait/synch/mutex/sql/LOCK_wsrep_desync | | wait/synch/mutex/sql/LOCK_wsrep_config_state | | wait/synch/cond/sql/COND_wsrep_ready | | wait/synch/cond/sql/COND_wsrep_sst | | wait/synch/cond/sql/COND_wsrep_sst_init | | wait/synch/cond/sql/wsrep_sst_thread | | wait/synch/cond/sql/COND_wsrep_rollback | | wait/synch/cond/sql/COND_wsrep_replaying | | wait/io/file/sql/wsrep_gra_log | +-----------------------------------------------+ 17 rows in set (0.00 sec) "profiling ("program profiling", "software profiling") is a form of dynamic program analysis that measures, for example, the space (memory) or time complexity of a program, the usage of particular instructions, or the frequency and duration of function calls. Most commonly, profiling information serves to aid program optimization. Profiling is achieved by instrumenting either the program source code or its binary executable form using a tool called a profiler (or code profiler). Profilers may use a number of different techniques, such as event-based, statistical, instrumented, and simulation methods." [openxs@fc23 maria10.1]$ perf record -p `pidof mysqld` sleep 20 & [2] 17935 [openxs@fc23 maria10.1]$ time bin/mysql -uroot -e'select benchmark(500000000, 2*2)' +---------------------------+ | benchmark(500000000, 2*2) | +---------------------------+ | 0 | +---------------------------+ real 0m13.204s user 0m0.004s sys 0m0.006s [openxs@fc23 maria10.1]$ [ perf record: Woken up 9 times to write data ] [ perf record: Captured and wrote 2.129 MB perf.data (53010 samples) ] [2]+ Done perf record -p `pidof mysqld` sleep 20 [openxs@fc23 maria10.1]$ perf report --stdio | head - 100 ==> standard input <== # To display the perf.data header info, please use --header/--header-only options. # # # Total Lost Samples: 0 # # Samples: 53K of event 'cycles:u' # Event count (approx.): 32683071926 # # Overhead Command Shared Object Symbol # ........ ....... .................. ........................................... head: cannot open '100' for reading: No such file or directory [openxs@fc23 maria10.1]$ q bash: q: command not found... [openxs@fc23 maria10.1]$ perf report --stdio | head -100 # To display the perf.data header info, please use --header/--header-only options. # # # Total Lost Samples: 0 # # Samples: 53K of event 'cycles:u' # Event count (approx.): 32683071926 # # Overhead Command Shared Object Symbol # ........ ....... .................. ........................................... # 59.16% mysqld mysqld [.] Item_func_mul::int_op 15.19% mysqld mysqld [.] Item_func_hybrid_field_type::val_int 9.03% mysqld mysqld [.] Item_func_benchmark::val_int 6.56% mysqld mysqld [.] Item_int::val_int 3.73% mysqld mysqld [.] Item_hybrid_func::result_type 3.23% mysqld mysqld [.] Type_handler_int_result::cmp_type 3.04% mysqld mysqld [.] Type_handler_int_result::result_type 0.02% mysqld [kernel.kallsyms] [k] __irqentry_text_start 0.02% mysqld libc-2.24.so [.] __memset_sse2_unaligned_erms ... Getting call-graph from oprofile: opreport --session-dir=/tmp --demangle=smart --symbols --merge tgid /home/openxs/dbs/maria10.1/bin/mysqld in --session-dir (if it was set), or `pwd`/oprofile_data, or, if that directory does not exist, the standard session-dir of /var/lib/oprofile is used load the OProfile module if required and make the OProfile driver interface available === perf session on CentOS 6.8 === [root@centos ~]# perf --version perf version 2.6.32-642.13.1.el6.x86_64.debug [root@centos ~]# rpm -q -a | grep perf perf-2.6.32-642.13.1.el6.x86_64 gperf-3.0.3-9.1.el6.x86_64 [root@centos ~]# [root@centos ~]# perf record -p `pidof mysqld` sleep 20 [ perf record: Woken up 8 times to write data ] [ perf record: Captured and wrote 2.151 MB perf.data (52139 samples) ] [root@centos ~]# perf report -n --stdio Failed to open [vsyscall], continuing without symbols # To display the perf.data header info, please use --header/--header-only option # # Samples: 52K of event 'cpu-clock' # Event count (approx.): 13034750000 # # Overhead Samples Command Shared Object Symbol # ........ ............ ....... .................. ......................... # 43.48% 22669 mysqld mysqld [.] Item_func_mul::int_op 22.23% 11588 mysqld mysqld [.] Item_int::val_int 14.82% 7725 mysqld mysqld [.] Item_func_numhybrid:: 10.80% 5632 mysqld mysqld [.] Item_func_benchmark:: 8.20% 4276 mysqld mysqld [.] Item_func_numhybrid:: 0.25% 131 mysqld [kernel.kallsyms] [k] finish_task_switch 0.05% 28 mysqld [kernel.kallsyms] [k] _spin_unlock_irqresto 0.04% 19 mysqld [vsyscall] [.] 0x000000000000014c 0.03% 14 mysqld [kernel.kallsyms] [k] clocksource_watchdog 0.02% 11 mysqld [kernel.kallsyms] [k] ioread32 0.01% 5 mysqld libc-2.12.so [.] __memset_sse2 0.01% 4 mysqld [kernel.kallsyms] [k] iowrite32 ... [root@centos ~]# perf report -n --header --stdio Failed to open [vsyscall], continuing without symbols # ======== # captured on: Sat Jan 28 20:17:07 2017 # hostname : centos # os release : 2.6.32-642.13.1.el6.x86_64 # perf version : 2.6.32-642.13.1.el6.x86_64.debug # arch : x86_64 # nrcpus online : 1 # nrcpus avail : 1 # cpudesc : AMD C-50 Processor # cpuid : AuthenticAMD,20,1,0 # total memory : 1536164 kB # cmdline : /usr/bin/perf record -p 1960 sleep 20 # event : name = cpu-clock, , type = 1, size = 104, { sample_period, sample_freq # HEADER_CPU_TOPOLOGY info available, use -I to display # HEADER_NUMA_TOPOLOGY info available, use -I to display # pmu mappings: tracepoint = 2, software = 1 # ======== # ... [root@centos ~]# perf record `pidof mysqld` sleep 20 Workload failed: No such file or directory [root@centos ~]# perf record -ag ^C[ perf record: Woken up 63 times to write data ] [ perf record: Captured and wrote 15.702 MB perf.data (226643 samples) ] [root@centos ~]perf record -ag & [1] 2353 [root@centos ~]# mysql -uroot -e'select benchmakr(500000000,2*2);' ERROR 1046 (3D000) at line 1: No database selected [root@centos ~]# mysql -uroot -e'select benchmakr(500000000,2*2);' test ERROR 1305 (42000) at line 1: FUNCTION test.benchmakr does not exist [root@centos ~]# mysql -uroot -e'select benchmark(500000000,2*2);' test +--------------------------+ | benchmark(500000000,2*2) | +--------------------------+ | 0 | +--------------------------+ [root@centos ~]# kill -sigint 2353 [ perf record: Woken up 90 times to write data ] [root@centos ~]# [ perf record: Captured and wrote 22.366 MB perf.data (322362 samples) ] [1]+ Interrupt perf record -ag [root@centos ~]# ps aux | grep perf root 2358 0.0 0.0 103312 864 pts/0 S+ 22:16 0:00 grep perf [root@centos ~]# perf report -g --stdio Failed to open [vsyscall], continuing without symbols no symbols found in /usr/sbin/fcoemon, maybe install a debug package? # To display the perf.data header info, please use --header/--header-only option # # Samples: 226K of event 'cpu-clock' # Event count (approx.): 56660750000 # # Children Self Command Shared Object Symbol # ........ ........ ............. ........................... .............. # 43.02% 42.82% mysqld mysqld [.] Item_func_ | ---Item_func_mul::int_op 21.74% 21.64% mysqld mysqld [.] Item_int:: | ---Item_int::val_int 14.84% 14.77% mysqld mysqld [.] Item_func_ | ---Item_func_numhybrid::val_int 10.80% 10.76% mysqld mysqld [.] Item_func_ | ---Item_func_benchmark::val_int 8.31% 8.28% mysqld mysqld [.] Item_func_ | ---Item_func_numhybrid::result_type 0.38% 0.38% mysqld [kernel.kallsyms] [k] finish_tas | ---finish_task_switch | |--33.83%-- Item_func_mul::int_op | |--23.05%-- 0x614 | | | --100.00%-- LinuxAIOHandler::poll | os_aio_handler |--33.83%-- Item_func_mul::int_op | |--23.05%-- 0x614 | | | --100.00%-- LinuxAIOHandler::poll | os_aio_handler | fil_aio_wait | io_handler_thread | start_thread | |--17.32%-- Item_int::val_int | |--10.21%-- Item_func_numhybrid::val_int | |--7.80%-- Item_func_benchmark::val_int | |--6.08%-- Item_func_numhybrid::result_type | |--0.57%-- 0xf00d | srv_master_thread | start_thread --1.15%-- [...] ... Incomplete stacks usually mean -fomit-frame-pointer was used https://perf.wiki.kernel.org/index.php/Main_Page In per-cpu mode mode, samples are collected for all threads executing on the monitored CPU. To switch perf record in per-cpu mode, the -a option must be used. By default in this mode, ALL online CPUs are monitored. perf trace perf trace -p `pidof mysqld` perf report --stdio -n -g folded (on 4.4 kernels) Here operf does NOT work well... [root@centos ~]# operf -s Your kernel's Performance Events Subsystem does not support your processor type. Please use the opcontrol command instead of operf. [root@centos ~]# opcontrol --init [root@centos ~]# opcontrol --start Using 2.6+ OProfile kernel interface. Using log file /root/samples/oprofiled.log Daemon started. Profiler running. [root@centos ~]# opcontrol --stop Stopping profiling. [root@centos ~]# opcontrol --dump [root@centos ~]# ps aux | grep mysqld root 1311 0.0 0.1 108316 1684 ? S 20:13 0:00 /bin/sh /usr/bin/mysqld_safe --datadir=/var/lib/mysql --socket=/var/lib/mysql/mysql.sock --pid-file=/var/run/mysqld/mysqld.pid --basedir=/usr --user=mysql mysql 1960 44.2 16.3 869860 250400 ? Sl 20:13 7:11 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock root 2577 0.0 0.0 103312 864 pts/0 S+ 20:29 0:00 grep mysqld [root@centos ~]# opreport --demangle=smart --symbols --merge tgid /usr/sbin/mysqld | head -20 Using /var/lib/oprofile/samples/ for samples directory. error: no sample files found: profile specification too strict ? ------ Impact of perf anf perf -g ----- openxs@ao756:~/dbs/maria10.1$ perf --version perf version 3.13.11-ckt39 openxs@ao756:~/dbs/maria10.1$ dpkg -S `which perf` linux-tools-common: /usr/bin/perf Without -g: openxs@ao756:~/dbs/maria10.1$ time bin/mysql -uroot -e'select benchmark(500000000, 2*2)' +---------------------------+ | benchmark(500000000, 2*2) | +---------------------------+ | 0 | +---------------------------+ real 0m19.787s user 0m0.011s sys 0m0.000s With -g: openxs@ao756:~/dbs/maria10.1$ time bin/mysql -uroot -e'select benchmark(500000000, 2*2)' +---------------------------+ | benchmark(500000000, 2*2) | +---------------------------+ | 0 | +---------------------------+ real 0m20.177s user 0m0.009s sys 0m0.004s 2017-01-22 21:42:21 140232387905472 [Note] InnoDB: Using SSE crc32 instructions for i in `seq 1 6`; do bin/mysqlslap -uroot --no-drop --create-schema=test --number-of-queries=1000 iternations=10 --concurrency=1 --query="update t$i set c2 = rand() where id between 2000 and 300000;" & done === More on impact of profiling === 5.7.17 No profiling: [openxs@fc23 5.7]$ time bin/mysql -uroot -e'select benchmark(500000000, 2*2)' +---------------------------+ | benchmark(500000000, 2*2) | +---------------------------+ | 0 | +---------------------------+ real 0m11.272s user 0m0.009s sys 0m0.002s perf record -a [openxs@fc23 ~]$ sudo perf record -a ^C[ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 1.125 MB perf.data (801 samples) ] [openxs@fc23 5.7]$ time bin/mysql -uroot -e'select benchmark(500000000, 2*2)' +---------------------------+ | benchmark(500000000, 2*2) | +---------------------------+ | 0 | +---------------------------+ real 0m11.474s user 0m0.007s sys 0m0.004s perf record -ag [openxs@fc23 ~]$ sudo perf record -ag ^C[ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 1.234 MB perf.data (966 samples) ] [openxs@fc23 5.7]$ time bin/mysql -uroot -e'select benchmark(500000000, 2*2)' +---------------------------+ | benchmark(500000000, 2*2) | +---------------------------+ | 0 | +---------------------------+ real 0m11.485s user 0m0.008s sys 0m0.003s [openxs@fc23 ~]$ sudo operf -s operf: Press Ctl-c or 'kill -SIGINT 1530' to stop profiling operf: Profiler started ^C* * * * WARNING: Profiling rate was throttled back by the kernel * * * * The number of samples actually recorded is less than expected, but is probably still statistically valid. Decreasing the sampling rate is the best option if you want to avoid throttling. Profiling done. [openxs@fc23 5.7]$ time bin/mysql -uroot -e'select benchmark(500000000, 2*2)' +---------------------------+ | benchmark(500000000, 2*2) | +---------------------------+ | 0 | +---------------------------+ real 0m13.057s user 0m0.007s sys 0m0.005s [openxs@fc23 ~]$ sudo operf -s -g operf: Press Ctl-c or 'kill -SIGINT 1756' to stop profiling operf: Profiler started ^C * * * ATTENTION: The kernel lost 3192 samples. * * * Decrease the sampling rate to eliminate (or reduce) lost samples. WARNING: Lost samples detected! See /home/openxs/oprofile_data/samples/operf.log for details. Lowering the sampling rate may reduce or eliminate lost samples. See the '--events' option description in the operf man page for help. Profiling done. [openxs@fc23 5.7]$ time bin/mysql -uroot -e'select benchmark(500000000, 2*2)' +---------------------------+ | benchmark(500000000, 2*2) | +---------------------------+ | 0 | +---------------------------+ real 0m13.450s user 0m0.007s sys 0m0.004s [openxs@fc23 ~]$ pt-pmp Tue Jan 31 13:19:33 EET 2017 10 __io_getevents_0_4(libaio.so.1),LinuxAIOHandler::collect(os0file.cc:2492),LinuxAIOHandler::poll(os0file.cc:2638),os_aio_linux_handler(os0file.cc:2694),os_aio_handler(os0file.cc:2694),fil_aio_wait(fil0fil.cc:5817),io_handler_thread(srv0start.cc:308),start_thread(libpthread.so.0),clone(libc.so.6) 3 pthread_cond_wait,os_event::wait(os0event.cc:165),os_event::wait_low(os0event.cc:165),os_event_wait_low(os0event.cc:534),srv_worker_thread(srv0srv.cc:2506),start_thread(libpthread.so.0),clone(libc.so.6) 1 sigwait(libpthread.so.0),signal_hand(mysqld.cc:2101),pfs_spawn_thread(pfs.cc:2188),start_thread(libpthread.so.0),clone(libc.so.6) 1 sigwaitinfo(libc.so.6),timer_notify_thread_func(posix_timers.c:77),pfs_spawn_thread(pfs.cc:2188),start_thread(libpthread.so.0),clone(libc.so.6) 1 pthread_cond_wait,os_event::wait(os0event.cc:165),os_event::wait_low(os0event.cc:165),os_event_wait_low(os0event.cc:534),srv_purge_coordinator_suspend(srv0srv.cc:2662),srv_purge_coordinator_thread(srv0srv.cc:2662),start_thread(libpthread.so.0),clone(libc.so.6) 1 pthread_cond_wait,os_event::wait(os0event.cc:165),os_event::wait_low(os0event.cc:165),os_event_wait_low(os0event.cc:534),buf_resize_thread(buf0buf.cc:3015),start_thread(libpthread.so.0),clone(libc.so.6) 1 pthread_cond_wait,os_event::wait(os0event.cc:165),os_event::wait_low(os0event.cc:165),os_event_wait_low(os0event.cc:534),buf_dump_thread(buf0dump.cc:781),start_thread(libpthread.so.0),clone(libc.so.6) 1 pthread_cond_wait,native_cond_wait(thr_cond.h:140),my_cond_wait(thr_cond.h:140),inline_mysql_cond_wait(thr_cond.h:140),Per_thread_connection_handler::block_until_new_connection(thr_cond.h:140),handle_connection(connection_handler_per_thread.cc:329),pfs_spawn_thread(pfs.cc:2188),start_thread(libpthread.so.0),clone(libc.so.6) 1 pthread_cond_wait,native_cond_wait(thr_cond.h:140),my_cond_wait(thr_cond.h:140),inline_mysql_cond_wait(thr_cond.h:140),compress_gtid_table(thr_cond.h:140),pfs_spawn_thread(pfs.cc:2188),start_thread(libpthread.so.0),clone(libc.so.6) 1 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:285),os_event::wait_time_low(os0event.cc:412),os_event_wait_time_low(os0event.cc:517),srv_monitor_thread(srv0srv.cc:1571),start_thread(libpthread.so.0),clone(libc.so.6) 1 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:285),os_event::wait_time_low(os0event.cc:412),os_event_wait_time_low(os0event.cc:517),srv_error_monitor_thread(srv0srv.cc:1737),start_thread(libpthread.so.0),clone(libc.so.6) 1 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:285),os_event::wait_time_low(os0event.cc:412),os_event_wait_time_low(os0event.cc:517),pc_sleep_if_needed(buf0flu.cc:2690),buf_flush_page_cleaner_coordinator(buf0flu.cc:2690),start_thread(libpthread.so.0),clone(libc.so.6) 1 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:285),os_event::wait_time_low(os0event.cc:412),os_event_wait_time_low(os0event.cc:517),lock_wait_timeout_thread(lock0wait.cc:501),start_thread(libpthread.so.0),clone(libc.so.6) 1 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:285),os_event::wait_time_low(os0event.cc:412),os_event_wait_time_low(os0event.cc:517),ib_wqueue_timedwait(ut0wqueue.cc:160),fts_optimize_thread(fts0opt.cc:3040),start_thread(libpthread.so.0),clone(libc.so.6) 1 pthread_cond_timedwait,os_event::timed_wait(os0event.cc:285),os_event::wait_time_low(os0event.cc:412),os_event_wait_time_low(os0event.cc:517),dict_stats_thread(dict0stats_bg.cc:421),start_thread(libpthread.so.0),clone(libc.so.6) 1 poll(libc.so.6),Mysqld_socket_listener::listen_for_connection_event(socket_connection.cc:845),Connection_acceptor::connection_event_loop(connection_acceptor.h:66),mysqld_main(connection_acceptor.h:66),__libc_start_main(libc.so.6),_start 1 nanosleep(libpthread.so.0),os_thread_sleep(os0thread.cc:279),srv_master_sleep(srv0srv.cc:2316),srv_master_thread(srv0srv.cc:2316),start_thread(libpthread.so.0),clone(libc.so.6) [openxs@fc23 5.7]$ time bin/mysql -uroot -e'select benchmark(500000000, 2*2)' +---------------------------+ | benchmark(500000000, 2*2) | +---------------------------+ | 0 | +---------------------------+ real 0m18.268s user 0m0.006s sys 0m0.003s