【案例分享4】event "single-task message" and DB_LINK

http://dbakevin.blogspot.mx/2012/04/event-single-task-message-and-dblink.html

Got 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_WAIT  WAIT_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. Wait  Total 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[oracle]_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_time  from 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 where  OWNER='GETS_DW_IDW' and NAME='UPDATE_B2B_VEH_STATUS_OBJID'
  2  ;
REFERENCED  REFERENCED_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

写了 32 篇文章,拥有财富 308,被 10 人关注

转播转播 分享分享 分享淘帖
回复

使用道具

P4 | 发表于 2012-4-14 00:05:34
感谢kevin.zhang的精典案例分析,学习如何发现并解决问题的思路。
回复

使用道具

您需要登录后才可以回帖 登录 | 加入社区

本版积分规则

意见
反馈