On Sat, 10 Jul 2004 13:42:20 -0700, Daniel Morgan wrote:
........
Daniel, I traced your code and found no extraordinary wait events.
You've probably come across a quirk in the internal PL/SQL optimizing
mechanism. The trace file is below this text. Oracle probably tried to
atone for the mistakes that people are usually making, so they optimized
the performance penalty away. That is the only explanation I have.
May the force be with you and your students.
/oracle/product/10g/admin/oracle/udump/10g_ora_1589.trc
Oracle Database 10g Enterprise Edition Release 10.1.0.2.0 - Production
With the Partitioning, OLAP and Data Mining options
ORACLE_HOME = /oracle/product/10g
System name: Linux
Node name: medo.noip.com
Release: 2.4.26
Version: #4 Fri May 7 20:37:06 EDT 2004
Machine: i686
Instance name: 10g
Redo thread mounted by this instance: 1
Oracle process number: 20
Unix process pid: 1589, image: oracle10g_at_medo.noip.com
- 2004-07-10 17:34:53.423
- ACTION NAME:() 2004-07-10 17:34:53.423
- MODULE NAME:(SQL*Plus) 2004-07-10 17:34:53.423
- SERVICE NAME:(oracle.noip.com) 2004-07-10 17:34:53.423
- SESSION ID:(92.18) 2004-07-10 17:34:53.423
QUERY
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
QUERY
DECLARE
c CHAR(5);
i PLS_INTEGER;
j PLS_INTEGER;
n NUMBER := 0;
BEGIN
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
n := n + 15;
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('n+15 = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
n := n+15.0;
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('n+15.0 = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
c := 15;
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('c=15 = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
c := TO_CHAR(15);
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('c=TO_CHAR = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
c := '15';
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('c=''15'' = ' || TO_CHAR(j));
END;
END;
- 2004-07-10 17:35:07.750
QUERY
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
- 2004-07-10 17:36:50.290
QUERY
DECLARE
c CHAR(5);
i PLS_INTEGER;
j PLS_INTEGER;
n NUMBER := 0;
BEGIN
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
n := n + 15;
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('n+15 = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
n := n+15.0;
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('n+15.0 = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
c := 15;
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('c=15 = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
c := TO_CHAR(15);
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('c=TO_CHAR = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
c := '15';
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('c=''15'' = ' || TO_CHAR(j));
END;
END;
- 2004-07-10 17:37:01.412
QUERY
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
- 2004-07-10 17:39:20.665
WAIT #1: nam='SQL*Net message from client' ela= 135988704 p1=1229996800 p2=1 p3=0
QUERY
DECLARE
c CHAR(5);
i PLS_INTEGER;
j PLS_INTEGER;
n NUMBER := 0;
BEGIN
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
n := n + 15;
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('n+15 = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
n := n+15.0;
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('n+15.0 = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
c := 15;
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('c=15 = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
c := TO_CHAR(15);
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('c=TO_CHAR = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
c := '15';
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('c=''15'' = ' || TO_CHAR(j));
END;
END;
PARSING IN CURSOR #2 len=1177 dep=0 uid=45 oct=47 lid=45 tim=1063960508463440 hv=2287539996 ad='5e39f9e8'
DECLARE
c CHAR(5);
i PLS_INTEGER;
j PLS_INTEGER;
n NUMBER := 0;
BEGIN
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
n := n + 15;
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('n+15 = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
n := n+15.0;
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('n+15.0 = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
c := 15;
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('c=15 = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
c := TO_CHAR(15);
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('c=TO_CHAR = ' || TO_CHAR(j));
END;
BEGIN
i := dbms_utility.get_time();
FOR i IN 1 .. 10000000
LOOP
c := '15';
END LOOP;
j := dbms_utility.get_time() - i;
dbms_output.put_line('c=''15'' = ' || TO_CHAR(j));
END;
END;
END OF STMT
PARSE #2:c=10000,e=346,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1063960508463428
- 2004-07-10 17:39:32.134
EXEC #2:c=9920000,e=11198650,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1063960519662291
WAIT #2: nam='SQL*Net message to client' ela= 3 p1=1229996800 p2=1 p3=0
WAIT #2: nam='SQL*Net message from client' ela= 306 p1=1229996800 p2=1 p3=0
QUERY
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
PARSING IN CURSOR #1 len=52 dep=0 uid=45 oct=47 lid=45 tim=1063960519663022 hv=1029988163 ad='5e3de70c'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #1:c=0,e=137,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1063960519663015
WAIT #1: nam='SQL*Net message to client' ela= 3 p1=1229996800 p2=1 p3=0
EXEC #1:c=0,e=300,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1063960519663381
- 2004-07-10 17:42:28.011
WAIT #1: nam='SQL*Net message from client' ela= 171754246 p1=1229996800 p2=1 p3=0
XCTEND rlbk=0, rd_only=1
--
Well-behaved women seldom make history
Received on Sat Jul 10 2004 - 16:48:46 CDT
