Database Reference
In-Depth Information
9 *** 2007-06-22 15:42:51.924
10 EXEC #1:c=0,e=9997915,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=176349294618
…
11 EXEC #1:c=70101,e=74082,p=0,cr=2,cu=0,mis=0,r=0,dep=0,og=1,tim=176349582606
12 ERROR #1:err=1646 tim=17634587
The first
tim
value after the timestamp in the header will serve as a reference. In the example,
“2007-06-22 15:42:41.018” in line 1 is approximately the same as 176338392169 microseconds
in line 2. The nearest
tim
value above the
ERROR
entry in line 4 is 176339220462 microseconds in
line 3. So between lines 2 and 3, (176339220462-176338392169) / 1000000 or 0.82 seconds have
passed. The nearest
tim
value above the second
ERROR
entry is 176349582606 in line 11. Between
line 3 and line 11, (176349582606-176339220462) / 1000000 or 10.36 seconds have passed. This
is reasonable, since the session was put to sleep for 10 seconds. The intermittent timestamp in
line 9 forced with
DBMS_SYSTEM.KSDDT
confirms this. Timestamp (
tim
) values of
ERROR
entries only
have centisecond resolution. This is apparent when subtracting 17633550 (
ERROR
entry in line 4)
from 17634587 (
ERROR
entry in line 12), which yields 10.37 seconds ((17634587-17633550) / 100).
Using the same approach, we can compute that the second error in line 12 occurred
(176349582606-176338392169) / 1000000 or 11.190 seconds after 15:42:41.018. So the second
error occurred at 15:42:52.208, which is about ten seconds after the trace file header was
written and about 0.3 seconds after the timestamp written by
DBMS_SYSTEM.KSDDT
. Of course,
this approach works for any trace file entry that has a
tim
field and not just
ERROR
entries. Why
there is an offset—about 3.7 seconds in my testing—between centisecond resolution
tim
values in
ERROR
entries and microsecond resolution
tim
values in other entries is a question for
Oracle development.
I remember an assignment due to an escalated service request. It was believed that the
DBMS was erroneously throwing “ORA-06502: PL/SQL: numeric or value error”. By taking a
level 1 trace and looking for
ERROR
entries, I was able to prove that there were no errors in the
communication between the DBMS instance and the client. It turned out that it was an appli-
cation coding error with a buffer that was too small. The ORA-06502 was thrown by the PL/SQL
engine of the Oracle Forms runtime environment, not the PL/SQL engine within the ORACLE
DBMS. Thus, there was no
ERROR
entry in the SQL trace file.
Application Instrumentation and Parallel Execution Processes
Among the three kinds of application instrumentation entries, solely the client identifier is
emitted to trace files from parallel execution processes. These trace files are created in the
directory assigned with the parameter
BACKGROUND_DUMP_DEST
and follow the naming scheme
ORACLE_SID
_p
nnn
_
spid
.trc
in Oracle10
g
, where
n
is a digit between 0 and 9 and
spid
corre-
sponds to
V$PROCESS.SPID
.
The term query coordinator refers to a process that controls parallel execution slaves. The
slaves perform the actual work. The query coordinator is the same process that serves the data-
base client. Since resource consumption, such as CPU time and I/O requests by parallel execution
slaves, is not rolled up into the statistics reported for the query coordinator, the client identifier
may be used in conjunction with the TRCSESS utility to get a full account of the resources
consumed by the query coordinator and the parallel execution processes it recruited.
The subsequent example shows how to use the TRCSESS utility to combine the trace file
from the query coordinator and four trace files from parallel execution processes into a single
trace file for formatting with TKPROF. A user with
SELECT
ANY
DICTIONARY
privilege might use
