ORA-3114 after upg to 10.1.0.5 and hitting "Fetch Last Page"

M

Mark Gorman

Member
We created a 10.1.0.5 database (64-bit database running on SUSE LINUX Enterprise Server 9 x86_64), and now we have all plsqldev clients in the network experiencing the same issue. Versions include 7.0.3.1123 and 6.0.5.931.

For a sufficiently wide table (more than 3 or 4 columns) of only native datatypes (varchar2s, number, date), hitting "Fetch Last Page" results in very slow fetching, progressively slower until no records are being fetched, and eventually a 3113 and 3114 error. This issue persists after a database restart.

Hoping you can help! We have become dependent on your excellent product.

Thanks,
Mark Gorman
Traq Wireless
 
ORA-03113 usually means that the Oracle Server process for the current session has crashed. Can you check if a user trace dump file exist on the database server that corresponds to this ORA-03113 error? Usually you will see an ORA-00600 error here, with some error codes that may help us find the cause of the problem. If it does, can you send it to me?
 
There was no udump trace created.

I went ahead and explicitly started a SQL trace and reproduced the issue. Interestingly, while the slowdown is still a major issue as progress essentially stopped at about 2600 records fetched, the connection did not drop.

I profiled the waits on the session as follows:
SQL> /
old 11: e.sid = &Sid
new 11: e.sid = 327

EVENT TIME_WAITED TOTAL_WAITS TOTAL_TIMEOUTS AVERAGE_WAIT MAX_WAIT
---------------------------------------- ----------- ----------- -------------- ------------ ----------
SQL*Net message from client 68418 51 0 1342 11758
db file scattered read 3 2 0 2 2
latch: library cache 0 1 0 0 0
SQL*Net message to client 0 52 0 0 0
SQL*Net more data to client 0 60 0 0 0

SQL> l
1 select
2 e.event,
3 e.time_waited,
4 e.total_waits,
5 e.total_timeouts,
6 e.average_wait,
7 e.max_wait
8 from
9 sys.v_$session_event e
10 where
11 e.sid = &Sid
12* order by 2 desc

Here are the last few lines from the trace:

PARSING IN CURSOR #1 len=19 dep=0 uid=193 oct=3 lid=3688782591164416193 tim=1140901367357085 hv=3438668132 ad='a25ae968'
SELECT * FROM link
END OF STMT
PARSE #1:c=2000,e=1970,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1140901367357083
=====================
PARSING IN CURSOR #2 len=61 dep=0 uid=193 oct=47 lid=193 tim=1140901367456951 hv=356401299 ad='a8ec2d08'
begin :id := sys.dbms_transaction.local_transaction_id; end;
END OF STMT
PARSE #2:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1140901367456948
EXEC #2:c=0,e=93,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1140901367457172
=====================
PARSING IN CURSOR #1 len=80 dep=0 uid=193 oct=47 lid=193 tim=1140901369658047 hv=4279631818 ad='a221be48'
begin
sys.dbms_output.get_lines(lines => :lines, numlines => :numlines);
end;
END OF STMT
PARSE #1:c=0,e=98,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1140901369658042
EXEC #1:c=0,e=142,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1140901369658329
FETCH #3:c=1000,e=237,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901371230338
FETCH #3:c=1000,e=249,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901371993219
FETCH #3:c=0,e=234,p=0,cr=3,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901372802470
FETCH #3:c=1000,e=253,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901373989574
FETCH #3:c=1000,e=271,p=0,cr=3,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901376041425
FETCH #3:c=0,e=231,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901376833040
FETCH #3:c=0,e=255,p=0,cr=3,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901378026242
FETCH #3:c=0,e=244,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901378791038
FETCH #3:c=0,e=217,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901379986661
FETCH #3:c=0,e=266,p=0,cr=3,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901380739295
FETCH #3:c=0,e=243,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901381941780
FETCH #3:c=0,e=252,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901383897376
FETCH #3:c=0,e=261,p=0,cr=3,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901384679670
FETCH #3:c=0,e=238,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901385825032
FETCH #3:c=1000,e=266,p=0,cr=3,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901386545335
FETCH #3:c=0,e=231,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901387308019
FETCH #3:c=0,e=239,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901388373128
FETCH #3:c=0,e=264,p=0,cr=3,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901390153734
FETCH #3:c=0,e=239,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901393364036
FETCH #3:c=0,e=266,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901399443686
*** 2007-01-08 13:04:05.165
FETCH #3:c=0,e=265,p=0,cr=3,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901411294405
*** 2007-01-08 13:04:29.040
FETCH #3:c=0,e=241,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901434610066
*** 2007-01-08 13:05:16.409
FETCH #3:c=3000,e=22467,p=3,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901480868263
*** 2007-01-08 13:06:50.710
FETCH #3:c=1000,e=244,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901572959860
*** 2007-01-08 13:08:51.095
FETCH #3:c=1000,e=13961,p=8,cr=3,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901690522595
*** 2007-01-08 13:10:51.420
FETCH #3:c=0,e=210,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901808027794
*** 2007-01-08 13:12:51.822
FETCH #3:c=0,e=231,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140901925607725
*** 2007-01-08 13:14:52.188
FETCH #3:c=0,e=213,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,tim=1140902043152383

You can see several minutes elapsing between each of the last few fetches, while the elapsed time (e) for the operation does not account for all this time. This indicates to me that the client is the one being waited upon. Note that plsqldev.exe is not consuming CPU on my workstation.

-Mark
 
It's a bit of a puzzle. Nothing goes wrong on the client, nothing goes wrong on the server, yet things get slower and slower, and end with an ORA-03113 that is not logged on the server.

It could be a client/server compatibility issue. Do these clients all have the same Oracle Net version? If so, what is the version, and can you test with a different version?
 
Hi, I am taking this issue over and following up for Mark. Have you been able to reproduce the issue? I Have also tested with Oracle client installs of 10.1.0.3-5, and 10.2.0.1 with the same issue.
 
It's always a good idea to do the same in SQL*Plus. Run the query and see what happens...

If in SQL*Plus, using the same home (so the Net version), everything is fine, you can blame PLSQLDev, otherwise issue isn't related to PLSQLDev...
 
Does the issue also occur when PL/SQL Developer is set to retrieve all records right away?
(Preferences -> SQL Window -> Records per Page = All records)

Could this be a network-related issue, where hardware/software between the client and server is dropping/throttling data, causing the transfer to become very slow?
 
The issue does not happen in SQL*Plus, which is why I doubt that this is an issue with anything other than PL/SQL Developer. I believe we tested with Oracle's SQL Developer, and the slowness wasn't manifested then either.

And yes, it happens with the all records option set also, as I have that set on my machine, and was able to reproduce the issue immediately.
 
You must log in or register to reply here.
Back
Top