<< 返回文章列表

数据恢复| 深入内核:监听器的工作原理与故障诊断分析

2017年12月26日
熊军
1201

【云和恩墨,提供7*24最专业的数据恢复(Oracle,MySQL,SQL server)服务,致力于为您的数据库系统做最后一道安全防护!服务热线:010-59007017-7030】数据恢复|数据库运维|性能优化|安全保障|Oracle培训|MySQL培训


在Oracle的官方文档《Oracle Database PerformanceTuning Guide》中,《The Oracle Performance Improvement Method—Top Ten Mistakes Found in Oracle Systems》一节对“糟糕的连接管理”做了这样的定义:应用程序与数据库的每一次交互,都要连接数据库后再断开。这个问题常常出现在应用服务器的无状态中间件上,它对性能的影响是巨大的,而且是完全不可伸缩的。这一小段文字也出现在Metalink的858539.1文档中。


还有很多地方提到连接管理的问题。连接管理,也就是应用系统连接到数据库的方式,其中之一就是,是使用长连接还是短连接。这方面在以前我并没有引起重视,甚至可以说是不以为然。因为现在使用Oracle数据库的大型高并发的应用系统,在连接数据库上,一般都使用了连接池,连接管理基本上不存在什么问题。


然而事实证明,我错了。就在前不久,遇上一套系统,Oracle数据库的连接数保持在4000个以上,高峰期高达6000个以上的高并发系统,在业务高峰期,业务人员反映系统速度非常慢。从数据库层面和OS层面的分析来看,与平时相比,没有太大的区别。然而,使用TNSPING检查监听,发现监听的处理速度非常慢,通常需要1秒,甚至有时需要4秒,连接数据库就更慢了。经过诊断,发现其中一个关键的应用居然用的短连接。不幸的是,这个应用连接数据库的速率非常快,而创建一个数据库的连接耗时非常长,闲时都在100ms以上。在业务高峰期,连接数据库的排队非常长,监听(Listener)已经不能够及时处理连接请求,严重影响了系统的性能。最后增加几个监听暂时解决了此问题。


下面将详细介绍这个监听问题的诊断处理过程,以及监听的具体工作方式。


问题诊断分析


先简单地介绍系统的环境:

是运行在HP-UX 11.31下的Oracle 9208。


对这个系统进行各方面的诊断,有如下的结果:

1. 监听采用最简单的配置,也就是没有过多的参数。在配置中使用的是IP地址,而不是主机名。

2. TNSPING测试的结果为1~4s之间。

3. 连接数据库的时间,在1~4s之间。

4. 连接上数据库后,执行SQL正常,SELECT返回大批量数据的速度也正常,数据库中也没有异常的NET方面的等待。

5. 使用操作系统工具PING数据库主机,返回的结果相当快,只有几毫秒,使用ftp传输大文件的速度也非常快。

6. 在数据库主机上使用TNSPING以及通过监听连接数据库,其结果与在客户端机器上一致。但是不通过监听,直接使用sqlplus “/ as sysdba”这样的方式连接数据库,速度非常快。

7. 检查数据库主机/etc目录下的resolv.conf、hosts、nsswitch.conf等配置文件,hosts文件没有问题,而resolv.conf和nsswitch.conf文件不存在。

8. 检查listener.log文件的内容,可以发现连接数据库比较频繁。从Statspack报告中的每秒登录数(Logons/Sec)也可以验证连接的频繁程度。

9. 重新启动监听后,在较短的时间段内,数据库连接速度比较快,但是很快就会回到速度非常慢的状况。检查监听进程的内存使用情况,发现消耗的内存并不多,排除了Oracle 9.2.0.8下“Bug 5576565 - Small listenermemory leak per connection”引起问题的可能。

10. 检查sqlnet.log文件内容,没有发现异常。

上面的各项诊断,所花的时间并不长,但是得到的结果却能够帮助我们缩小搜索故障来源的范围。上面的诊断结果表明,数据库本身没有问题,网络没有问题。那么问题会在哪里?


如果把通过监听连接数据库看作执行一条SQL,那么连接数据库所花的时间,可用响应时间=服务时间+等待时间来计算。这里响应时间为从客户端发起数据库连接到最终连接上数据库所经过的时间,服务时间为从连接过程中监听和Server Process真正处理连接请求所消耗的时间,而等待时间就是在连接过程中排队等待处理的时间。


