午睡醒来收到几封CPU使用率预警邮件。登录对应服务器，打开资源监视器CPU，看到sqlservr.exe进程的CPU达到40%(平常服务器CPU消耗在10%以内)。查看CPU信息跟踪表，近一小时的CPU都维持在40%左右。
图1 CPU使用率预警邮件
图2 CPU信息跟踪表
开启profiler跟踪，筛选CPU>60毫秒的事件。发现有一个存储过程调用非常频繁，而且cpu>90 read>2800。查看此过程，语句很简单，返回记录数很少，表上有对应索引。但从profiler所得开销看，语句肯定没有使用索引。之前遇到类似的问题，只需删除存储过程的计划缓存，cpu、read就降下去了。
--返回做IO数目最多的存储过程以及它们的执行计划(微秒)
SELECT TOP 20 DB_NAME(a.database_id) DBname
,OBJECT_NAME(OBJECT_ID ,database_id) ‘proc name‘
,a.cached_time
,a.last_execution_time
,a.execution_count
,a.last_logical_reads
,a.total_logical_reads / a.execution_count avg_logical_reads
,a.total_logical_writes / a.execution_count avg_logical_writes
,a.total_physical_reads / a.execution_count avg_physical_reads
--,a.total_worker_time / a.execution_count AS avg_worker_time
,a.total_elapsed_time / a.execution_count avg_elapsed_time
--,b.text
,c.query_plan
,a.plan_handle
FROM sys.dm_exec_procedure_stats AS a
CROSS APPLY sys.dm_exec_sql_text(a.sql_handle) b
CROSS APPLY sys.dm_exec_query_plan(a.plan_handle) c
where OBJECT_NAME(OBJECT_ID ,database_id) =‘ProcName‘
ORDER BY
a.total_logical_reads/a.execution_count desc
--DBCC FREEPROCCACHE(0x0500080094EA1B2F40A1B3DE000000000000000000000000)
图3 处理前消耗情况
图4 处理后消耗情况
图5 半分钟内过程调用情况
问题现象很明显(不定期会重现)，就是一个很简单的过程，频繁调用，突然在某个时间点，过程消耗变得很大；只要把对应缓存计划删除，消耗立马降下去。问题的本质是执行计划的变更。过程最开始执行(或者手动执行时)走的是索引查找+键查找；出问题的时候变成了表扫描！
图6 手动执行时的执行计划
查看CPU信息跟踪表，找出此次CPU上涨的起始时间(2015-09-11 11:15:51.447)。查询过程涉及表所依赖的存储过程，查询是否有作业对表(直接或者通过存储过程)进行数据变更，分析表中数据变更与CPU上涨的时间是否吻合。
--表依赖的过程
select name,object_id,text from sys.procedures a,syscomments b
where a.object_id=b.id and text like ‘%Table%‘
--作业调用的表/过程
select top 3 sj.name,sjs.command
from msdb.dbo.sysjobs sj
inner join msdb.dbo.sysjobsteps sjs
on sj.job_id=sjs.job_id
where sjs.command like ‘%TableOrProc%‘
发现有两个过程，被两个作业调用，有对表中数据清空然后再写入。其中一个作业是每天凌晨03:03(排除)，另一个作业是每小时执行一次。查看每小时执行一次的作业历史记录，发现在11:15的时候作业耗时46秒，其他时候基本为0。也就是那个时间点对表中数据进行了清空再写入的操作。
select top 20 sj.name,sjh.step_id,sjh.message,sjh.run_status
,msdb.dbo.agent_datetime(run_date,run_time),sjh.run_duration
from msdb.dbo.sysjobhistory sjh
inner join msdb.dbo.sysjobs sj
on sjh.job_id=sj.job_id
where sj.name=‘jobname‘
order by msdb.dbo.agent_datetime(run_date,run_time) desc
图7 作业历史执行时间
查询统计信息更新时间
图8 统计信息更新时间
数据清空再写入，导致统计信息更新，进而影响执行计划？现在查看统计信息是在11:15更新的，会不会是刚好清空表的时候，程序调用了过程，表中没数据，生成了一个表扫描的执行计划，之后就一直重用这个计划？总之就是表数据变更(清空)影响统计信息，进而影响执行计划的重新生成(表扫描)，接着数据再次写入，统计信息会再次更新，但执行计划却还是旧的(表扫描)，导致消耗变大。如果手动执行，它会依据新的统计信息，生成新的执行计划(索引查找+键查找)……找个时间后期测试下