Re: TKPROF showing incomplete data

  • From: Jonathan Lewis <jlewisoracle@xxxxxxxxx>
  • To: Oracle List <oracle-l@xxxxxxxxxxxxx>
  • Date: Tue, 1 Feb 2022 17:02:59 +0000

Amir,

Thanks for letting the list know.
Seeing olutions to unexpected little problems can save people a lot of time.

Regards
Jonathan Lewis



On Tue, 1 Feb 2022 at 14:16, Amir Hameed <axhameed@xxxxxxxxx> wrote:

Copying Oracle List.
Thank you Jonathan for pointing out the anomaly which was the root cause
of the incorrect data getting displayed in the TKP file. The file that I
have also contain the same characters at the same location, which shows
that it somehow got corrupted during tracing.

Thank you,
Amir


On Tuesday, February 1, 2022, 04:09:02 AM EST, Jonathan Lewis <
jlewisoracle@xxxxxxxxx> wrote:



Unless the trace file has been corrupted in zipping or in transit then the
problem is simply that a spurious batch of zero bytes has got into the file.
When I unzipped the file it held 447,145 lines
When I applied tkprof it reported "  116645  lines in trace file."
When I opened the file and jumped to line 116645 I saw the line after is
held 131 "^@" symbols, which I think is the representation of ascii 0 in vi
So one line of nulls got printed, and tkprof stopped when it hit them.
After deleting the line and re-running tkprof I got a summary showing:

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current
 rows
------- ------  -------- ---------- ---------- ---------- ----------
 ----------
Parse     1245      0.23       0.27          0        111          6
    0
Execute  53646      3.41       5.26        185      38683      12318
 1328
Fetch    51956     69.15    1205.38     263481    1536458         60
58954
------- ------  -------- ---------- ---------- ---------- ----------
 ----------
total   106847     72.80    1210.93     263666    1575252      12384
60282

Misses in library cache during parse: 234
Misses in library cache during execute: 219

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total
Waited
  ----------------------------------------   Waited  ----------
 ------------
  library cache pin                             289        0.00
 0.11
  library cache lock                            360        0.00
 0.13
  db file sequential read                    263725        0.53
1142.32
  Disk file operations I/O                      206        0.01
 0.15
  gc cr grant 2-way                              95        0.00
 0.03
  gc current block 3-way                        406        0.00
 0.25
  row cache lock                                 55        0.00
 0.02
  gc current block 2-way                      10254        0.04
 4.18
  gc cr multi block request                       1        0.00
 0.00
  gc cr block 2-way                             590        0.00
 0.24
  gc cr block busy                               66        0.00
 0.14
  gc current grant busy                         201        0.00
 0.12
  latch: shared pool                              1        0.00
 0.00
  enq: TO - contention                            7        0.00
 0.00
  enq: TT - contention                            3        0.00
 0.00
  gc current block congested                    120        0.02
 0.08
  latch: gc element                              12        0.00
 0.00
  gc cr block congested                          12        0.00
 0.00
  gc cr block 3-way                             157        0.00
 0.09
  latch: cache buffers lru chain                  1        0.00
 0.00
  latch: gcs resource hash                        1        0.00
 0.00
  latch: object queue header operation            1        0.00
 0.00
  latch: row cache objects                        2        0.00
 0.00
  gc cr grant congested                           1        0.00
 0.00
  gc current grant 2-way                        155        0.00
 0.04
  gc current block busy                          14        0.01
 0.04
  KJC: Wait for msg sends to complete             2        0.00
 0.00
  gc current grant congested                      2        0.00
 0.00
  gc buffer busy release                          1        0.00
 0.00
  gc current split                                1        0.00
 0.00
  enq: TX - index contention                      1        0.01
 0.01
  enq: HW - contention                            1        0.00
 0.00
  enq: FB - contention                            1        0.00
 0.00
  gc current multi block request                  1        0.00
 0.00
  utl_file I/O                                   24        0.00
 0.00

  307  user  SQL statements in session.
  163  internal SQL statements in session.
  470  SQL statements in session.

********************************************************************************
Trace file: temp1.trc
Trace file compatibility: 12.2.0.0
Sort options: default

       1  session in tracefile.
     307  user  SQL statements in trace file.
     163  internal SQL statements in trace file.
     470  SQL statements in trace file.
     329  unique SQL statements in trace file.
  447144  lines in trace file.
    1215  elapsed seconds in trace file.

Regards
Jonathan Lewis




On Mon, 31 Jan 2022 at 23:33, Amir Hameed <axhameed@xxxxxxxxx> wrote:

Hi Cary,
Attached, please find the trace file in zipped format. I am also copying
Jonathan as he was the first person who had provided his feedback, in case
he would like to look at it as well.

Thank you,
Amir


Other related posts: