Re: ORA-03135 running plsql locally
- From: mike boligan <mboligan@xxxxxxxxx>
- To: tim@xxxxxxxxx
- Date: Thu, 11 Oct 2012 12:39:28 -0700 (PDT)
Tim,
No worries for the late response, good advice is always useful....
I did check in the alert log for the 3136 error and was only able to find it at
startup of the database, which I suspect is tied to all the the disks not being
mounted by the time the db comes up.
There was nothing in the memory tables, I did get data as you suggested
when changing to the dba_ table. I pasted the results below, sorry for the
poor formatting.
The thing that sticks out to me is the first line of the results of the last
query. Waited for 246,614 milliseconds (?) on db file sequential read with a
blkstate of "NO HOLDER" (not really sure what the means, the docs just list
the domain of values, not the meaning, background process maybe?). Not sure if
there is enough information to figure this out now, but I will be ready next
time anyway.
I also checked all of those in_ columns in the view and the only one that was Y
was in_sql_execution.
SQL_ID CNT TIME_WAITED
------------- -------- ------------
3vcuyr8dbrf2p 3 0
1 row selected.
Elapsed: 00:00:00.94
SQL>
SQL> select event,
2 count(*) cnt,
3 sum(decode(session_state, 'ON CPU', wait_time,
4 time_waited))/1000000 time_waited
5 -- from gv$active_session_history
6 from dba_hist_active_sess_history
7 where sample_time >= to_date('03-OCT-2012 05:40:00','DD-MON-YYYY
HH24:MI:SS')
8 and sample_time < to_date('03-OCT-2012 05:40:59', 'DD-MON-YYYY
HH24:MI:SS')
9 group by event
10 order by time_waited desc;
EVENT CNT TIME_WAITED
------------------------------ -------- ------------
db file sequential read 1 0
2 0
2 rows selected.
Elapsed: 00:00:00.03
SQL>
SQL> select event,
2 sql_id,
3 count(*) cnt,
4 sum(decode(session_state, 'ON CPU', wait_time,
5 time_waited))/1000000 time_waited
6 -- from gv$active_session_history
7 from dba_hist_active_sess_history
8 where sample_time >= to_date('03-OCT-2012 05:40:00','DD-MON-YYYY
HH24:MI:SS')
9 and sample_time < to_date('03-OCT-2012 05:40:59', 'DD-MON-YYYY
HH24:MI:SS')
10 group by event, sql_id
11 order by time_waited desc;
EVENT SQL_ID CNT TIME_WAITED
------------------------------ ------------- --------
------------
db file sequential read 3vcuyr8dbrf2p 1 0
3vcuyr8dbrf2p 2 0
2 rows selected.
SQL>
SQL> select e.object_name || decode(e.object_name,'','','.') ||
2 e.procedure_name entry_name,
3 p.object_name || decode(p.object_name,'','','.') ||
4 p.procedure_name name,
5 x.sql_id,
6 x.sql_plan_hash_value,
7 x.module,
8 x.event,
9 x.time_waited,
10 x.cnt
11 from dba_procedures e,
12 dba_procedures p,
13 (select plsql_entry_object_id,
14 plsql_entry_subprogram_id,
15 plsql_object_id,
16 plsql_subprogram_id,
17 module,
18 sql_id,
19 sql_plan_hash_value,
20 event,
21 sum(decode(session_state, 'ON CPU', wait_time,
time_waited))/1000000 time_waited,
22 count(*) cnt
23 -- from gv$active_session_history
24 from dba_hist_active_sess_history
25 where sample_time >= to_date('03-OCT-2012 05:40:00','DD-MON-YYYY
HH24:MI:SS')
26 and sample_time < to_date('03-OCT-2012 05:40:59', 'DD-MON-YYYY
HH24:MI:SS')
27 group by plsql_entry_object_id,
28 plsql_entry_subprogram_id,
29 plsql_object_id,
30 plsql_subprogram_id,
31 module,
32 sql_id,
33 sql_plan_hash_value,
34 event) x
35 where e.object_id (+) = x.plsql_entry_object_id
36 and e.subprogram_id (+) = x.plsql_entry_subprogram_id
37 and p.object_id (+) = x.plsql_object_id
38 and p.subprogram_id (+) = x.plsql_subprogram_id
39 order by 7 desc, 1, 2, 3, 4;
Entry
Package.procedure Package.procedure
SQL_ID SQL_PLAN_HASH_VALUE
MODULE
EVENT TIME_WAITED
----------------------------------- -------------------------------
------------- -------------------
--------------------------------------------------
------------------------------ ------------
CNT
--------
PROCESS_PKG.MAIN
3vcuyr8dbrf2p 2528273879
SQL*Plus db file sequential
read 0
1
PROCESS_PKG.MAIN
3vcuyr8dbrf2p 2528273879
SQL*Plus
0
2
2 rows selected.
SQL>
SQL> select sample_time,
2 session_id||'.'||session_serial# sid,
3 session_state state,
4 decode(session_state, 'ON CPU', wait_time, time_waited)
time_waited,
5 blocking_session||'.'||blocking_session_serial# blksid,
6 blocking_session_status blkstate,
7 user_id,
8 sql_id,
9 module,
10 event,
11 p1, p2, p3,
12 action
13 -- from gv$active_session_history
14 from dba_hist_active_sess_history
15 where sample_time >= to_date('03-OCT-2012 05:40:00','DD-MON-YYYY
HH24:MI:SS')
16 and sample_time < to_date('03-OCT-2012 05:40:59', 'DD-MON-YYYY
HH24:MI:SS')
17 order by sample_time;
SAMPLE_TIME SID STATE TIME_WAITED BLKSID
BLKSTATE USER_ID SQL_ID
MODULE EVENT
-------------------------- ---------- ---------- ------------ ----------
---------- ---------- -------------
--------------------------------------------------
------------------------------
P1 P2 P3 ACTION
---------- ---------- ---------- ----------------------------------------
03-OCT-12 05.40.00.284 AM 163.59695 WAITING 246,614 . NO
HOLDER 76 3vcuyr8dbrf2p
SQL*Plus db file sequential read
6 2438632 1
03-OCT-12 05.40.10.295 AM 163.59695 ON CPU 233 . NOT IN
WAI 76 3vcuyr8dbrf2p SQL*Plus
T
6 2440714 1
03-OCT-12 05.40.20.299 AM 163.59695 ON CPU 275 . NOT IN
WAI 76 3vcuyr8dbrf2p SQL*Plus
T
6 2442871 1
3 rows selected.
Thanks,
Mike
--- On Thu, 10/11/12, Tim Gorman <tim@xxxxxxxxx> wrote:
From: Tim Gorman <tim@xxxxxxxxx>
Subject: Re: ORA-03135 running plsql locally
To: oracle-l@xxxxxxxxxxxxx
Date: Thursday, October 11, 2012, 12:23 PM
Mike,
Sorry for late response, hope I'm not entering this thread too late...
This error is a database issue (not a network issue) having to do with
establishing a connection, so it can happen regardless of whether you
are connecting via a network, via IPC, or even BEQ. This is not the
termination of an established connection (which would be ORA-03113 or
ORA-03114), but a connection that never happened. Chances are good
someone has been fiddling with the SQLNET.ORA parameter
INBOUND_CONNECT_TIMEOUT (default 60 secs) with the only result that it
takes longer for you to get the error. Increasing a timeout rarely
resolves anything, but instead masks the problem, as is likely the case
here.
When a connection is being established, several SQL statements are run
as SYS before authentication and authorization are complete and the
session connects as the requested user account. During this time, while
these SQL statements against the Oracle data dictionary are being run,
the same kind of contention or blocking can occur which might happen to
any SQL statement.
In your "alert.log" files are logged ORA-03136 error messages which
correspond to the ORA-03135 messages that your shell script (and likely
other end-user programs). The only useful thing about these logged
ORA-03136 error messages is their timestamp. Please use that timestamp
to query into the Active Session History views using a SQL*Plus script
similar to the following...
set echo on feedback on timing on pagesize 100 linesize 200 trimout
on trimspool on tab off
col sample_time format a26
col day format a12
col min_sample_time format a5
col max_sample_time format a5
col inst# format 9990
col sid format a10
col state format a10
col blksid format a10
col blkstate format a10
col time_waited format 999,999,990
col event format a30
col plsql_entry_object_id format 999990
col plsql_entry_subprogram_id format 999990
col plsql_object_id format 999990
col plsql_subprogram_id format 999990
col program format a30
col module format a50
col action format a40
col entry_owner format a6 heading "Entry|Owner"
col entry_name format a35 heading "Entry|Package.procedure"
col owner format a6 heading "Owner"
col name format a31 heading "Package.procedure"
col cnt format 999,990
col duration format a20
spool ashq
clear breaks computes
select sql_id,
count(*) cnt,
sum(decode(session_state, 'ON CPU', wait_time,
time_waited))/1000000 time_waited
from gv$active_session_history /* dba_hist_active_sess_history */
where sample_time >= to_date('xxxxx','DD-MON-YYYY HH24:MI:SS')
and sample_time < to_date('yyyyy', 'DD-MON-YYYY HH24:MI:SS')
group by sql_id
order by time_waited desc;
select event,
count(*) cnt,
sum(decode(session_state, 'ON CPU', wait_time,
time_waited))/1000000 time_waited
from gv$active_session_history /* dba_hist_active_sess_history */
where sample_time >= to_date('xxxxx','DD-MON-YYYY HH24:MI:SS')
and sample_time < to_date('yyyyy', 'DD-MON-YYYY HH24:MI:SS')
group by event
order by time_waited desc;
select event,
sql_id,
count(*) cnt,
sum(decode(session_state, 'ON CPU', wait_time,
time_waited))/1000000 time_waited
from gv$active_session_history /* dba_hist_active_sess_history */
where sample_time >= to_date('xxxxx','DD-MON-YYYY HH24:MI:SS')
and sample_time < to_date('yyyyy', 'DD-MON-YYYY HH24:MI:SS')
group by event, sql_id
order by time_waited desc;
select e.object_name || decode(e.object_name,'','','.') ||
e.procedure_name entry_name,
p.object_name || decode(p.object_name,'','','.') ||
p.procedure_name name,
x.sql_id,
x.sql_plan_hash_value,
x.module,
x.event,
x.time_waited,
x.cnt
from dba_procedures e,
dba_procedures p,
(select plsql_entry_object_id,
plsql_entry_subprogram_id,
plsql_object_id,
plsql_subprogram_id,
module,
sql_id,
sql_plan_hash_value,
event,
sum(decode(session_state, 'ON CPU', wait_time,
time_waited))/1000000 time_waited,
count(*) cnt
from gv$active_session_history /*
dba_hist_active_sess_history */
where sample_time >= to_date('xxxxx','DD-MON-YYYY HH24:MI:SS')
and sample_time < to_date('yyyyy', 'DD-MON-YYYY HH24:MI:SS')
group by plsql_entry_object_id,
plsql_entry_subprogram_id,
plsql_object_id,
plsql_subprogram_id,
module,
sql_id,
sql_plan_hash_value,
event) x
where e.object_id (+) = x.plsql_entry_object_id
and e.subprogram_id (+) = x.plsql_entry_subprogram_id
and p.object_id (+) = x.plsql_object_id
and p.subprogram_id (+) = x.plsql_subprogram_id
order by 7 desc, 1, 2, 3, 4;
select sample_time,
session_id||'.'||session_serial# sid,
session_state state,
decode(session_state, 'ON CPU', wait_time, time_waited)
time_waited,
blocking_session||'.'||blocking_session_serial# blksid,
blocking_session_status blkstate,
user_id,
sql_id,
module,
event,
p1, p2, p3,
action
from gv$active_session_history /* dba_hist_active_sess_history */
where sample_time >= to_date('xxxxx','DD-MON-YYYY HH24:MI:SS')
and sample_time < to_date('yyyyy', 'DD-MON-YYYY HH24:MI:SS')
order by sample_time;
spool off
set echo off feedback 6 timing off linesize 130 tab on
...where the date/timestamp value of "xxxxx" is about 30-60 seconds
prior to one or more of the timestamps of the ORA-03136 error(s) in the
alert.log, and the date/timestamp value of "yyyyy" is about 10-20
seconds after that timestamp.
So, if you have a bunch of ORA-03136 errors logged on 02-OCT 2012 at
15:35:17, 15:35:22, 15:35:27, then you might want to replace "xxxxx"
with the value of "02-OCT-2012 15:34:00" and "yyyyy" with the value of
"02-OCT-2012 15:35:40", or something like that.
In the FROM clauses of each of the queries above, you'll notice that
GV$ACTIVE_SESSION_HISTORY is used, while DBA_HIST_ACTIVE_SESS_HISTORY is
commented out. If your queries return no rows for the requested
SAMPLE_TIME values, then it means that the data has been rolled out of
the memory-based GV$ view and is now stored in the table-based DBA_HIST
view. The data in the GV$ view is much more granular (i.e. 1-second
samples) so the information there is more useful, but retained for a
shorter period of time. The data in the table-based DBA_HIST views is a
little less granular (i.e. 10-second samples), but it is still quite
useful for diagnosing problems like these.
Good luck and please feel free to share your findings with the list as
you go? The causes of the problem might be quite subtle and require
more data gathering, and I don't want to influence your investigations
by suggesting possible causes. It is more useful to go where the ASH
data leads, rather than trying to force a conclusion.
Good luck!
Thanks!
--
Tim Gorman
consultant -> Evergreen Database Technologies, Inc.
postal => PO Box 352151, Westminster CO 80035
website => http://www.EvDBT.com/
email => Tim@xxxxxxxxx
mobile => +1-303-885-4526
fax => +1-303-484-3608
Lost Data? => http://www.ora600.be/ for info about DUDE...
On 10/7/2012 5:08 AM, David Roberts wrote:
> In this scenario It appears that the 'server side process' has failed,
> although that isn't always true.
> I suggest that you inspect the alert log and the dump directories to see if
> there are logs/dumps from the appropriate time that you can pass onto
> Oracle support or us for interpretation.
>
> Dave
>
> On Wed, Oct 3, 2012 at 8:18 PM, mike boligan <mboligan@xxxxxxxxx> wrote:
>
>> Hi,
>> I am running Oracle 11.2.0.2.0 64 bit on Solaris 10. I have a process
>> that runs on the database server and calls a plsql package via a shell
>> script like so:
>>
>> sqlplus user/pass @scriptname parm1 parm2
>>
>> The package runs for roughly 2600 seconds and sometimes gets a ORA-03135.
>> The package does not fail in the same spot every time. It does not seem to
>> fail after x minutes either. I do have sqlnet.expire_time in sqlnet.ora
>> on the server, not sure that helps any as this should be using IPC. I do
>> see alot of log switching while the job runs, but I don't see how the
>> increased activity could cause this error.
>>
>> Maybe I am missing something, but I don't think I should get this error
>> when running a script locally on the database server. Has anyone ever seen
>> a similar situation or fill me in on anything I am overlooking? I am
>> trying avoid a sqlnet trace because of space concerns on where the output
>> would go.
>>
>> TIA,
>> Mike
>>
>> --
>> //www.freelists.org/webpage/oracle-l
>>
>>
>>
>
> --
> //www.freelists.org/webpage/oracle-l
>
>
>
>
>
--
//www.freelists.org/webpage/oracle-l
--
//www.freelists.org/webpage/oracle-l
Other related posts:
