Now, that’s weird.
A little surprising might be more accurate and maybe I’m missing something.
During the various tests with and without parallel hints and different parallel_io_cap_enabled settings, I expected the runs that didn’t use parallelism to show up “db file scattered read” events in the trace files. For example, here’s the explain plan and wait event summary generated by tkprof from a test on version 10.2.0.2
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT GROUP BY (cr=0 pr=0 pw=0 time=64 us)
0 HASH JOIN (cr=0 pr=0 pw=0 time=15 us)
65536000 TABLE ACCESS FULL TEST_TAB2 (cr=1118253 pr=1052301 pw=0 time=1441796425 us)
47535880 TABLE ACCESS FULL TEST_TAB1 (cr=832521 pr=832491 pw=0 time=1378575273 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
db file scattered read 135042 0.16 983.67
direct path write temp 5961 6.05 833.35
db file sequential read 15370 0.04 17.56
local write wait 4482 0.39 479.14
SQL*Net break/reset to client 2 0.01 0.01
and here’s the same section from an 11.1.0.6 trace file. The test isn’t quite identical – I don’t have the 10g database around any more – but I suppose I could try it later.
Rows Row Source Operation
------- ---------------------------------------------------
113 SORT GROUP BY (cr=2265134 pr=2479358 pw=2479358 time=0 us cost=945776
size=787633200 card=65636100)
65529137 HASH JOIN (cr=2265134 pr=2479358 pw=2479358 time=2198939 us cost=647314
size=787633200 card=65636100)
65536000 TABLE ACCESS FULL TEST_TAB2 (cr=1130519 pr=1130495 pw=1130495 time=8362747 us
cost=267173 size=393816600 card=65636100)
65536000 TABLE ACCESS FULL TEST_TAB1 (cr=1134615 pr=1134591 pw=1134591 time=9715954 us
cost=268141 size=393880800 card=65646800)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 9 0.00 0.00
direct path read 27807 0.90 260.40
direct path write temp 6912 0.71 38.93
direct path read temp 6912 0.04 18.31
SQL*Net message from client 9 0.00 0.00
It looks to me like Oracle is using Direct Path Reads where it would previously have used Multiblock Reads. Let me try another simple test to see.
SQL> exec dbms_session.set_identifier('FTS');
PL/SQL procedure successfully completed.
SQL> alter session set tracefile_identifier='FTS';
Session altered.
SQL> exec dbms_monitor.client_id_trace_enable(client_id => 'FTS');
PL/SQL procedure successfully completed.
SQL> set autotrace on
SQL> select count(*) from testuser.test_tab1;
COUNT(*)
----------
65536000
Execution Plan
----------------------------------------------------------
Plan hash value: 1745491793
------------------------------------------------------------------------
| Id | Operation | Name | Rows | Cost (%CPU)| Time |
------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 1407K (1)| 01:57:17 |
| 1 | SORT AGGREGATE | | 1 | | |
| 2 | TABLE ACCESS FULL| TEST_TAB1 | 65M| 1407K (1)| 01:57:17 |
------------------------------------------------------------------------
Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
1134615 consistent gets
1134591 physical reads
0 redo size
420 bytes sent via SQL*Net to client
420 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
SQL> exec dbms_monitor.client_id_trace_disable(client_id => 'FTS');
PL/SQL procedure successfully completed.
So I expect to see a single trace file in the user_dump_dest directory
[oracle@ISP4400 PX]$ cd /u01/app/oracle/diag/rdbms/test11/TEST11/trace [oracle@ISP4400 trace]$ ls -ltra total 9128 drwxr-x--- 13 oracle oracle 4096 Sep 16 11:33 .. -rw-rw-r-- 1 oracle oracle 6725 Sep 19 20:49 ccf.sql -rw-rw-r-- 1 oracle oracle 1650 Sep 19 20:50 ccf2.sql drwxrwxr-x 2 oracle oracle 4096 Sep 22 00:32 cdmp_20070922003230 -rw-rw---- 1 oracle oracle 298602 Sep 23 12:52 TEST11_ora_9977_default.trm -rw-rw---- 1 oracle oracle 5085019 Sep 23 12:52 TEST11_ora_9977_default.trc -rw-rw---- 1 oracle oracle 59 Sep 23 13:01 TEST11_m000_10050.trm -rw-rw---- 1 oracle oracle 882 Sep 23 13:01 TEST11_m000_10050.trc -rw-rw---- 1 oracle oracle 113602 Sep 23 13:23 TEST11_ora_10100_FTS.trm -rw-r----- 1 oracle oracle 196158 Sep 23 13:24 alert_TEST11.log -rw-rw---- 1 oracle oracle 1696437 Sep 23 13:24 TEST11_ora_10100_FTS.trc
(Note the new *.trm Trace Mapping file.)
When I look at the contents of the trace file, sure enough, all of the i/o wait events are direct path reads.
PARSING IN CURSOR #1 len=39 dep=0 uid=0 oct=3 lid=0 tim=1190549917314881
hv=1002667060 ad='6d964890' sqlid='0quzqwnxw6z1n'
select count(*) from testuser.test_tab1
END OF STMT
PARSE #1:c=2999,e=2606,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1190549917314863
EXEC #1:c=0,e=131,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1190549917315423
WAIT #1: nam='SQL*Net message to client' ela= 20 driver id=1650815232
#bytes=1 p3=0 obj#=-1 tim=1190549917315531
WAIT #1: nam='direct path read' ela= 12764 file number=6 first dba=10
block cnt=15 obj#=70940 tim=1190549917337012
WAIT #1: nam='direct path read' ela= 18221 file number=6 first dba=25
block cnt=83 obj#=70940 tim=1190549917359346
I had a quick look at this page in the documentation and it implies that direct path reads would be associated with parallelism.
On a healthy system, physical read waits should be the biggest waits
after the idle waits. However, also consider whether there are direct
read waits (signifying full table scans with parallel query) or db file scattered read waits on an operational (OLTP) system that should be doing small indexed accesses.
but these statements aren’t using PX. I probably am missing something.
Any ideas?
Could you post the tkprof of the count(*) query?
Here is the raw trace file
and here it is run through tkprof with no additional sort options.
And here’s another funny thing. The pw statistic (physical writes) matches the pr (physical reads) statistic.
I’d guess that’s a bug – but is is the same when you get the scattered read going ?
Yes, it is the same with scattered reads, this is that statement in the tkprof output.
Doug,
Shades of _serial_direct_read = true. What’s the setting of that parameter on your installation ?
This suggests that the feature may be piggy-backing on the parallel_adaptive_multiuser feature – which decides the actual degree of parallelism to use at run-time. So we get a parallel plan at optimisation time – which produces a direct path strategy – but a single thread at run-time.
I’ll have to check whether a query that runs serially in 10g because it has been downgraded does the same thing.
One interesting omission is the absence of the segment checkpoint that normally precedes a direct path tablescan.
Damn, I knew there was something I forgot. This was in my notes on this from yesterday because I immediately thought of that parameter.
SQL> l
1 select a.ksppinm name,
2 b.ksppstvl value,
3 b.ksppstdf deflt,
4 decode (a.ksppity, 1, ‘boolean’, 2, ‘string’, 3, ‘number’, 4, ‘file’, a.ksppity) type,
5 a.ksppdesc description
6 from
7 sys.x$ksppi a,
8 sys.x$ksppcv b
9 where a.indx = b.indx
10* and a.ksppinm like ‘\_serial_direct%’ escape ‘\’
SQL> /
NAME
——————————————————————————–
VALUE
——————————————————————————–
DEFLT TYPE
——— —————————————-
DESCRIPTION
——————————————————————————–
_serial_direct_read
FALSE
TRUE boolean
enable direct read in serial
Just waiting for the server to boot up and I’ll post the trace file.
Jonathan,
This suggests that the feature may be piggy-backing on the parallel_adaptive_multiuser feature – which decides the actual degree of parallelism to use at run-time. So we get a parallel plan at optimisation time – which produces a direct path strategy – but a single thread at run-time.
Similar to my initial thoughts, but it looks even stranger than that to me. The final example in the blog, the one that I’ve just uploaded the trace and tkprof output for, isn’t even attempting to use a parallel plan as far as I can tell!
However, I think you’re right that this is what’s going on when using parallel_io_cap_enabled in the first blog, because the parallel plan appears and then executes serially.
Mmmm, I wonder if it’s anything to do with picking up an earlier plan?
I’ll give it a try later after bouncing the instance. For now, it’s work time.
I’ll have to check whether a query that runs serially in 10g because it has been downgraded does the same thing.
I don’t think it does from memory, but can definitely worth checking. I still have to install 10g on the server though, after wiping it all out for 11g. I know, I should use VMs …
Ah, I couldn’t resist it. Here’s everything I just did plus the select statement from the tkprof output. Goodness know how well this will show up in a comment!
And I have the full trace file if anyone needs it. Now I must dash along the road 😉
I noticed that “direct path read” was the top wait event for my 11.2.0.2 database and that the IO timings were not great – 38-70ms. I’m finding in my research that Oracle decided to change how it determines how blocks are read for FTS based on how big the table is. It uses _small_table_threshold and the size of the table compared to the buffer cache (less than 2%) to determine if it’s going to do a scattered read or a direct path read.
My problem is that every time I see a session doing a direct path read and I trace it, the IO timings are good (less than 10ms or better). I’m wondering if there is some sort of accounting error going on somewhere?
This is a 15TB data warehouse with parallelism used constantly.
Hi Ed,
Apologies for the sluggish reply but I’ve been very busy lately.
Yes, there are a number of things which determine whether Oracle will use a scattered or direct path read.
As for the strange IO timings in trace files, I think dprs are recorded differently but there are also a number of bugs kicking around in the timings in trace files so maybe it’s something like that?
I’d be tempted to open an SR to get to the bottom of it if I were you.
Cheers,
Doug