Welcome, Guest
Username: Password: Remember me

TOPIC: Interpreting an unaccounted-for between dbcalls

Interpreting an unaccounted-for between dbcalls 3 months 1 day ago #439

From method-r profiler result, the 1st line of subroutine shows me "unaccounted-for between dbcalls" and it spent 83%, even though "unaccounted-for within dbcalls" with 0% After searching this web blog and this article looks alike.

The following table shows the decomposition of total task response time by internal subroutine.
Subroutine	Duration		Cumulative duration	Call
count	Duration per call (seconds)	Drill-down
seconds	% R	seconds	% R	mean	min	skew	max
8.	Total	12,717.100	100.0%					
1.	unaccounted-for between dbcalls	10,612.924	83.5%		10,612.924	83.5%	299	35.494729	0.000009	▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁█	6,878.471677	SQL
2.	CPU service, unreported call(s)	2,098.873	16.5%		12,711.797	100.0%	1	2,098.872794	2,098.872794	▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁█	2,098.872794	SQL
3.	unaccounted-for within dbcalls	4.261	0.0%		12,716.058	100.0%	25,654	0.000166	-0.190306	▁▁▁▁▃▁▁▁▁▁▁▁▁▁▂██▃▇▁▁▁	1.151326	
4.	CPU service, EXEC calls	0.452	0.0%		12,716.510	100.0%	6,088	0.000074	-0.035353	▁▂▂▃█▅▁▁▁▁	0.039003	
5.	CPU service, FETCH calls	0.438	0.0%		12,716.948	100.0%	14,118	0.000031	0.000000	▁▂▃▂▂█▁▁▁▁▁	0.062481	
6.	CPU service, PARSE calls	0.140	0.0%		12,717.089	100.0%	1,369	0.000102	-0.031468	▁▁▁▆█▁▁▁▁▁	0.008010	
7.	CPU service, CLOSE calls	0.011	0.0%		12,717.100	100.0%	6,004	0.000002	-0.000079	▁█▂▁▁▁▁▁▁▁▁	0.000243	


The tkprof result provides me a different perspective. The total time of non-recursive and recursive are shorter than profiler total measured task response time (3-hr 31-minute).
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       44      0.07       0.14          0        196         30           0
Execute     75      0.13       0.28          8        124         35          16
Fetch       92      0.25       2.02       2563      63574          0         325
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      211      0.46       2.44       2571      63894         65         341

Misses in library cache during parse: 38
Misses in library cache during execute: 38


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     1325      0.10       0.18          5        171         32           0
Execute   5988      0.29       0.55         16        326        117          22
Fetch    14026      0.18       2.42        616      29154          4       28286
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    21339      0.58       3.15        637      29651        153       28308


There are several questions here
1) Is it necessary to remove the unaccounted-for .. waits , and why ?
2) The web site blog uses "neutralize" the unwanted line. How could I do that ?
3) How could I further examine this output relative to tkprof ?

Your comments and expertise are welcome.
Attachments:
The administrator has disabled public write access.

Interpreting an unaccounted-for between dbcalls 3 months 1 day ago #440

Bundit, to answer your fist question, I have to ask you a question: what user experience does the trace file represent? The file contains 3.5 hours' worth of trace data. The Profiler, which expects its input to be a single user experience, works to explain to you where every bit of that time has gone.

If this trace file truly does represent a single end-user experience (in other words, someone waited 3.5 hours for one task execution from your system), then the 'unaccounted-for between dbcalls' time row of your profile report is telling you that 83.5% of your user's time was spent between Oracle dbcalls, doing something for which the Oracle Database doesn't have instrumentation. However, in your trace file, it looks like tracing was activated and deactivated a few times within the file. Your big 'unaccounted-for between dbcalls' occurrences probably represent the spans of time during which the session's tracing was turned off.

This tracing on/off/on/off behavior indicates to me that this trace file probably describes more than one distinct user experience. If it does, then you'll need to split the trace file into separate files, one per distinct user experience, and profile those. After you've done that, any 'unaccounted-for between dbcalls' time that is left will then convey a different meaning (most likely corresponding to the duration your process spent involuntary preempted).

Regarding your second question, there are three articles at method-r.com/blog that I think will interest you: the two whose titles begin with "Removing..." (I know you've seen at least one of those), and the one whose title begins with "Connection Pooling...." These posts make use of the mrskew utility, which is a program distributed with the Method R Tools software package.

The answer to your third question is tricky. Oracle's tkprof will "eat anything," so to speak. It doesn't track the time (tim field) values within your trace file, so it blissfully neglects all unaccounted-for time. It also doesn't track RPCs. it's difficult to compare tkprof output to Method R Profiler output, because tkprof doesn't make any effort to distinguish between (i) OS calls whose durations are counted within dbcalls from (ii) OS calls whose durations occur between dbcalls. This is one of the reasons why none of the numbers in a tkprof report add up: the "elapsed seconds in trace file" figure at the bottom doesn't match the sums above it; the "elapsed" column values doesn't fit the "Total Waited" values; and so on. It's a mess. It's one of the main reasons we don't use it.
The administrator has disabled public write access.