Home > Oracle, Performance > Consistent reads – who is the culprit?

Consistent reads – who is the culprit?


In many occasions, SQLs failed with “ORA-01555 snapshot too old error” due to DMLs along with the SELECT query.  There is no view in Oracle database to tell us who is or which transaction is forcing to read UNDO for consistency.  Below example shows,

SQL> select count(*) from test;

Execution Plan
----------------------------------------------------------
Plan hash value: 3467505462
-------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
-------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 580 (3)| 00:00:04 |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | TABLE ACCESS FULL| TEST | 237K| 580 (3)| 00:00:04 |
-------------------------------------------------------------------
Note
-----
 - dynamic sampling used for this statement

Statistics
----------------------------------------------------------
 0 recursive calls
 0 db block gets
 5534 consistent gets
 3724 physical reads
 0 redo size
 524 bytes sent via SQL*Net to client
 523 bytes received via SQL*Net from client
 2 SQL*Net roundtrips to/from client
 0 sorts (memory)
 0 sorts (disk)
 1 rows processed

And when I execute the same query second time, the statistics was totally different.

SQL> select count(*) from test;

Execution Plan
----------------------------------------------------------
Plan hash value: 3467505462
-------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
-------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 580 (3)| 00:00:04 |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | TABLE ACCESS FULL| TEST | 237K| 580 (3)| 00:00:04 |
-------------------------------------------------------------------
Note
-----
 - dynamic sampling used for this statement

Statistics
----------------------------------------------------------
 0 recursive calls
 0 db block gets
 284398 consistent gets
 14148 physical reads
 0 redo size
 524 bytes sent via SQL*Net to client
 523 bytes received via SQL*Net from client
 2 SQL*Net roundtrips to/from client
 0 sorts (memory)
 0 sorts (disk)
 1 rows processed

284398 vs 5534 consistent gets and 14148 vs 3724 physical reads – the difference is too high.    I know why there is a difference, but in production systems, it is hard to find the user who has executed the DML.   I used below step by step method to find the actual user, transaction and SQLs related to the consistent gets.

Initially identify, which Undo block the SQL is querying, from v$session_wait.

SQL> set linesize 200
col event for a30
col username for a20
set pagesize 40
col p1 for 999999999999
col OSUSER for a12
select v.inst_id,v.seq#,v.sid,username,v.event,v.p1,v.p2,v.p3,last_call_et,sql_hash_value,sql_id,SQL_CHILD_NUMBER
from gv$session_wait v, gv$session s where v.event not like '%message%' and s.sid=v.sid and
s.INST_ID=v.INST_ID and username is not null
order by last_call_et;
INST_ID SEQ# SID USERNAME EVENT P1 P2 P3 LAST_CALL_ET SQL_HASH_VALUE SQL_ID SQL_CHILD_NUMBER
---------- ---------- ---------- -------------------- ------------------------------ ------------- ---------- ---------- ------------ -------------- ------------- ----------------
 1 50707 84 THOMAS db file sequential read 3 133637 1 0 1689401402 c99yw1xkb4f1u 0

The file_id is  3 and the block number 133637.  To investigate I need to identify any single UNDO block belongs to the transaction as the transaction level information is common.    Also confirmed the file_id 3 is an Undo file.

SQL> select file_name from dba_data_files where file_id=3;
FILE_NAME
/oradata/prak/data/undo1.dbf

Let me dump the undo block to get more information about the offending transaction.

SQL> alter system dump datafile 3 block 133637;
System altered.

In the trace files, look for mainly Obejct ID and transaction information.

UNDO BLK:
xid: 0x0002.004.0000aca1 seq: 0xc13 cnt: 0x1b irb: 0x1b icl: 0x0 flg: 0x0000
Rec Offset Rec Offset Rec Offset Rec Offset Rec Offset
---------------------------------------------------------------------------
0x01 0x1ec0 0x02 0x1d9c 0x03 0x1c7c 0x04 0x1b58 0x05 0x1a34
0x06 0x1914 0x07 0x17f0 0x08 0x16cc 0x09 0x15b0 0x0a 0x1494
0x0b 0x1374 0x0c 0x1250 0x0d 0x112c 0x0e 0x1008 0x0f 0x0ee4
0x10 0x0dc8 0x11 0x0ca8 0x12 0x0b80 0x13 0x0a60 0x14 0x0940
0x15 0x0824 0x16 0x0704 0x17 0x05e4 0x18 0x04c4 0x19 0x03a0
0x1a 0x027c 0x1b 0x0158
*-----------------------------
* Rec #0x1 slt: 0x04 objn: 56134(0x0000db46) objd: 56134 tblspc: 4(0x00000004)
* Layer: 11 (Row) opc: 1 rci 0x00
Undo type: Regular undo Last buffer split: No
Temp Object: No
Tablespace Undo: No
rdba: 0x00c20a04
*-----------------------------
KDO undo record:
KTB Redo
op: 0x02 ver: 0x01
compat bit: 4 (post-11) padding: 1
op: C uba: 0x00c20a04.0c13.1b
KDO Op code: URP row dependencies Disabled
 xtype: XA flags: 0x00000000 bdba: 0x0101252e hdba: 0x0100fdb3
