Home » RDBMS Server » Performance Tuning » Elapsed time (11.2.0.2 , Linux)
Elapsed time [message #559926] Sat, 07 July 2012 14:53 Go to next message
gkrishn
Messages: 487
Registered: December 2005
Location: Putty a dark screen
Senior Member
I am comparing elapsed time between my query execution, and tkprof output.

SQL> begin
for i in 1..10 loop
insert into testtab1 values (i);
end loop;
end;
/  2    3    4    5    6

PL/SQL procedure successfully completed.

Elapsed: 00:03:16.59


ie, 196 seconds .

Now tkprof output.

INSERT INTO TESTTAB1
VALUES
 (:B1 )


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 1000000    111.25     127.23          0       1542    1026500     1000000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   1000001    111.25     127.23          0       1542    1026500     1000000


1)why is elapsed time more here. 127 seconds ?
2)my cpu seconds is 111 .where was it waiting 16 seconds (since elapsed i see 127sec) .

Thanks
Re: Elapsed time [message #559927 is a reply to message #559926] Sat, 07 July 2012 15:02 Go to previous messageGo to next message
BlackSwan
Messages: 21967
Registered: January 2009
Senior Member
>for i in 1..10 loop
How does 10 INSERT (above) end up being reported as below?
>Execute 1000000

>2)my cpu seconds is 111 .where was it waiting 16 seconds (since elapsed i see 127sec) .
Details to answer this question are contained within actual trace file.

