Method R Profile: /sample/dbm011_ora_33518.html

License 283 registered to Cary Millsap, Method R Corporation.

2022-01-19T10:08:46-06:00 mrprof XML created

2022-01-19T10:08:46-06: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:/sample/dbm011_ora_33518.trc
Tags:0. Baseline
Session ID:1180.63725
Experience ID:
Client ID:
Task ID:SERVICE = SYS$USERS MODULE = sqlplus@dubexadbadm01.cintradub.com (TNS V1-V3) ACTION =
Oracle Database release:12.1.0.2.0
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
Errors and warnings:0 Oracle parse errors, 0 Oracle other errors, 1 mrprof kernel warning

This profile report is an aggregation of an Oracle extended SQL trace file that accounts for 8.244514 seconds. If this is longer than the duration of the experience you want to investigate, then use mrcrop to crop out the unwanted calls that have no bearing upon your analysis. For more information, consult the following resources:

If your trace file time scope is correct, then you can think of this report as an invoice explaining how your time was spent, with call counts and durations acting as quantities and prices. It will help you answer the four most important questions about an application’s performance:

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:

SubroutineDurationCallsDuration per call (seconds)
secondsRmeanminmaxskew
1CPU: FETCH dbcalls6.99793784.9%195,0760.000036·5.038223▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▂▁▂█▁▁▁
2cell single block physical read1.41801617.2%5,5120.0002570.0002060.000534▁▁▁█▁▁▁▁▁▁▁
3gc cr disk read0.1612612.0%2,7470.0000590.0000180.000208▁▁█▁▁▁▁▁▁▁▁
4unaccounted-for between calls0.0064470.1%120.0005370.0000240.005797▁▁▁▁▁▁▁▁▁▁▁▁▁▂▁█▁▁▁▁▁▁
510 other subroutines−0.339147−4.1%195,137−0.000002−0.3637660.001370▁▁▁▁▄▁▁█▁▁▁▁█▁▁▁▁▁▁▁▁▁
6Total (14)8.244514100.0%398,4840.000021−0.3637665.038223

1.2. Profile by Database Call

It is good for your duration to be dominated by “FETCH” calls, but it is important for their work to be efficient. You want your application making as few “FETCH” calls as possible, and you want each call executing as few LIOs as possible.

Database callDurationContribution (seconds)CallsRowsLIOsPIOs (r)Library cache misses
secondsRCPUnon-CPUtotalcrcu
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. Just one statement consumed 87.2% of the total experience duration. mrprof aggregates into a single statement all similar but unshareable statements that could have used placeholders in their SQL text but did not.

StatementDurationExecutionsRowsLIOs (cr+cu)PIOs (r)Distinct plansDistinct cursorsDistinct textsStatement sizeOptimizer goal
secondsRlinesbytes
1[fpmabaybx9hgf] select owner, segment_name from dba_extents wher…7.18844987.2%11282,0565,512·112119ALL_ROWS
2[1n1bm7xa28vtq] select file#, block#, type#, nvl(spare1,0), hwmi…1.04803212.7%5195,063217,419··113106CHOOSE
3[PROF000000006] r-only commit follows fpmabaybx9hgf0.0062350.1%·····1···
4[3u1qfzgtyz494] BEGIN :file_id := 1; :block_id := 45888; dbms_mo…0.001563·11···111119ALL_ROWS
5[3fkaxqzh9g4vm] select ts#, flags from ts$ where bitmapped <> 0 …0.000235·159··116103CHOOSE
6Total (5)8.244514100.0%8195,070499,4845,512·5412447ALL_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. The Profile by Statement section aggregates all the appearances of each statement into one row.

Cursor statementIncluding descendantsExcluding descendants
DurationExecutionsRowsLIOs (cr+cu)PIOs (r)DurationExecutionsRowsLIOs (cr+cu)PIOs (r)
secondsRsecondsR
1[fpmabaybx9hgf] select owner, segment_name from dba_extents wher…8.23671699.9%7195,069499,4845,5127.18844987.2%11282,0565,512
21[1n1bm7xa28vtq] select file#, block#, type#, nvl(spare1,0), hwmi…1.04803212.7%5195,063217,419·1.04803212.7%5195,063217,419·
31[3fkaxqzh9g4vm] select ts#, flags from ts$ where bitmapped <> 0 …0.000235·159·0.000235·159·
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·11··0.001563·11··
6Total (5)8.244514100.0%8195,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 2OT3J6uRiaK.

