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?


Comments : 2 Comments »

Categories : General Administration