I believe you mis-report reality
Re: Elapsed time [message #559928 is a reply to message #559927] Sat, 07 July 2012 15:06 Go to previous messageGo to next message
gkrishn
Messages: 487
Registered: December 2005
Location: Putty a dark screen
Senior Member
Sorry its "for i in 1..1000000 loop" . i did another test with 10 so pasted that by mistake.

begin
for i in 1..1000000 loop
insert into testtab1 values (i);
end loop;
end;
Re: Elapsed time [message #559929 is a reply to message #559928] Sat, 07 July 2012 15:09 Go to previous messageGo to next message
BlackSwan
Messages: 21967
Registered: January 2009
Senior Member
I decline to waste more of my time trying to discern fact from fiction.
Re: Elapsed time [message #559930 is a reply to message #559929] Sat, 07 July 2012 15:12 Go to previous messageGo to next message
gkrishn
Messages: 487
Registered: December 2005
Location: Putty a dark screen
Senior Member
"typo" happanes to human.
Re: Elapsed time [message #559931 is a reply to message #559930] Sat, 07 July 2012 15:13 Go to previous messageGo to next message
gkrishn
Messages: 487
Registered: December 2005
Location: Putty a dark screen
Senior Member
oracle> more $HOME/loopInsert.txt

TKPROF: Release 11.2.0.2.0 - Development on Sat Jul 7 15:12:03 2012

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

Trace file: _ora_27000840_loopInsert.trc
Sort options: default

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

begin
for i in 1..1000000 loop
insert into testtab1 values (i);
end loop;
end;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1     61.77      69.34          0       1548          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     61.77      69.34          0       1548          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 33

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net break/reset to client                   2        0.00          0.00
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2     1227.59       1244.66
********************************************************************************

SQL ID: 3spdmu10hvsd0 Plan Hash: 0

INSERT INTO TESTTAB1
VALUES
 (:B1 )


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 1000000    111.25     127.23          0       1542    1026500     1000000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   1000001    111.25     127.23          0       1542    1026500     1000000

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 33     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=439 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        1        0.00          0.00
  latch: shared pool                              2        0.00          0.00
  log file switch (private strand flush incomplete)
                                                  1        0.05          0.05
********************************************************************************

SQL ID: 23wm3kz7rps5y Plan Hash: 0

commit


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          1           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          1           0

Misses in library cache during parse: 0
Parsing user id: 33

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1      768.28        768.28
********************************************************************************

SQL ID: 06nvwn223659v Plan Hash: 0

alter session set events '10046 trace name context off'


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Parsing user id: 33



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
Execute      3     61.77      69.34          0       1548          1           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6     61.77      69.34          0       1548          1           1

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       4        0.00          0.00
  SQL*Net message from client                     4     1227.59       2023.80
  SQL*Net break/reset to client                   2        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          2           0
Execute 1000004    111.25     127.23          0       1542    1026500     1000000
Fetch        6      0.00       0.00          0         10          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   1000014    111.25     127.24          0       1552    1026502     1000002

Misses in library cache during parse: 2
Misses in library cache during execute: 2

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        1        0.00          0.00
  latch: shared pool                              2        0.00          0.00
  log file switch (private strand flush incomplete)
                                                  1        0.05          0.05

    4  user  SQL statements in session.
    3  internal SQL statements in session.
    7  SQL statements in session.
********************************************************************************
Trace file: ora_27000840_loopInsert.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       1  session in tracefile.
       4  user  SQL statements in trace file.
       3  internal SQL statements in trace file.
       7  SQL statements in trace file.
       6  unique SQL statements in trace file.
 8000549  lines in trace file.
    2209  elapsed seconds in trace file.

[Updated on: Sat, 07 July 2012 15:14]

Report message to a moderator

Re: Elapsed time [message #559932 is a reply to message #559930] Sat, 07 July 2012 15:19 Go to previous messageGo to next message
BlackSwan
Messages: 21967
Registered: January 2009
Senior Member
gkrishn wrote on Sat, 07 July 2012 13:12
"typo" happanes to human.


since when does COPY & PASTE produces "typos"?
Re: Elapsed time [message #559933 is a reply to message #559932] Sat, 07 July 2012 15:20 Go to previous messageGo to next message
gkrishn
Messages: 487
Registered: December 2005
Location: Putty a dark screen
Senior Member
DONT KNow the exact date. i will let you know.
Re: Elapsed time [message #559940 is a reply to message #559926] Sun, 08 July 2012 00:32 Go to previous messageGo to next message
Michel Cadot
Messages: 57644
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
1)
TKPROF returns times measures on database server side.
SQL*Plus returns time measure on client side.

2)
Difference between elapsed and cpu is indeed wait+ready time. There may be Oracle waits but also server waits (for instance, wait for cpu or in run queue).

Regards
Michel
Re: Elapsed time [message #559949 is a reply to message #559940] Sun, 08 July 2012 01:53 Go to previous messageGo to next message
John Watson
Messages: 4102
Registered: January 2010
Location: Global Village
Senior Member
Quote:
TKPROF returns times measures on database server side.
SQL*Plus returns time measure on client side.
I find that SET AUTOTRACE TRACEONLY is very useful, it suppresses the output so you often get a closer correlation.
Re: Elapsed time [message #559950 is a reply to message #559949] Sun, 08 July 2012 01:56 Go to previous messageGo to next message
Michel Cadot
Messages: 57644
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Yes, I agree, but in this it is just a PL/SQL loop without any output and we have to take care that autotrace does not return the actual execution plan but the explain plan one.

Regards
Michel
Re: Elapsed time [message #559956 is a reply to message #559926] Sun, 08 July 2012 03:44 Go to previous messageGo to next message
gkrishn
Messages: 487
Registered: December 2005
Location: Putty a dark screen
Senior Member
Thanks Mike and John .Appreciate your help in explaining basics .

begin
for i in 1..1000000 loop
insert into testtab1 values (i);
end loop;
end;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1     61.77      69.34          0       1548          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     61.77      69.34          0       1548          0           1




Can you explain why execute shows JUST "1" here.
"for i in 1..1000000 loop" for loop not supposed to run 1000000 times ?
Re: Elapsed time [message #559958 is a reply to message #559956] Sun, 08 July 2012 03:48 Go to previous messageGo to next message
Michel Cadot
Messages: 57644
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
You execute only once the PL/SQL block.

Regards
Michel
Re: Elapsed time [message #559959 is a reply to message #559958] Sun, 08 July 2012 03:52 Go to previous messageGo to next message
gkrishn
Messages: 487
Registered: December 2005
Location: Putty a dark screen
Senior Member
So , one plsql execute + 1000000 INSERTs .
61 seconds is the time for for loop (iterations) ?
Re: Elapsed time [message #559960 is a reply to message #559959] Sun, 08 July 2012 04:17 Go to previous messageGo to next message
Michel Cadot
Messages: 57644
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
It is the time for the whole pl/sql block including all what is done and called in it.

Regards
Michel
Re: Elapsed time [message #559963 is a reply to message #559960] Sun, 08 July 2012 04:52 Go to previous messageGo to next message
gkrishn
Messages: 487
Registered: December 2005
Location: Putty a dark screen
Senior Member
Thats confusing me again ! plsql block elapsed is 69 seconds ,inside that INSERT elapsed is 127 sec.

insert is within plsql block , so total elapsed isnt the sum of 69+127 ?
Re: Elapsed time [message #560254 is a reply to message #559960] Wed, 11 July 2012 09:50 Go to previous message
LNossov
Messages: 283
Registered: July 2011
Location: Germany
Senior Member
Unfortunately no.

It a result of select from v$sql:

113  ---- DISK_READS=22, DISK_READS_PER_EX=22, BUFFER_GETS=2094623, BUFFER_GETS_PER_EX=2094623
114  ---- DIRECT_WRITES=0, DIRECT_WRITES_PER_EX=0
115  ---- PARSE_CALLS=1, EXECUTIONS=1, ROWS_PROCESSED=1
116  ---- IS_SHAREABLE=Y, IS_BIND_SENSITIVE=N, IS_BIND_AWARE=N
117  ---- CPU/Elapsed Time (sec.) total=277.4634/281.1268, per ex.=277.4634/281.1268
118  ---- PL/SQL Exec Time (sec.) total=73.3869, per ex.=73.3869
119  ---- JAVA Exec Time (sec.) total=0.0000, per ex.=0.0000
120  ---- Application Wait Time (sec.) total=0.0000, per ex.=0.0000
121  ---- Concurrency Wait Time (sec.) total=0.0001, per ex.=0.0001
122  ---- Cluster Wait Time (sec.) total=0.0000, per ex.=0.0000
123  ---- User IO Wait Time (sec.) total=0.5653, per ex.=0.5653
124  ---- IO_INTERCONNECT_BYTES=180224, IO_INTERCONNECT_BYTES_PER_EX=180224
125  ---- Service : leo1121.de.oracle.com
126  ---- Module : sqlplus.exe
127  ---- USER="SYS", SCHEMA="SYS", OPTIMIZER_MODE=ALL_ROWS, OPTIMIZER_ENV_HASH_VALUE=336968051, USERS_OPEN=0, USERS_EXEC=0, LAST_ACTIVE_TIME=11.07.2012 16:13:11
128  ---- SQL_ID=>fpwyxnau2f1ts<, ADDRESS=>000007FF05767240<, HASH_VALUE=>3022456632<, OLD_HASH_VALUE=>2100988528<, CHILD_NUMBER=>0<
129  begin
130  --	insert into t1 select level, level*10, level*100, level*1000, level*10000, level*1000000 from dual connect by level <= 100000;
131  	for i in 1..2000000 loop
132  		insert into t1 values (i, i*10, i*100, i*1000, i*10000, i*1000000);
133          end loop;
134  	commit;
135  end;


It is from the 10046 trace:

begin
--	insert into t1 select level, level*10, level*100, level*1000, level*10000, level*1000000 from dual connect by level <= 100000;
	for i in 1..2000000 loop
		insert into t1 values (i, i*10, i*100, i*1000, i*10000, i*1000000);
        end loop;
	commit;
end;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.00          0          0          0           0
Execute      1    181.25     184.04          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2    181.27     184.04          0          0          0           1

...

INSERT INTO T1 
VALUES
 (:B1 , :B1 *10, :B1 *100, :B1 *1000, :B1 *10000, :B1 *1000000)


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 2000000     96.17      97.05         22      21388    2072780     2000000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   2000001     96.17      97.05         22      21388    2072780     2000000



So 97.05 + 184.04 = 281.09 ~ 281.1268 (281.1268 is elapsed time from the first output).

Regards
Leonid
Previous Topic: DB time in AWR Report - (CPU time,I/O and waits)?
Next Topic: Oracle 10g showing problem with index (2 Merged)
Goto Forum:
  


Current Time: Thu Apr 24 05:14:54 CDT 2014

Total time taken to generate the page: 0.25584 seconds