第6章　performance_schema应用示例荟萃 - xiaoboluo768/qianjinliangfang GitHub Wiki

6.1　利用等待事件排查MySQL性能问题

# 启用所有等待事件的instruments
mysql> use performance_schema
Database changed
# 修改setup_instruments 表的enabled和timed字段为yes，表示启用对应的instruments
mysql> update setup_instruments set enabled='yes', timed='yes' where name like 'wait/%';
Query OK, 269 rows affected (0.00 sec)
Rows matched: 323  Changed: 269  Warnings: 0

# 查看修改结果，enabled和timed字段为yes即表示当前instruments已经启用（但此时采集器并不会立即采集事件数据，需要保存这些等待事件的表，当consumers启用之后才会开始采集）
mysql> select * from setup_instruments where name like 'wait/%';
......
323 rows in set (0.01 sec)

# 启用等待事件的consumers
mysql> update setup_consumers set enabled='yes' where name like '%wait%';
Query OK, 3 rows affected (0.00 sec)
Rows matched: 3  Changed: 3  Warnings: 0

mysql> select * from setup_consumers where name like '%wait%';
......
3 rows in set (0.00 sec)

[root@localhost～]# sysbench --test=oltp --db-driver=mysql --mysql-table-engine=innodb--\
mysql -host=10.10.10.10 --mysql-port=3306 --mysql-db=sbtest --mysql-user= 'qbench' --mysql-\
password='qbench' --test= /usr/share/doc/sysbench/tests/ db/oltp.lua --oltp-table-size\
=5000000--oltp-tables-count= 8 --num-threads= 16 --max-time=1800 --max-requests=0 --report-\
interval=1 run
......

# 通过top命令查看到CPU资源绝大部分都消耗在了%wa上，说明I/O设备性能出现严重不足
[root@localhost ~]# top
......

# 使用iostat命令查看磁盘负载，通过%util列可以看到，磁盘处于100%满负载状态
avg-cpu:  %user  %nice %system %iowait  %steal  %idle
          1.77    0.00    2.28  95.70    0.00    0.25

Device: rrqm/s  wrqm/s r/s  w/s  rsec/s  wsec/s avgrq-sz avgqu-sz  await  svctm  %util
dm-2 0.00    0.00  277.00  160.00  8864.00  2774.00  26.63 47.84  112.98  2.29 100.10

avg-cpu:  %user  %nice %system %iowait  %steal  %idle
          5.05    0.00  11.62  64.14    0.00  19.19

Device: rrqm/s  wrqm/s   r/s  w/s  rsec/s  wsec/s avgrq-sz avgqu-sz  await  svctm  %util
dm-2 0.00 0.00  267.00  244.00  8544.00  4643.00    25.81   28.20  40.29  1.96 100.00

# 为了方便查询等待事件统计，我们可以先创建一个视图，用于实时统计当前等待事件（非历史数据）
mysql> create view sys.test_waits as select sum(TIMER_WAIT) as TIMER_WAIT,sum(NUMBER_OF_BYTES) as NUMBER_OF_BYTES, EVENT_NAME,OPERATION from events_waits_current where EVENT_NAME!='idle' group by EVENT_NAME,OPERATION;
Query OK, 0 rows affected (0.04 sec)

# 使用上面创建的视图进行查询，并对查询结果进行降序排列。从下面的查询结果中可以看到，时间开销排名前5的有4个都是与I/O相关的等待事件，剩下1个是与binlog相关的互斥等待事件
mysql> select sys.format_time (TIMER_WAIT),sys.format_bytes(NUMBER_OF_BYTES),EVENT_NAME, OPERATION from sys.test_waits where sys.format_time(TIMER_WAIT) not regexp 'ns|us' order by TIMER_WAIT desc;
......
6 rows in set (0.01 sec)

# 当然，你也可以直接查询events_waits_current表（返回的数据行数可能比较多，且对查询结果没有做分组聚合，是逐行的事件记录数据）
mysql> select THREAD_ID,EVENT_NAME,sys.format_time (TIMER_WAIT),INDEX_NAME,NESTING_EVENT_ TYPE,OPERATION,NUMBER_OF_BYTES from events_waits_current where EVENT_NAME!='idle' order by TIMER_WAIT desc;
......
57 rows in set (0.00 sec)