4.1.1. Profile by Statement

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

StatementDurationExecutionsRowsLIOs (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%11282,0565,512·112119ALL_ROWS
2Total (1)7.188449100.0%87.2%11282,0565,512·112119ALL_ROWS

4.1.2. Profile by Caller

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

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

4.1.3. Profile by Subroutine

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

SubroutineDurationCallsDuration per call (seconds)
seconds%Rmeanminmaxskew
1CPU: FETCH dbcalls5.97008183.1%72.4%22.9850400.9318585.038223▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▂█▁▁▁
2cell single block physical read1.41801619.7%17.2%5,5120.0002570.0002060.000534▁▁▁█▁▁▁▁▁▁▁
3gc cr disk read0.1612612.2%2.0%2,7470.0000590.0000180.000208▁▁█▁▁▁▁▁▁▁▁
4unaccounted-for between calls0.000440··60.0000730.0000390.000186▁▁▁▁▁▁▁▁▁▁▁▁▁█▆▁▁▁▁▁▁▁
58 other subroutines−0.361349−5.0%−4.4%15−0.024090−0.3637660.001370▁▁▁▁█▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁
6Total (12)7.188449100.0%87.2%8,2820.000868−0.3637665.038223

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

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

Database callDurationContribution (seconds)CallsRowsLIOsPIOs (r)Library cache misses
seconds%RCPUnon-CPUtotalcrcu
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
21UNION-ALL ()0.000010··8.235555100.0%99.9%1···
312NESTED LOOPS ()0.000002··0.001553······1,0422321
4123NESTED LOOPS ()0.000003··0.001551······2881
51234TABLE ACCESS BY INDEX ROWID FILE$ (17)0.000019··0.000035··11··1101
612345INDEX UNIQUE SCAN I_FILE1 (43)0.000016··0.000016··11····1
71234TABLE ACCESS CLUSTER UET$ (13)0.001224··0.001513···2,028··1781
812345INDEX RANGE SCAN I_FILE#_BLOCK# (9)0.000289··0.000289··2,02813··1·1
9123VIEW SYS_DBA_SEGS (6176)··········1,0401441
101234UNION ALL PUSHED PREDICATE ()··········
1112345NESTED LOOPS OUTER ()··········1,0281391
12123456NESTED LOOPS ()··········1,0271211
131234567HASH JOIN ()··········1,025891
1412345678NESTED LOOPS ()··········2311
15123456789NESTED LOOPS ()··········1101
1612345678910INDEX UNIQUE SCAN I_FILE2 (44)···········71
1712345678910TABLE ACCESS CLUSTER TS$ (16)··········131
181234567891011INDEX UNIQUE SCAN I_TS# (7)············1
19123456789TABLE ACCESS CLUSTER SEG$ (14)··········1211
2012345678910INDEX UNIQUE SCAN I_FILE#_BLOCK# (9)············1
2112345678VIEW SYS_OBJECTS (6174)··········1,02210,237,348176,506
22123456789UNION-ALL ()··········
2312345678910TABLE ACCESS STORAGE FULL TAB$ (4)··········2954,039,375175,625
2412345678910TABLE ACCESS STORAGE FULL TABPART$ (700)··········2161
2512345678910TABLE ACCESS STORAGE FULL CLU$ (5)··········295141
2612345678910TABLE ACCESS STORAGE FULL IND$ (19)··········29511,077583
2712345678910TABLE ACCESS STORAGE FULL INDPART$ (705)··········2161
2812345678910TABLE ACCESS BY INDEX ROWID BATCHED LOB$ (108)··········1276,132292
291234567891011INDEX FULL SCAN I_LOB2 (110)··········1·519
3012345678910TABLE ACCESS STORAGE FULL TABSUBPART$ (712)··········2161
3112345678910TABLE ACCESS STORAGE FULL INDSUBPART$ (717)··········2521
3212345678910TABLE ACCESS STORAGE FULL LOBFRAG$ (733)··········2181
331234567TABLE ACCESS BY INDEX ROWID BATCHED OBJ$ (18)··········2321
3412345678INDEX RANGE SCAN I_OBJ1 (36)··········1·1
35123456TABLE ACCESS CLUSTER USER$ (22)··········1181
361234567INDEX UNIQUE SCAN I_USER# (11)············1
3712345NESTED LOOPS OUTER ()··········5871
38123456NESTED LOOPS ()··········4691
391234567MERGE JOIN CARTESIAN ()··········3451
4012345678NESTED LOOPS ()··········2421
41123456789INDEX UNIQUE SCAN I_FILE2 (44)···········71
42123456789TABLE ACCESS STORAGE FULL UNDO$ (15)··········2351
4312345678BUFFER SORT ()··········131
44123456789TABLE ACCESS CLUSTER TS$ (16)··········131
4512345678910INDEX UNIQUE SCAN I_TS# (7)············1
461234567TABLE ACCESS CLUSTER SEG$ (14)··········1241
4712345678INDEX UNIQUE SCAN I_FILE#_BLOCK# (9)············1
48123456TABLE ACCESS CLUSTER USER$ (22)··········1181
491234567INDEX UNIQUE SCAN I_USER# (11)············1
5012345NESTED LOOPS OUTER ()··········4551
51123456NESTED LOOPS ()··········3371
521234567NESTED LOOPS ()··········2131
5312345678TABLE ACCESS BY INDEX ROWID FILE$ (17)··········1101
54123456789INDEX UNIQUE SCAN I_FILE2 (44)············1
5512345678TABLE ACCESS CLUSTER TS$ (16)··········131
56123456789INDEX UNIQUE SCAN I_TS# (7)············1
571234567TABLE ACCESS CLUSTER SEG$ (14)··········1241
5812345678INDEX UNIQUE SCAN I_FILE#_BLOCK# (9)············1
59123456TABLE ACCESS CLUSTER USER$ (22)··········1181
601234567INDEX UNIQUE SCAN I_USER# (11)············1
6112345NESTED LOOPS OUTER ()··········3521
62123456NESTED LOOPS ()··········2341
631234567NESTED LOOPS ()··········1101
6412345678INDEX UNIQUE SCAN I_FILE2 (44)···········71
6512345678TABLE ACCESS CLUSTER TS$ (16)··········131
66123456789INDEX UNIQUE SCAN I_TS# (7)············1
671234567TABLE ACCESS CLUSTER SEG$ (14)··········1241
6812345678INDEX UNIQUE SCAN I_FILE#_BLOCK# (9)············1
69123456TABLE ACCESS CLUSTER USER$ (22)··········1181
701234567INDEX UNIQUE SCAN I_USER# (11)············1
7112HASH JOIN ()0.002000··8.233992100.0%99.9%1···1,3983,10812
72123FIXED TABLE FULL X$KTFBUE ()7.01243685.1%85.1%7.01243685.1%85.1%3414,2675,512·2619,500250
73123NESTED LOOPS ()0.000220··1.21955614.8%14.8%2,028···1,3724,780,39126,411
741234TABLE ACCESS BY INDEX ROWID FILE$ (17)0.000015··0.000032··11··1101
7512345INDEX UNIQUE SCAN I_FILE1 (43)0.000017··0.000017··11····1
761234VIEW SYS_DBA_SEGS (6176)0.0229900.3%0.3%1.21930414.8%14.8%2,028···1,3714,516,28126,411
7712345UNION-ALL ()0.0552000.7%0.7%1.19631414.5%14.5%194,911···
78123456HASH JOIN RIGHT OUTER ()0.0670670.8%0.8%1.06073912.9%12.9%194,889···1,18026,308,391189,269
791234567TABLE ACCESS STORAGE FULL USER$ (22)0.000077··0.000077··756··21,35075
801234567HASH JOIN ()0.1992792.4%2.4%0.99359512.1%12.1%194,889···1,17722,901,549189,269
8112345678INDEX STORAGE FAST FULL SCAN I_OBJ2 (37)0.0261680.3%0.3%0.0261680.3%0.3%220,9702,015··4670,68820,959
8212345678HASH JOIN ()0.0630680.8%0.8%0.7681489.3%9.3%194,889···1,17216,844,941189,269
83123456789TABLE ACCESS STORAGE FULL TS$ (16)0.000078··0.000078··79··2217
84123456789HASH JOIN ()0.0706930.9%0.9%0.7050028.6%8.6%194,889···1,16916,277,134189,269
8512345678910INDEX FULL SCAN I_FILE2 (44)0.000022··0.000022··51··1355
8612345678910HASH JOIN ()0.2225982.7%2.7%0.6342877.7%7.7%194,889···1,16714,952,251189,269
871234567891011TABLE ACCESS STORAGE FULL SEG$ (14)0.0955991.2%1.2%0.0955991.2%1.2%194,9115,585··793,974,649189,269
881234567891011VIEW SYS_OBJECTS (6174)0.0287720.3%0.3%0.3160903.8%3.8%205,435···1,02210,298,480177,560
89123456789101112UNION-ALL ()0.0581560.7%0.7%0.2873183.5%3.5%205,435···
9012345678910111213TABLE ACCESS STORAGE FULL TAB$ (4)0.1563521.9%1.9%0.1563521.9%1.9%201,69121,227··2954,039,375175,625
9112345678910111213TABLE ACCESS STORAGE FULL TABPART$ (700)0.000226··0.000226··52915··28,416526
9212345678910111213TABLE ACCESS STORAGE FULL CLU$ (5)0.0354030.4%0.4%0.0354030.4%0.4%1021,226··29514010
9312345678910111213TABLE ACCESS STORAGE FULL IND$ (19)0.0363000.4%0.4%0.0363000.4%0.4%2,15721,226··29511,077583
9412345678910111213TABLE ACCESS STORAGE FULL INDPART$ (705)0.000206··0.000206··46323··27,328458
9512345678910111213TABLE ACCESS BY INDEX ROWID BATCHED LOB$ (108)0.000539··0.000627··519126··1276,132292
961234567891011121314INDEX FULL SCAN I_LOB2 (110)0.000088··0.000088··5191··1·519
9712345678910111213TABLE ACCESS STORAGE FULL TABSUBPART$ (712)0.000023··0.000023··323··251232
9812345678910111213TABLE ACCESS STORAGE FULL INDSUBPART$ (717)0.000010··0.000010···3··2521
9912345678910111213TABLE ACCESS STORAGE FULL LOBFRAG$ (733)0.000015··0.000015··343··259433
100123456HASH JOIN OUTER ()0.000279··0.000984··21···277839
1011234567HASH JOIN ()0.000409··0.000656··21···256219
10212345678HASH JOIN ()0.000006··0.000215··21···235949
103123456789NESTED LOOPS ()0.000009··0.000209··21···235949
10412345678910STATISTICS COLLECTOR ()0.000010··0.000086··21···
1051234567891011NESTED LOOPS ()0.000010··0.000076··21···288221
106123456789101112TABLE ACCESS STORAGE FULL UNDO$ (15)0.000037··0.000037··213··273521
107123456789101112INDEX UNIQUE SCAN I_FILE2 (44)0.000029··0.000029··214···71
10812345678910TABLE ACCESS CLUSTER SEG$ (14)0.000076··0.000114··2121··1241
1091234567891011INDEX UNIQUE SCAN I_FILE#_BLOCK# (9)0.000038··0.000038··2116····1
110123456789TABLE ACCESS STORAGE FULL SEG$ (14)··········1241
11112345678TABLE ACCESS STORAGE FULL TS$ (16)0.000032··0.000032··79··2217
1121234567TABLE ACCESS STORAGE FULL USER$ (22)0.000049··0.000049··756··21,35075
113123456HASH JOIN ()0.000004··0.0418530.5%0.5%····82551
1141234567NESTED LOOPS ()0.000002··0.0418490.5%0.5%····82551
11512345678NESTED LOOPS ()0.000001··0.0418470.5%0.5%····82551
116123456789STATISTICS COLLECTOR ()0.000002··0.0418460.5%0.5%····
11712345678910HASH JOIN OUTER ()0.000003··0.0418440.5%0.5%····81451
1181234567891011NESTED LOOPS OUTER ()0.000002··0.0418410.5%0.5%····81451
119123456789101112STATISTICS COLLECTOR ()0.000002··0.0418390.5%0.5%····
12012345678910111213HASH JOIN ()0.000003··0.0418370.5%0.5%····80271
1211234567891011121314NESTED LOOPS ()0.000001··0.0418340.5%0.5%····80271
122123456789101112131415STATISTICS COLLECTOR ()0.000003··0.0418330.5%0.5%····
12312345678910111213141516TABLE ACCESS STORAGE FULL SEG$ (14)0.0418300.5%0.5%0.0418300.5%0.5%·5,585··79241
124123456789101112131415TABLE ACCESS CLUSTER TS$ (16)··········131
12512345678910111213141516INDEX UNIQUE SCAN I_TS# (7)············1
1261234567891011121314TABLE ACCESS STORAGE FULL TS$ (16)··········131
127123456789101112TABLE ACCESS CLUSTER USER$ (22)··········1181
12812345678910111213INDEX UNIQUE SCAN I_USER# (11)············1
1291234567891011TABLE ACCESS STORAGE FULL USER$ (22)··········1181
130123456789INDEX UNIQUE SCAN I_FILE2 (44)············1
13112345678TABLE ACCESS BY INDEX ROWID FILE$ (17)··········1101
1321234567TABLE ACCESS STORAGE FULL FILE$ (17)··········1101
133123456HASH JOIN OUTER ()0.000007··0.0375380.5%0.5%1···81521
1341234567NESTED LOOPS OUTER ()0.000005··0.0375310.5%0.5%1···81521
13512345678STATISTICS COLLECTOR ()0.000003··0.0375150.5%0.5%1···
136123456789HASH JOIN ()0.000003··0.0375120.5%0.5%1···80341
13712345678910NESTED LOOPS ()0.000011··0.0375090.5%0.5%1···80341
1381234567891011STATISTICS COLLECTOR ()0.000004··0.0374830.5%0.5%1···
139123456789101112NESTED LOOPS ()0.000003··0.0374790.5%0.5%1···79311
14012345678910111213TABLE ACCESS STORAGE FULL SEG$ (14)0.0374620.5%0.5%0.0374620.5%0.5%15,585··79241
14112345678910111213INDEX UNIQUE SCAN I_FILE2 (44)0.000014··0.000014··11···71
1421234567891011TABLE ACCESS CLUSTER TS$ (16)0.000011··0.000015··11··131
143123456789101112INDEX UNIQUE SCAN I_TS# (7)0.000004··0.000004··11····1
14412345678910TABLE ACCESS STORAGE FULL TS$ (16)··········131
14512345678TABLE ACCESS CLUSTER USER$ (22)0.000007··0.000011··11··1181
146123456789INDEX UNIQUE SCAN I_USER# (11)0.000004··0.000004··11····1
1471234567TABLE 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 from dba_extents
  2. where file_id=:file_id and :block_id between block_id 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 oTOoneTbj6.

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. Improvement opportunities may include:

StatementDurationExecutionsRowsLIOs (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%5195,063217,419··113106CHOOSE
2Total (1)1.048032100.0%12.7%5195,063217,419··113106CHOOSE

4.2.2. Profile by Caller

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

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

4.2.3. Profile by Subroutine

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

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

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

Database callDurationContribution (seconds)CallsRowsLIOsPIOs (r)Library cache misses
seconds%RCPUnon-CPUtotalcrcu
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/workbench/9.2.1.2/cdefs.xml
2--encodingUTF-8
3--env0
4--error-emit5
5--first-member1
6--fix-tim-values0
7--force-match-plans1
8--force-match-statement-texts1
9--input-base
10--input-type
11--license0
12--member
13--negative-betweeners-allowed1
14--patch-negative-counts1
15--scriptunix
16--script-comment#
17--script-extension
18--sql-text-width180
19--stash100
20--trace
21--trcsess1
22--trcunit0.000001
23--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:/workbench/9.2.1.2/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:/workbench/9.2.1.2/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:

12022-01-19T10:08:46.733314 mrprofk: OIOOIM05: e value increased from 7302334 to 7302381 to cover seemingly extraneous syscalls first appearing at line 54 for FETCH #140597082030520 dbcall at input line 203467
22022-01-19T10:08:46.733806 mrprofk: SUMMARY: OIOOIM05 0 elided, 1 total