“Dump Online Redo for Buffers in Pin History”
I’ve just been investigating why a certain report ran slow last night.
Got to be a bit careful with ASH once it goes into the repository – DBA_HIST_ACTIVE_SESS_HISTORY – because it’s a sample of a sample.
Normally, I prefer looking at the raw data to see what is and isn’t in the sample, time gaps, etc, but in this case an aggregation is quite clear:
SQL> select sql_exec_id
2 , sql_plan_line_id plan_line
3 , decode(event,null,session_state,event) event
4 , count(*)
5 , to_char(min(sample_time),'HH24:MI') min_time
6 , to_char(max(sample_time),'HH24:MI') max_time
7 , round(sum(delta_time)/1000000,2) delta
8 from dba_hist_active_sess_history
9 where sql_id = '2b1y41hau5qhr'
10 and sample_time >= trunc(sysdate) -1
11 group by trunc(sample_time), sql_exec_id, sql_plan_line_id, event
12 , session_state
13 order by 5 asc;
SQL_EXEC_ID PLAN_LINE EVENT COUNT(*) MIN_T MAX_T DELTA
----------- ---------- ------------------------------ ---------- ----- ----- ----------
control file sequential read 6 19:57 20:19 58.83
log file sequential read 289 19:58 20:48 2897.27
ON CPU 11 20:01 20:47 110.27
16777217 18 db file sequential read 1 20:48 20:48 10.02
16777217 63 ON CPU 3 20:48 20:49 30.09
16777217 16 db file sequential read 1 20:48 20:48 10.03
6 rows selected.
SQL>
Bottom line: this query is related to a problem I had with an ORA-00600 a couple of weeks ago happenign during the query transformation phase of a hard parse. We did not release a fix for this, prefering to defer until the next major release for the application, because the ORA-00600 was not fatal.
However, whilst the ORA-00600 is not fatal to the end process it is very much a performance problem and the impact depends on how much work the session has done when it gets the error.
If we look in the alert log, we find the ORA-00600 in question along with some interesting timestamps that broadly correlate with the episodes of log file sequential read from the ASH output above:
Tue May 08 19:57:14 2012
Errors in file /......directory.../trace file.trc (incident=2356995):
ORA-00600: internal error code, arguments: [kkqtSetOp.1], [], [], [], [], [], [], [], [], [], [], []
...
Tue May 08 20:48:25 2012
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
Errors in file /......directory.../trace file.trc (incident=2356996):
ORA-00600: internal error code, arguments: [kkqtSetOp.1], [], [], [], [], [], [], [], [], [], [], []
If we look at the incident files in question, the second (incident=2356996) is a continuation of the first (incident=2356995).
So what are these log file sequential reads all about?
Following the ORA-00600, it’s diagnostic information – specifically the action “Dump Online Redo for Buffers in Pin History”.
In this case, the getting and dumping of these buffers took the best part of the 50 minutes and once done the query continued on its merry way and the process completed.
What we see in the incident file is a timeline like this starting at 19:57:18:
*** timestamp before redo dump: 05/08/2012 19:57:18
***********************************************
* Dump Online Redo for Buffers in Pin History *
***********************************************
$$$$$$$ Dump Online Redo for DBA list (tsn.rdba in hex):
0xa.05dbf102 0xa.05dbf103 0xa.05dbf104 0xa.05dbf105 0xa.05dbf107 0xa.05dbf109 0xa.05dbf110 0xa.05dbf111 0xa.05dbf113 0xa.05dbf115 0xa.05dbf116 0xa.05dbf119 0xa.05dbf11b 0xa.05dbf11c 0xa.05dbf11e 0xa.05dbf11f:
DUMP REDO
Opcodes *.*
DBAs (file#, block#):
(23, 1831170) (23, 1831171) (23, 1831172) (23, 1831173) (23, 1831175) (23, 1831177) (23, 1831184) (23, 1831185) (23, 1831187) (23, 1831189) (23, 1831190) (23, 1831193) (23, 1831195) (23, 1831196) (23, 1831198) (23, 1831199) .
SCNs: scn: 0x0000.00000000 thru scn: 0xffff.ffffffff
Times: 05/08/2012 18:57:18 thru eternity
Initial buffer sizes: read 1024K, overflow 832K, change 805K
*** 2012-05-08 19:57:34.263
Log read is SYNCHRONOUS though disk_asynch_io is enabled!
Log read is SYNCHRONOUS though disk_asynch_io is enabled!
Log read is SYNCHRONOUS though disk_asynch_io is enabled!
Log read is SYNCHRONOUS though disk_asynch_io is enabled!
*** 2012-05-08 19:57:57.137
Thread 1 low checkpoint scn: 0x077b.9d30745d
SCN Start Scan Point: scn: 0x077b.9d30745d (8227499570269)
Initial buffer sizes: read 1024K, overflow 832K, change 805K
INCARNATION:
START: scn: 0x077a.31629df7 (8221395951095) Timestamp: 04/02/2012 14:41:00
END: scn: 0xffff.ffffffff
*** 2012-05-08 19:58:09.227
Log read is SYNCHRONOUS though disk_asynch_io is enabled!
descrip:"Thread 0001, Seq# 0000018211, SCN 0x077b9d30745d-0x077b9d31adcd"
.....
Through to 20:48:25 when:
*** 2012-05-08 20:48:25.097
END OF DUMP REDO
***********************************************
* End Dumping Redo for Buffers in Pin History *
***********************************************
*** timestamp after redo dump: 05/08/2012 20:48:25
*** time cost of this redo dump is 3067 seconds
Credit to Coskan for his observations, asking the right questions and pointing me in the direction of this post by Jonathan Lewis, including the comments, particularly #12 from Timur Akhmadeev which pointed in the right direction.
This is now the second time in a matter of a few weeks that I’ve seen this dump behaviour itself cause serious knock-on issues.
The previous time was on one occasion during my ORA-00600 post-upgrade storm where this recursive getting and dumping of redo buffers – this time caused by an ORA-07445 – meant that certain allocated resources were not freed in a timely fashion resulting in a large queue for “library cache : mutex x” until the dumping session was killed.
