最近碰到了这样一个有趣的问题: 有一条SQL语句,大部分时间它的执行时间是几十个毫秒; 但是偶尔某次的执行时间会长于2秒钟。因为应用对这个语句的执行时间非常的敏感,我们必须诊断是因为什么原因导致它偶尔执行时间长于2秒。
这个问题为什么会有挑战性呢?因为我们很难收集慢的时候的10046 trace:首先我们不知道这个问题什么时候会发生,也不知道会在哪个session里发生。如果对所有的session全天开启10046 trace, 会产生很多比较大的trace并影响数据库整体的性能。
好在这个数据库是11g的,在11g中event++的特性允许我们只对某个特定的SQL收集10046 trace. 即在运行这条SQL时开启10046 trace,在这条SQL运行完之后关闭10046 trace.这样可以显著的降低生成的trace的大小。但是因为我们无法确定哪个session会产生问题,所以只要运行过这个SQL的session都会产生一个trace文件。
开启的步骤是(要把下面的awsh60c8mpfu1替换成那条SQL的SQL_ID):
alter system set events 'sql_trace [sql: awsh60c8mpfu1] level 12';
而关闭的步骤是(要把下面的awsh60c8mpfu1替换成那条SQL的SQL_ID):
alter system set events 'sql_trace [sql: awsh60c8mpfu1] off';
在收集到很多10046 trace,并使用tkprof格式化后(需指定AGGREGATE=NO,这样tkprof会对每一次执行都生成汇总报告),我们最后定位到了问题发生时SQL语句读取物理块时花费了更多的时间。
: