oracle DCD

November 12th, 2008

Goto comments

Leave a comment DCD是Dead Connection Detection的缩写，用于检查死掉但没有断开的session。

在server端的sqlnet.ora文件中设置SQLNET.EXPIRE_TIME这一参数可以启用这一功能

SQLNET.EXPIRE_TIME ＝ 20

可以设置为任意数值，单位为分钟。

当新连接建立的时候，会读取sqlnet.ora中的这一设定，当20分钟间隔到达时，对inactive的session发送”probe” SQL*NET packet来确认client是否活着。如果已经死掉，那么相对应的resource会被自动清除。

DCD可以用于防止防火墙的timeout。

如果client和server中间有防火墙，防火墙设有timeout参数，例如设置为一个小时，当一个小时中client和server间没有数据传输的时候，防火墙会断开连接。开启DCD后，通过设置SQLNET.EXPIRE_TIME的值小于防火墙的timeout参数可以避免这一情况。“probe” package确保防火墙不会断开idle的session。

但是最近我遇到一种情况就是当client发出一个大的查询，在server端是active的状态，但是timeout时间段没有数据传输回client端，比方说做一个大的hash join，group by，或者sort。 这种情况下，一开始我猜想server认为其是active的状态，不会发送packet到client端，而防火墙认为两者间没有网络传输，到了timeout的时间直接就切断了连接(后来证明该猜想是不正确的)。server trace到的一些异常信息为：

WAIT #1: nam=’enqueue’ ela= 1533 p1=1347616774 p2=1 p3=2

WAIT #1: nam=’SQL*Net break/reset to client’ ela= 67 p1=1413697536 p2=0 p3=0

WAIT #1: nam=’SQL*Net break/reset to client’ ela= 2 p1=1413697536 p2=1 p3=0

WAIT #1: nam=’SQL*Net break/reset to client’ ela= 21 p1=1413697536 p2=0 p3=0

WAIT #1: nam=’SQL*Net break/reset to client’ ela= 1 p1=1413697536 p2=1 p3=0

WAIT #1: nam=’SQL*Net break/reset to client’ ela= 14 p1=1413697536 p2=0 p3=0

WAIT #1: nam=’SQL*Net break/reset to client’ ela= 1 p1=1413697536 p2=1 p3=0

WAIT #1: nam=’SQL*Net break/reset to client’ ela= 15 p1=1413697536 p2=0 p3=0

WAIT #1: nam=’SQL*Net break/reset to client’ ela= 1 p1=1413697536 p2=1 p3=0

WAIT #1: nam=’SQL*Net break/reset to client’ ela= 16 p1=1413697536 p2=0 p3=0

WAIT #1: nam=’SQL*Net break/reset to client’ ela= 1 p1=1413697536 p2=1 p3=0

FATAL ERROR IN TWO-TASK SERVER: error = 12152

*** 2008-11-10 21:56:38.738

ksedmp: internal or fatal error

ORA-01013: user requested cancel of current operation

我想到的解决办法大致有以下几种：

1. 修改Query的执行计划，使其结果能够立即输出，在我遇到的case中，我使用nest loop来代替hash join，这样的话能够确保timeout时间内有数据传输，并且修改计划后大大加快了执行速度。对于group by和sort的情况可以把数据pull到client上做group或者sort的操作。

2. split query使其能够在timeout时间段内完成。

3. 在server端直接跑出结果，然后从client端直接抓取结果集。

4. 修改防火墙timeout参数，使其大于query的执行时间

经过后来的一些实验，证明开始的猜想是不正确的。实验中expired_time设置为20分钟，下面是truss server process的结果

truss command: “truss -r all -w all -aefd -o dcd_truss.log -p “

head -100 dcd_truss.log

Base time stamp: 1227249877.0673 [ Thu Nov 20 23:44:37 GMT 2008 ]

16244: psargs: oracleGBCUST9 (DESCRIPTION=(LOCAL=NO)(SDU=8192))

16244: read(15, 0×103803DC6, 2064) (sleeping…)

16244: 1168.4591 Received signal #14, SIGALRM, in read() [caught]

