Method R Profile: dbm011_ora_33518.html

License 283 registered to Cary Millsap <cary.millsap@method-r.com>, Method R Corporation.

2018-05-21T10:14:12-05:00 mrprof XML created

2018-05-21T10:14:12-05:00 mrprof HTML created

Experience duration:R = t1t0 = 8.244514 seconds
Experience begin time:t0 = 2017-04-13T18:19:39.048109
Experience end time:t1 = 2017-04-13T18:19:47.292623
Input file name:dbm011_ora_33518.trc
Tags:0. Baseline
Oracle release:12.1.0.2.0
Oracle session id:1180.63725
Throughput:195,070 rows at 23,660.58 rows per second
Workload:499,484 LIOs at 2.56 LIOs per row
Transactions:1 commit, 0 rollbacks
Service / module / action:SYS$USERS / sqlplus@dubexadbadm01.cintradub.com (TNS V1-V3) /
Client identifier:None specified
Errors and warnings:0 Oracle parse errors, 0 Oracle other errors, 1 mrprof kernel warning

This profile report is an aggregation of “dbm011_ora_33518.trc”, an Oracle extended SQL trace file that accounts for 8.244514 seconds.

You can think of this report as an invoice with quantities and prices (call counts and latencies), explaining how your time was spent. It will help you answer the four most important questions about an application’s performance:

However, this report can answer these questions only if the duration of the trace file on which it is based matches the duration of the experience you want to investigate. If your end-user experience did not last 8.244514 seconds, then consult the following resources:

The advisory paragraphs that accompany the data in this document are meant to enhance your interpretation of the data. In cases where they run afoul of sound judgment, please open a case with Method R Support .

1. Experience-Level Profiles

This section shows the total experience duration decomposed along different dimensions.

1.1. Profile by Subroutine

Your experience duration was dominated by “CPU: FETCH dbcalls” calls. These are all high-productivity calls; their dominance means that the Oracle Database is working hard for your application. Now you should determine whether all of that work is actually necessary. Consult the Profile by Statement and Profile by Cursor sections for the next step of your diagnosis.

SubroutineDurationCallsDuration per call (seconds)
secondsRmeanminskewmax
1CPU: FETCH dbcalls6.99793784.9%195,0760.000036·▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▂▁▂█▁▁▁5.038223
2cell single block physical read1.41801617.2%5,5120.0002570.000206▁▁▁█▁▁▁▁▁▁▁0.000534
3gc cr disk read0.1612612.0%2,7470.0000590.000018▁▁█▁▁▁▁▁▁▁▁0.000208
4unaccounted-for between calls0.0064470.1%120.0005370.000024▁▁▁▁▁▁▁▁▁▁▁▁▁▂▁█▁▁▁▁▁▁0.005797
510 other subroutines−0.339147−4.1%195,137−0.000002−0.363766▁▁▁▁▄▁▁█▁▁▁▁█▁▁▁▁▁▁▁▁▁0.001370
6Total (14)8.244514100.0%

1.2. Profile by Database Call

It is okay for your duration to be dominated by “FETCH” calls, but it is important to ensure that this “FETCH” call work is efficient. Consult the Profile by Statement and Profile by Cursor sections to continue your diagnosis.

Database callDurationContribution (seconds)CallsRowsLIOsPIOs (r)Library cache misses
secondsRCPUothertotalcrcu
1FETCH8.23491399.9%6.9979371.236976195,076195,069499,484499,0154695,512·
2between dbcalls0.0072120.1%·0.00721216······
3EXEC0.002071··0.00207181·····
4PARSE0.000207··0.0002077······
5CLOSE0.000094··0.0000948······
6synthetic0.000017··0.0000171······
7STAT····3······
8COMMIT R-ONLY····1······
9Total (8)8.244514100.0%6.9979371.246577195,120195,070499,484499,0154695,512·
10Total per execution1.03056412.5%0.8747420.15582224,390.0024,383.7562,435.5062,376.8858.62689.00·
11Total per fetch0.000042·0.0000360.0000061.001.002.562.56·0.03·
12Total per row0.000042·0.0000360.0000061.001.002.562.56·0.03·

1.3. Profile by Statement

This experience executed five statements Note that mrprof aggregates into a single statement all similar but unshareable statements that could have used placeholders in their SQL text but did not. Just one statement consumed 87.2% of the total experience duration. Click the expensive statement to determine where it spent your time.

