Hi,
Recently we have encountered one performance issue, which is most likely caused by a sudden increase in the buffer gets per execution.
The SQL is an update statement, updating a table using a primary key (we have checked to confirm the running execution plan is using the primary key), and one field being updated is a BLOB column.
As shown in the below statistics, there is no major change in the number of executions during the every 20 minutes monitoring interval. However, the buffer gets per executions has been more than double, and the CPU time is almost doubled, hence the exec_time (elapsed time) has been doubled.
The same SQL has been running for the past four years in multiple similar databases. The database is Oracle 9.2.0.4 running on Solaris 9. For the past 300 days, the average elapsed time per execution is about 0.0093s, while the average buffer gets per execution is about 670. The update statement has been executed about 9 times per second.
The question is why there is a sudden increase in the buffer gets? The sudden increase happened twice for the past two days.
<pre>
B_TIME E_TIME EXECUTIONS_DIFF EXEC_TIME CPU_TIME BUFFER_GETS EXEC_PER_DAY
--------------------------------------------------------------------------------
------------------------------------------------------------------------------------------------
------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------
2009-11-25-14:04 2009-11-25-14:23 8513 .0069 .0068 315.56 646329
2009-11-25-14:23 2009-11-25-14:43 10170 .007 .0068 312.28 726188
2009-11-25-14:43 2009-11-25-15:05 11873 .0072 .0069 320.17 787885
2009-11-25-15:05 2009-11-25-15:23 8633 .011 .0101 844.83 675014
2009-11-25-15:23 2009-11-25-15:44 9668 .0144 .0137 1448.51 680778
2009-11-25-15:44 2009-11-25-16:04 9671 .0163 .0156 1809.04 702163
2009-11-25-16:04 2009-11-25-16:25 10260 .0188 .0177 2107.67 711447
2009-11-25-16:25 2009-11-25-16:44 9827 .0157 .0151 1834.3 739593
2009-11-25-16:44 2009-11-25-17:05 10586 .0171 .0164 2008.25 714555
...
2009-11-26-08:04 2009-11-26-08:24 11028 .0182 .0172 1979.61 800688
2009-11-26-08:24 2009-11-26-08:44 10533 .0154 .0149 1734.62 750248
2009-11-26-08:44 2009-11-26-09:04 9367 .018 .0168 2043.95 685274
2009-11-26-09:04 2009-11-26-09:24 10307 .0214 .0201 2552.43 729938
2009-11-26-09:24 2009-11-26-09:45 10932 .0251 .0234 3111.48 762328
2009-11-26-09:45 2009-11-26-10:05 10992 .0278 .0254 3386.41 797404
...
2009-11-26-15:03 2009-11-26-15:16 7183 .0425 .0348 4615.42 746824
2009-11-26-15:16 2009-11-26-15:23 2921 .0417 .0373 4887.75 682092
2009-11-26-15:23 2009-11-26-15:43 9597 .0393 .0352 4603.62 679656
2009-11-26-15:43 2009-11-26-16:03 8797 .0411 .0362 4783.66 630755
2009-11-26-16:03 2009-11-26-16:23 9957 .0453 .0391 5168.28 718100
2009-11-26-16:23 2009-11-26-16:43 11209 .0436 .0369 4870.77 808395
2009-11-26-16:43 2009-11-26-17:03 10729 .0428 .0375 5119.56 766103
2009-11-26-17:03 2009-11-26-17:23 9116 .0409 .0363 4912.58 659098
</pre>
Yesterday I did a trace on one of the sessions running the update statement, and below is the tkprof output:
<pre>
call count cpu elapsed disk query current rows
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------------
------------------------------------------------------------------------------------------
------------------------------------------------------------------------------------------
--------------------------------------------------------------------------------
Parse 76 0.03 0.00 0 0 0 0
Execute 76 4.58 5.14 0 567843 19034 76
Fetch 0 0.00 0.00 0 0 0 0
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------------
------------------------------------------------------------------------------------------
------------------------------------------------------------------------------------------
--------------------------------------------------------------------------------
total 152 4.61 5.14 0 567843 19034 76
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 88
Rows Row Source Operation
--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
1 UPDATE (cr=30 r=0 w=0 time=6232 us)
1 INDEX UNIQUE SCAN <PK Index Name> (cr=3 r=0 w=0 time=58 us)(object id 81122)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
--------------------------------------------------------------------------------
Waited--------------------------------------------------------------------------------
--------------------------------------------------------------------------------
SQL*Net message to client 152 0.00 0.00
SQL*Net message from client 152 0.00 0.22
SQL*Net more data from client 1894 0.00 0.03
SQL*Net break/reset to client 152 0.00 0.00
buffer busy waits 14 0.00 0.00
enqueue 1 0.61 0.61
********************************************************************************
</pre>
GaoYuan