Databases Reference
In-Depth Information
'user I/O wait time')
ORDER BY action, stat_name;
ACTION STAT_NAME VALUE
----------- ------------------------ -----
exif_insert DB CPU .02
exif_insert DB time .02
exif_insert sql execute elapsed time .01
exif_insert user I/O wait time 0
lob_load DB CPU 2.7
lob_load DB time 8.75
lob_load sql execute elapsed time 0
lob_load user I/O wait time 5.85
The total “DB time”, which does not include network latency and think time (
SQL*Net message
from client
), for both actions was 8.77 seconds. This was reasonably close to the response time
reported by the UNIX utility
time
(9.9 s). Since the latter measurement includes compilation of
the Perl program and connecting to the DBMS instance, some discrepancy had to be expected.
Thanks to instrumentation, it is very obvious that the bulk of response time is due to the action
“lob_load”, which deals with loading the
BLOB
column.
Whereas the extended SQL trace file failed to account for CPU usage due to LOB loading,
V$SERV_MOD_ACT_STATS
reported 2.7 seconds of CPU usage for loading 10 LOBs. The bulk of the
response time was attributed to user I/O wait time. This correlated with the large amount of
db
file sequential read
and
direct path read
as well as
direct path write
operations associated with
cursor 4 of the SQL trace file. Since at least 8.77 seconds (total “DB time” for both actions) out
of 9.93 seconds (response time measured by the UNIX utility
time
) or 88% are spent in the DBMS
instance, the assumption that reading the JPEG file does not contribute significantly to response
time had proven to be correct.
Figures in
V$SERV_MOD_ACT_STATS
are cumulative since instance startup. To disable statistics
collection, these calls to
DBMS_MONITOR
need to be used:
SQL> EXEC dbms_monitor.serv_mod_act_stat_disable('TEN.oradbpro.com', -
> 'img_load', 'exif_insert')
SQL> EXEC dbms_monitor.serv_mod_act_stat_disable('TEN.oradbpro.com','img_load', -
> 'lob_load')
Disabling statistics collection in this way does not clear the statistics. If statistics collection
on the same module and action is re-enabled at a later time, the measurements taken before
are made available again, unless the instance has been restarted.
For the sake of comparing measurements taken before and after improving the response
time, I recorded another run with level 8 SQL trace enabled through event 10046, since I did not
want the additional executions and round-trips caused by ILO to impact the results. The resulting
ESQLTRCPROF report is reproduced here:
