The profile splits the total time of the session into components: the CPU of each call type, each wait event and the time the trace does not explain. It is the section that says where the time went, and the analysis starts with the largest component.
What the section shows
The Response time profile section (Profile in the index) has one row per component, from the longest duration to the shortest, and a Total row equal to the Total time in the Summary. The rows add up to exactly the total time, with no rounding: the percentages close at 100%.
| Component | What it measures |
|---|---|
CPU: FETCH dbcalls and the other call types | The CPU (c=) of the calls of that type, without the CPU of the recursive calls they triggered, which goes to the call type of those calls. |
| Each wait event | The sum of ela= over the event's WAIT lines, such as db file sequential read or SQL*Net message from client. |
unaccounted-for time within calls | The part of the call duration (e=) that is neither CPU, nor a wait recorded inside the call, nor a recursive call. |
unaccounted-for time between calls | The total time minus the level-0 calls and the waits between them: intervals in which the trace recorded nothing. |
Next to the name comes the type: the Oracle wait class for events (Idle, User I/O, Network and others), cpu or unaccounted-for. The same profile grouped by class is right below (wait classes and recursive SQL).
How to read it
| Column | What it says |
|---|---|
| Component | The component name. Click it to open the card (the card for each row). |
| Duration (s) | The time of the component, in seconds, with six decimal places. |
| % of total | The share of total time, with the bar next to it. |
| Occurrences | For waits, how many WAIT lines the event has. For CPU and for unaccounted-for time within calls, how many calls. Blank for the time between calls. |
| Avg (s) | The duration divided by the occurrences. |
| Min (s) and Max (s) | The shortest and the longest occurrence. Blank for unaccounted-for time. |
Unaccounted-for time within calls can come out negative: CPU is measured with a coarser granularity than time, and in short calls the recorded CPU can exceed the duration. It does not indicate a database problem (CPU above elapsed time).
In the sample report, SQL*Net message from client adds up to 0.005000 s in a single wait, 71.3% of the total of 0.007010 s. The second row, db file sequential read, has 2 reads with an average of 0.000650 s.
The card for each row
Click a component name to open its card. The card gives the name in plain language (db file sequential read is Single-block read), the original name, what the component measures and three parts:
- Normal when
- The expected behavior, with reference numbers when they exist. For
db file sequential read: an average of 0.1 to 1 ms on SSD or flash and 5 to 10 ms on disk. - A concern when
- The pattern that indicates a problem and its most common cause.
- Where to look
- What to check and in which part of the report, with a link to the section or to the exact row: the component row in the profile, its table in Latency, its group in Statements by component, the Objects. Items that end in in the database or outside the report are checks the trace does not cover, such as
v$session.blocking_session.
The console has a card of its own for more than 50 wait events, for the CPU of each call type and for the two unaccounted-for times. An event outside the catalog opens the card of its class; the RAC gc events share one card. When the place it points to does not exist in the report, the card points to the whole section or shows the place without a link.
When it is a concern
- A single component takes most of the total time: the analysis starts with it (dominant component, dominant CPU).
SQL*Net message from clientis among the first rows: the database waited for the application, and SQL tuning does not reduce that time (session waiting for the application).- Unaccounted-for time within calls weighs on the total: CPU queueing, paging or uninstrumented code (within calls). A negative value is an effect of CPU measurement.
- Unaccounted-for time between calls weighs on the total: the trace has gaps (gaps between calls).
- A wait event weighs on the total and its Avg (s) is above what the card calls normal: the resource is slow. With a normal average and many occurrences, the problem is volume, and the cause is usually in the plan.
Where to go next
- Profile of the sample report, and the db file sequential read row: click the event name to open the card.
- Statements by component, to see which statements spent the time of the largest component.
- Latency distribution, to tell many fast occurrences from a few slow ones.
- The method, for the order of the analysis.