6.2.1　找出谁持有全局读锁

# 执行加锁语句
mysql> flush table with read lock;
Query OK, 0 rows affected (0.00 sec)

# 查询以下加锁线程的process id，以便与后续排查过程对应
mysql> select connection_id();
......
1 row in set (0.00 sec)

mysql> use sbtest
Database changed
mysql> select * from sbtest1 limit 1\G
*************************** 1. row ***************************
......

mysql> select connection_id();
......
1 row in set (0.00 sec)

mysql> update sbtest1 set pad='xxx' where id=21; # 操作被阻塞

mysql> select connection_id();
......
1 row in set (0.00 sec)

# 查询processlist信息，这里只能看到process id为5的线程State为Waiting for global read lock，表示正在等待全局读锁
mysql> show processlist;
......
4 rows in set (0.00 sec)

# 继续查询information_schema.innodb_locks、innodb_lock_waits、innodb_trx表，发现三个表均为空
mysql> select * from information_schema.innodb_locks;
Empty set, 1 warning (0.00 sec)

mysql> select * from information_schema.innodb_lock_waits;
Empty set, 1 warning (0.00 sec)

mysql> select * from information_schema.innodb_trx\G
Empty set (0.00 sec)

# 再使用show engine innodb status;查看（这里只需要看TRANSACTION段落即可），仍然无任何有用的锁信息
mysql> show engine innodb status;
......

# 通过performance_schema.metadata_locks表来排查谁持有全局读锁，全局读锁在该表中通常记录着同一个会话的OBJECT_TYPE为global和commit、LOCK_TYPE都为SHARED的两把显式锁
mysql> select * from performance_schema.metadata_locks where OWNER_THREAD_ID!=sys.ps_ thread_id(connection_　id())\G
......

# 查看process id为4和5的线程各自对应的内部线程ID是多少
mysql> select sys.ps_thread_id(4);
......
1 row in set (0.00 sec)

mysql> select sys.ps_thread_id(5);
......
1 row in set (0.00 sec)

6.2.2　找出谁持有MDL锁

# 会话1，显式开启一个事务，并执行一条update语句更新sbtest1表不提交
mysql> use sbtest
Database changed
mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> update sbtest1 set pad='yyy' where id=1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

# 会话2，对sbtest1表执行DDL语句添加一个普通索引
mysql> use sbtest
Database changed
mysql> alter table sbtest1 add index i_c(c);  # 被阻塞

mysql> show processlist;
......
3 rows in set (0.00 sec)

mysql> select * from performance_schema.metadata_locks where OWNER_THREAD_ID!=sys.ps_thread_ id(connection_id())\G
......
5 rows in set (0.00 sec)

mysql> select * from information_schema.innodb_trx\G
......
1 row in set (0.00 sec)

mysql> select * from performance_schema.events_statements_current where thread_id=136\G
......
1 row in set (0.00 sec)

6.2.3　找出谁持有表级锁

# 会话1，加表级锁
mysql> use sbtest
Database changed
mysql> select connection_id();
......
1 row in set (0.00 sec)

mysql> lock table sbtest1 read;
Query OK, 0 rows affected (0.00 sec)

# 会话2，对该表执行update更新
mysql> use sbtest
Database changed
mysql> select connection_id();
......
1 row in set (0.00 sec)
mysql> update sbtest1 set pad='xxx' where id=1; # 被阻塞

mysql> show processlist;
......
4 rows in set (0.00 sec)

mysql> select * from performance_schema.metadata_locks where OWNER_THREAD_ID!=sys.ps_thread_id (connection_id())\G
......
3 rows in set (0.00 sec)

mysql> select * from information_schema.INNODB_TRX;
Empty set (0.00 sec)

mysql> select * from information_schema.INNODB_LOCKS;
Empty set, 1 warning (0.00 sec)