StatementDurationRowsLIOs (cr+cu)PIOs (r)Distinct plansDistinct cursorsDistinct textsStatement sizeOptimizer goal
secondsRlinesbytes
1[fpmabaybx9hgf] select owner, segment_name from dba_extents wher…7.18844987.2%1282,0565,5121115122ALL_ROWS
2[1n1bm7xa28vtq] select file#, block#, type#, nvl(spare1,0), hwmi…1.04803212.7%195,063217,419·1113106CHOOSE
3[PROF000000006] r-only commit follows fpmabaybx9hgf0.0062350.1%····1···
4[3u1qfzgtyz494] BEGIN :file_id := 1; :block_id := 45888; dbms_mo…0.001563·1···111119ALL_ROWS
5[3fkaxqzh9g4vm] select ts#, flags from ts$ where bitmapped <> 0 …0.000235·59·1116103CHOOSE
6Total (5)8.244514100.0%195,070499,4845,51235415450ALL_ROWS, CHOOSE

1.4. Profile by Cursor

This application code path executed for this experience organized its SQL and PL/SQL statements into five cursors. The following grove (multi-root tree) depicts the parent-child relationships among these cursors, listing the most time-consuming cursors in a sibling group first. If a statement appears many times in the grove, then it appeared in many distinct places in the code path. The Profile by Statement section aggregates all the appearances of each statement into one row.

Cursor statementIncluding descendantsExcluding descendants
DurationRowsLIOs (cr+cu)PIOs (r)DurationRowsLIOs (cr+cu)PIOs (r)
secondsRsecondsR
1[fpmabaybx9hgf] select owner, segment_name from dba_extents wher…8.23671699.9%195,069499,4845,5127.18844987.2%1282,0565,512
2·    [1n1bm7xa28vtq] select file#, block#, type#, nvl(spare1,0), hwmi…1.04803212.7%195,063217,419·1.04803212.7%195,063217,419·
3·    [3fkaxqzh9g4vm] select ts#, flags from ts$ where bitmapped <> 0 …0.000235·59·0.000235·59·
4[PROF000000006] r-only commit follows fpmabaybx9hgf0.0062350.1%···0.0062350.1%···
5[3u1qfzgtyz494] BEGIN :file_id := 1; :block_id := 45888; dbms_mo…0.001563·1··0.001563·1··
6Total (5)8.244514100.0%195,070499,4845,512

2. Skew Histograms

This section reveals the detail of each relevant skew pictogram from the Profile by Subroutine section above.

2.1. Skew Data for CPU: FETCH dbcalls

This call’s minimum duration was 0.000000 seconds; its maximum duration was 5.038223 seconds; and its average duration was 0.000036 seconds. The following table shows the distribution detail for your call durations. From this detail, you can estimate how much time you will save if you can eliminate certain calls.

Skew pictogram:▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▂▁▂█▁▁▁
Range {min ≤ e < max} (seconds)DurationCallsDuration per call (seconds)
minmaxseconds%Rmeanminmax
1−∞−1,000.000000····
2−1,000.000000−100.000000····
3−100.000000−10.000000····
4−10.000000−1.000000····
5−1.000000−0.100000····
6−0.100000−0.010000····
7−0.010000−0.001000····
8−0.001000−0.000100····
9−0.000100−0.000010····
10−0.000010−0.000001····
11−0.0000010.000000····
120.0000000.000001···194,143···
130.0000010.000010····
140.0000100.000100····
150.0001000.0010000.1278721.8%1.6%1280.0009990.0009990.000999
160.0010000.0100000.79999911.4%9.7%7990.0010010.0010000.001999
170.0100000.1000000.0999851.4%1.2%40.0249960.0249960.024997
180.1000001.0000000.93185813.3%11.3%10.9318580.9318580.931858
191.00000010.0000005.03822372.0%61.1%15.0382235.0382235.038223
2010.000000100.000000····
21100.0000001,000.000000····
221,000.000000····
23Total (22)6.997937100.0%84.9%195,0760.000036·5.038223

2.2. Skew Data for cell single block physical read

This call’s minimum duration was 0.000206 seconds; its maximum duration was 0.000534 seconds; and its average duration was 0.000257 seconds. The following table shows the distribution detail for your call durations. From this detail, you can estimate how much time you will save if you can eliminate certain calls.

Skew pictogram:▁▁▁█▁▁▁▁▁▁▁
Range {min ≤ e < max} (seconds)DurationCallsDuration per call (seconds)
minmaxseconds%Rmeanminmax
10.0000000.000001····
20.0000010.000010····
30.0000100.000100····
40.0001000.0010001.418016100.0%17.2%5,5120.0002570.0002060.000534
50.0010000.010000····
60.0100000.100000····
70.1000001.000000····
81.00000010.000000····
910.000000100.000000····
10100.0000001,000.000000····
111,000.000000····
12Total (11)1.418016100.0%17.2%5,5120.0002570.0002060.000534

3. Contribution to Subroutine by Statement

This section shows which SQL or PL/SQL statements are responsible for each subroutine that is a dominant contributor to overall experience duration.

3.1. Statement Contributors to CPU: FETCH dbcalls

The following table lists the dominant SQL statement contributors to the CPU: FETCH dbcalls subroutine call type, which contributed 84.9% of the total experience duration.