itli: 2 ispac: 0 maxfr: 4858
tabn: 0 slot: 21(0x15) flag: 0x2c lock: 0 ckix: 255
ncol: 14 nnew: 1 size: -3
col 0: [ 3] 53 59 53

From the trace, you can get the actual transaction id which forced UNDO for my select statement is 0×0002.004.0000aca1 and object ID is 56134.  Confirm you got the correct object.

SQL> select object_name,owner from dba_objects where object_id=56134 ;
OBJECT_NAM OWNER
---------- ------------------------------
TEST THOMAS

Well, you got the table name as TEST which is the table I have used in the SELECT statement.

From trace, collect the XID for the transaction, is 0×0002.004.0000aca1 and convert trace XID to database used format as in V$transaction using the below rule.

0×0002.004.0000aca1 => XID Trace

000200040000aca1      => Remove ’0x’ and repalce first ‘.’ with ’0′ and remove second ‘.’ to get the XID

Armed with the XID, use the flashback transaction details to examine more about the transaction as

SQL> SELECT xid, operation, start_scn, commit_scn, logon_user, undo_sql
 FROM flashback_transaction_query
 WHERE xid = HEXTORAW('000200040000aca1');
XID OPERATION START_SCN COMMIT_SCN LOGON_USER
---------------- -------------------------------- ---------- ---------- ----------------
UNDO_SQL
----------------------------------------------------------------------------------------
000200040000ACA1 UPDATE 55095447 THOMAS
update "THOMAS"."TEST" set "OWNER" = 'SYS' where ROWID = 'AAANtGAAEAAASlwAA+';
000200040000ACA1 UPDATE 55095447 THOMAS
update "THOMAS"."TEST" set "OWNER" = 'SYS' where ROWID = 'AAANtGAAEAAASlwAA9';
000200040000ACA1 UPDATE 55095447 THOMAS
update "THOMAS"."TEST" set "OWNER" = 'SYS' where ROWID = 'AAANtGAAEAAASlwAA8';
000200040000ACA1 UPDATE 55095447 THOMAS
update "THOMAS"."TEST" set "OWNER" = 'SYS' where ROWID = 'AAANtGAAEAAASlwAA7';
000200040000ACA1 UPDATE 55095447 THOMAS
update "THOMAS"."TEST" set "OWNER" = 'SYS' where ROWID = 'AAANtGAAEAAASlwAA6';
000200040000ACA1 UPDATE 55095447 THOMAS
update "THOMAS"."TEST" set "OWNER" = 'SYS' where ROWID = 'AAANtGAAEAAASlwAA5';
000200040000ACA1 UPDATE 55095447 THOMAS
update "THOMAS"."TEST" set "OWNER" = 'SYS' where ROWID = 'AAANtGAAEAAASlwAA4';
000200040000ACA1 UPDATE 55095447 THOMAS
update "THOMAS"."TEST" set "OWNER" = 'SYS' where ROWID = 'AAANtGAAEAAASlwAA3';
000200040000ACA1 UPDATE 55095447 THOMAS
update "THOMAS"."TEST" set "OWNER" = 'SYS' where ROWID = 'AAANtGAAEAAASlwAA2';
000200040000ACA1 UPDATE 55095447 THOMAS
update "THOMAS"."TEST" set "OWNER" = 'SYS' where ROWID = 'AAANtGAAEAAASlwAA1';
000200040000ACA1 UPDATE 55095447 THOMAS
update "THOMAS"."TEST" set "OWNER" = 'SYS' where ROWID = 'AAANtGAAEAAASlwAA0'

Now you have enough data to proceed – the username,  XID,  start SCN, end SCN etc.  If required you can use log miner to get more details.  I hope Oracle will soon externalize views to identify who is forcing me consistent gets.

About these ads
  1. venu
    July 19, 2013 at 3:18 pm | #1

    very good

  1. No trackbacks yet.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: