Oracle TKPROF Insert data doesn't match text results

Question

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?

Answer 1

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:

ELAPSED_TIME

NUMBER

Elapsed time (in microseconds) used by this cursor for parsing, executing, and fetching. If the cursor uses parallel execution, then ELAPSED_TIME is the cumulative time for the query coordinator, plus all parallel query slave processes.

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.