一次解决问题的经过

问题处理经过:

Tcaplus 出现的一个奇怪的问题, 现象描述如下:

从不知道哪一天开始, 升级的时候全部挂起, restore 事务全部挂起, 重启任何进程都挂起. 找来一帮大神帮忙看, 发现tcapsvr 启动的时候, 被卡住了30秒, tcm 是发出启动命令后5秒检查进程是否启动, 这时就会报启动失败. 如果去看tcapsvr 进程, 30秒之后就会正常运行.

后来发现如果在重启之前, 先把机器上的tagent 重启一遍, 就可避免这个现象.
tcapsvr 启动的时候会做一件事情, 去绑定tbus 通道, 这个时间等待30秒, 说明tbus 通道被锁了30秒. 那么谁会去锁tbus 呢? 大神们经过研究, 写了一个工具, 可以把tbus 锁打印出来, 如果是写锁会打印出加锁的进程. 跑了工具后发现进程id 是0, 也就是说这个是个读锁. tbus 一直被读锁占用, 启动任何进程的时候都要等30秒才会强制释放读锁, 也就造成了事务挂起.

接下来要做的就是去查这个读锁是谁加上的. 我们目前观察到的现象是重启tagent 释放锁之后, 过几天这个锁又加上了. 具体多久不清楚. 所以老大们决定先释放所有的锁, 然后让我加上监控, 每分钟去检查一次加锁的时间, 找到就告警. 于是昨天下午分3批把飞机大战的机器做了监控. 有的重启tagent, 有的全部重启, 有的删除共享内存重启. 今天早上收到一堆告警, 三批机器基本上同时出现了读锁. 然后查了一下时间, 发现都是10:01~10:18 分加上的. 这就说明是这段时间做了什么事情, 导致加锁.
Alex 有句话, 叫做”随便看看, 不一定能看出什么”. 秉承着这样的精神, 我就开始猜是什么事情导致的. 开始我觉得可能是tcm 会不会每天早上10 搞什么事情, 但是这个猜测不好入手去查. 正迷惘间, 俊峰说”去看看history 或者事务”, 我就敲了history 查了10点多那段时间的所有命令, 果然在满屏的命令中, 找到了一行 tbusmgr -L | head 这句话, 时间刚好跟加锁的时间对上. 基本上八九不离十了.

从tbusmgr 的代码里面看, 逻辑很简单: 加锁 -> print 一堆变量 -> 释放锁. 这么简单的逻辑不可能会有问题, 除非异常中断. flyma 到我位子上来gdb 看了一圈, 感觉不可能啊. 因为带管道符, gdb 没法断点, 所以没查出来什么原因. 不过思路基本上成型了, 一定是在print 的时候异常中断了, 导致后面释放锁的代码没有走到. 于是flyma 执行了一条命令: “strace -o output /usr/local/tsf4g_release/tools/tbusmgr -k 2088 -L | head”, 把要执行的命令strace 打出来, 然后看output 文件最后赫然写着:
write(1, “eTime – N/A\nChannel 16 informat”…, 4096) = -1 EPIPE (Broken pipe)
— SIGPIPE (Broken pipe) @ 0 (0) —
+++ killed by SIGPIPE +++

进程被管道杀掉了!!! flyma 看了一脸懵逼.

原因找到就好, 一方面tbusmgr 的工具要加上防御性代码, 防止管道杀掉进程. 一方面运维方面以后不要用 “tbusmgr -L | head”, 防止把tbus 通道锁上.

最后我们来学习一下Linux 程序开发的一些工具,

• strace: 捕获系统调用和信号处理 strace -o -Ttt 命令或pid
• ltrace: 捕获动态库调用和信息处理
• pstack 打印堆栈
• tcpdump 捕获tcp 信息

找到原因后我们常常说:”原来这么简单”. 但是找原因的过程却很迷茫, 常常无从下手, 只能靠猜. 但是这个时候一定要坚持去猜, 去验证, 最后才能找出原因

最后说下怎么看一个多线程的进程怎样查看各个子线程id

• top -H -p pid
• ps -efL | grep tagent
• pstack pid, 其实pstack 就是一个脚本