Elapsed time [message #559926] |
Sat, 07 July 2012 14:53 |
gkrishn
Messages: 506 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 #559928 is a reply to message #559927] |
Sat, 07 July 2012 15:06 |
gkrishn
Messages: 506 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 #559931 is a reply to message #559930] |
Sat, 07 July 2012 15:13 |
gkrishn
Messages: 506 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 #559949 is a reply to message #559940] |
Sun, 08 July 2012 01:53 |
John Watson
Messages: 8938 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 #559956 is a reply to message #559926] |
Sun, 08 July 2012 03:44 |
gkrishn
Messages: 506 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 #559959 is a reply to message #559958] |
Sun, 08 July 2012 03:52 |
gkrishn
Messages: 506 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 #559963 is a reply to message #559960] |
Sun, 08 July 2012 04:52 |
gkrishn
Messages: 506 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 |
|
LNossov
Messages: 318 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
|
|
|