mysql> select * from information_schema.INNODB_LOCK_WAITS;
Empty set, 1 warning (0.00 sec)

mysql> select * from performance_schema.table_handles where OWNER_THREAD_ID!=0\G
......
1 row in set (0.00 sec)  

mysql> select * from performance_schema.events_statements_current where thread_id=113\G
......
1 row in set (0.00 sec)

# 如何知道内部ID为113的线程对应的process id是多少呢？可以通过performance_schema.threads表查询
mysql> select processlist_id from performance_schema.threads where thread_id=113;
......
1 row in set (0.00 sec)

# 执行kill
mysql> kill 18;
Query OK, 0 rows affected (0.00 sec)

mysql> show processlist;
......
3 rows in set (0.00 sec)

# 返回执行update语句的会话2，语句已经执行成功
mysql> update sbtest1 set pad='xxx' where id=1;
Query OK, 0 rows affected (7 min 50.23 sec)
Rows matched: 0 Changed: 0 Warnings: 0

6.2.4　找出谁持有行级锁

mysql> use xiaoboluo
Database changed
mysql> select * from t_luoxiaobo limit 1;
......
1 row in set (0.00 sec)

mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> update t_luoxiaobo set datet_time=now() where id=2;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> select * from data_locks\G
......
2 rows in set (0.00 sec)

mysql> use xiaoboluo
Database changed
mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> update t_luoxiaobo set datet_time=now() where id=2;  # 被阻塞

mysql> select * from performance_schema.data_locks\G
......
4 rows in set (0.00 sec)

mysql> select * from sys.innodb_lock_waits\G
......
1 row in set (0.02 sec)

SELECT r.trx_wait_started AS wait_started,
      TIMEDIFF(NOW(), r.trx_wait_started) AS wait_age,
      TIMESTAMPDIFF(SECOND, r.trx_wait_started, NOW()) AS wait_age_secs,
      rl.lock_table AS locked_table,
      rl.lock_index AS locked_index,
      rl.lock_type AS locked_type,
      r.trx_id AS waiting_trx_id,
      r.trx_started as waiting_trx_started,
      TIMEDIFF(NOW(), r.trx_started) AS waiting_trx_age,
      r.trx_rows_locked AS waiting_trx_rows_locked,
      r.trx_rows_modified AS waiting_trx_rows_modified,
      r.trx_mysql_thread_id AS waiting_pid,
      sys.format_statement(r.trx_query) AS waiting_query,
      rl.lock_id AS waiting_lock_id,
      rl.lock_mode AS waiting_lock_mode,
      b.trx_id AS blocking_trx_id,
      b.trx_mysql_thread_id AS blocking_pid,
      sys.format_statement(b.trx_query) AS blocking_query,
      bl.lock_id AS blocking_lock_id,
      bl.lock_mode AS blocking_lock_mode,
      b.trx_started AS blocking_trx_started,
      TIMEDIFF(NOW(), b.trx_started) AS blocking_trx_age,
      b.trx_rows_locked AS blocking_trx_rows_locked,
      b.trx_rows_modified AS blocking_trx_rows_modified,
      CONCAT('KILL QUERY ', b.trx_mysql_thread_id) AS sql_kill_blocking_query,
      CONCAT('KILL ', b.trx_mysql_thread_id) AS sql_kill_blocking_connection
  FROM information_schema.innodb_lock_waits w
      INNER JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id
      INNER JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id
      INNER JOIN information_schema.innodb_locks bl ON bl.lock_id = w.blocking_lock_id
      INNER JOIN information_schema.innodb_locks rl ON rl.lock_id = w.requested_lock_id
ORDER BY r.trx_wait_started;

6.3.1　查看最近的TOP SQL语句

mysql> select THREAD_ID,EVENT_NAME, SOURCE,sys.format_time(TIMER_WAIT),sys.format_time (LOCK_TIME),SQL_TEXT,CURRENT_SCHEMA,MESSAGE_TEXT, ROWS_AFFECTED,ROWS_SENT,ROWS_EXAMINED from events_statements_history where CURRENT_SCHEMA!= 'performance_schema' order by TIMER_WAIT desc limit 10\G
......
10 rows in set (0.00 sec)

