昨天中午的时候，接到开发同学的电话，说有一个在线数据迁移，碰到了一些问题，希望我能够帮忙看看是哪里的原因。
从电话里的反馈得知，他们在做业务数迁移，会把数据库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语句，我相信结局一定让人唏嘘感叹。
从电话里的反馈得知，他们在做业务数迁移，会把数据库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语句，我相信结局一定让人唏嘘感叹。