StatementDurationCallsDuration per call (seconds)
seconds%Rmeanminmax
1[fpmabaybx9hgf] select owner, segment_name from dba_extents wher…5.97008185.3%72.4%22.9850400.9318585.038223
2[1n1bm7xa28vtq] select file#, block#, type#, nvl(spare1,0), hwmi…1.02785614.7%12.5%195,0680.000005·0.024997
3[3fkaxqzh9g4vm] select ts#, flags from ts$ where bitmapped <> 0 …···6···
4Total (3)6.997937100.0%84.9%195,076

3.2. Statement Contributors to cell single block physical read

The following table lists the dominant SQL statement contributors to the cell single block physical read subroutine call type, which contributed 17.2% of the total experience duration.

StatementDurationCallsDuration per call (seconds)
seconds%Rmeanminmax
1[fpmabaybx9hgf] select owner, segment_name from dba_extents wher…1.418016100.0%17.2%5,5120.0002570.0002060.000534
2Total (1)1.418016100.0%17.2%5,512

4. Statement Detail

This section contains detail for each SQL or PL/SQL statement that is a dominant contributor to overall experience duration, ranked in descending order of contribution to experience duration.

4.1. Statement Report for SQL ID fpmabaybx9hgf

Statement fpmabaybx9hgf “select owner, segment_name from dba_extents wher…” was the most time-consuming statement of the overall 8.244514-second experience.

Its mrprof shared SQL ID is l8RzafJyMPw.

4.1.1. Profile by Statement

Statement fpmabaybx9hgf consumed 7.188449 seconds (87.2%) of the total experience duration.

StatementDurationRowsLIOs (cr+cu)PIOs (r)Distinct plansDistinct cursorsDistinct textsStatement sizeOptimizer goal
seconds%Rlinesbytes
1[fpmabaybx9hgf] select owner, segment_name from dba_extents wher…7.188449100.0%87.2%1282,0565,5121115122ALL_ROWS
2Total (1)7.188449100.0%87.2%1282,0565,5121115122ALL_ROWS

4.1.2. Profile by Caller

Statement fpmabaybx9hgf was executed from only one place in your application source code.

ContextDurationRowsLIOs (cr+cu)PIOs (r)
seconds%R
1Root cursor7.188449100.0%87.2%1282,0565,512
2Total (1)7.188449100.0%87.2%1282,0565,512

4.1.3. Profile by Subroutine

Statement fpmabaybx9hgf was dominated by “CPU: FETCH dbcalls” calls:

SubroutineDurationCallsDuration per call (seconds)
seconds%Rmeanminskewmax
1CPU: FETCH dbcalls5.97008183.1%72.4%22.9850400.931858▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▂█▁▁▁5.038223
2cell single block physical read1.41801619.7%17.2%5,5120.0002570.000206▁▁▁█▁▁▁▁▁▁▁0.000534
3gc cr disk read0.1612612.2%2.0%2,7470.0000590.000018▁▁█▁▁▁▁▁▁▁▁0.000208
4unaccounted-for between calls0.000440··60.0000730.000039▁▁▁▁▁▁▁▁▁▁▁▁▁█▆▁▁▁▁▁▁▁0.000186
58 other subroutines−0.361349−5.0%−4.4%15−0.024090−0.363766▁▁▁▁█▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁0.001370
6Total (12)7.188449100.0%87.2%

4.1.4. Profile by Database Call

Statement fpmabaybx9hgf touched the database buffer cache 282,056 times but processed only one row. The statement is efficient only if it joins 28,206 or more base tables, or if it is an aggregation.

To have excellent performance and scalability, it is vital to eliminate unnecessary database calls. Each database call of course incurs the CPU cost of executing the call, but additionally, each call executed by a client program increases your network I/O call count and the unaccounted-for time your application spends both within and between calls. Opportunities to eliminate database calls include:

The statement obtained 5,512 Oracle blocks from OS read calls, which means that your kernel process found the block it needed in the database buffer cache on 98.0% of buffer touches.

Your statement duration was dominated by one type of database call:

Database callDurationContribution (seconds)CallsRowsLIOsPIOs (r)Library cache misses
seconds%RCPUothertotalcrcu
1FETCH7.187342100.0%87.2%5.9700811.21726121282,056281,5874695,512·
2between dbcalls0.000723···0.0007237······
3EXEC0.000336···0.0003361······
4PARSE0.000025···0.0000251······
5CLOSE0.000023···0.0000231······
6STAT·····1······
7Total (6)7.188449100.0%87.2%5.9700811.218368131282,056281,5874695,512·
8Total per execution7.188449100.0%87.2%5.9700811.21836813.001.00282,056.00281,587.00469.005,512.00·
9Total per fetch3.594224100.0%43.6%2.9850400.6091846.500.50141,028.00140,793.50234.502,756.00·
10Total per row7.188449100.0%87.2%5.9700811.21836813.001.00282,056.00281,587.00469.005,512.00·

