How Many Topics can be Packed into a Short OTN Thread?

21 01 2010

January 21, 2010

This thread from 2008 has 31 replies:
http://forums.oracle.com/forums/thread.jspa?messageID=2502493&tstart=0

The thread starts off with a simple statement, without a lot of technical detail (kind of like this example):

“We are runing in 10g (10.2.0.3), when using full table scan, the perfromance is very slow. Is a bug in ASM or SQL program problem? How can I vertify the problem come from? I have runing health check in oracle but found nothing.”

So, where does the thread head?  Topics?

  • “By definition the Full Table Scan access is the most feared enemy, you should avoid that monster when your tables are huge (many rows &/or long rows).”
  • “Not all full table scans are bad, not all indexes are good”
  • Enabling a 10046 trace file for a session might help.
  • “Usually you don’t want your applications to access a very large part of a large table. This will be very slow and could deteriorate the performance of your application severely.”
  • “We had the same issues with full table scans in 10.2.0.3 where we had gathered system stats”
  • “If I’m not mistaken, Oracle says that if you query 7.5% of the table rows and above you are usually better off with an FTS”  A link was provided by someone else to a site that made a similar claim.
  • “I can very easily give you an example where an index would be the best option to query 99% of data. I can very easily give you an example where a FTS is the best option to query 1% of data.”
  • What is noise in a thread?
  • A full tablescan reads all of the blocks up to the high watermark – but does it always?
  • “The only way to improve the end-to-end performance of a full-table scan is Oracle parallel query (OPQ).” – or is it?
  • “That’s improved the tablescan by a factor of nearly 30 simply by changing the array fetch size”
  • Properly setting the DB_FILE_MULTIBLOCK_READ_COUNT will have an impact on the performance of a full table scan.
  • The value of a 10046 trace, a test case.

In this OTN thread I provided a nice litte test case that showed a 10046 trace where a full table scan operation did not read all of the table blocks up to the high watermark for the table.  That test case appears below:

CREATE TABLE T1(
  C1 NUMBER(10),
  C2 VARCHAR2(255),
  C3 VARCHAR2(255),
  C4 VARCHAR2(255));

INSERT INTO
  T1
SELECT
  ROWNUM RN,
  LPAD('A',255,'A'),
  LPAD('B',255,'B'),
  LPAD('C',255,'C') 
FROM
  DUAL
CONNECT BY
  LEVEL<=500000;

COMMIT;

We have a table with 500,000 rows with possibly 10 rows per 8KB block (AVG_ROW_LEN is 772). Now, flush the buffer cache to force physical reads:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

Now, let’s force a full table scan (a 10046 trace is enabled at level 8, and a DBMS_XPLAN is generated):

SELECT
  *
FROM
  T1
WHERE
  ROWNUM<=1000;

DBMS_XPLAN (partial output):

----------------------------------------------------------------------------------------------
| Id  | Operation          | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
----------------------------------------------------------------------------------------------
|*  1 |  COUNT STOPKEY     |      |      1 |        |   1000 |00:00:00.10 |     123 |    176 |
|   2 |   TABLE ACCESS FULL| T1   |      1 |    500K|   1000 |00:00:00.08 |     123 |    176 |
----------------------------------------------------------------------------------------------

Did the TABLE ACCESS FULL (full table scan) operation in the plan indicate that Oracle read all blocks up to the high water mark (I intentially excluded the Access/Filter Predicates)? Oracle did NOT read all blocks up to the high water mark, regardless of what the plan shows. The proof is in the 10046 trace file:

=====================
PARSING IN CURSOR #11 len=54 dep=0 uid=63 oct=3 lid=63 tim=1044938463796 hv=4195490999 ad='1c501fdc' sqlid='g386bagx1475r'
SELECT
  *
FROM
  T1
WHERE
  ROWNUM<=1000
