{"id":1320,"date":"2007-09-23T12:00:00","date_gmt":"2007-09-23T12:00:00","guid":{"rendered":"http:\/\/orcldoug.com\/blog\/?p=1320"},"modified":"2007-09-23T12:00:00","modified_gmt":"2007-09-23T12:00:00","slug":"parallel-query-and-11g-part-2","status":"publish","type":"post","link":"http:\/\/orcldoug.com\/blog\/2007\/09\/23\/parallel-query-and-11g-part-2\/","title":{"rendered":"Parallel Query and 11g – Part 2"},"content":{"rendered":"

Now, that’s<\/em> weird. <\/p>\n

A little surprising might be more accurate and maybe I’m missing something.<\/p>\n

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<\/p>\n

Rows     Row Source Operation\n-------  ---------------------------------------------------\n      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=64 us)\n      0   HASH JOIN  (cr=0 pr=0 pw=0 time=15 us)\n65536000    TABLE ACCESS FULL TEST_TAB2 (cr=1118253 pr=1052301 pw=0 time=1441796425 us)\n47535880    TABLE ACCESS FULL TEST_TAB1 (cr=832521 pr=832491 pw=0 time=1378575273 us)\n\nElapsed times include waiting on following events:\n  Event waited on                             Times   Max. Wait  Total Waited\n  ----------------------------------------   Waited  ----------  ------------\n  SQL*Net message to client                       1        0.00          0.00\n  db file scattered read                     135042        0.16        983.67    \n  direct path write temp                       5961        6.05        833.35\n  db file sequential read                     15370        0.04         17.56\n  local write wait                             4482        0.39        479.14\n  SQL*Net break\/reset to client                   2        0.01          0.01<\/pre>\n
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.<\/p>\n
Rows     Row Source Operation\n-------  ---------------------------------------------------\n    113  SORT GROUP BY (cr=2265134 pr=2479358 pw=2479358 time=0 us cost=945776 \n         size=787633200 card=65636100)\n65529137   HASH JOIN  (cr=2265134 pr=2479358 pw=2479358 time=2198939 us cost=647314 \n           size=787633200 card=65636100)\n65536000    TABLE ACCESS FULL TEST_TAB2 (cr=1130519 pr=1130495 pw=1130495 time=8362747 us \n            cost=267173 size=393816600 card=65636100)\n65536000    TABLE ACCESS FULL TEST_TAB1 (cr=1134615 pr=1134591 pw=1134591 time=9715954 us \n            cost=268141 size=393880800 card=65646800)\n\nElapsed times include waiting on following events:\n  Event waited on                             Times   Max. Wait  Total Waited\n  ----------------------------------------   Waited  ----------  ------------\n  SQL*Net message to client                       9        0.00          0.00\n  direct path read                            27807        0.90        260.40  \n  direct path write temp                       6912        0.71         38.93\n  direct path read temp                        6912        0.04         18.31\n  SQL*Net message from client                     9        0.00          0.00<\/pre>\n
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.<\/p>\n
SQL> exec dbms_session.set_identifier('FTS');\n\nPL\/SQL procedure successfully completed.\n\nSQL> alter session set tracefile_identifier='FTS';\n\nSession altered.\n\nSQL> exec dbms_monitor.client_id_trace_enable(client_id => 'FTS');\n\nPL\/SQL procedure successfully completed.\n\nSQL> set autotrace on\n\nSQL> select count(*) from testuser.test_tab1;\n\n  COUNT(*)\n----------\n  65536000\n\nExecution Plan\n----------------------------------------------------------\nPlan hash value: 1745491793\n\n------------------------------------------------------------------------\n| Id  | Operation          | Name      | Rows  | Cost (%CPU)| Time     |\n------------------------------------------------------------------------\n|   0 | SELECT STATEMENT   |           |     1 |  1407K  (1)| 01:57:17 |\n|   1 |  SORT AGGREGATE    |           |     1 |            |          |\n|   2 |   TABLE ACCESS FULL| TEST_TAB1 |    65M|  1407K  (1)| 01:57:17 |\n------------------------------------------------------------------------\n\nStatistics\n----------------------------------------------------------\n          1  recursive calls\n          0  db block gets\n    1134615  consistent gets\n    1134591  physical reads\n          0  redo size\n        420  bytes sent via SQL*Net to client\n        420  bytes received via SQL*Net from client\n          2  SQL*Net roundtrips to\/from client\n          0  sorts (memory)\n          0  sorts (disk)\n          1  rows processed\n\nSQL> exec dbms_monitor.client_id_trace_disable(client_id => 'FTS');\n\nPL\/SQL procedure successfully completed.<\/pre>\n
So I expect to see a single trace file in the user_dump_dest directory<\/p>\n
[oracle@ISP4400 PX]$ cd \/u01\/app\/oracle\/diag\/rdbms\/test11\/TEST11\/trace\n[oracle@ISP4400 trace]$ ls -ltra\ntotal 9128\ndrwxr-x---  13 oracle oracle    4096 Sep 16 11:33 ..\n-rw-rw-r--   1 oracle oracle    6725 Sep 19 20:49 ccf.sql\n-rw-rw-r--   1 oracle oracle    1650 Sep 19 20:50 ccf2.sql\ndrwxrwxr-x   2 oracle oracle    4096 Sep 22 00:32 cdmp_20070922003230\n-rw-rw----   1 oracle oracle  298602 Sep 23 12:52 TEST11_ora_9977_default.trm\n-rw-rw----   1 oracle oracle 5085019 Sep 23 12:52 TEST11_ora_9977_default.trc\n-rw-rw----   1 oracle oracle      59 Sep 23 13:01 TEST11_m000_10050.trm\n-rw-rw----   1 oracle oracle     882 Sep 23 13:01 TEST11_m000_10050.trc\n-rw-rw----   1 oracle oracle  113602 Sep 23 13:23 TEST11_ora_10100_FTS.trm<\/strong>\n-rw-r-----   1 oracle oracle  196158 Sep 23 13:24 alert_TEST11.log\n-rw-rw----   1 oracle oracle 1696437 Sep 23 13:24 TEST11_ora_10100_FTS.trc<\/strong><\/pre>\n
(Note the new *.trm Trace Mapping file.)<\/p>\n
When I look at the contents of the trace file, sure enough, all of the i\/o wait events are direct path reads.<\/p>\n
PARSING IN CURSOR #1 len=39 dep=0 uid=0 oct=3 lid=0 tim=1190549917314881 \n     hv=1002667060 ad='6d964890' sqlid='0quzqwnxw6z1n'\nselect count(*) from testuser.test_tab1\nEND OF STMT\nPARSE #1:c=2999,e=2606,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1190549917314863\nEXEC #1:c=0,e=131,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1190549917315423\nWAIT #1: nam='SQL*Net message to client' ela= 20 driver id=1650815232 \n     #bytes=1 p3=0 obj#=-1 tim=1190549917315531\nWAIT #1: nam='direct path read' ela= 12764 file number=6 first dba=10 \n     block cnt=15 obj#=70940 tim=1190549917337012\nWAIT #1: nam='direct path read' ela= 18221 file number=6 first dba=25 \n     block cnt=83 obj#=70940 tim=1190549917359346<\/pre>\n
I had a quick look at this page<\/a> in the documentation and it implies that direct path reads would be associated with parallelism.
<\/em><\/p>\n
On a healthy system, physical read waits should be the biggest waits
\nafter the idle waits. However, also consider whether there are direct
\nread 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.<\/em><\/p><\/blockquote>\n
but these statements aren’t using PX. I probably am missing something. <\/p>\n
Any ideas?<\/p>\n","protected":false},"excerpt":{"rendered":"
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… Continue reading Parallel Query and 11g – Part 2<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[1],"tags":[],"class_list":["post-1320","post","type-post","status-publish","format-standard","hentry","category-uncategorized","entry"],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":1597,"url":"http:\/\/orcldoug.com\/blog\/2014\/05\/02\/statistics-on-partitioned-tables-part-6c-copy_table_stats-bugs-and-patches\/","url_meta":{"origin":1320,"position":0},"title":"Statistics on Partitioned Tables – Part 6c – COPY_TABLE_STATS – Bugs and Patches","date":"May 2, 2014","format":false,"excerpt":"I wanted to talk about a few of the bugs and patches you need to be aware of if you plan to use DBMS_STATS.COPY_TABLE_STATS. Believe me, when entering the world of stats on (sub-)partitioned objects, you had better be prepared to spend a lot of time on My Oracle Support\u2026","rel":"","context":"With 4 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1112,"url":"http:\/\/orcldoug.com\/blog\/2009\/10\/29\/10g-consolidated-trace-files-and-px\/","url_meta":{"origin":1320,"position":1},"title":"10g Consolidated Trace Files and PX","date":"October 29, 2009","format":false,"excerpt":"At the end of my Tracing Parallel Execution presentation at the Scottish OUG conference, Michael M\u00f8ller of Miracle asked whether the consolidated trace files produced by the DBMS_MONITOR package and trcsess utility are in strict time order. i.e. Will I see the actions of the query coordinator, then the actions\u2026","rel":"","context":"With 7 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1321,"url":"http:\/\/orcldoug.com\/blog\/2007\/09\/24\/11g-and-direct-path-reads\/","url_meta":{"origin":1320,"position":2},"title":"11g and direct path reads","date":"September 24, 2007","format":false,"excerpt":"Curioser and curioser ....I've been thinking about this on and off today and I really can't understand the behaviour I'm seeing. In fact, it's a good job it was a busy day or it might have sent me round the twist \ud83d\ude09 I've been playing around a little tonight, trying\u2026","rel":"","context":"With 27 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1697,"url":"http:\/\/orcldoug.com\/blog\/2013\/03\/11\/not-all-deadlocks-are-created-the-same\/","url_meta":{"origin":1320,"position":3},"title":"Not all Deadlocks are created the same","date":"March 11, 2013","format":false,"excerpt":"I've blogged about deadlocks in Oracle at least once before. I said then that although the following message in deadlock trace files is usually true, it isn't always. The following deadlock is not an Oracle error. Deadlocks of\u00a0 this type can be expected if certain SQL statements are\u00a0\u00a0\u00a0\u00a0\u00a0 issued. The\u2026","rel":"","context":"Similar post","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1072,"url":"http:\/\/orcldoug.com\/blog\/2006\/08\/31\/if-youre-gonna-screw-up\/","url_meta":{"origin":1320,"position":4},"title":"If you’re gonna screw up …","date":"August 31, 2006","format":false,"excerpt":"... you should always aim high (or desperately low would be more accurate). I was sitting at my desk today, deleting some old databases (that phrase in itself should be warning enough) when I typed in the followingdunha1e:oracle#rm -fR *I looked down at my notes to have a think about\u2026","rel":"","context":"With 28 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1428,"url":"http:\/\/orcldoug.com\/blog\/2008\/08\/14\/time-matters-an-infinite-capacity-for-waiting\/","url_meta":{"origin":1320,"position":5},"title":"Time Matters – An Infinite Capacity for Waiting*","date":"August 14, 2008","format":false,"excerpt":"When I was teaching the 10g Performance class at my last customer site, I remarked that the total number of seconds you see in the \"Top 5 Timed Events\" section of a Statspack or AWR report will often be greater than the total number of seconds between the snapshot intervals.\u2026","rel":"","context":"With 6 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]}],"_links":{"self":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1320","targetHints":{"allow":["GET"]}}],"collection":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/comments?post=1320"}],"version-history":[{"count":0,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1320\/revisions"}],"wp:attachment":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/media?parent=1320"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/categories?post=1320"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/tags?post=1320"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}