Sep 23: Parallel Query and 11g - Part 2

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?
Posted by Doug Burns Comments: (10) Trackbacks: (0)
Defined tags for this entry: , ,
Related entries by tags:
Resource Manager and 11g
Parallel Tidbits
11g and direct path reads
Parallel Query and 11g
Oracle 11g - Total Recall

Trackbacks
Trackback specific URI for this entry

No Trackbacks

Comments
Display comments as (Linear | Threaded)

#1 - Mr. Ed 2007-09-24 04:10 - (Reply)

Could you post the tkprof of the count(*) query?

#2 - Jonathan Lewis said:
2007-09-24 07:45 - (Reply)

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.

#3 - Doug Burns said:
2007-09-24 07:57 - (Reply)

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.

#4 - Doug Burns said:
2007-09-24 08:07 - (Reply)

Here is the raw trace file

and here it is run through tkprof with no additional sort options.

#5 - Doug Burns said:
2007-09-24 08:19 - (Reply)

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 ...

#6 - Doug Burns said:
2007-09-24 08:33 - (Reply)

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 ;-)

CODE:
SQL> startup ORACLE instance started. Total System Global Area 1540046848 bytes Fixed Size                  1300100 bytes Variable Size             805308796 bytes Database Buffers          721420288 bytes Redo Buffers               12017664 bytes Database mounted. Database opened. SQL> connect testuser/testuser Connected. SQL> exec dbms_session.set_identifier('FTS2'); PL/SQL procedure successfully completed. SQL> alter session set tracefile_identifier='FTS2'; Session altered. SQL> exec dbms_monitor.client_id_trace_enable(client_id => 'FTS2'); 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 ----------------------------------------------------------         218  recursive calls           0  db block gets     1134640  consistent gets     1134594  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           5  sorts (memory)           0  sorts (disk)           1  rows processed SQL> exit Disconnected from Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Pr            oduction With the Partitioning, OLAP, Data Mining and Real Application Testing options [oracle@ISP4400 trace]$ cd /u01/app/oracle/diag/rdbms/test11/TEST11/trace/ [oracle@ISP4400 trace]$ ls -ltra *.trc -rw-rw----  1 oracle oracle 5085019 Sep 23 12:52 TEST11_ora_9977_default.trc [SNIPPED] -rw-rw----  1 oracle oracle 1777529 Sep 24 08:27 TEST11_ora_3427_FTS2.trc [oracle@ISP4400 trace]$ tkprof TEST11_ora_3427_FTS2.trc doug2.out TKPROF: Release 11.1.0.6.0 - Production on Mon Sep 24 08:29:08 2007 Copyright (c) 1982, 2007, Oracle.  All rights reserved. [Snippet of tkprof output ...] SQL ID : 0quzqwnxw6z1n select count(*) from  testuser.test_tab1 call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse        1      0.02       0.02          0          0          0           0 Execute      1      0.00       0.00          0          0          0           0 Fetch        2     57.32     247.17    1134592    1134615          0           1 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total        4     57.34     247.19    1134592    1134615          0           1 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 88 Rows     Row Source Operation -------  ---------------------------------------------------       1  SORT AGGREGATE (cr=1134615 pr=1134592 pw=1134592 time=0 us) 65536000   TABLE ACCESS FULL TEST_TAB1 (cr=1134615 pr=1134592 pw=1134592 time=9271414 us cost=1407353 size=0 card=65646800) Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   SQL*Net message to client                       2        0.00          0.00   db file sequential read                         1        0.00          0.00   direct path read                            12084        0.13        105.99   SQL*Net message from client                     2        0.00          0.00

#7 - Jonathan lewis said:
2007-09-24 21:28 - (Reply)

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 ?

#8 - Doug Burns said:
2007-09-24 21:40 - (Reply)

Yes, it is the same with scattered reads, this is that statement in the tkprof output.

CODE:
SQL ID : 31gjn7yb9u5td update test_tab2 set str_pad='WHATEVER' where  pk_id=1 call     count       cpu    elapsed       disk      query    current        rows ------- ------  -------- ---------- ---------- ---------- ----------  ---------- Parse        1      0.00       0.00          0          0          0           0 Execute      1    100.96     330.08    1079051    1130541          3           1 Fetch        0      0.00       0.00          0          0          0           0 ------- ------  -------- ---------- ---------- ---------- ----------  ---------- total        2    100.96     330.09    1079051    1130541          3           1 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 88 Rows     Row Source Operation -------  ---------------------------------------------------       0  UPDATE  TEST_TAB2 (cr=1130541 pr=1079051 pw=1079051 time=0 us)       1   TABLE ACCESS FULL TEST_TAB2 (cr=1130541 pr=1079051 pw=1079051 time=0 us cost=1403756 size=107 card=1) Elapsed times include waiting on following events:   Event waited on                             Times   Max. Wait  Total Waited   ----------------------------------------   Waited  ----------  ------------   db file sequential read                         9        0.01          0.01   db file scattered read                      11333        0.05        242.80   SQL*Net message to client                       1        0.00          0.00   SQL*Net message from client                     1        4.85          4.85

#9 - Ed 2011-11-16 16:41 - (Reply)

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.

#10 - Doug Burns said:
2011-11-28 00:55 - (Reply)

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


Add Comment

Standard emoticons like :-) and ;-) are converted to images.
E-Mail addresses will not be displayed and will only be used for E-Mail notifications.
BBCode format allowed