我的电脑网络位置重启消失_DB2 跟踪之消失的监听端口

《DB2 跟踪之消失的监听端口》

一般数据库出问题了，我们一般比较习惯的会根据数据库日志(比如 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。