ITOO线上问题（二）

    2018年1月19日，近代史考试，下面我来写一下本次考试出现的问题，以及解决问题的思路，和大家一起分享。

    近代史考试也是要分为上午三场，下午三场，出现问题的仍然为上午场，因为中午的时候我们发现了问题，所以下午考试的时候没有发生任何问题。

    首先，第一场考试的时候，我们mysql服务器的服务器CPU是四核的，也就是说cpu占用最大可达到400%，我们首先top一下，在输入大写的P（M为按内存占用排序），就可以看到按cpu占用排序的应用。

    正常时，综合当时的考试人数，cpu在30%、40%左右波动，第一场考试后半场的时候我们发现了mysql服务器的异常，mysql服务器的占用达到了200%多，有时候甚至可以达到300%多，再看单核占用，四个和的cpu占用并不是平均分布的，其中有一两个核的占用是非常高的，达到90%多，甚至一度维持在100%，其他剩下的三个核的占用是非常低的，甚至连10%都不到，这是非常有问题的，其实单核的占用率一般只要不超过75%是没有关系的，也就是说四个核的占用在300%左右是没有关系的，但是前提是每个核的占用大概都是均匀分布的，但是现在的情况不是，现在的情况是有些核占用特别高，有些核基本就是在闲着。（由此，在写代码时可以给我们一些启发，如果某一个sql特别复杂，某个核在执行这个任务时，可能cpu占用就会特别高，这是非常危险的，这时候如果把这个sql分为拆分开来写，是有利于多核均匀分布来执行的，但是如果拆分的过于分散，IO的次数就会增多，影响性能）

    当时mysql服务器cpu的占用稳定在200%，甚至300%没有下降的趋势，但是也没有进一步上升的趋势，我们继续观察了第二场考试，直到第二场考试结束，cpu的占用基本就稳定在300%左右了（以上我说的数据均为主机数据，从机也是4核，一直其中有一核占用较高，其他三核基本空闲，较高的核占用也不到10%，因为仅仅又一核在根据日志同步主机的数据而已，没有其他 操作），由于随着学生的答题记录增多，数据库的数据也一直在增长，我们担心第三章考试数据库承受不住压力，决定第二场考试结束后，扩展mysql服务器cpu的核数，由原来的四核扩展到八核，因为扩展cpu和核数需要关闭服务器，为了保险，我们现在mysql主服务器（也就是231）停掉进行扩展，由于231停掉了，这时候原本是从机的232变为主机，231服务器成功扩展后，再启动231，关闭232对232进行扩展，同样将232扩展为八核，再启动232，这样成功启动后，同样是231为主，232为从。两台mysql服务器均变为八核，也就是数现在两台mysql服务器的cpu占用率都可达到800%。

    在这个过程中我们一直在观察druid的监控页面想从中找出异常sql，但是没有收获，后来又想用mysql的慢查询，将执行较慢的sql写到日志里，执行方法如下：

    当时我们的mysql慢查询也是没有开启的，需要开启慢查询并设置记录时间等操作，另一原因就是我们在druid的监控页面并没有发现异常的sql语句，所以决定这个先作为备用方案。

就这个状况一直持续到考试结束，cpu的占用一直维持在300%，由于我们对cpu的核数进行了扩展，现在的状况是完全可以接受的，但是出现这种现象肯定是有问题的。上午考试结束后，我们就开始一步步排查问题。

    我们发现，考试已经结束在没有学生答题的情况下，CPU的占用率仍然为200%多，而且，我们的mysql服务器中八个核中有两个核的占用为100%，其他六个核基本处在空闲状态。

    首先我们排查是不是我们的服务出现了问题，我们首先关闭了考评服务，发现mysql服务器CPU占用并没有变化，紧接着又分别关闭了成绩、教学、基础、权限等服务，CPU占用仍无明显变化。这就排除了各个服务对数据库的影响。

    紧接着，以为有两个核的占用仍为100%，我们想知道mysql服务器到底在干什么，便执行如下命令查看着在运行的sql语句：

use information_schema;
select * from information_schema.`PROCESSLIST` where info is not null;

当时，我们查询出3条结果来，三条记录的STATE分别是executing（线程已开始执行语句）、Execution of init_command（线程正在执行的init_command系统变量）、 Execution of init_command。

executing对应的sql语句为

select * from information_schema.`PROCESSLIST` where info is not null;

是我们刚刚执行的sql语句。

Execution of init_command对应的sql语句是itoo系统中一个关于查询试题的sql语句，经过对比两个sql语句是一样的。正好是两个查询视图的sql语句正好对应两个核的cpu占用率为100%，过了一会，我们有查询了mysql正在执行的sql，发现一条sql已经执行完毕，仅有一条查询视图的sql在执行，这时候再去看mysql服务器，也只剩下一个核的占用为100%，这样我们就准确定位了问题。

    去代码中找相应的sql，我们发现这正是定时器执行的sql，通过查看日志，我们发现定时器确实执行了，但是定时器在思修考试的时候我们已经关闭了，为什么又开启了呢？原因是我们关闭定时器的时候直接替换的生成的class下的文件，并没有改代码重新构建，由于思修考试当晚我们改动了一些东西，我们又重新构建了代码，导致原本关闭了定时器的代码被覆盖，定时器又开启了。之后我们把那条sql语句拿出来执行，发现仅仅是执行那条sql语句就需要20多分钟，而定时器设置的定时任务时10分钟执行一次，这样就造成sql执行堆积的现象。