客户新上线的一套重要生产系统,某个存储过程每小时调用约11万次,每次调用的逻辑读超过了10000,消耗的CPU占数据库CPU Time的25-30%。很显然,这样一个存储过程是值得优化的。

不幸的是,这个存储过程的业务逻辑很复杂,光是参数就有9个。而存储过程所在的包其代码超过了1万行。通过复查代码的方式,耗时耗力,还不一定能够找出问题。

诊断性能问题,首要的是了解这个存储过程所大概要完成的业务功能,然后通过trace或instrument收集足够详细的性能数据。从客户和开发商那里了解到,存在性能问题的存储过程,主要用于系统之间的数据查询接口,根据不同的参数输入查询不同的数据,那么,对于这种小数据量的存储过程,可以考虑使用10046事件来分析是哪些SQL产生了这么多的逻辑读。

但是通过10046事件,发现存储过程中实际执行的SQL并不多,同时并没有逻辑读高的SQL语句。也许问题并没有出现在SQL语句中,而是出现在存储过程中其他非SQL部分。虽然用10046没有找到SQL语句,但还是有重大发现,在过程执行时,大量的逻辑读来自于current方式的读,这显示不是通常的SELECT语句所产生的。接下来我们用dbms_profiler来分析存储过程:

  1. selectdbms_profiler.start_profilerfromdual;
  2. execintf.CRM_SERVICE_INTF.QueryService(.....);
  3. execdbms_profiler.stop_profiler;

然后使用来自MOS文档“Implementing and Using the PL/SQL Profiler [ID 243755.1]”中的profiler.sql脚本,生成一个profiler的结果文件,格式为html。下面是部分的内容:
在存储过程中的clob数据类型

点击其显示的代码行(line),跳转到相应的源代码,发现大量的字符串拼接代码,很明显是用于拼接成XML格式。这很容易理解,因为现在系统之间的文本数据交互,xml几乎成了标准。从上面的截图中也可以看到很多类型于xml:=xml || ‘xxxx’ 这样的代码。是这样的代码引起的问题吗?

检查代码发现,这里用于拼接字符串的变量xml,被定义为clob类型,这引起了我极大的关注。在oracle的标准数据类型中,lob类型由于其能够存储大数据的本质,导致其内部格式和操作是最复杂的。有理由怀疑是clob的大量拼接引起的问题。

在有怀疑对象后,我们可以构造下面的测试来进行验证:

首先创建下面3个不同的存储过程,但是实现的功能是一致的:

  1. createorreplaceprocedurep1(v_outoutclob)
  2. is
  3. v_lobclob;
  4. begin
  5. v_lob:='';
  6. forrecin(selectobject_namefromdba_objectswhererownum<=1000)loop
  7. v_lob:=v_lob||rec.object_name;
  8. endloop;
  9. v_out:=v_lob;
  10. end;
  11. /
  12. createorreplaceprocedurep2(v_outoutclob)
  13. is
  14. v_lobvarchar2(32767);
  15. begin
  16. v_lob:='';
  17. forrecin(selectobject_namefromdba_objectswhererownum<=1000)loop
  18. v_lob:=v_lob||rec.object_name;
  19. endloop;
  20. v_out:=v_lob;
  21. end;
  22. /
  23. createorreplaceprocedurep3(v_outoutclob)
  24. is
  25. v_lobclob;
  26. v_strvarchar2(32767);
  27. v_cntnumber;
  28. begin
  29. v_lob:='';
  30. v_cnt:=0;
  31. v_str:='';
  32. forrecin(selectobject_namefromdba_objectswhererownum<=1000)loop
  33. v_str:=v_str||rec.object_name;
  34. v_cnt:=v_cnt+1;
  35. ifv_cnt=50then
  36. v_cnt:=0;
  37. v_lob:=v_lob||v_str;
  38. v_str:='';
  39. endif;
  40. endloop;
  41. ifv_cnt<>0then
  42. v_lob:=v_lob||v_str;
  43. endif;
  44. v_out:=v_lob;
  45. end;
  46. /

第1个存储过程,P1,完全使用clob类型来拼接字符串;第2个存储过程,P2,使用varchar2类型拼接字符串,只有在过程最后将varchar2转成clob;第3个存储过程,P3,先使用varchar2类型拼接成较长的字符串,然后再用较长的字符串用clob类型来拼接。

下面看看P1和P2的差距:

  1. SQL>varv_lob1clob;
  2. SQL>varv_lob2clob;
  3. SQL>begin
  4. 2sys.runstats_pkg.rs_start;
  5. 3p1(:v_lob1);
  6. 4sys.runstats_pkg.rs_middle;
  7. 5p2(:v_lob2);
  8. 6sys.runstats_pkg.rs_stop;
  9. 7end;
  10. 8/
  11. Run1ranin5hsecs
  12. Run2ranin0hsecs
  13. run1ranin50000000%ofthetime
  14. NameRun1Run2Diff
  15. STAT...lobreads9990-999
  16. LATCH.cachebufferslruchain1,0000-1,000
  17. STAT...freebufferrequested1,0129-1,003
  18. STAT...lobwrites2,0001-1,999
  19. STAT...lobwritesunaligned2,0001-1,999
  20. LATCH.objectqueueheaderoper2,0249-2,015
  21. STAT...consistentgets3,581580-3,001
  22. STAT...consistentgetsfromca3,581580-3,001
  23. STAT...consistentchanges5,05142-5,009
  24. STAT...dbblockchanges5,06152-5,009
  25. STAT...callstogetsnapshots7,00810-6,998
  26. STAT...dbblockgetsfromcach14,07557-14,018
  27. STAT...dbblockgets14,07557-14,018
  28. STAT...sessionlogicalreads17,656637-17,019
  29. LATCH.cachebufferschains46,1511,083-45,068
  30. STAT...sessionugamemory138,60815,072-123,536
  31. STAT...sessionugamemorymax315,052131,024-184,028
  32. STAT...sessionpgamemorymax393,216131,072-262,144
  33. STAT...sessionpgamemory393,21665,536-327,680
  34. Run1latchestotalversusruns--differenceandpct
  35. Run1Run2DiffPct
  36. 49,7891,674-48,1152,974.25%
  37. PL/SQL过程已成功完成。

从上面的数据来看,差距是巨大的,执行P1时产生的一致性读(consistent gets)和当前模式读(db block gets),都远远大于执行P2时产生的一致读和当前模式读。特别是大量的db block gets验证了之前使用10046事件跟踪存储过程执行得到的结果。上面的数据中,甚至是会话消耗的内存都有很明显的差异。同时,还有其他对性能显著影响的地方,cache buffers chains latch,cache buffers lru chain latch,object queue header operation latch,这3种latch的获取次数是相当多的,在大并发时无疑将引起争用。实际上,在客户的这套系统中,这3种latch的争用经常出现,只是目前还没形成特别严重的后果。

再看看P1和P3的差异:

  1. SQL>varv_lob1clob;
  2. SQL>varv_lob2clob;
  3. SQL>begin
  4. 2sys.runstats_pkg.rs_start;
  5. 3p1(:v_lob1);
  6. 4sys.runstats_pkg.rs_middle;
  7. 5p3(:v_lob2);
  8. 6sys.runstats_pkg.rs_stop;
  9. 7end;
  10. 8/
  11. Run1ranin7hsecs
  12. Run2ranin2hsecs
  13. run1ranin350%ofthetime
  14. NameRun1Run2Diff
  15. STAT...lobreads99919-980
  16. LATCH.cachebufferslruchain1,00220-982
  17. STAT...freebufferrequested1,01229-983
  18. STAT...lobwrites2,00040-1,960
  19. STAT...lobwritesunaligned2,00040-1,960
  20. LATCH.objectqueueheaderoper2,01649-1,967
  21. STAT...consistentgetsfromca3,579639-2,940
  22. STAT...consistentgets3,579639-2,940
  23. STAT...consistentchanges5,051143-4,908
  24. STAT...dbblockchanges5,061153-4,908
  25. STAT...callstogetsnapshots7,007146-6,861
  26. STAT...dbblockgets14,075346-13,729
  27. STAT...dbblockgetsfromcach14,075346-13,729
  28. STAT...sessionlogicalreads17,654985-16,669
  29. LATCH.cachebufferschains46,1471,999-44,148
  30. STAT...sessionugamemory189,01265,464-123,548
  31. STAT...sessionpgamemory196,60865,536-131,072
  32. STAT...sessionpgamemorymax262,14465,536-196,608
  33. STAT...sessionugamemorymax315,05265,560-249,492
  34. Run1latchestotalversusruns--differenceandpct
  35. Run1Run2DiffPct
  36. 49,3802,264-47,1162,181.10%

二者的差异同样很明显。

不仅如此,在存储过程中,执行P1过程之后,甚至在临时表空间中产生了临时段,而这个临时段是不会自动清除的,经测试,即使没有用于返回结果的clob参数,在过程内部生成的clob所占的临时段也不会自动清除,只有会话退出才会清除掉。如果更深入跟踪,也许可以发现大量的逻辑读来源于这个临时段。

  1. SQL>selecttablespace,contents,segtype,blocksfromv$sort_usage;
  2. TABLESPACECONTENTSSEGTYPEBLOCKS
  3. -----------------------------------------------------------
  4. TEMPTEMPORARYLOB_DATA128

通过验证,证明clob类型的数据的确是引起客户系统中存储过程大量逻辑读和Latch争用的原因,找到了这个原因,优化就相对简单了。

在PL/SQL存储过程中,clob是相当方便的一种数据类型,由于其能够存储超长字符数据的特性,使得在这种用于数据交换的存储过程中用得较多。然而,从上面的数据中,不难发现,如果大量使用clob运算,将普通的字符串拼接成clob,其CPU消耗、逻辑读、甚至是latch的获取都是非常高的,对性能影响非常大。实际上在10g中,存储过程中的varchar2类型,其长度最大可以达到32767,所以如果返回的结果确保不超过这个长度,完全可以使用varchar2类型,只是在返回时再转换为clob,正如上面的存储过程P2所做的那样。如果其长度超过了32767,也可以如存储过程P3一样,先将短小的字符串拼接成较大的字符串,然后将较大的字符串拼接到clob中。