值得注意的是,由于监听是串行处理的,因此,如果“服务时间”太长,而并发连接很多,那么就会引起排队,也就是产生等待时间。如果监听处理连接的速率低于连接请求的速率,那么排队就会越来越长,客户端连接所需要的排队时间也就越来越长,也就是“等待时间”就会越来越长。这类似于我们在售票窗口买车票,只有一个窗口的时候,如果售票员处理速度比较慢,而买票的人又不停地增加,就会导致买票的人排队越来越长。


从listener.log来看,监听处理一个连接的时间并不是很长,在这个文件中记录的时间戳没有精确到毫秒,平均来看在100ms左右,平均每秒只能处理10个连接。如果每秒的连接数在10个,最理想的情况每个连接请求都没有排队,那么每个连接的时间为100ms左右,然而,如果在某一时刻,有一个突发的连接高峰,将导致产生连接排队,而导致后续的连接请求所花的时间加长。假如连接队列中有10个请求,那么将导致后面的每个请求将需要1100ms左右。


虽然平均每个连接耗时100 ms,相对于其他系统来说,时间偏长,但是也并不算太离谱,毕竟这个时间跟系统的繁忙程度、负载有比较大的关系。那么这个问题,基本上可以判断是连接过于频繁所致。在进一步处理之前,可以通过监听trace或操作系统的truss、tusc等工具来确认监听在处理连接时,没有其他的问题。由于使用truss等工具,跟踪监听进程的系统调用,得到的结果更容易进行分析,因此下面将通过HP-UX上的tusc工具得到的结果,详细介绍监听的连接处理过程,即监听的工作原理。


监听的工作原理

HP-UX下的tusc与AIX、Solaris下的truss、Linux下的strace类似,都是跟踪进程的系统调用的工具。不过在HP-UX下,tusc需要单独下载安装,在http://hpux.connect.org.uk/hppd/hpux/Sysadmin/alpha.html可以下载到最新的版本。


在使用tusc时,首先须通过命令“ps -ef | grep tnslsnr”得到监听进程tnslsnr的进程号(pid)。要注意的是,可能有多个tnslsnr进程,我们所要的是父进程(ppid)为1的监听进程号。在问题诊断时,得到的监听进程号为4595。下面将按下列步骤使用tusc来跟踪这个进程的系统调用。

1.在数据库主机上执行tusc命令:

tusc –T hires –fp 4595 > 1.log

2.在客户端使用sqlplus连接数据库,并得到对应的Server Process的进程号:

SQL> select spid from v$process where addr=(select paddr from v$sessionwhere sid=(select sid from v$mystat where rownum=1));


SPID

------------

19190

3.在数据库主机上按CTRL+C,中止tusc的运行。

在得到的输出文件1.log中,内容格式如下:

( Attached to process4595 ("/oracle/app/oracle/product/9.2.0/bin/tnslsnr LISTENER-inherit") [64-bit] )
1244792894.476963 [4595] read(17, 0x9fffffffffff6950, 64) .....................[sleeping]
1244792894.487425 [4595] read(17, "N T P 0   1 9 1 8 5 \n", 64) ................     = 11
1244792894.488420 [4595] getpid()..............................................     =4595 (1)
1244792894.488498 [4595] fcntl(17, F_SETFD, 1).................................     = 0
1244792894.488735 [4595] write(16, "\0\0\0= ", 4)..............................     = 4
1244792894.489328 [4595] write(16, "( A D D R E S S = ( P R O T O C".., 61) ...     = 61
1244792894.489445 [4595] write(16, "\0\00401", 4)..............................     = 4


从输出可以看到,每一行就是一次系统调用(System Call),可分为5部分,以第1个系统调用为例:

1.1244792894.488735,系统调用完成时的时间戳,以秒为单位,也就是从1970年1月1日0时0分0秒至当前所经过的秒数。

2.[4595],发起系统调用的进程号。

3.Read,系统调用函数名。

4.(17, 0x9fffffffffff6950, 64),系统调用的参数。

5.[sleeping],系统调用的结果。

首先我们从图6-1中来了解一下监听的连接处理过程。


image.png

图6-1  监听的连接处理过程示意图


由图中可以看到,参与连接的共有四个部分。下面简单地介绍一下上面的流程示意图中的各个过程。

1. 首先客户端向监听进程发起数据库连接请求。这个过程又分为两个步骤:

1) 通过三次握手机制建立TCP连接。这一步一般来说比较快,只是在客户端操作系统与监听所在操作系统内核之间的交互过程,不涉及监听进程。这个连接过程之所以很快,实际上是因为操作系统有自己的队列,只要正在发起连接的请求数没有超过队列的大小,就可以迅速完成。针对Oracle监听来说,这个连接队列,由两个参数控制,其一是监听的QUEUESIZE参数,也就是系统调用listen过程的BACKLOG参数;其二是操作系统的内核参数,比如AIX下的SOMAXCONN,HP-UX下的TCP_CONN_REQUEST_MAX等。

2) 监听进程接受客户端的连接。在客户端发起数据库连接请求这一过程中,如果监听进程太忙,则在建立TCP连接之后,要等待一段时间,监听进程才能真正地接受连接请求,监听进程接受连接将使用操作系统调用accept。


2. 监听进程Fork一个子进程,这里我们称为“监听子进程1”,然后等待子进程退出。在这一步中,如果子进程退出之前所耗的时间越长,那么监听等待的时间也越长,在这个等待过程中监听不能做任何其他动作。如果子进程异常,不能退出,监听进程将Hang住。在一个连接频繁的系统上,我们使用ps-ef | greptnslsnr命令看到的父进程不为1的tnslsnr进程,就是这样的子进程。

3. 监听子进程1 Fork一个子进程,这里我们称为“子进程2”。

4. 监听子进程1完成工作,立即结束。监听进程然后又会一直等待,等待什么?这里是等待Oracle Server Process发送数据过来。

5. 子进程2 执行系统调用exec,调用的是oracle这个可执行文件,这样这个子进程2就变更为Oracle Server Process。也就是说,ServerProcess与“子进程2”具有相同的进程号。Server Process进行一些初始化操作。

6. Server Process向监听进程传递一些特定的数据,包括进程号等,典型的数据是“N T P 0  1 9 1 9 0”,这里19190为进程号,每个字符用空格分开。

7. 监听进程向Server Process发送客户端的数据,这个数据用于Server Process验证客户端。然后监听进程向listener.log写入日志。这个时候,监听进程的工作就完成了,继续处理下一个连接请求。

8. Server Process向客户端发送数据,响应客户端的连接。

9. 客户端与ServerProcess之间进行交互,完成连接过程,然后再提交SQL执行真正的工作等。


下面我们结合如上监听处理流程,针对这个故障案例,来看看监听处理过程中是否存在问题。

由于tusc跟踪了监听以及产生的子进程的所有调用,所以在输出的结果中包含了很多进程的系统调用信息,我们要将这些信息按进程分离出来:

grep “\[4595\]” 1.log> 4595.out
grep “\[19190\]” 1.log > 19190.out


4595是监听进程的进程号,19190是客户端连接上数据库后Server Process的进程号(spid)。根据前面的介绍,Server Process会向监听进程发送一组特别的数据,在4595.out中搜索“1 9 1 9 0”(注意字符之间有空格),就可以找到监听处理这个连接的所有调用信息。


下面我们将根据这些调用信息来详细分析监听的处理过程。

1. 监听接受客户端的TCP连接,并获取客户端发过来的TNS数据包,代码如下:

image.png


2.监听进程打开用于与子进程通信的管道,同时Fork一个子进程,也就是前面我们称之为“监听子进程1”的子进程,进程号为19189。然后监听进程一直等待,直到19189这个子进程结束:

image.png


3.在监听进程等待子进程19189结束的同时,子进程19189完成的工作相对比较简单,仅仅是Fork一个子进程,也就是前面称之为“子进程2”的子进程,新的子进程号为19190。子进程19189完成Fork子进程之后,就立即退出。代码如下:

image.png


4.回到监听主进程,监听进程在子进程19189退出后,在管道上读取数据,这是一个会阻塞的操作,只有在管道上读到数据后,才会返回,从下面的信息可以看到,read这个调用阻塞了95ms左右:

image.png


5.监听进程被阻塞的同时,“子进程2”,也就是进程号为19190的进程,通过exec调用,转而成为Oracle Server Process:

image.pngimage.png


6.ServerProcess执行初始化动作,然后向管道中写入数据:

image.png


7.监听进程从管道读到Server Process写来的数据之后,将客户端信息通过管道传递到Server Process,然后关闭管道,写入日志到listener.log中,至此针对此连接请求,监听的处理已经完成,继续处理下一个连接请求:

image.png


8.Server Process与客户端交互,完成剩余的所有工作。


从上面的分析来看,监听处理从1244792894.645890开始,在1244792894.788147结束,如前所述,这两串数字是以秒为单位表示的当前时间。处理这个连接耗时142 ms,不过考虑到使用tusc带来的负荷引起的时间消耗,与100ms相差是不大的。


