【案例分享4】event "single-task message" and DB_LINK
http://dbakevin.blogspot.mx/2012/04/event-single-task-message-and-dblink.htmlGot one task, need to execute one script in DB.
Before execution, i went through the script once.
The script is simple, only create synonyms and grant privileges.
But soon i encountered some trouble, the script hung a long time at creating its first Synonym.
It costed 10+ minutes to create one synonym！
No enqueue, latch, row cache lock, shared pool, library cache lock/pin contention are found in the DB during that period.
Below is from v$session when the session is hang:
SSID SERIAL# OSUSER USERNAME
----------------------------------- --------------- --------MACHINE LOGON_TIME STATE
----------------------------------- --------------- ---------、
STATUS SQL_ID
----- ---------- ---------- -------------------- ----------------
EVENT SECONDS_IN_WAITWAIT_TIME BLOCKING_SESSION PROGRAM
----------------------------------- --------------- ----------
878 35556 oracle SYS tnsp02331
10-APR-12：04:29 WAITING
ACTIVE 8fw67w96t0d6t
single-task message 134 0 sqlplus@tnsp02331 (TNS V1-V3)
We can see from the red part the session was waiting for an unnormal event"single-task message".
I traced the session, from below tkprof output we can clearly see that create one synonym cost more then 400+ seconds.
********************************************************************************
SQL ID: 8fw67w96t0d6t
Plan Hash: 0
create or replace public synonym UPDATE_B2B_VEH_STATUS_OBJID for
GETS_DW_IDW.UPDATE_B2B_VEH_STATUS_OBJID
call count cpu elapsed disk query current rows
------- -------------- ---------- ---------- ---------- --------------------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.07 439.21 17 78 2 0
Fetch 0 0.00 0.00 0 0 0 0
------- -------------- ---------- ---------- ---------- --------------------
total 1 0.07 439.21 17 78 2 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Elapsed times include waiting on following events:
Event waited on Times Max. WaitTotal Waited
---------------------------------------- Waited----------------------
log file sync 1 0.10 0.10
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
Below is from the 10046 raw trace:
tnsp02331_tsdwhsp2>cat tsdwhsp2_ora_29218.trc|grep single-task
WAIT #0: nam='single-task message' ela= 219438260 p1=0 p2=0 p3=0 obj#=108 tim=9691451515850
WAIT #0: nam='single-task message' ela= 219460416 p1=0 p2=0 p3=0 obj#=108 tim=9691670988676
WAIT #0: nam='single-task message' ela= 219426821 p1=0 p2=0 p3=0 obj#=108 tim=9691890784783
.........
.........
We can see most time used at waiting event 'single-task message'.
Searched on google and metalink, didn't find much useful information, and most articles indicate this event as some Oracle's bug.
Below is Oracle's definition of the event:
single-task message:When running single task, this event indicates that the session waits for the client side of the executable.
Since i was execute the script from local machine via sqlplus, then where is the "the client side of the executable" came from?
Till now very naturally we should consider weather this "the client side" somehow might be related to db link?
Let's check.
The synonym is build on below procedure:
SQL> select owner,object_name,object_type,status,last_ddl_timefrom dba_objects where owner='GETS_DW_IDW' and object_name='UPDATE_B2B_VEH_STATUS_OBJID';
OWNER OBJECT_NAME OBJECT_TYPE STATUS LAST_DDL_TIME
--------------- -------------------- -------------------- --------------------- -------------------
GETS_DW_IDW UPDATE_B2B_VEH_STATU PROCEDURE INVALID 2012-04-10 06:42:33
It is INVALID now since some base objects were missed:
SQL> select REFERENCED_OWNER,REFERENCED_NAME,REFERENCED_TYPE,DEPENDENCY_TYPE from DBA_DEPENDENCIES whereOWNER='GETS_DW_IDW' and NAME='UPDATE_B2B_VEH_STATUS_OBJID'
2;
REFERENCEDREFERENCED_NAME REFERENCED_TYPE DEPENDENCY_T
----------- -------------------- ------------------- -------------
SYS STANDARD PACKAGE HARD
PUBLIC EOA_B2B_VEH_STATUS NON-EXISTENT HARD
GETS_DW_IDW EOA_B2B_VEH_STATUS NON-EXISTENT HARD
Let's try to compile the procedure:
SQL> set timing on
SQL> alter procedure GETS_DW_IDW.UPDATE_B2B_VEH_STATUS_OBJID compile;
alter procedure GETS_DW_IDW.UPDATE_B2B_VEH_STATUS_OBJID compile
*
ERROR at line 1:
ORA-04052: error occurred when looking up remote object SA.GETS_IDW_RMD_LOAD@EOA_DB.WORLD
ORA-00604: error occurred at recursive SQL level 1
ORA-12532: TNS:invalid argument
Elapsed: 00:14:17.60
Even recompile this procedure cost 14 minutes. And this procedure do related to DB link.
But how can a db link making recompiling a procedure costing so long time?
Below is the definition of the db link:
SQL> select HOST from dba_db_links where DB_LINK='EOA_DB.WORLD';
HOST
----------------
tsrdprd1
Let's check the TNS entry:
SQL> ho tnsping tsrdprd1
TNS Ping Utility for Solaris: Version 11.1.0.7.0 - Production on 10-APR-2012 07:08:49
Copyright (c) 1997, 2008, Oracle.All rights reserved.
Used parameter files:
Used TNSNAMES adapter to resolve the alias
Attempting to contact (DESCRIPTION = (ADDRESS_LIST = (ADDRESS = (COMMUNITY = TCP) (PROTOCOL = TCP) (Host = getsrmddb.corporate.ge.com) (Port = 1521))) (CONNECT_DATA = (SID = TSRDPRD1)))
---hang ten minutes there, and then report:
TNS-12532: TNS:invalid argument
We can see that tnsping cost 10 minutes, which means, in our issue the most of waiting time was waiting for db link timeout.
The timeout is controled by TCP/IP protocal, so Unfortunately there is no way we can turn it at oracle level.
Now let's review the definition of that event again:
single-task message:When running single task, this event indicates that the session waits for the client side of the executable.
It should make sense to all of us now.And the solution is simple.Either correct or drop the issue DB LINK.
感谢kevin.zhang的精典案例分析，学习如何发现并解决问题的思路。
页:
[1]