4.1.5. Profile by Execution Plan

Statement fpmabaybx9hgf recorded only one distinct execution plan in its trace file for this experience.

The LIO and PIO counts shown here, obtained from Oracle Database “STAT” lines, may include counts inclusive of statement descendants; thus, the counts shown here may not match the counts shown in other sections.

Plan hash valueDurationContribution (seconds)Duration per rowExecutionsRowsLIOs (cr)PIOs (r+w)Row source opsCostSize (bytes)
seconds%Rrow source opsother
121441100807.188449100.0%87.2%8.235556−1.0471077.18844911499,0155,5121472,4401,716
2Total (1)7.188449100.0%87.2%8.235556−1.0471077.18844911499,0155,512
3Total per execution7.188449100.0%87.2%8.235556−1.0471071.001.00499,015.005,512.00
4Total per row7.188449100.0%87.2%8.235556−1.0471071.001.00499,015.005,512.00

4.1.5.1. Execution Plan 2144110080

Statement fpmabaybx9hgf used execution plan 2144110080.

Row source operation (object id)Duration of selfDuration incl descendantsRowsLIOs (cr)PIOsCostSize (bytes)Cardinality
seconds%Rseconds%Rrw
1VIEW DBA_EXTENTS (6189)0.000001··8.235556100.0%99.9%1···2,4401,71613
2·    UNION-ALL ()0.000010··8.235555100.0%99.9%1···
3·    ·    NESTED LOOPS ()0.000002··0.001553······1,0422321
4·    ·    ·    NESTED LOOPS ()0.000003··0.001551······2881
5·    ·    ·    ·    TABLE ACCESS BY INDEX ROWID FILE$ (17)0.000019··0.000035··11··1101
6·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE1 (43)0.000016··0.000016··11····1
7·    ·    ·    ·    TABLE ACCESS CLUSTER UET$ (13)0.001224··0.001513···2,028··1781
8·    ·    ·    ·    ·    INDEX RANGE SCAN I_FILE#_BLOCK# (9)0.000289··0.000289··2,02813··1·1
9·    ·    ·    VIEW SYS_DBA_SEGS (6176)··········1,0401441
10·    ·    ·    ·    UNION ALL PUSHED PREDICATE ()··········
11·    ·    ·    ·    ·    NESTED LOOPS OUTER ()··········1,0281391
12·    ·    ·    ·    ·    ·    NESTED LOOPS ()··········1,0271211
13·    ·    ·    ·    ·    ·    ·    HASH JOIN ()··········1,025891
14·    ·    ·    ·    ·    ·    ·    ·    NESTED LOOPS ()··········2311
15·    ·    ·    ·    ·    ·    ·    ·    ·    NESTED LOOPS ()··········1101
16·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE2 (44)···········71
17·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER TS$ (16)··········131
18·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_TS# (7)············1
19·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER SEG$ (14)··········1211
20·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE#_BLOCK# (9)············1
21·    ·    ·    ·    ·    ·    ·    ·    VIEW SYS_OBJECTS (6174)··········1,02210,237,348176,506
22·    ·    ·    ·    ·    ·    ·    ·    ·    UNION-ALL ()··········
23·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL TAB$ (4)··········2954,039,375175,625
24·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL TABPART$ (700)··········2161
25·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL CLU$ (5)··········295141
26·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL IND$ (19)··········29511,077583
27·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL INDPART$ (705)··········2161
28·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS BY INDEX ROWID BATCHED LOB$ (108)··········1276,132292
29·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX FULL SCAN I_LOB2 (110)··········1·519
30·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL TABSUBPART$ (712)··········2161
31·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL INDSUBPART$ (717)··········2521
32·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL LOBFRAG$ (733)··········2181
33·    ·    ·    ·    ·    ·    ·    TABLE ACCESS BY INDEX ROWID BATCHED OBJ$ (18)··········2321
34·    ·    ·    ·    ·    ·    ·    ·    INDEX RANGE SCAN I_OBJ1 (36)··········1·1
35·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER USER$ (22)··········1181
36·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_USER# (11)············1
37·    ·    ·    ·    ·    NESTED LOOPS OUTER ()··········5871
38·    ·    ·    ·    ·    ·    NESTED LOOPS ()··········4691
39·    ·    ·    ·    ·    ·    ·    MERGE JOIN CARTESIAN ()··········3451
40·    ·    ·    ·    ·    ·    ·    ·    NESTED LOOPS ()··········2421
41·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE2 (44)···········71
42·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL UNDO$ (15)··········2351
43·    ·    ·    ·    ·    ·    ·    ·    BUFFER SORT ()··········131
44·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER TS$ (16)··········131
45·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_TS# (7)············1
46·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER SEG$ (14)··········1241
47·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE#_BLOCK# (9)············1
48·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER USER$ (22)··········1181
49·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_USER# (11)············1
50·    ·    ·    ·    ·    NESTED LOOPS OUTER ()··········4551
51·    ·    ·    ·    ·    ·    NESTED LOOPS ()··········3371
52·    ·    ·    ·    ·    ·    ·    NESTED LOOPS ()··········2131
53·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS BY INDEX ROWID FILE$ (17)··········1101
54·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE2 (44)············1
55·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER TS$ (16)··········131
56·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_TS# (7)············1
57·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER SEG$ (14)··········1241
58·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE#_BLOCK# (9)············1
59·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER USER$ (22)··········1181
60·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_USER# (11)············1
61·    ·    ·    ·    ·    NESTED LOOPS OUTER ()··········3521
62·    ·    ·    ·    ·    ·    NESTED LOOPS ()··········2341
63·    ·    ·    ·    ·    ·    ·    NESTED LOOPS ()··········1101
64·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE2 (44)···········71
65·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER TS$ (16)··········131
66·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_TS# (7)············1
67·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER SEG$ (14)··········1241
68·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE#_BLOCK# (9)············1
69·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER USER$ (22)··········1181
70·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_USER# (11)············1
71·    ·    HASH JOIN ()0.002000··8.233992100.0%99.9%1···1,3983,10812
72·    ·    ·    FIXED TABLE FULL X$KTFBUE ()7.01243685.1%85.1%7.01243685.1%85.1%3414,2675,512·2619,500250
73·    ·    ·    NESTED LOOPS ()0.000220··1.21955614.8%14.8%2,028···1,3724,780,39126,411
74·    ·    ·    ·    TABLE ACCESS BY INDEX ROWID FILE$ (17)0.000015··0.000032··11··1101
75·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE1 (43)0.000017··0.000017··11····1
76·    ·    ·    ·    VIEW SYS_DBA_SEGS (6176)0.0229900.3%0.3%1.21930414.8%14.8%2,028···1,3714,516,28126,411
77·    ·    ·    ·    ·    UNION-ALL ()0.0552000.7%0.7%1.19631414.5%14.5%194,911···
78·    ·    ·    ·    ·    ·    HASH JOIN RIGHT OUTER ()0.0670670.8%0.8%1.06073912.9%12.9%194,889···1,18026,308,391189,269
79·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL USER$ (22)0.000077··0.000077··756··21,35075
80·    ·    ·    ·    ·    ·    ·    HASH JOIN ()0.1992792.4%2.4%0.99359512.1%12.1%194,889···1,17722,901,549189,269
81·    ·    ·    ·    ·    ·    ·    ·    INDEX STORAGE FAST FULL SCAN I_OBJ2 (37)0.0261680.3%0.3%0.0261680.3%0.3%220,9702,015··4670,68820,959
82·    ·    ·    ·    ·    ·    ·    ·    HASH JOIN ()0.0630680.8%0.8%0.7681489.3%9.3%194,889···1,17216,844,941189,269
83·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL TS$ (16)0.000078··0.000078··79··2217
84·    ·    ·    ·    ·    ·    ·    ·    ·    HASH JOIN ()0.0706930.9%0.9%0.7050028.6%8.6%194,889···1,16916,277,134189,269
85·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX FULL SCAN I_FILE2 (44)0.000022··0.000022··51··1355
86·    ·    ·    ·    ·    ·    ·    ·    ·    ·    HASH JOIN ()0.2225982.7%2.7%0.6342877.7%7.7%194,889···1,16714,952,251189,269
87·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL SEG$ (14)0.0955991.2%1.2%0.0955991.2%1.2%194,9115,585··793,974,649189,269
88·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    VIEW SYS_OBJECTS (6174)0.0287720.3%0.3%0.3160903.8%3.8%205,435···1,02210,298,480177,560
89·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    UNION-ALL ()0.0581560.7%0.7%0.2873183.5%3.5%205,435···
90·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL TAB$ (4)0.1563521.9%1.9%0.1563521.9%1.9%201,69121,227··2954,039,375175,625
91·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL TABPART$ (700)0.000226··0.000226··52915··28,416526
92·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL CLU$ (5)0.0354030.4%0.4%0.0354030.4%0.4%1021,226··29514010
93·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL IND$ (19)0.0363000.4%0.4%0.0363000.4%0.4%2,15721,226··29511,077583
94·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL INDPART$ (705)0.000206··0.000206··46323··27,328458
95·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS BY INDEX ROWID BATCHED LOB$ (108)0.000539··0.000627··519126··1276,132292
96·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX FULL SCAN I_LOB2 (110)0.000088··0.000088··5191··1·519
97·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL TABSUBPART$ (712)0.000023··0.000023··323··251232
98·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL INDSUBPART$ (717)0.000010··0.000010···3··2521
99·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL LOBFRAG$ (733)0.000015··0.000015··343··259433
100·    ·    ·    ·    ·    ·    HASH JOIN OUTER ()0.000279··0.000984··21···277839
101·    ·    ·    ·    ·    ·    ·    HASH JOIN ()0.000409··0.000656··21···256219
102·    ·    ·    ·    ·    ·    ·    ·    HASH JOIN ()0.000006··0.000215··21···235949
103·    ·    ·    ·    ·    ·    ·    ·    ·    NESTED LOOPS ()0.000009··0.000209··21···235949
104·    ·    ·    ·    ·    ·    ·    ·    ·    ·    STATISTICS COLLECTOR ()0.000010··0.000086··21···
105·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    NESTED LOOPS ()0.000010··0.000076··21···288221
106·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL UNDO$ (15)0.000037··0.000037··213··273521
107·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE2 (44)0.000029··0.000029··214···71
108·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER SEG$ (14)0.000076··0.000114··2121··1241
109·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE#_BLOCK# (9)0.000038··0.000038··2116····1
110·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL SEG$ (14)··········1241
111·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL TS$ (16)0.000032··0.000032··79··2217
112·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL USER$ (22)0.000049··0.000049··756··21,35075
113·    ·    ·    ·    ·    ·    HASH JOIN ()0.000004··0.0418530.5%0.5%····82551
114·    ·    ·    ·    ·    ·    ·    NESTED LOOPS ()0.000002··0.0418490.5%0.5%····82551
115·    ·    ·    ·    ·    ·    ·    ·    NESTED LOOPS ()0.000001··0.0418470.5%0.5%····82551
116·    ·    ·    ·    ·    ·    ·    ·    ·    STATISTICS COLLECTOR ()0.000002··0.0418460.5%0.5%····
117·    ·    ·    ·    ·    ·    ·    ·    ·    ·    HASH JOIN OUTER ()0.000003··0.0418440.5%0.5%····81451
118·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    NESTED LOOPS OUTER ()0.000002··0.0418410.5%0.5%····81451
119·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    STATISTICS COLLECTOR ()0.000002··0.0418390.5%0.5%····
120·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    HASH JOIN ()0.000003··0.0418370.5%0.5%····80271
121·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    NESTED LOOPS ()0.000001··0.0418340.5%0.5%····80271
122·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    STATISTICS COLLECTOR ()0.000003··0.0418330.5%0.5%····
123·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL SEG$ (14)0.0418300.5%0.5%0.0418300.5%0.5%·5,585··79241
124·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER TS$ (16)··········131
125·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_TS# (7)············1
126·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL TS$ (16)··········131
127·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER USER$ (22)··········1181
128·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_USER# (11)············1
129·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL USER$ (22)··········1181
130·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE2 (44)············1
131·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS BY INDEX ROWID FILE$ (17)··········1101
132·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL FILE$ (17)··········1101
133·    ·    ·    ·    ·    ·    HASH JOIN OUTER ()0.000007··0.0375380.5%0.5%1···81521
134·    ·    ·    ·    ·    ·    ·    NESTED LOOPS OUTER ()0.000005··0.0375310.5%0.5%1···81521
135·    ·    ·    ·    ·    ·    ·    ·    STATISTICS COLLECTOR ()0.000003··0.0375150.5%0.5%1···
136·    ·    ·    ·    ·    ·    ·    ·    ·    HASH JOIN ()0.000003··0.0375120.5%0.5%1···80341
137·    ·    ·    ·    ·    ·    ·    ·    ·    ·    NESTED LOOPS ()0.000011··0.0375090.5%0.5%1···80341
138·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    STATISTICS COLLECTOR ()0.000004··0.0374830.5%0.5%1···
139·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    NESTED LOOPS ()0.000003··0.0374790.5%0.5%1···79311
140·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL SEG$ (14)0.0374620.5%0.5%0.0374620.5%0.5%15,585··79241
141·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_FILE2 (44)0.000014··0.000014··11···71
142·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER TS$ (16)0.000011··0.000015··11··131
143·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_TS# (7)0.000004··0.000004··11····1
144·    ·    ·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL TS$ (16)··········131
145·    ·    ·    ·    ·    ·    ·    ·    TABLE ACCESS CLUSTER USER$ (22)0.000007··0.000011··11··1181
146·    ·    ·    ·    ·    ·    ·    ·    ·    INDEX UNIQUE SCAN I_USER# (11)0.000004··0.000004··11····1
147·    ·    ·    ·    ·    ·    ·    TABLE ACCESS STORAGE FULL USER$ (22)··········1181
148Total (147)8.235556100.0%99.9%499,0155,512·