END OF STMT
PARSE #11:c=0,e=2282,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1044938463790
EXEC #11:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1044938464457
WAIT #11: nam='SQL*Net message to client' ela= 7 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938464504
WAIT #11: nam='db file sequential read' ela= 40853 file#=1 block#=84361 blocks=1 obj#=72319 tim=1044938505437
WAIT #11: nam='reliable message' ela= 232 channel context=563314104 channel handle=563285032 broadcast message=564250208 obj#=72319 tim=1044938506251
WAIT #11: nam='enq: KO - fast object checkpoint' ela= 163 name|mode=1263468550 2=65558 0=1 obj#=72319 tim=1044938506489
WAIT #11: nam='direct path read' ela= 41814 file number=1 first dba=84362 block cnt=7 obj#=72319 tim=1044938586589
WAIT #11: nam='direct path read' ela= 19323 file number=1 first dba=87305 block cnt=48 obj#=72319 tim=1044938606571
FETCH #11:c=0,e=142335,p=86,cr=15,cu=0,mis=0,r=100,dep=0,og=4,tim=1044938606885
WAIT #11: nam='SQL*Net message from client' ela= 1258 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938608214
WAIT #11: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938608305
FETCH #11:c=0,e=690,p=0,cr=12,cu=0,mis=0,r=100,dep=0,og=4,tim=1044938608971
WAIT #11: nam='SQL*Net message from client' ela= 656 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938609666
WAIT #11: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938609725
FETCH #11:c=0,e=687,p=0,cr=12,cu=0,mis=0,r=100,dep=0,og=4,tim=1044938610396
WAIT #11: nam='SQL*Net message from client' ela= 579 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938611012
WAIT #11: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938611072
FETCH #11:c=0,e=681,p=0,cr=12,cu=0,mis=0,r=100,dep=0,og=4,tim=1044938611734
WAIT #11: nam='SQL*Net message from client' ela= 742 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938612512
WAIT #11: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938612575
WAIT #11: nam='direct path read' ela= 4898 file number=1 first dba=87361 block cnt=30 obj#=72319 tim=1044938618207
FETCH #11:c=0,e=5901,p=42,cr=12,cu=0,mis=0,r=100,dep=0,og=4,tim=1044938618458
WAIT #11: nam='SQL*Net message from client' ela= 631 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938619135
WAIT #11: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938619197
FETCH #11:c=0,e=681,p=0,cr=12,cu=0,mis=0,r=100,dep=0,og=4,tim=1044938619860
WAIT #11: nam='SQL*Net message from client' ela= 581 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938620476
WAIT #11: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938620532
FETCH #11:c=0,e=683,p=0,cr=12,cu=0,mis=0,r=100,dep=0,og=4,tim=1044938621199
WAIT #11: nam='SQL*Net message from client' ela= 920 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938622154
WAIT #11: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938622219
WAIT #11: nam='direct path read' ela= 8072 file number=1 first dba=87391 block cnt=42 obj#=72319 tim=1044938630900
FETCH #11:c=0,e=8966,p=48,cr=12,cu=0,mis=0,r=100,dep=0,og=4,tim=1044938631167
WAIT #11: nam='SQL*Net message from client' ela= 613 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938631822
WAIT #11: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938631880
FETCH #11:c=0,e=686,p=0,cr=12,cu=0,mis=0,r=100,dep=0,og=4,tim=1044938632550
WAIT #11: nam='SQL*Net message from client' ela= 583 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938633168
WAIT #11: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938633271
FETCH #11:c=0,e=675,p=0,cr=12,cu=0,mis=0,r=100,dep=0,og=4,tim=1044938633928
WAIT #11: nam='SQL*Net message from client' ela= 602 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938634565
WAIT #11: nam='direct path read' ela= 22151 file number=1 first dba=86793 block cnt=48 obj#=72319 tim=1044938656764
FETCH #11:c=0,e=22249,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1044938656854
STAT #11 id=1 cnt=1000 pid=0 pos=1 obj=0 op='COUNT STOPKEY (cr=123 pr=176 pw=176 time=37561 us)'
STAT #11 id=2 cnt=1000 pid=1 pos=1 obj=72319 op='TABLE ACCESS FULL T1 (cr=123 pr=176 pw=176 time=34756 us cost=8433 size=386000000 card=500000)'
WAIT #11: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938656998
WAIT #11: nam='SQL*Net message from client' ela= 132538 driver id=1413697536 #bytes=1 p3=0 obj#=72319 tim=1044938789567
=====================

From the trace file we see many interesting details, including the absence of the typical db file scattered reads commonly associated with full table scans. From the trace it is also possible to see that 100 rows were read at a time, with a fairly consistent delay between requests for each set of the 100 rows. What else might we see in the trace file that would help us identify the source of a performance problem?

« »


Actions

Information

2 responses

21 01 2010
Taral Desai (01:44:14) :

Hi Charles,

It’s very interesting one. Also, can you please elaborate if possible from Jonathan post saying

” through the index, you will hit the root block of the index one, and the table block once for a total of 2 LIOs. If you do a tablescan you will access the segment header block twice (9i onwards) and the table block once for a total of 3 LIO”

1. Table scan will access segment block twice . How can we arrive at this number any proof

2. So, does this means that ever block access has 3 LIO for table.

3. If i am understanding right then for Index range scan it will hit root + branch + blevel (total 3 LIO) for ever scan.(every value scan) any example

Reply
22 01 2010
Charles Hooper (07:53:09) :

I was hoping that Jonathan would see your question and provide you with a very carefully constructed answer to your questions. The results could be different depending on whether you are using dictionary managed tablespaces, locally managed tablespaces with manual freelist management, or locally managed tablespaces with ASSM AUTO ALLOCATEd management.

How to demonstrate what is happening? Setting event 10200 causes all logical IOs to be written to a trace file. See:
http://www.freelists.org/post/oracle-l/Logical-IO,3
http://www.juliandyke.com/Diagnostics/Events/EventReference.html#10200

Keep in mind that Jonathan is referring to a very specific case in the response that you quoted, a case where there is a table with a single row in a table with a single column that also has an index on that single column. In such a case, the index structure will contain a single block – the root block, so an index access to the one block would require reading the index root block, and then the table block pointed to by the index entry. I believe that Richard Foote’s blog contains several examples of how this would work for very small index structures.