mysql> select SCHEMA_NAME,DIGEST_TEXT,COUNT_STAR, sys.format_time(SUM_TIMER_WAIT) as sum_time, sys.format_time(MIN_TIMER_WAIT) as min_time,sys.format_time(AVG_TIMER_WAIT) as avg_time, sys.format_time(MAX_TIMER_WAIT) as max_time,sys.format_time(SUM_LOCK_TIME) as sum_lock_time, SUM_ROWS_AFFECTED,SUM_ROWS_SENT,SUM_ROWS_EXAMINED from events_statements_summary_by_digest where SCHEMA_NAME is not null order by COUNT_STAR desc limit 10\G
......
10 rows in set (0.00 sec)

6.3.2　查看最近执行失败的SQL语句

mysql> select * from;
......

mysql> use performance_schema
Database changed
mysql> select THREAD_ID,EVENT_NAME,SOURCE,sys.format_time(TIMER_WAIT) as exec_time,sys. format_time (LOCK_TIME) as lock_time,SQL_TEXT, CURRENT_SCHEMA,MESSAGE_TEXT,ROWS_AFFECTED, ROWS_SENT,ROWS_EXAMINED,MYSQL_ERRNO from events_statements_history where MYSQL_ERRNO =1064\G
......
1 row in set (0.01 sec)

mysql > select THREAD_ID, EVENT_NAME,SOURCE,sys.format_time(TIMER_WAIT) as exec_time, sys.format_time(LOCK_TIME) as lock_time,SQL_TEXT, CURRENT_SCHEMA,MESSAGE_TEXT,ROWS_AFFECTED, ROWS_SENT,ROWS_EXAMINED,MYSQL_ERRNO,errors from events_statements_history where errors> 0\G
......
1 row in set (0.00 sec)

mysql> select * ;
ERROR 1096 (HY000): No tables used
mysql> select * from sbtest4 where id between 100 and 2000 and xx=1;
ERROR 1054 (42S22): Unknown column 'xx' in 'where clause'

mysql> select SCHEMA_NAME, DIGEST_TEXT,COUNT_STAR, sys.format_time(AVG_TIMER_WAIT) as avg_time,sys.format_time(MAX_TIMER_WAIT) as max_time,sys.format_time(SUM_LOCK_TIME) as sum_lock_time,SUM_ERRORS,FIRST_SEEN,LAST_SEEN from events_statements_summary_by_digest where SUM_ERRORS!=0\G
......
11 rows in set (0.00 sec)

mysql> select THREAD_ID, EVENT_NAME,SOURCE,sys.format_time(TIMER_WAIT) as exec_time, sys.format_time(LOCK_TIME) as lock_time,SQL_TEXT, CURRENT_SCHEMA,MESSAGE_TEXT,ROWS_AFFECTED, ROWS_SENT,ROWS_EXAMINED,MYSQL_ERRNO from events_statements_history where MYSQL_ERRNO!=0\G
......
3 rows in set (0.00 sec)

6.4　查看SQL语句执行阶段和进度信息

mysql>show processlist;
......
2 rows in set (0.00 sec)

6.4.1　查看SQL语句执行阶段信息

mysql> use performance_schema
Database changed
mysql> update setup_instruments set enabled='yes',timed='yes' where name like 'stage/%';
Query OK, 120 rows affected (0.00 sec)
Rows matched: 129 Changed: 120 Warnings: 0

mysql> update setup_consumers set enabled='yes' where name like '%stage%';
Query OK, 3 rows affected (0.00 sec)
Rows matched: 3 Changed: 3 Warnings: 0

mysql> select sys.ps_thread_id(connection_id());
......
1 row in set (0.00 sec)

# 先关闭其他线程的事件记录功能，使用前面步骤查询到的thread_id
mysql> update performance_schema.threads set INSTRUMENTED='NO' where THREAD_ID!=119;
Query OK, 101 rows affected (0.00 sec)
Rows matched: 101 Changed: 101 Warnings: 0

# 清空阶段事件的三个表
mysql> truncate events_stages_current; truncate events_stages_history;truncate events_ stages_history_long;
Query OK, 0 rows affected (0.00 sec)
......

root@localhost : sbtest 06:06:37> select count(*) from sbtest.sbtest4 where id between 100 and 200;
......
1 row in set (0.00 sec)

mysql> select THREAD_ID,EVENT_NAME,SOURCE,sys.format_time(TIMER_WAIT) as exec_time,WORK_ COMPLETED, WORK_ESTIMATED from events_stages_history_long;
......
15 rows in set (0.01 sec)

mysql> truncate events_stages_current;truncate events_stages_history;truncate events_ stages_history_long;
Query OK, 0 rows affected (0.00 sec)
......

mysql> alter table sbtest1 add index i_c(c);

mysql> select THREAD_ID,EVENT_NAME, SOURCE,sys.format_time(TIMER_WAIT) as exec_time,WORK_ COMPLETED,WORK_ESTIMATED from events_stages_history_long;
......
12 rows in set (0.01 sec)

mysql> select THREAD_ID,EVENT_NAME,SOURCE,sys.format_time (TIMER_WAIT) as exec_time,WORK_COMPLETED, WORK_ESTIMATED from events_stages_history_long;
......
24 rows in set (0.01 sec)

6.4.2　查看SQL语句执行进度信息

mysql> select * from sys.session where conn_id!=connection_id()\G
......
1 row in set (0.33 sec)

6.5　查看最近的事务执行信息

mysql> update setup_instruments set enabled='yes',timed='yes' where name like 'transaction';
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> update setup_consumers set enabled='yes' where name like '%transaction%';
Query OK, 3 rows affected (0.00 sec)
Rows matched: 3  Changed: 3  Warnings: 0

mysql> truncate events_transactions_current; truncate events_transactions_history; truncate events_transactions_history_long;
Query OK, 0 rows affected (0.00 sec)
......

mysql> use sbtest
Database changed
mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> update sbtest1 set pad='yyy' where id=1;
Query OK, 1 row affected (0.01 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> select THREAD_ID, EVENT_NAME,STATE,TRX_ID, GTID,SOURCE,TIMER_WAIT,ACCESS_MODE, ISOLATION_LEVEL,AUTOCOMMIT,NESTING_EVENT_ID,NESTING_EVENT_TYPE from events_transactions_ current\G
......
1 row in set (0.00 sec)

mysql> rollback;
Query OK, 0 rows affected (0.01 sec)

mysql> select THREAD_ID, EVENT_NAME,STATE,TRX_ID, GTID,SOURCE,TIMER_WAIT,ACCESS_MODE, ISOLATION_LEVEL,AUTOCOMMIT,NESTING_EVENT_ID,NESTING_EVENT_TYPE from events_transactions_ history_long\G
......
1 row in set (0.00 sec)

# 会话2
mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> update sbtest1 set pad='yyy' where id=1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> commit;
Query OK, 0 rows affected (0.01 sec)

# 会话1
mysql> select THREAD_ID, EVENT_NAME,STATE,TRX_ID, GTID,SOURCE,TIMER_WAIT,ACCESS_MODE, ISOLATION_LEVEL,AUTOCOMMIT,NESTING_EVENT_ID,NESTING_EVENT_TYPE from events_transactions_ current\G
......
2 rows in set (0.00 sec)

mysql> select * from information_schema.innodb_trx\G
......
1 row in set (0.00 sec)

6.6　查看多线程复制报错详情

mysql> show slave status\G
......
1 row in set (0.00 sec)

mysql> select * from performance_schema.replication_applier_status_by_worker where LAST_ERROR_MESSAGE!=''\G
......
1 row in set (0.00 sec)

• 温馨提示：关于performance_schema系统库更详细的内容，可参阅微信公众号“沃趣技术”。或详见开源文档：performance_schema详解

---

上一篇：第5章　performance_schema配置详解 | 下一篇：第7章　sys系统库初相识