There was only one set of placeholder values used with execution plan 2144110080.

NameType codeTypeValue
1:file_id2NUMBER1
2:block_id2NUMBER45888

4.1.6. Statement Text

The following list is the complete text of statement fpmabaybx9hgf. Opportunities for placeholder use are highlighted.

  1. select owner, segment_name
  2. from dba_extents
  3. where file_id=:file_id
  4. and :block_id between block_id
  5. and block_id+blocks-1

4.2. Statement Report for SQL ID 1n1bm7xa28vtq

Statement 1n1bm7xa28vtq “select file#, block#, type#, nvl(spare1,0), hwmi…” was the 2nd most time-consuming statement of the overall 8.244514-second experience.

Its mrprof shared SQL ID is gllGN6DPmaU.

4.2.1. Profile by Statement

Statement 1n1bm7xa28vtq consumed 1.048032 seconds (12.7%) of the total experience duration.

The statement is a query that returned 195,063 rows. Any time a query returns more than ten rows, it signals a potential opportunity for an application design improvement. If the query’s output is being displayed for a user to see, consider that people are normally not interested in seeing more than ten rows at once [Tow-Millsap law]. If the query is feeding an application for summarization or joining, consider doing such work in SQL or PL/SQL within the database where the processing can be vastly more efficient.

