客户新上线的一套重要生产系统,某个存储过程每小时调用约11万次,每次调用的逻辑读超过了10000,消耗的CPU占数据库CPU Time的25-30%。很显然,这样一个存储过程是值得优化的。
不幸的是,这个存储过程的业务逻辑很复杂,光是参数就有9个。而存储过程所在的包其代码超过了1万行。通过复查代码的方式,耗时耗力,还不一定能够找出问题。
诊断性能问题,首要的是了解这个存储过程所大概要完成的业务功能,然后通过trace或instrument收集足够详细的性能数据。从客户和开发商那里了解到,存在性能问题的存储过程,主要用于系统之间的数据查询接口,根据不同的参数输入查询不同的数据,那么,对于这种小数据量的存储过程,可以考虑使用10046事件来分析是哪些SQL产生了这么多的逻辑读。
但是通过10046事件,发现存储过程中实际执行的SQL并不多,同时并没有逻辑读高的SQL语句。也许问题并没有出现在SQL语句中,而是出现在存储过程中其他非SQL部分。虽然用10046没有找到SQL语句,但还是有重大发现,在过程执行时,大量的逻辑读来自于current方式的读,这显示不是通常的SELECT语句所产生的。接下来我们用dbms_profiler来分析存储过程:
select dbms_profiler.start_profiler from dual; exec intf.CRM_SERVICE_INTF.QueryService(.....); exec dbms_profiler.stop_profiler;
然后使用来自MOS文档“Implementing and Using the PL/SQL Profiler [ID 243755.1]”中的profiler.sql脚本,生成一个profiler的结果文件,格式为html。下面是部分的内容:
点击其显示的代码行(line),跳转到相应的源代码,发现大量的字符串拼接代码,很明显是用于拼接成XML格式。这很容易理解,因为现在系统之间的文本数据交互,xml几乎成了标准。从上面的截图中也可以看到很多类型于xml:=xml || ‘xxxx’ 这样的代码。是这样的代码引起的问题吗?
检查代码发现,这里用于拼接字符串的变量xml,被定义为clob类型,这引起了我极大的关注。在oracle的标准数据类型中,lob类型由于其能够存储大数据的本质,导致其内部格式和操作是最复杂的。有理由怀疑是clob的大量拼接引起的问题。
在有怀疑对象后,我们可以构造下面的测试来进行验证:
首先创建下面3个不同的存储过程,但是实现的功能是一致的:
create or replace procedure p1 ( v_out out clob) is v_lob clob; begin v_lob:=''; for rec in (select object_name from dba_objects where rownum< =1000) loop v_lob:=v_lob || rec.object_name; end loop; v_out:=v_lob; end; / create or replace procedure p2 ( v_out out clob) is v_lob varchar2(32767); begin v_lob:=''; for rec in (select object_name from dba_objects where rownum<=1000) loop v_lob:=v_lob || rec.object_name; end loop; v_out:=v_lob; end; / create or replace procedure p3 ( v_out out clob) is v_lob clob; v_str varchar2(32767); v_cnt number; begin v_lob:=''; v_cnt:=0; v_str:=''; for rec in (select object_name from dba_objects where rownum<=1000) loop v_str:=v_str || rec.object_name; v_cnt:=v_cnt+1; if v_cnt = 50 then v_cnt:=0; v_lob:=v_lob || v_str; v_str:=''; end if; end loop; if v_cnt <>0 then v_lob:=v_lob || v_str; end if; v_out:=v_lob; end; /