《DB2 跟踪之消失的监听端口》
![123f42ba4d04be62f84a563c4aa04abc.png](https://img-blog.csdnimg.cn/img_convert/123f42ba4d04be62f84a563c4aa04abc.png)
一般数据库出问题了,我们一般比较习惯的会根据数据库日志(比如 DB2DIAG.LOG)来分析。
DB2 除了数据库日志,还有一个对 DB2 内部函数调用的跟踪工具,叫 db2trc。
它在 DB2 知识库中层级位置如下:
故障诊断和支持 > 故障诊断技巧 > 故障诊断工具 > 跟踪 > DB2 跟踪
简要了一下 DB2 跟踪:
简要地说,它是开启跟踪 DB2 内部函数调用的另一种方式,此方式最贴近于 DB2 的函数源码,已经追踪到函数调用层面、以及函数所处理一此数据的信
息。
其使用步骤少,主要就 3 步:开启跟踪、、格式化、分析日志。
由于其跟踪的信息量非常大,且跟踪时会对 DB2 实例性能带来性能影响,应该注意最小化跟踪,比如跟踪特定时间、跟踪特定 EDU 以减少跟踪的时间及
范围,重现问题时采取最省力方式重现;其中分析过程较为复杂,主要由于信息量大,加之对 DB2 源代码的不了解。
所以,此方式一般是仅当 IBM 软件支持机构要求时,才应该使用跟踪。
好,回到案例(广发银行,AIX 环境)。
正常情况下,某 DB2 实例配置网络监听端口及服务名称如下:
在/etc/services 文件:
DB2_db2inst1 60000/tcp
某天,此 DB2 实例配置网络监听端口值被修改为 88888,如下:
在/etc/services 文件:
DB2_db2inst1 88888/tcp
重启 DB2 实例成功后,应用用户想通过 JDBC 驱动联接到此实例的 88888 端口,但报联接失败。
从操作系统系统层面进行检查,确实没有 88888 端口在监控。
再从 DB2 的诊断日志(db2diag.log)分析,并没有更多有关端口监听的信息。
因为实例默认的诊断日志级别是 3,想尝试提高诊断日志级别,看看是否有更多的信息。
于是修改诊断日志级别是 4,以记录更详实的日志:
db2 update dbm cfg using diaglevel 4 immediate
DB20000I The UPDATE DATABASE MANAGER CONFIGURATION command completed
successfully.
验证配置生效:
db2 get dbm cfg show detail|grep -w -i -E "diaglevel|svcename"
Diagnostic error capture level (DIAGLEVEL) = 4 4
TCP/IP Service name (SVCENAME) = DB2_db2inst1 DB2_db2inst1
重现问题;
诊断日志是记录了更多的详细信息,但也没有与"DB2_db2inst1"或"88888"的信息。
只是增加一些 TCP 通讯启动及监听的信息:
2016-06-18-12.47.51.295022+480 I31359G379 LEVEL: Info
PID : 5279 TID : 2923424656 PROC : db2sysc
INSTANCE: db2inst1 NODE : 000
EDUID : 1 EDUNAME: db2sysc
FUNCTION: DB2 UDB, common communication, sqlcctcpconnmgr, probe:160
MESSAGE : DIA3218I "2" TCP/IP connection manager(s) was/were successfully
started.
2016-06-18-12.47.51.295345+480 I31739G360 LEVEL: Info
PID : 5279 TID : 2923424656 PROC : db2sysc
INSTANCE: db2inst1 NODE : 000
EDUID : 1 EDUNAME: db2sysc
FUNCTION: DB2 UDB, common communication, sqlcctcp_start_listen, probe:80
MESSAGE : DIA3000I "TCPIP" protocol support was successfully started.
对我们分析具体的原因暂不有帮助。
好吧。我们使用 DB2 跟踪来试试。
再来重现问题:
先停止实例:
db2stop
归档诊断日志:
db2diag -A
:
开启跟踪(跟踪结果转存到二进制的文件 trc.dump 中):
db2trc on -t -f ./trc.dump
Trace is turned on
(重现问题)
启动 DB2 实例:
db2start
SQL1063N DB2START processing was successful.
归档诊断日志:
db2diag -A
db2diag: Moving "/home/db2inst1/sqllib/db2dump/db2diag.log"
to "/home/db2inst1/sqllib/db2dump/db2diag.log_2016-06-18-12.48.03"
:
停止跟踪:
db2trc off
Trace is turned off
:
格式化及分析
到目前为止。我们已经收集了数据,但还得将转存的二制进文件进行格式化。
格式化为更人性化的格式:
db2trc flow -t trc.dump trc.flw
Total number of trace records : 131981
Trace truncated : NO
Trace wrapped : NO
Number of trace records formatted : 1179 (pid: 5250 tid 3051686736 node: 0)
Number of trace records formatted : 197 (pid: 5252 tid 3051656912 node: -1)
Number of trace records formatted : 719 (pid: 5263 tid 10049232 node: -1)
Number of trace records formatted : 11 (pid: 5264 tid 10049232 node: -1)
Number of trace records formatted : 652 (pid: 5264 tid 2955294416 node: -1)
Number of trace records formatted : 11 (pid: 5265 tid 10049232 node: -1)
Number of trace records formatted : 13928 (pid: 5265 tid 1983776 node: 0)
Number of trace records formatted : 14 (pid: 5277 tid 1983776 node: 0)
Number of trace records formatted : 2372 (pid: 5277 tid 3054496656 node: 0)
Number of trace records formatted : 1636 (pid: 5279 tid 3054496656 node: 0)
Number of trace records formatted : 27 (pid: 5280 tid 3054496656 node: 0)
Number of trace records formatted : 27 (pid: 5281 tid 3054496656 node: 0)
Number of trace records formatted : 27 (pid: 5282 tid 3054496656 node: 0)
Number of trace records formatted : 19172 (pid: 5279 tid 2923424656 node: 0)
Number of trace records formatted : 130 (pid: 5279 tid 2954881936 node: 0)
Number of trace records formatted : 157 (pid: 5279 tid 2953833360 node: 0)
Number of trace records formatted : 11 (pid: 5286 tid 2923424656 node: 0)
Number of trace records formatted : 235 (pid: 5286 tid 2954692304 node: -1)
Number of trace records formatted : 237 (pid: 5279 tid 2952784784 node: 0)
Number of trace records formatted : 229 (pid: 5279 tid 2951736208 node: 0)
Number of trace records formatted : 269 (pid: 5279 tid 2950687632 node: 0)
Number of trace records formatted : 244 (pid: 5279 tid 2949639056 node: 0)
Number of trace records formatted : 485 (pid: 5279 tid 2948590480 node: 0)
Number of trace records formatted : 628 (pid: 5279 tid 2947541904 node: 0)
Number of trace records formatted : 396 (pid: 5279 tid 2946493328 node: 0)
Number of trace records formatted : 256 (pid: 5279 tid 2945444752 node: 0)
Number of trace records formatted : 60 (pid: 5303 tid 3384400 node: -1)
Number of trace records formatted : 76171 (pid: 5303 tid 3052501216 node: 0)
Number of trace records formatted : 197 (pid: 5303 tid 3004689296 node: 0)
Number of trace records formatted : 17 (pid: 5303 tid 2994199440 node: 0)
Number of trace records formatted : 1407 (pid: 5303 tid 2980260752 node: 0)
Number of trace records formatted : 630 (pid: 5307 tid 8124640 node: -1)
Number of trace records formatted : 11 (pid: 5308 tid 8124640 node: -1)
Number of trace records formatted : 652 (pid: 5308 tid 2955175632 node: -1)
Number of trace records formatted : 11 (pid: 5309 tid 8124640 node: -1)
Number of trace records formatted : 2078 (pid: 5309 tid 2332384 node: 0)
Number of trace records formatted : 1179 (pid: 5311 tid 3052018512 node: 0)
Number of trace records formatted : 197 (pid: 5313 tid 3051288272 node: -1)
Number of trace records formatted : 618 (pid: 5325 tid 3246304 node: 0)
Number of trace records formatted : 1179 (pid: 5327 tid 3052297040 node: 0)
Number of trace records formatted : 197 (pid: 5329 tid 3051357904 node: -1)
Number of trace records formatted : 1179 (pid: 5341 tid 3052014416 node: 0)
Number of trace records formatted : 197 (pid: 5343 tid 3051603664 node: -1)
Number of trace records formatted : 1179 (pid: 5355 tid 3052264272 node: 0)
Number of trace records formatted : 197 (pid: 5357 tid 3051124432 node: -1)
Number of trace records formatted : 1179 (pid: 5369 tid 3052497744 node: 0)
Number of trace records formatted : 197 (pid: 5371 tid 3051497168 node: -1)
db2trc format trc.dump trc.fmt
Trace truncated : NO
Trace wrapped : NO
Total number of trace records : 131981
Number of trace records formatted : 131981
从上面的 2 个格式化输出,得知共有【13 万+】条跟踪记录信息。
即有 13 万+函数调用记录。
简单看看格式化出来的信息:
首先格式化的文件:trc.flw
Marker : @TRACE@
【头信息,省略】
pid = 7656 tid = 6020 node = 0
1 0.000000000 clp_bp_con data [probe 21]
2 0.000102209 | sqlorque entry
3 0.000103920 | sqlorque data [probe 5]
4 0.000106058 | sqlorque data [probe 6]
5 0.000110334 | | sqloWaitInterrupt entry
118442 4.999979900 | | sqloWaitInterrupt exit [rc = 0x870F00B9 = -2029059911 = SQLO_SEM_TIMEOUT]
118443 5.000012829 | sqlorque exit [rc = 0x870F00B9 = -2029059911 = SQLO_SEM_TIMEOUT]
118444 5.000016678 clp_bp_con data [probe 21]
118445 5.000134711 | sqlorque entry
118446 5.000137704 | sqlorque data [probe 5]
118447 5.000140270 | sqlorque data [probe 6]
118448 5.000144974 | | sqloWaitInterrupt entry
pid = 6672 tid = 8684 node = -1
6 0.146392625 sqlo_init_GMT_timer_services entry
7 0.146410159 sqlo_init_GMT_timer_services exit
8 0.146455490 sqloInitializeLatchTuningInfo entry
9 0.146462333 | sqloGetEnvInternal entry
10 0.146463616 | | sqloInitEnvironment entry
11 0.146465754 | | | sqloPRegQueryDefaultValue entry
12 0.146466609 | | | | sqloGetDefGlobProfKey entry
13 0.146466609 | | | | | sqloGetCurrentInstallationName entry
14 0.146467037 | | | | | | sqloGetThisDllPathFromDllInit entry
15 0.146467465 | | | | | | sqloGetThisDllPathFromDllInit data [probe 80]
16 0.146468748 | | | | | | sqloGetThisDllPathFromDllInit exit
17 0.146469175 | | | | | sqloGetCurrentInstallationName data [probe 10]
18 0.146469603 | | | | | | sqloGetInstallNameFromDllPath entry
19 0.146470031 | | | | | | sqloGetInstallNameFromDllPath data [probe 10]
20 0.146509375 | | | | | | sqloGetInstallNameFromDllPath data [probe 20]
21 0.146547436 | | | | | | sqloGetInstallNameFromDllPath data [probe 30]
22 0.146547864 | | | | | | | sqlo_InstallName_PathCompare entry
23 0.146692839 | | | | | | | sqlo_InstallName_PathCompare data [probe 101]
24 0.146693694 | | | | | | | sqlo_InstallName_PathCompare data [probe 103]
25 0.146694122 | | | | | | | sqlo_InstallName_PathCompare exit [rc = 1]
26 0.146694977 | | | | | | sqloGetInstallNameFromDllPath data [probe 31]
27 0.146699681 | | | | | | sqloGetInstallNameFromDllPath exit
28 0.146700964 | | | | | sqloGetCurrentInstallationName data [probe 10]
29 0.146701392 | | | | | sqloGetCurrentInstallationName exit
30 0.146701392 | | | | sqloGetDefGlobProfKey exit
31 0.146744585 | | | sqloPRegQueryDefaultValue exit
32 0.146752710 | | | EnvQueryDB2SystemVariables entry
33 0.146753138 | | | | EnvGetDB2SysVar entry
34 0.146756559 | | | | EnvGetDB2SysVar exit [rc = 0x00000021 = 33]
(。。。。。。后面省略)
展示了函数的调用堆栈。
格式是:调用的顺序号、历时、函数调用层次及函数名、类型(entry,data,exit),及信息(如探测点或返回码等)
这个是按每个 tid(线程)的函数调用分组展示。
再简单看另一个格式化后的文件:trc.fmt:
【头信息,省略】
1 entry DB2 UDB oper system services sqloGetEnvInternal fnc (1.3.15.1143.0)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 0
bytes 12
Data1 (PD_TYPE_SINT,4) signed integer:
644
2 exit DB2 UDB oper system services sqloGetEnvInternal fnc (2.3.15.1143.0)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 14000
rc = 0x870F0104 = -2029059836 = RC_ENV_NOT_FOUND
bytes 12
Data1 (PD_TYPE_PTR,4) Pointer:
0x00000000
3 entry DB2 UDB config/install sqlfcsys cei (1.3.6.2.2)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 18000
4 entry DB2 UDB config/install sqlf_read_dbm_and_verif cei (1.3.6.81.2)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 20000
5 entry DB2 UDB config/install sqlfpath fnc (1.3.6.35.0)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 22000
6 entry DB2 UDB base sys utilities sqledflt cei (1.3.5.174.2)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 24000
7 entry DB2 UDB oper system services sqloInstancePath cei (1.3.15.789.2)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 25000
8 exit DB2 UDB oper system services sqloInstancePath cei (2.3.15.789.2)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 27000
rc = 0
9 exit DB2 UDB base sys utilities sqledflt cei (2.3.5.174.2)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 30000
rc = 0
10 exit DB2 UDB config/install sqlfpath fnc (2.3.6.35.0)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 40000
rc = 0
11 data DB2 UDB config/install sqlf_read_dbm_and_verif cei (3.3.6.81.2.4)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 42000 probe 4
bytes 38
Data1 (PD_TYPE_STRING,30) String:
/home/db2inst1/sqllib/db2systm
12 entry DB2 UDB config/install sqlf_openfile fnc (1.3.6.66.0)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 45000
bytes 24
Data1 (PD_TYPE_SINT,4) signed integer:
10
Data2 (PD_TYPE_UINT,4) unsigned integer:
10000
13 entry DB2 UDB oper system services sqloopenp cei (1.3.15.823.2)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 50000
bytes 74
Data1 (PD_TYPE_FILE_NAME,30) File name:
/home/db2inst1/sqllib/db2systm
Data2 (PD_TYPE_SQO_FILE_OPEN_OPTIONS,4) SQO Open File Options:
SQLO_REVISE, SQLO_READONLY, SQLO_SHAREREAD, SQLO_WRITETHRU, SQLO_DELAY, SQLO_EXPLOCK
Data3 (PD_TYPE_HEXINT,4) Hex integer:
0x000001A0
Data4 (PD_TYPE_PTR,4) Pointer:
0x00000000
(。。。。。。后面省略)
展示了函数的调用顺序。
格式是:调用的顺序号、类型(entry,data,exit),产品及 DB2 组件,函数名, 历时
进程 ID,线程 ID,历时
字节数(内容的长度)
内容的解析
这个是按主线程顺序。
这个文件的显示一些函数所处理数据的具体信息,例如:
28 data DB2 UDB trace services sqltGetDiagPath cei (3.3.20.5.2.10)
pid 5250 tid 3051686736 cpid -1 node -1 sec 0 nsec 300000 probe 10
bytes 38
Data1 (PD_TYPE_DEFAULT,30) Hexdump:
2F68 6F6D 652F 6462 3269 6E73 7431 2F73 /home/db2inst1/s
716C 6C69 622F 6462 3264 756D 702F qllib/db2dump/
展示的是数据段;函数名为 sqltGetDiagPath(),看函数名判断是获取 DB2 诊断日志路径;获取到值为:/home/db2inst1/sqllib/db2dump/。
通过对比,看到 trc.fmt 不仅包含了函数的调用顺序、历时,更主要是包含了函数处理的相关数据信息。
这为我们此次分析数据信息提供了比较好的线索入口。
于是,尝试先从此文件入手.
从格式化时得知,此文件包含了 13 万+的函数调用记录呀。
先简单从文件中查找"DB2_db2inst1"或"88888"。没有发现值 为"88888"的字眼,但发现有值为"DB2_db2inst1"的字眼
在如下函数 sqloPdbTcpIpGetPortByName()调用相关片段:
从序号为 220 的调用信息来分析,函数 sqloPdbTcpIpGetPortByName()所处理的数据(data)信息:DATA1 为 DB2_db2inst1;DATA2 为 tcp
我们的配置"DB2_db2inst1 88888/tcp"的中的服务名称及服务类型是一致的;
再继续分析,序号为 221 的,记录了函数 sqloPdbTcpIpGetPortByName()的所处理的数据(data):DATA1,其对应的十六进制值为:0000 5B38。
这个值代表什么?先换算成十进制值,得到:23352,与我们配置的值 88888 会什么关系呢?
先来看看 88888 对应的十六进制值是多少:0001 5B38。日志中的显示的值(0000 5B38)难道只取了 88888 对应十六进制的后 4 位?
好吧,先 OS 验证一下。
看看系统中端口 23352 是否在监听了?又是不是我们 DB2 实例在占用此端口来监听。
以下是验证过程及结果:
从中可以看出,端口 23352 是在监听,且为 DB2 实例主进程 db2sysc 所占有。
至今,消失的监听端口已经找回,通过调整应用 JDBC 所联端口值,可以联上 DB2 实例及数据了。
另外,经显示操作系统的端口范围是:0~~65535,那为什么是这些范围呢?
我们从 C 语言+网络编程的角度分析分析。
(包括 32 位及 64 位环境)
网络编程时需要创建一个 socket 的地址信息,其数据结构如下:
其中分别定义结构成员:地址类型、端口、IP 地址的数据类型。
我们关注与端口有关的结构成员,如图所选中的绿色底的变量名:sin_port,其数据类型 unsigned short int,为无符号短整型,占用 2 个字节(共 16
个位),其数值范围为 0~~2 的 16 次方,即:0~~65535。
以下我们来验证一下:
定义一个 unsigned short int 数据类型的变量 i,给它值:88888;再打印 unsigned short int 数据类型所占内存字节数;最后把 i 的值打印出来。
编译通过,但在代码第 6 行有个 Warning,数值被 truncated 为无符号数据类型。
执行显示:nsigned short int 数据类型的占用内存字节数为:2; 值被 truncated 后变为 23352。