StatementDurationRowsLIOs (cr+cu)PIOs (r)Distinct plansDistinct cursorsDistinct textsStatement sizeOptimizer goal
seconds%Rlinesbytes
1[1n1bm7xa28vtq] select file#, block#, type#, nvl(spare1,0), hwmi…1.048032100.0%12.7%195,063217,419·1113106CHOOSE
2Total (1)1.048032100.0%12.7%195,063217,419·1113106CHOOSE

4.2.2. Profile by Caller

Statement 1n1bm7xa28vtq was executed from only one place in your application source code.

ContextDurationRowsLIOs (cr+cu)PIOs (r)
seconds%R
1Child of [fpmabaybx9hgf] select owner, segment_name from dba_extents wher…1.048032100.0%12.7%195,063217,419·
2Total (1)1.048032100.0%12.7%195,063217,419·

4.2.3. Profile by Subroutine

Statement 1n1bm7xa28vtq was dominated by “CPU: FETCH dbcalls” calls:

SubroutineDurationCallsDuration per call (seconds)
seconds%Rmeanminskewmax
1CPU: FETCH dbcalls1.02785698.1%12.5%195,0680.000005·▁▁▁▁▁▁▁▁▁▁▁▁▁▁▂█▂▁▁▁▁▁0.024997
2unaccounted-for within dbcalls0.0201761.9%0.2%195,083·−0.001974▁▁▁▁▁▁▁█▁▁▁▁█▁▁▁▁▁▁▁▁▁0.001073
3CPU: CLOSE dbcalls···5··▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁·
4CPU: EXEC dbcalls···5··▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁·
5CPU: PARSE dbcalls···5··▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁·
6Total (5)1.048032100.0%12.7%

