一次性能突发情况的紧急修复(r9笔记第18天)

昨天中午的时候，接到开发同学的电话，说有一个在线数据迁移，碰到了一些问题，希望我能够帮忙看看是哪里的原因。 从电话里的反馈得知，他们在做业务数迁移，会把数据库1中的数据迁移到数据库2中，当然会根据逻辑要求迁移大部分的数据。基于这种逻辑的复杂性，所以这次 迁移时由开发同学来主导，我们来负责支持。从他们的描述，迁移之后有一些页面直接卡住不动了。影响到了内部的一些业务，所以希望我能够紧急协助看看能不能 优化一下。 赶到公司之后，首先我查看了整体的复杂情况，发现CPU使用率较高。top的结果如下： top - 10:01:59 up 962 days, 15:53, 2 users, load average: 5.64, 5.10, 4.25 Tasks: 329 total, 3 running, 319 sleeping, 0 stopped, 7 zombie Cpu(s): 28.9%us, 1.0%sy, 0.0%ni, 49.7%id, 20.3%wa, 0.0%hi, 0.0%si, 0.0%st Mem: 32867892k total, 32660452k used, 207440k free, 16280k buffers Swap: 16777200k total, 7332520k used, 9444680k free, 29440936k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 11588 oracle 20 0 12.0g 43m 43m R 99.8 0.1 29809:08 oraclehadoop (LOCAL=NO) 20028 oracle 20 0 12.0g 143m 143m R 99.8 0.4 29796:54 oraclehadoop (LOCAL=NO) 8851 oracle 20 0 12.0g 944m 924m D 29.2 2.9 5:52.34 oraclehadoop (LOCAL=NO) 19119 mysql 20 0 8605m 1.1g 4148 S 2.7 3.6 62546:09 /usr/sbin/mysqld --basedir=/usr/ --datadir=/home/mysql_3306 --plugin-di 22408 oracle 20 0 12.0g 1.3g 1.3g D 2.0 4.0 0:19.05 oraclehadoop (LOCAL=NO) 可以看到CPU使用率较高，IOwait也较高。 从top进程可以看出来这个服务器还有mysql服务，当然资源使用率不高，前两位的进程CPU占用率都是99.8%，所以首先可以从这个地方入手。 我绑定了进程，查看到对应的会话正在执行的SQL.

$ sh showpid.sh 11588
*******************************************
Process has found, pid: 11588  ,  addr: 000000034F08CAE0    

####### Process Information from OS level as below ########
oracle   11588     1 99 May10 ?        20-16:50:45 oraclehadoop (LOCAL=NO)
oracle   26906 26639  0 10:03 pts/2    00:00:00 sh showpid.sh 11588
##############################################

       SID    SERIAL# USERNAME        OSUSER          MACHINE              PROCESS         TERMINAL        TYPE       LOGIN_TIME
---------- ---------- --------------- ---------------  -------------------- --------------- --------------- ----------  -------------------
       572      43627 APP_XXX_BG      xxxx                  xxxxxx               5312:9940           XXXX          USER       2016-05-10  16:19:19

SQL_ID                         SQL_TEXT
------------------------------ ------------------------------------------------------------
af3gvjsgn5d06                  select clicktime from ua_td_click_log  where not regexp_like
                                (clicktime, '^(-{0,1}+{0,1})[0-9]+(.{0,1}[0-9]+)$')

看到这个语句，着实让我吓了一跳，也折射出对于这方面监控还不到位，里面有个会话竟然活跃天数达到了20多天。而执行的语句就是一个简单的select. 查看了执行计划，资源消耗还是很惊人的。所以当即和开发同学取得了联系，他们确认可以清理掉这两个会话。 kill session这类操作我们需要给自己留一点后路，那就是在kill之前呢还是要找到指定的进程号，这样在数据库层面kill session后，可以马上在系统层面可以验证是否资源合理释放，而如果数据库层面处理不够到位，我们还可以从系统层面来辅助，当然这充分证明我的猜想。 kill session果真出现了延迟，会话被标记为KILLED，但是迟迟没有释放系统资源，这个时候从系统层面来进一步清理来辅助，在系统层面清理了进程之 后，数据库层面的会话资源马上就得到了释放。 当然这个处理只是一个很自然的排查思路，可以处理一些看起来很明显的问题，但是我们需要进一步思考，这个系统目前有系统的页面来调用显示实时数据，但是目 前业务系统页面是卡顿的，说明这个语句存在问题，而目前找到的两个top会话相关的数据是两个开发人员连接数据的客户端，纯属个人行为，和业务系统的卡顿 影响不大。还有一个问题就是iowait,可以看到系统的iowait还是很高的。如果单单是查询不足以产生这样的影响，而且也说不通，我们需要着重关注 那些DML语句。 所以这个时候问题分析才刚刚开始，我们需要关注那些资源消耗较高的会话，可以结合ASH绑定v$session来处理，可以看到当前的活跃会话执行的 SQL情况。果然不出所料，发现了大量的会话执行SQL的时间超过了30分钟，有些持续近1个小时，这些会话执行的语句都是指向了一个select,一个 insert，如此一来，问题似乎就说得通了。当然为什么insert会卡顿，主要原因还是在于insert语句是子查询的形式，根本还是在于 select的问题。经过一番分析，这样的语句有2个。 面对这种情况，和开发同学进行了进一步沟通，首先先清理了哪些持续时间依旧的会话，然后他们调整语句的执行频度，关注执行情况，我在后台分析语句的执行计 划情况。因为语句很长，而且执行计划较为复杂，涉及的表又很多，很快得出一个行之有效的方案着实是有难度的，但是和开发同学的反馈得知，这个系统是从数据 库1迁移而来，在数据库1中执行还是很快的，他们从前台的页面就有直观的感受，有了这一点非常宝贵的信息之后，为问题的分析和排查就提供了很有效的帮助。 我在源数据库中查看到了同样的SQL_ID的语句，发现执行计划确实存在一些差别，两个库中的表结构都是一致的，数据基本一致，出现这种情况，首先要排除 统计信息的干扰，当然我在目标库中分析之后也尝试收集了统计信息，但是开发再次执行查询问题还是依旧。所以由此可见统计信息并没有对语句的执行计划产生根 本性的改进。 对于这个问题，我抓紧使用Tuning包收集了一个报告，Oracle给出的建议是调整一些索引，调整执行计划等，这些索引可以按照建议的方式去加，但是 风险不可控，很可能添加了索引之后，其它相关的语句的执行计划也会随着影响，这种牵一发而动全身的方式还是有一些风险。 我们可以移花积木，把源库中的执行计划关键信息拷贝出来，直接替换目标库中的执行计划。这个工作听起来还是挺有意思，用SQLT实现就会很轻松。我用 SQLT指定的包导出了执行计划的详细信息，然后拷贝到目标端。调整之后再次让开发同学密切关注，发现语句的性能一下子就好了很多，原来的CPU使用率问 题马上得到了环节，而iowait也随着语句的改进也保持在一个很低的值。这个操作就充分证明了调优的效果还是很明显的。 后面持续关注，根据开发同学的反馈，业务都恢复了正常，终于松了一口气。 而这类问题我们需要跟进一步，来探索一下为什么同样表结构，基本一致的数据为什么会产生截然不同的SQL语句，我相信结局一定让人唏嘘感叹。