16244: 1168.4594 read(15, 0×103803DC6, 2064) Err#91 ERESTART

16244: 1168.4596 lwp_sigmask(SIG_SETMASK, 0×9FBFF057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 1168.4597 lwp_sigmask(SIG_SETMASK, 0×9FBFF057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 1168.4598 lwp_sigmask(SIG_SETMASK, 0×9FBFF057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 1168.4599 setitimer(ITIMER_REAL, 0xFFFFFFFF7FFFB138, 0×00000000) = 0

16244: 1168.4600 lwp_sigmask(SIG_SETMASK, 0×9FBFD057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 1168.4601 lwp_sigmask(SIG_SETMASK, 0×9FBFF057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 1168.4602 setitimer(ITIMER_REAL, 0xFFFFFFFF7FFFB498, 0×00000000) = 0

16244: 1168.4603 lwp_sigmask(SIG_SETMASK, 0×9FBFD057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 1168.4604 setitimer(ITIMER_REAL, 0xFFFFFFFF7FFFB7B8, 0×00000000) = 0

16244: 1168.4605 lwp_sigmask(SIG_SETMASK, 0×9FBFD057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 1168.4606 setcontext(0xFFFFFFFF7FFFB6C0)

16244: read(15, 0×103803DC6, 2064) (sleeping…)

16244: 2368.4691 Received signal #14, SIGALRM, in read() [caught]

16244: 2368.4694 read(15, 0×103803DC6, 2064) Err#91 ERESTART

16244: 2368.4696 lwp_sigmask(SIG_SETMASK, 0×9FBFF057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 2368.4697 lwp_sigmask(SIG_SETMASK, 0×9FBFF057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 2368.4698 getpid() = 16244 [1]

16244: 2368.4700 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10 - this indicates a write of DCD package

16244: 2368.4704 lwp_sigmask(SIG_SETMASK, 0×9FBFF057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 2368.4705 setitimer(ITIMER_REAL, 0xFFFFFFFF7FFFB138, 0×00000000) = 0

16244: 2368.4706 lwp_sigmask(SIG_SETMASK, 0×9FBFD057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 2368.4707 lwp_sigmask(SIG_SETMASK, 0×9FBFF057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 2368.4708 setitimer(ITIMER_REAL, 0xFFFFFFFF7FFFB498, 0×00000000) = 0

16244: 2368.4710 lwp_sigmask(SIG_SETMASK, 0×9FBFD057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 2368.4711 setitimer(ITIMER_REAL, 0xFFFFFFFF7FFFB7B8, 0×00000000) = 0

16244: 2368.4712 lwp_sigmask(SIG_SETMASK, 0×9FBFD057, 0×0000FFF7) = 0xFFBFFEFF [0x0000FFFF]

16244: 2368.4713 setcontext(0xFFFFFFFF7FFFB6C0)

而从这以后，都是每20分钟写一次DCD package

16244: 2368.4700 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 3568.4800 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 4768.4900 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 5968.5000 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 7168.5101 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 8368.5201 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 9568.5303 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 10768.5402 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 11968.5501 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 13168.5502 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 14368.5601 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 15568.5700 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 16768.5804 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 17968.5901 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 19168.6102 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

16244: 20368.6201 write(15, “\0\n\0\006\0\0\0\0\0″, 10) = 10

从结果中看出，第一次1168s(加上开启session和truss之间大约32s的延迟，1200 seconds=20 minutes)的时候并没有写DCD package，而是在2368秒，也就是40分钟的时候第一次写DCD package，也就是说expired_time只有小于FW timeout的二分之一的时候才会发生作用。当FW timeout设定为30分钟，而DCD expired time设置为20分钟时，仍然会有timeout出现，将FW timeout时间从30分钟改为1个小时，该问题被彻底解决。

检测DCD是否打开和运行正常最好的方法就是 产生一个服务跟踪文件, 查找 DCD探测包.

要产生一个服务跟踪文件, 在sqlnet.ora文件中设置TRACE_LEVEL_SERVER=16,

TACE_DIRECTORY_SERVER=;

跟踪文件svr_;

.trc文件会在那个目录下产生.