4.2.4. Profile by Database Call

Statement 1n1bm7xa28vtq touched the database buffer cache 217,419 times and processed 195,063 rows, an average of 1.11 LIOs per row. The statement used the buffer cache efficiently.

To have excellent performance and scalability, it is vital to eliminate unnecessary database calls. Each database call of course incurs the CPU cost of executing the call, but additionally, each call executed by a client program increases your network I/O call count and the unaccounted-for time your application spends both within and between calls. Opportunities to eliminate database calls include:

The statement obtained zero Oracle blocks from OS read calls, which means that your kernel process found the block it needed in the database buffer cache on 100.0% of buffer touches.

Database callDurationContribution (seconds)CallsRowsLIOsPIOs (r)Library cache misses
seconds%RCPUothertotalcrcu
1FETCH1.04739099.9%12.7%1.0278560.019534195,068195,063217,419217,419···
2EXEC0.000436···0.0004365······
3PARSE0.000154···0.0001545······
4CLOSE0.000052···0.0000525······
5STAT·····1······
6Total (5)1.048032100.0%12.7%1.0278560.020176195,084195,063217,419217,419···
7Total per execution0.209606100.0%2.5%0.2055710.00403539,016.8039,012.6043,483.8043,483.80···
8Total per fetch0.000005100.0%·0.000005·1.001.001.111.11···
9Total per row0.000005100.0%·0.000005·1.001.001.111.11···

4.2.5. Profile by Execution Plan

Statement 1n1bm7xa28vtq recorded only one distinct execution plan in its trace file for this experience.

The LIO and PIO counts shown here, obtained from Oracle Database “STAT” lines, may include counts inclusive of statement descendants; thus, the counts shown here may not match the counts shown in other sections.