在实际测试时,特别是TNSPING测试时可以发现,客户端发起连接后,过了比较长的时间,监听才通过accept调用得到客户端连接请求的TCP连接。当然这个过程中监听进程并没有闲着,只不过在忙着处理其他的连接。由此可以看到,客户端连接时,的确是由于连接队列太长,导致要等很长时间才能得到监听进程的处理。也就是数据库连接过于频繁,引起请求队列过长,导致了连接等待时间变得很长。


问题的解决

针对这个监听的问题,解决办法有以下3种:

1.将使用短连接方式的应用,修改为使用连接池方式,这是最根本最彻底的解决方案,但是却须花费很长的时间来修改应用。

2.增加更多的监听,以增加监听处理能力。

3.由于每个连接的处理时间需要100ms左右,时间偏长,进行优化,这个难度太大,短期内不会有效果,同时不一定能成功。

根据系统的实际情况,只能以增加更多的监听来解决问题。


由于系统比较复杂,存在多台应用服务器,每台服务器上又运行了数个不同的模块,而每个模块又可能会有不同的连接数据库的方式。同时还有众多的系统间的接口和一些外部应用连接到数据库上。因此不能简单地增加多个监听就了事,还要定量地分析,是哪些服务器上的哪些应用模块,连接过于频繁。这个可以通过listener.log来进行,然而,我们有更好的方式来分析,那就是使用触发器。通过登录触发器,记录每一个连接的会话信息,包括用户名、IP地址、登录时间等。有了这些信息,就能够很容易地达到目的。


首先建一个表,用于存储用户登录时的会话信息。

代码如下:

create table LOG$INFORMATION

(

   LOGON_TIME TIMESTAMP,

   HOST_NAME VARCHAR2(100),

   USERNAME VARCHAR2(40),

   SCHEMANAME VARCHAR2(40),

   SESSIONUSER VARCHAR2(40),

   IP_ADDRESS VARCHAR2(100)

);


然后我们建一个登录触发器来记录登录时的会话信息:

CREATE OR REPLACE TRIGGER TR_LOGIN_RECORD

 AFTER LOGON ON DATABASE

BEGIN

 INSERT INTO LOG$INFORMATION

 select

   systimestamp,

   sys_context('USERENV','HOST'),

   sys_context('USERENV','CURRENT_USER'),

   sys_context('USERENV','CURRENT_SCHEMA'),

   sys_context('USERENV','SESSION_USER'),

   sys_context('USERENV','IP_ADDRESS')

   from dual;

 COMMIT;

EXCEPTION

 WHEN OTHERS THEN

   NULL;

END;

/


经过一段时间后,我们再来查看记录的数据:

SQL> select host_name,sessionuser,ip_address,count(*)

   from log$information group byhost_name,sessionuser,ip_address

   having count(*)>=100

   order by 4;


HOST_NAME                       SESSIONUSER               IP_ADDRESS          COUNT(*)
---------------------------     -----------------------   --------------    ----------
workf1                          USER1                     192.168.0.86             100
app14                           USER2                     192.168.0.146            102
app9                            USER2                     192.168.0.141            145
app4                            USER2                     192.168.0.74             153
app10                           USER2                     192.168.0.142            171
app3                            USER2                     192.168.0.73             195
app2                            USER2                     192.168.0.72             209
app2                            USER3                     192.168.0.72             329
app4                            USER3                     192.168.0.74             755
app10                           USER3                     192.168.0.142           1086
app1                            USER3                     192.168.0.71            1109
app11                           USER3                     192.168.0.143           1308
app9                            USER3                     192.168.0.141           1579
app14                           USER3                     192.168.0.146           1713
app3                            USER3                     192.168.0.73            2371


为避免泄露客户隐私,已将上面的输出做了处理。


可以看到,某几台服务器连接频率非常高,都是同一个用户。通过开发确认连接频繁的几个应用模块,为每个模块增加单独的监听,修改应用模块的连接配置,这样问题就暂时得到了解决。


总结

本章通过一个监听问题处理案例,介绍了在Linux/Unix下监听的工作原理,同时指出了在频繁的短连接时存在的问题以及如何处理。


虽然本文提到的监听问题,暂时得到了解决。但根本上还是要从应用入手,使用连接池和长连接。一方面多个监听会增加维护的复杂度,另一方面,也是最重要的方面,连接数据库的开销非常大,特别是对dedicated server方式连接更是如此,使SQL的执行效率变得非常低,比如一个SQL可能只要执行10ms,结果连接数据库就花了100ms。


因此,数据库连接管理,也非常值得我们重视。