Recently we ran a 10046 trace on some scripts running long and generating the tkprof output from that trace file. The top two sqls are shown below and I am looking for some clarifications.
1. Dynamic sampling is shown for this query but I am not sure if that means good or bad
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"),
NVL(SUM(C2),:"SYS_B_1")
FROM
(SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("EQMIGRATIONTABLELOOKUP")
FULL("EQMIGRATIONTABLELOOKUP") NO_PARALLEL_INDEX("EQMIGRATIONTABLELOOKUP")
*/ :"SYS_B_2" AS C1, CASE WHEN "EQMIGRATIONTABLELOOKUP"."TABLETYPE"=
:"SYS_B_3" AND "EQMIGRATIONTABLELOOKUP"."ENABLEDTOMIGRATE"=:"SYS_B_4" AND
"EQMIGRATIONTABLELOOKUP"."ISTRUNCATENEEDED"=:"SYS_B_5" THEN :"SYS_B_6" ELSE
:"SYS_B_7" END AS C2 FROM "ARKMIG_I1CODE"."EQMIGRATIONTABLELOOKUP"
"EQMIGRATIONTABLELOOKUP") SAMPLESUB
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 1 7 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 1 7 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 283 (recursive depth: 2)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=7 pr=1 pw=0 time=655 us)
93 93 93 TABLE ACCESS FULL EQMIGRATIONTABLELOOKUP (cr=7 pr=1 pw=0 time=595 us cost=3 size=6544 card=409)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
gc cr grant 2-way 1 0.00 0.00
db file sequential read 1 0.00 0.00
********************************************************************************First of all I am not sure why this shows up on top because I dont see long wait events not long parses/executes. Is this something I should be looking at ? Also, similar output shows up for a bunch of sqls with dynamic sampling. Is this supposed to be good or bad ? I am not sure. Need some guidance in determining that.
2. This is the other top sql and I see it has a long number for execute.
SELECT SYS_GUID()
FROM
SYS.DUAL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 154714986 456.52 463.16 0 0 0 0
Fetch 154714986 127.85 131.53 0 0 0 154714986
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 309429972 584.37 594.70 0 0 0 154714986
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 283 (recursive depth: 3)
********************************************************************************
what do I make of this ? This is not even for the entire duration of the sql but only about 2 hrs.
Thanks in advance for your help.
1. The optimizer can choose to do dynamic sampling when executing your query. There are several reasons for this. A common one is your table has no stats! For example:
create table t as
select rownum x from dual connect by level <= 1000;
alter session set sql_trace = true;
set serveroutput off
select count(*) from t;
select * from table(dbms_xplan.display_cursor(null, null, 'BASIC LAST +NOTE'));
PLAN_TABLE_OUTPUT
EXPLAINED SQL STATEMENT:
------------------------
select count(*) from t
Plan hash value: 1071362934
-----------------------------------
| Id | Operation | Name |
-----------------------------------
| 0 | SELECT STATEMENT | |
| 1 | SORT AGGREGATE | |
| 2 | TABLE ACCESS FULL| T |
-----------------------------------
Note
-----
- dynamic sampling used for this statement (level=2) As the note section shows, Oracle Database used dynamic sampling for this query. And the trace file contains this query:
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false')
NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"),
NVL(SUM(C2),:"SYS_B_1")
FROM
(SELECT /*+ NO_PARALLEL("T") FULL("T") NO_PARALLEL_INDEX("T") */ :"SYS_B_2"
AS C1, :"SYS_B_3" AS C2 FROM "CHRIS"."T" "T") SAMPLESUBFor more details on what the different sampling levels mean and when they kick in, see:
http://docs.oracle.com/cd/E11882_01/server.112/e41573/stats.htm#PFGRF95254 If the overall parse times for your query are tiny it's not worth worrying about. But if parsing in general and dynamic sampling queries in particular take a significant fraction of your SQL's runtime look further to see what's going on.
2. This tells you you're executing
SELECT SYS_GUID() FROM SYS.DUAL
154 million times in the trace period! With a total runtime of ~600s, that's less than 4μs/exec. i.e. Each execution is speedy.
But 154M calls seems excessive to me... So the question to ask yourself is:
Why are you calling sys_guid() so often? Are you really using this to generate PKs for 154m rows?
That seems unlikely to me, but I know nothing about your app or the timeframe you've used to capture this data.