So, how to set up a test case (note that I modified this to have a table with two columns)?

CREATE TABLE T1 (
  C1 NUMBER,
  C2 NUMBER,
  PRIMARY KEY (C1));
 
INSERT INTO T1 VALUES(1,1);
 
COMMIT;
 
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE)

OK, we now have a table defined with two columns, with a primary key index, and a single row. Now the test case:

SELECT /*+ GATHER_PLAN_STATISTICS FULL(T1) */
  *
FROM
  T1;
 
SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
 
SELECT /*+ GATHER_PLAN_STATISTICS INDEX(T1) */
  *
FROM
  T1;
 
SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));
 
ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT FOREVER, LEVEL 1';
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'Event10200Test1';
 
SELECT /*+ GATHER_PLAN_STATISTICS FULL(T1) */
  *
FROM
  T1;
 
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'Event10200Test2';
 
SELECT /*+ GATHER_PLAN_STATISTICS INDEX(T1) */
  *
FROM
  T1;
 
ALTER SESSION SET EVENTS '10200 TRACE NAME CONTEXT OFF';

The output from the above for Oracle 10.2.0.x with an ASSM AUTO ALLOCATEd tablespace follows:

SQL_ID  0yp492wfxqf3q, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS FULL(T1) */   * FROM   T1
 
Plan hash value: 3617692013
 
------------------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------
|   1 |  TABLE ACCESS FULL| T1   |      1 |      1 |      1 |00:00:00.01 |       7 |
------------------------------------------------------------------------------------
 
SQL_ID  2v0wvvx7sjxj8, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS INDEX(T1) */   * FROM   T1
 
Plan hash value: 3727918903
 
------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------------------------
|   1 |  TABLE ACCESS BY INDEX ROWID| T1           |      1 |      1 |      1 |00:00:00.01 |       2 |
|   2 |   INDEX FULL SCAN           | SYS_C0020540 |      1 |      1 |      1 |00:00:00.01 |       1 |
------------------------------------------------------------------------------------------------------

As you can see from the above, the full table scan required 7 logical IOs, and the index access required 2 logical IOs (1 for the index root block, and a second for the parent operation’s table access). Let’s take a look in the trace files:
From event10200test1 (full table scan – slightly trimmed for space):

Consistent read started for block 4 : 0110ae0c
Consistent read finished for block 4 : 110ae0c
Consistent read finished for block 4 : 110ae0c
Consistent read started for block 4 : 0110ae0d
Consistent read finished for block 4 : 110ae0d
Consistent read finished for block 4 : 110ae0d
Consistent read started for block 4 : 0110ae0e
Consistent read finished for block 4 : 110ae0e
Consistent read finished for block 4 : 110ae0e
Consistent read started for block 4 : 0110ae0f
Consistent read finished for block 4 : 110ae0f
Consistent read finished for block 4 : 110ae0f
Consistent read started for block 4 : 0110ae10
Consistent read finished for block 4 : 110ae10
Consistent read finished for block 4 : 110ae10

From event10200test1 (index full scan – slightly trimmed for space):

Consistent read started for block 4 : 0110ae1c
Consistent read finished for block 4 : 110ae1c
Consistent read started for block 4 : 0110ae0e
Consistent read finished for block 4 : 110ae0e
Consistent read finished for block 4 : 110ae0e

So, what are those blocks? Well, you could execute something like this to look at the table’s blocks (note that this could be very slow):

SELECT /*+ ORDERED */
  DE.BLOCK_ID+C.COUNTER BLOCK_ID,
  TO_CHAR(DE.BLOCK_ID+C.COUNTER,'XXXXXXXX') HEX_BLOCK_ID,
  DE.BLOCKS,
  C.COUNTER+1 COUNTER
FROM
  (SELECT
    BLOCK_ID,
    BLOCKS
  FROM
    DBA_EXTENTS
  WHERE
    OWNER=USER
    AND SEGMENT_NAME IN ('T1')) DE,
  (SELECT
    ROWNUM-1 COUNTER
  FROM
    DUAL
  CONNECT BY
    LEVEL<=64) C
WHERE
  DE.BLOCKS>C.COUNTER
ORDER BY
  C.COUNTER;
 
  BLOCK_ID HEX_BLOCK     BLOCKS    COUNTER
---------- --------- ---------- ----------
   1093129    10AE09          8          1
   1093130    10AE0A          8          2
   1093131    10AE0B          8          3
   1093132    10AE0C          8          4
   1093133    10AE0D          8          5
   1093134    10AE0E          8          6
   1093135    10AE0F          8          7
   1093136    10AE10          8          8

So, during the full table scan, Oracle read blocks 4, 5, 6, 7, and 8 – for a total of 5 logical IO blocks reads. But, the DBMS_XPLAN output clearly showed that were 7 logical IO blocks read, so what about the other two logical IOs. I suppose that there is another event that needs to be set to see those logical IOs.

Reply

Leave a Reply

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

Gravatar
WordPress.com Logo

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

Facebook photo

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

Cancel

Connecting to %s


%d bloggers like this: