ITPub博客

首页 > 数据库 > MySQL > 【Mysql】Mysql负载过大,app访问延迟

【Mysql】Mysql负载过大,app访问延迟

MySQL 作者:小亮520cl 时间:2016-03-11 14:47:25 0 删除 编辑
收到线上某业务后端的MySQL实例负载比较高的告警信息,于是登入服务器检查确认

1. 首先我们进行OS层面的检查确认

  1. 我们一般先看整体负载如何,负载高的话,肯定所有的进程跑起来都慢
  2. [yejr@imysql.com:~ ]# w 11:52:58 up 702 days, 56 min, 1 user, load average: 7.20, 6.70, 6.47 USER TTY FROM LOGIN@ IDLE JCPU PCPU WHAT root pts/0 1.xx.xx.xx 11:51 0.00s 0.03s 0.00s w

或者 
sar -q 的观察结果
[yejr@imysql.com:~ ]# sar -q 1 Linux 2.6.32-431.el6.x86_64 (yejr.imysql.com) 01/13/2016 _x86_64_ (24 CPU) 02:51:18 PM runq-sz plist-sz ldavg-1 ldavg-5 ldavg-15 blocked 02:51:19 PM 4 2305 6.41 6.98 7.12 3 02:51:20 PM 2 2301 6.41 6.98 7.12 4 02:51:21 PM 0 2300 6.41 6.98 7.12 5 02:51:22 PM 6 2301 6.41 6.98 7.12 8 02:51:23 PM 2 2290 6.41 6.98 7.12 8


load average大意表示当前CPU中有多少任务在排队等待,等待越多说明负载越高,跑数据库的服务器上,一般load值超过5的话,已经算是比较高的了。


我们可以看到此时系统的负载有点高
点击(此处)折叠或打开

  1. 某些进程/服务消耗更多CPU资源(服务响应更多请求或存在某些应用瓶颈);
  2. 发生比较严重的swap(可用物理内存不足);
  3. 发生比较严重的中断(因为SSD或网络的原因发生中断);
  4. 磁盘I/O比较慢(会导致CPU一直等待磁盘I/O请求);



这时我们可以执行下面的命令来判断到底瓶颈在哪个子系统
  1. top命令
  2. [yejr@imysql.com:~ ]# top top - 11:53:04 up 702 days, 56 min, 1 user, load average: 7.18, 6.70, 6.47 Tasks: 576 total, 1 running, 575 sleeping, 0 stopped, 0 zombie Cpu(s): 7.7%us, 3.4%sy, 0.0%ni, 77.6%id, 11.0%wa, 0.0%hi, 0.3%si, 0.0%st ----%us 和 %wa 的值较高,表示当前比较大的瓶颈可能是在用户进程消耗的CPU以及磁盘I/O等待上。
  3. Mem: 49374024k total, 32018844k used, 17355180k free, 115416k buffers Swap: 16777208k total, 117612k used, 16659596k free, 5689020k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 14165 mysql 20 0 8822m 3.1g 4672 S 162.3 6.6 89839:59 mysqld 40610 mysql 20 0 25.6g 14g 8336 S 121.7 31.5 282809:08 mysqld 49023 mysql 20 0 16.9g 5.1g 4772 S 4.6 10.8 34940:09 mysqld

如果%us过高
  1. 1:有大量的排序工作
  2. 2:sql索引不合理
  3. 查看慢日志,分析优化SQL

如果%sy过高
  1. 1.sys占用cpu过高,并且swap大量使用而memory还有剩余。表示NUMA没关,关了就好了

  2. 2.sys占用cpu过高,可以使用perf top(centos6.0之后的命令)查看内核的具体使用情况
%sys过高还可以参考下面这篇文章
http://mysql.taobao.org/monthly/2015/05/02/

既然wait比较高,那么就要分析一下磁盘的io了
  1. [root@HaoDai_App_DB01 ~]# iostat -x -m 2
    Linux 2.6.32-504.16.2.el6.x86_64 (HaoDai_App_DB01)      03/18/2016      _x86_64_        (40 CPU)


    avg-cpu:  %user   %nice %system %iowait  %steal   %idle
               4.29    0.00    0.20    0.05    0.00   95.46


    Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
    sda               0.00     2.97    0.04    0.48     0.00     0.01    72.81     0.00    0.49   0.28   0.01
    sdb               0.00   143.43    0.00  131.67     0.00     1.04    16.10     0.01    0.10   0.07   0.91


    avg-cpu:  %user   %nice %system %iowait  %steal   %idle
              12.54    0.00    0.38    0.03    0.00   87.06


    Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
    sda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
    sdb               0.00   174.00    0.00  137.50     0.00     1.17    17.40     0.03    0.19   0.14   1.95

  2. 如果,吞吐量(rMB/s+wMB/s)过低,但是util过高表示:随机io特别的严重(可用pt-ioprofile去定位导致问题出现的表)
  3. IOPS=R/s+W/s

再利用 iotop 确认到底哪些进程消耗的磁盘I/O资源最多:
  1. Total DISK READ: 60.38 M/s | Total DISK WRITE: 640.34 K/s
  2.   TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
  3. 16397 be/4 mysql 8.92 M/s 0.00 B/s 0.00 % 94.77 % mysqld --basedir=/usr/local/m~og_3320/mysql.sock --port=3320       ---排前面的都是mysql
  4.  7295 be/4 mysql 10.98 M/s 0.00 B/s 0.00 % 93.59 % mysqld --basedir=/usr/local/m~og_3320/mysql.sock --port=3320
  5. 14295 be/4 mysql 10.50 M/s 0.00 B/s 0.00 % 93.57 % mysqld --basedir=/usr/local/m~og_3320/mysql.sock --port=3320
  6. 14288 be/4 mysql 14.30 M/s 0.00 B/s 0.00 % 91.86 % mysqld --basedir=/usr/local/m~og_3320/mysql.sock --port=3320
  7. 14292 be/4 mysql 14.37 M/s 0.00 B/s 0.00 % 91.23 % mysqld --basedir=/usr/local/m~og_3320/mysql.sock --port=3320
  8. 。
  9. 可以看到,端口号是3320的实例消耗的磁盘I/O资源比较多,那就看看这个实例里都有什么查询在跑吧。


2:接着从mysql层面去检查
  1. 1检查一下并发以及mysql是那些语句再执行
    1. [yejr@imysql.com(db)]> mysqladmin processlist|grep -v Sleep +----+----+----------+----+-------+-----+--------------+-----------------------------------------------------------------------------------------------+ | Id |User| Host | db |Command|Time | State | Info | +----+----+----------+----+-------+-----+--------------+-----------------------------------------------------------------------------------------------+ | 25 | x | 10.x:8519 | db | Query | 68 | Sending data | select max(Fvideoid) from (select Fvideoid from t where Fvideoid>404612 order by Fvideoid) t1 | | 26 | x | 10.x:8520 | db | Query | 65 | Sending data | select max(Fvideoid) from (select Fvideoid from t where Fvideoid>484915 order by Fvideoid) t1 | | 28 | x | 10.x:8522 | db | Query | 130 | Sending data | select max(Fvideoid) from (select Fvideoid from t where Fvideoid>404641 order by Fvideoid) t1 | | 27 | x | 10.x:8521 | db | Query | 167 | Sending data | select max(Fvideoid) from (select Fvideoid from t where Fvideoid>324157 order by Fvideoid) t1 | | 36 | x | 10.x:8727 | db | Query | 174 | Sending data | select max(Fvideoid) from (select Fvideoid from t where Fvideoid>324346 order by Fvideoid) t1 | +----+----+----------+----+-------+-----+--------------+-----------------------------------------------------------------------------------------------+


  2. 2:可以看到有不少慢查询还未完成,从slow query log中也能发现,这类SQL发生的频率很高。这是一个非常低效的SQL写法,导致需要对整个主键进行扫描,但实际上只需要取得一个最大值而已,从slow query log中可看到
  3. Rows_sent: 1 Rows_examined: 5502460
  4. 每次都要扫描500多万行数据,却只为读取一个最大值,效率非常低。

    经过分析,这个SQL稍做简单改造即可在个位数毫秒级内完成,原先则是需要150-180秒才能完成,提升了N次方。
    改造的方法是:对查询结果做一次倒序排序,取得第一条记录即可。而原先的做法是对结果正序排序,取最后一条记录,汗啊。。


在这个例子中,产生瓶颈的原因比较好定位,SQL优化也不难,实际线上环境中,通常有以下几种常见的原因导致负载较高:

  1. 一次请求读写的数据量太大,导致磁盘I/O读写值较大,例如一个SQL里要读取或更新几万行数据甚至更多,这种最好是想办法减少一次读写的数据量;
  2. SQL查询中没有适当的索引可以用来完成条件过滤、排序(ORDER BY)、分组(GROUP BY)、数据聚合(MIN/MAX/COUNT/AVG等),添加索引或者进行SQL改写吧;
  3. 瞬间突发有大量请求,这种一般只要能扛过峰值就好,保险起见还是要适当提高服务器的配置,万一峰值抗不过去就可能发生雪崩效应;
  4. 因为某些定时任务引起的负载升高,比如做数据统计分析和备份,这种对CPU、内存、磁盘I/O消耗都很大,最好放在独立的slave服务器上执行;
  5. 服务器自身的节能策略发现负载较低时会让CPU降频,当发现负载升高时再自动升频,但通常不是那么及时,结果导致CPU性能不足,抗不过突发的请求;
  6. 使用raid卡的时候,通常配备BBU(cache模块的备用电池),早期一般采用锂电池技术,需要定期充放电(DELL服务器90天一次,IBM是30天),我们可以通过监控在下一次充放电的时间前在业务低谷时提前对其进行放电,不过新一代服务器大多采用电容式电池,也就不存在这个问题了。
  7. 文件系统采用ext4甚至ext3,而不是xfs,在高I/O压力时,很可能导致%util已经跑到100%了,但iops却无法再提升,换成xfs一般可获得大幅提升;
  8. 内核的io scheduler策略采用cfq而非deadline或noop,可以在线直接调整,也可获得大幅提升。
  9. 基本如果%us使用过高 或者 %us和%iowait都高,一般都是并发时的sql写的不好导致的



用这个思路来分析一下我们生产上157负载高的原因(19:00持续到19:05)
  1. 1  uptime  w 检查负载已经达到了50了,,物理cpu个数 : 2 每个物理CPU内核个数 : 10
  2. 很明显负载比较高了

  2  top查看 分析cpu
  cpu_iowait如图:

显示的iowait不高啊,暂时排除io导致的系统负载高

cpu_user如图:

19:00左右显示的用户进程消耗的CPU基本快100%了

看一下内存也没问题


登录mysql查看,显示并发达到1000多了,因为7点有一个抢单活动,纯并发导致的系统压力啊!!可以检查一下慢sql
看下这篇文档:http://imysql.com/2014/06/04/mysql-optimization-case-index-lead-to-high-cpu-load.shtml

虽然不是慢sql但是优化一下就好了 压力与负载都降下来了
 



补充一点:

在这个case里涉及到的锁有记录锁、lock_sys->mutex和trx_sys->mutex,究竟是哪个锁等待时间最长呢?我们可以用下面的方法确认一下:

mysql> SELECT COUNT_STAR, SUM_TIMER_WAIT, AVG_TIMER_WAIT, EVENT_NAME FROM performance_schema.events_waits_summary_global_by_event_name where COUNT_STAR > 0 and EVENT_NAME like 'wait/synch/%' order by SUM_TIMER_WAIT desc limit 10; +------------+------------------+----------------+--------------------------------------------+ | COUNT_STAR | SUM_TIMER_WAIT   | AVG_TIMER_WAIT | EVENT_NAME                                 |
+------------+------------------+----------------+--------------------------------------------+ |   36847781 | 1052968694795446 |       28575867 | wait/synch/mutex/innodb/lock_mutex         |
|       8096 |   81663413514785 |    10086883818 | wait/synch/cond/threadpool/timer_cond      |
|         19 |    3219754571347 |   169460766775 | wait/synch/cond/threadpool/worker_cond     |
|   12318491 |    1928008466219 |         156446 | wait/synch/mutex/innodb/trx_sys_mutex      |
|   36481800 |    1294486175099 |          35397 | wait/synch/mutex/innodb/trx_mutex          |
|   14792965 |     459532479943 |          31027 | wait/synch/mutex/innodb/os_mutex           |
|    2457971 |      62564589052 |          25346 | wait/synch/mutex/innodb/mutex_list_mutex   |
|    2457939 |      62188866940 |          24909 | wait/synch/mutex/innodb/rw_lock_list_mutex |
|     201370 |      32882813144 |         163001 | wait/synch/rwlock/innodb/hash_table_locks  |
|       1555 |      15321632528 |        9853039 | wait/synch/mutex/innodb/dict_sys_mutex     |
+------------+------------------+----------------+--------------------------------------------+ 10 rows in set (0.01 sec) 

从上面的表可以确认,lock_mutex(在MySQL源码里对应的是lock_sys->mutex)的锁等待累积时间最长(SUM_TIMER_WAIT)。lock_sys表示全局的InnoDB锁系统,在源码里看到InnoDB加/解某个记录锁的时候(这个case里是X锁),同时需要维护lock_sys,这时会请求lock_sys->mutex。

在这个case里,因为在Searching rows for update的阶段频繁地加/解X锁,就会频繁请求lock_sys->mutex,导致lock_sys->mutex锁总等待时间过长,同时在等待的时候消耗了大量CPU。


来自 “ ITPUB博客 ” ,链接:https://blog.itpub.net/29096438/viewspace-2055613/ ,如需转载,请注明出处,否则将追究法律责任。

请登录后发表评论 登录
全部评论
毕业以后专业任职数据库工程师职位,itpub一直作为自己的笔记记录的地方,blog写的不详细,草书笔记,仅供参考!

注册时间:2013-09-12

  • 博文量
    529
  • 访问量
    1126968