Plan hash valueDurationContribution (seconds)Duration per rowExecutionsRowsLIOs (cr)PIOs (r+w)Row source opsCostSize (bytes)
seconds%Rrow source opsother
116052854791.048032100.0%12.7%0.0340971.0139350.00051752,0287,556·1430,210
2Total (1)1.048032100.0%12.7%0.0340971.0139350.00051752,0287,556·
3Total per execution0.209606100.0%2.5%0.0068190.2027871.00405.601,511.20·
4Total per row0.000517100.0%·0.0000170.000500·1.003.73·

4.2.5.1. Execution Plan 1605285479

Statement 1n1bm7xa28vtq used execution plan 1605285479.

Row source operation (object id)Duration of selfDuration incl descendantsRowsLIOs (cr)PIOsCostSize (bytes)Cardinality
seconds%Rseconds%Rrw
1TABLE ACCESS STORAGE FULL SEG$ (14)0.034097100.0%0.4%0.034097100.0%0.4%2,0287,556··430,2101,007
2Total (1)0.034097100.0%0.4%7,556··

There were five distinct placeholder value sets. The following placeholder values contributed the greatest duration (0.911353 seconds) for this execution plan 1605285479.

NameType codeTypeValue
1:12NUMBER5

4.2.6. Statement Text

The following list is the complete text of statement 1n1bm7xa28vtq. Opportunities for placeholder use are highlighted.

  1. select file#, block#, type#, nvl(spare1,0), hwmincr, cachehint, nvl(scanhint,0)
  2. from seg$
  3. where ts# = :1

5. Environment

This section lists settings that may be useful for troubleshooting.

5.1. Command Line Options

Command line option values used by the mrprof kernel:

OptionValue
1--cdefs/Users/carymillsap/.method-r/workbench/8.0.2.6/cdefs.xml
2--encodingUTF-8
3--env0
4--error-emit5
5--first-member1
6--fix-tim-values0
7--force-sql-formatting0
8--help0
9--ignore-multiple-sessions1
10--ignore-multiple-sessions-file/dev/null
11--input-base
12--input-type
13--license0
14--member
15--negative-betweeners-allowed1
16--patch-negative-counts1
17--scriptunix
18--script-comment#
19--script-extension
20--sql-text-width180
21--stash100
22--trace
23--trcsess1
24--trcunit0.000001
25--version0
26--xsd

5.2. Transform Parameters

Values recorded in the params file at the time of the XSL transformation (highlighting indicates a value that was specified in the params file to be different from the default):

Params file URI:file:/Users/carymillsap/.method-r/workbench/8.0.2.6/prof.xml
NameDefault valueParams file valueUsed value
1ADVISORYtruetruetrue
2CONTRIBUTIONS-MINIMUM-LIST-LENGTH444
3CREATE-SHAREABLE-HTMLtruetruetrue
4DISTINCT-TEXT-THRESHOLD111
5EXECS-PER-PARSE-THRESHOLD222
6LIBRARY-CACHE-MISSES-PER-STATEMENT-THRESHOLD111
7LIOS-PER-ROW-THRESHOLD101010
8LOCALE-CODEAAA
9PIOS-PER-LIO-THRESHOLD.10.10.1
10PROFILE-DISPLAYED-THRESHOLD.050.050.05
11PROFILE-RELEVANCE-THRESHOLD.200.20.2
12ROWS-PER-EXEC-THRESHOLD222
13ROWS-PER-FETCH-THRESHOLD222
14SHOW-CONFIDENTIALITY-LABELfalsefalsefalse
15SHOW-CUMULATIVE-DURATIONSfalsefalsefalse
16SHOW-LITERAL-HIGHLIGHTINGtruetruetrue
17SHOW-PROFILER-STATEMENT-IDfalsefalsefalse
18SHOW-ZERO-VALUE-STRINGtruetruetrue
19SQL-TEXT-PREFIX-LENGTH484848

5.3. Call Definitions

Values recorded in the call definitions file at the time of the XSL transformation:

Call definitions file URI:file:/Users/carymillsap/.method-r/workbench/8.0.1.1/cdefs.xml
SubroutineQualifierLabelTolerance (seconds)
1SQL*Net message from client$e >= 1.000think time
2SQL*Net message from client0.100
3db file sequential read0.005
4db file scattered read$p3 <= 16blocks ≤ 160.004
5db file scattered read$p3 <= 3216 < blocks ≤ 320.008
6db file scattered readblocks > 320.016
7CPU: PARSE dbcalls0.250

5.4. Environment Variables

There are no environment variables listed in the input data.

5.5. Diagnostics

Diagnostic messages printed by the mrprof kernel:

12018-05-21T10:14:12.524960 mrprofk: OIOOIM05: e value increased from 7302334 to 7302381 to cover seemingly extraneous syscalls at lines 54..376 for FETCH #140597082030520 dbcall at input line 203467
22018-05-21T10:14:12.525505 mrprofk: SUMMARY: OIOOIM05 0 elided, 1 total