1. 概述
XXX年X月XX日,由联通总控发出两次超时告警信息,这次对日志分析查看是否当时存在Tuxedo队列排队、Tuxedo服务异常终止或者繁忙时是否有Tuxedo服务自动增长等。
2. 日志分析结果
日志中主要有以下错误:
103356.crmapp1!BBL.23218.1.0: LIBTUX_CAT:541: WARN: Server GRPCSCRM1/4022 terminated
103356.crmapp1!TMSYSEVT.29334.1.0: LIBTUX_CAT:1477: ERROR: .SysServerDied: qcscrm1l2server, group GRPCSCRM1, id 4022 server died
103356.crmapp1!BBL.23218.1.0: LIBTUX_CAT:557: INFO: Server GRPCSCRM1/4022 being restarted
103356.crmapp1!TMSYSEVT.29334.1.0: LIBTUX_CAT:1476: ERROR: .SysServerRestarting: qcscrm1l2server, group GRPCSCRM1, id 4022 server restarting
上述日志内容是GRPCSCRM1组的id为4021的服务被异常终止,然后该服务被自动重启,而其他的日志为TMSYSEVT服务的报告结果,主要为监控系统使用,查看被异常终止的服务的结果为:
tuxapp1 26039 1 255 14:21:57 pts/7 0:31 qcscrm1l2server -C dom=ubss -g 300 -i 4021 -u crmapp1 -U /ngbss/tuxapp1/log/ulog -m 0 -A -p 1,30:2,30 -- -T
查看异常终止的原因,查看是否生成core文件:
tuxapp1@crmapp1[/ngbss/tuxapp1/bin]$ls -l | grep core
-rw------- 1 tuxapp1 ngbss 941425584 Jan 29 10:32 core
显示在10点32分生成了core文件,查看该core所属进程:
tuxapp1@crmapp1[/ngbss/tuxapp1/bin]$file core
core: ELF-64 core file - IA64 from 'qcscrm1l2server' - received SIGSEGV
显示生成的core文件与日志中被重启服务是同一个即qcscrm1l2server,显示异常终止的原因是被操作系统发出的SIGSEGV信号终止。
下面解释一下SIGSEGV信号,在POSIX兼容的平台上,SIGSEGV是当一个进程执行了一个无效的内存引用,或发生段错误时发送给它的信号,在一个程序接收到SIGSEGV时的默认动作是异常终止。
也就是说进程执行到一个操作时,进行操作的指针是一个空指针或者操作一个数组时发生了段错误等。下面具体查看是哪里出现问题。
tuxapp1@crmapp1[/ngbss/tuxapp1/bin]$gdb qcscrm1l2server core
HP gdb 6.1 for HP Itanium (32 or 64 bit) and target HP-UX 11iv2 and 11iv3.
Copyright 1986 - 2009 Free Software Foundation, Inc.
Hewlett-Packard Wildebeest 6.1 (based on GDB) is covered by the
GNU General Public License. Type "show copying" to see the conditions to
change it and/or distribute copies. Type "show warranty" for warranty/support.
..
Core was generated by `qcscrm1l2server'.
Program terminated with signal 11, Segmentation fault.
SEGV_MAPERR - Address not mapped to object
warning: Load module /oracle/app/oracle/product/10.2.0/lib/libnnz10.so has been stripped.
Debugging information is not available.
warning: No unwind information found.
Skipping this library /bea/tuxedo/tuxedo10gR3/lib/libticudata.sl.36.
#0 0xc00000001dd1a950:0 in __rw::__string_ref<char,std::char_traits<char>,std::allocator<char> >::__references (this=0xffffffffffffffe0)
at /opt/aCC/include_std/rw/string_ref:237
237 return __string_ref_rep<_Allocator>::__refs_+1;
请具体查看上述标注的代码,查看是否有空指针或者数据越界等情况。
而上述问题出现频率并不频繁,并不是引起超时的主要原因。
3.超时问题分析及建议
在实际生产中,发生服务请求超时的原因很多,下面结合现场情况,具体分析:
1、当请求执行时间较长长时,会导致服务超时,而如果一个队列中的一个或几个服务发生这种情况会导致队列中的请求排队,从而引起较多的服务超时现象。对于这种情况在服务器条件允许的条件下建议将引经常排队的服务初始值调大,如从5调到7。
2、爆发性的请求量突增,也就是在某一个时间点有超过服务数几倍的请求到来时,会造成服务超时,当时队列肯定存在短时间的排队,在这段时间内服务进程执行正常,每一个请求都可以顺利完成但是当后续的请求排队的时间加上执行请求的时间有可能会导致部分请求超时,直到将队列中的请求执行完成,而通常这段时间比较短并不会触发Tuxedo配置的自增长特性。
注:现场的所有Tuxedo服务的自增长特性的触发条件是30s内队列的请求数超过2时,Tuxedo系统启动新的进程来缓解队列中的压力。
以上两种原因对于实时性比较严格的服务来说是比较容易出现超时的,主要的手段是优化代码或者增加服务数来缓解。
3、队列中的服务进程中的一个或者多个进程hang,导致队列中能够正常执行请求的服务进程hang,而在稍微有些压力的时刻就会导致队列排队过多,导致超时的发生。但是最近并没出现这种问题,在前一段时间发生过。
建议:1、在数据库和主机条件允许的条件下,将经常出现排队的队列的服务进程初始值增加例如从5调到7,并重新编译配置文件后启动Tuxedo。下面列出经常出现排队的队列名:qcscrm2l3、qcscrm1l2、qcscrm3l3、qcscrm2l2、qcscrm4l2,从长期的工作中所有以qcscrm开头的队列均是请求数较多的队列。
下面以qcscrm1l2为例,如何修改初始值。
直接搜索qcscrm1l2关键字,找到RQADDR=’qcscrm1l2’列,如下:
"qcscrm1l2server" SRVGRP="GRPCSCRM1" SRVID=4020
CLOPT="-A -p 1,30:2,30 -- -T"
RQADDR="qcscrm1l2"
RQPERM=0666 REPLYQ=Y RPPERM=0666 MIN=5 MAX=10 CONV=N
SYSTEM_ACCESS=FASTPATH
MAXGEN=5 GRACE=3600 RESTART=Y
MINDISPATCHTHREADS=0 MAXDISPATCHTHREADS=1 THREADSTACKSIZE=0
SICACHEENTRIESMAX="500"
修改MIN=5为MIN=7后重新编译ubb配置文件,重新启动即可,使用tmadmin工具判断是否生效:
在tmadmin中执行psr -q qcscrm1l2 如果有七个服务即为修改成功。
2、查看具体告警信息的内容,追查业务逻辑查看报警的操作需要调用哪些Tuxedo服务来准确定位出现问题的服务队列和进程。
该贴被funny编辑于2014-2-18 0:02:16该贴被funny编辑于2014-2-18 0:05:27该贴被funny编辑于2014-2-18 0:10:56