I'm trying to make sense of the output from a SQL Trace from an Oracle 12.2 database on Windows. I've used TKPROF to interpret the the resulting trace files. This utility generates a text file output and a SQL file output. But the data don't match up between the two files.
The data was generated using syntax like tkprof Trace.trc trace.trc.txt insert=trace.trc.sql
For a specific query, the TKPROF output via text file is:
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 13 0.04 0.03 0 0 1 0
Fetch 13 0.00 0.07 6 26 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 27 0.04 0.11 6 26 1 0
But TKPROF's SQL output generates data for that query that doesn't have the same numbers for the Elapsed column.
Here's the Insert statement:
INSERT INTO tkprof_table (
date_of_insert, cursor_num, depth, user_id,
parse_cnt, parse_cpu, parse_elap, parse_disk, parse_query, parse_current, parse_miss,
exe_count, exe_cpu, exe_elap, exe_disk, exe_query, exe_current, exe_miss, exe_rows,
fetch_count, fetch_cpu, fetch_elap, fetch_disk, fetch_query, fetch_current, fetch_rows,
ticks, sql_statement
)
VALUES
(
SYSDATE, 4, 0, 9,
1, 0, 86, 0, 0, 0, 0,
13,46875, 31424, 0, 0, 1, 2, 0,
13, 0, 79075, 6, 26, 0, 0, 152918
, 'SELECT [...]')
And then converting those SQL columns to match the text file's table layout that becomes:
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0 86 0 0 0 0
Execute 13 46875 31424 0 0 1 0
Fetch 13 0 79075 6 26 0 0
Oracle's documentation says the TKPROF Elapsed values are
"total elapsed time in seconds for all parse, execute, or fetch calls
for the statement."
And I believe that's accurate for the text file output. But the SQL data must be some other measure. I can't find any documentation that defines a unit of measure for the mismatched data.
There's a "ticks" column, that appears to correspond to CPU ticks. But I don't know if that's what the mismatched values are too. If so, how do I convert that data to seconds?
Or it looks like these values may be microseconds. Is that correct? Is there anywhere that definitively defines that unit of measure?
Best Answer
Those values are just fine. They are just truncated in the tkprof output and displayed as seconds instead of microseconds.
Time for SQL executions is typically measured in microseconds.
See V$SQL for example:
Tkprof also displays time in microseconds at the row source operations section (and displays the unit as
us
).I did not find any explicit reference for describing all the columns of TKPROF_TABLE, stating the time unit to be microsecond, but its quite logical.