A little quiz on tkprof

I found this in a trace file recently

INSERT 
INTO T (X)
VALUES(:B1)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       15      0.00       0.00          0          0          0           0
Execute     15      0.00       0.00          0          4         44           2
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       30      0.00       0.00          0          4         44           2

the obvious question being:  How can I execute an insert-values 15 times and only insert 2 rows.

Background Information:

  • There are no triggers of any kind on the table, and no database-wide triggers that might impact the experiment
  • No ‘special interception code’ (eg row level security, views, query rewrite etc)
  • No errors are raised by any of the 15 inserts.
  • No indexes on the table

14 thoughts on “A little quiz on tkprof

  1. Is some clever person putting comments into the SQL inside the PL/SQL?

    create table t
    (x number not null)
    /

    begin
    dbms_monitor.session_Trace_enable;
    for i in 1..5 loop
    insert /*one*/ into t (x) values (i);
    insert /*two*/ into t (x) values (i);
    insert /*three*/ into t (x) values (i);
    end loop;
    dbms_monitor.session_Trace_disable;
    end;
    /

    INSERT INTO T (X)
    VALUES
    (:B1 )

    call count cpu elapsed disk query current rows
    ——- —— ——– ———- ———- ———- ———- ———-
    Parse 15 0.00 0.00 0 0 0 0
    Execute 15 0.01 0.00 0 18 86 15
    Fetch 0 0.00 0.00 0 0 0 0
    ——- —— ——– ———- ———- ———- ———- ———-
    total 30 0.01 0.00 0 18 86 15

  2. > I found this in a trace file recently

    You found that in the tkprof-fed tracefile… What’s in the tracefile? Can/will you share that with us too, or would that give it away?

  3. “…the obvious question being: How can I execute an insert-values 15 times and only insert 2 rows. …”
    That’s not a question on tkprof ?

    The obvious answer: ignore_row_on_dupkey_index or log errors

    create table t ( x number primary key using index ( create unique index tu on t( x ) ));
    begin
    dbms_monitor.session_Trace_enable;
    for i in 1..8 loop
    for j in 1..2 loop
    insert /*+ ignore_row_on_dupkey_index(t,tu) */ into t values(j);
    end loop;
    end loop;
    end;
    /

    But this question is not a question on tkprof ?

    tkprof shows to me
    INSERT /*+ ignore_row_on_dupkey_index(t,tu) */ INTO T
    VALUES
    (:B1 )

    call count cpu elapsed disk query current rows
    ——- —— ——– ———- ———- ———- ———- ———-
    Parse 1 0.00 0.00 0 0 0 0
    Execute 16 0.01 0.03 12 5 198 2
    Fetch 0 0.00 0.00 0 0 0 0
    ——- —— ——– ———- ———- ———- ———- ———-
    total 17 0.01 0.03 12 5 198 2

    Probably there is a tkprof option not known to me which suppresses comments and thus hints in SQL called from PL/SQL as David Kurtz’s answer suggests ?

  4. after some tests with temporary tables, dropped tables, lobs stored out of line, single table hash clusters, and other – even more unlikely – ideas; i don’t have an explanation. Like Matthias I think there are two alternatives (assuming that the line “No errors are raised by any of the 15 inserts” does not mean that you simply catched the errors):
    1. the query indeed was executed 15 times but inserted only two rows
    or
    2. tkprof does not tell the truth in this case
    I still have no idea how 1. could happen and I didn’t find the slightest hint related to 2.

    So perhaps there is a third alterna… – no there is no such thing as a third alternative – a third option; because “when you have eliminated the impossible, whatever remains, however improbable, must be the truth?”
    So here is No. 3: you faked the output. No? Ok, then I am lost.

    Regards

    Martin

  5. Hi, easy enough :-)

    declare
      type tt is table of number;
      t tt := tt ();
    begin
      for i in 1 .. 14 loop
        forall i in indices of t
          insert into t values (t(i));
      end loop;
      t.extend(2);
      forall i in indices of t
        insert into t values (t(i));
    end;
    /
    
    • And Valentin has hit the nail on the head…. and indeed there is an overhead, so it might pay to check the array count before leaping into the FORALL, for example

      SQL> declare
      2 type tt is table of number;
      3 t tt := tt ();
      4 begin
      5 for i in 1 .. 100000 loop
      6 forall i in indices of t
      7 insert into t values (t(i));
      8 end loop;
      9 end;
      10 /

      PL/SQL procedure successfully completed.

      Elapsed: 00:00:02.20

      SQL> declare
      2 type tt is table of number;
      3 t tt := tt ();
      4 begin
      5 for i in 1 .. 100000 loop
      6 if t.count > 0 then
      7 forall i in indices of t
      8 insert into t values (t(i));
      9 end if;
      10 end loop;
      11 end;
      12 /

      PL/SQL procedure successfully completed.

      Elapsed: 00:00:00.03

  6. Changing a litle bit Valentin’s example

    SQL> alter session set session_cached_cursors = 0;
    
    Session altered.
    
    SQL> @46on 12
    
    Session altered.
    
    SQL> declare
      2    type tt is table of number;
      3    t tt:= tt();
      4    begin
      5      for i in 1..15 loop
      6      if i =15 then
      7        t.extend(2);
      8      end if;
      9       forall i in indices of t
     10         insert into t1 values (t(i));
     11      end loop;
     12    end;
     13  /
    
    PL/SQL procedure successfully completed.
    
    SQL> @46off
    
    Session altered.
    
    SQL ID: cn34nbdsakp6b
    Plan Hash: 0
    INSERT INTO T1 
    VALUES
     (:B1 )
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse       15      0.00       0.00          0          0          0           0
    Execute     15      0.00       0.03          2          4         33           2
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total       30      0.00       0.03          2          4         33           2
    

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s