最近遇到一个 C++ 工程CPU占用100%的问题,经过排查,发现原来是不再使用的代码片段的问题,本文记录了排查的过程,并给出示例代码片段。
发现问题某日,运维反馈生产环境某台设备出现问题,某个进程占用 cpu 较高,几乎为 100%,已连续出现几天,现场人员重启过若干次,问题依旧。领导指派我排查。
排查过程首先查看该进程的日志文件,未发现异常。
无意间执行 df 命令,发现磁盘已经满了,经查,是另一进程的日志文件占用过高,已近700GB。利用 scp 将部分日志文件迁移到另一台服务器,用 vim打开日志,定位到1000多行发现出错信息:open read pipe failed : Permission denied,定位到文末,也是相同的出错语句,得到结论,该语句频繁输出,导致文件过大,占用空间。
删除日志文件,磁盘恢复,但 CPU 依然满载,使用了iotop -oP、iostat、pidstat -d 1命令查看,发现还跟 rsyslog 有关。
网上有相关问题的介绍,根据文章,使用service rsyslog status查看 syslog 的服务状态,输出如下:
Oct 29 11:06:57 localhost.localdomain systemd[1]: Starting System Logging Service... Oct 29 11:06:57 localhost.localdomain rsyslogd[4836]: [origin software="rsyslogd" swVersion="8.24.0-34.el7" x-pid="4836" x-info="http://www.rsyslog.com"] start Oct 29 11:06:57 localhost.localdomain systemd[1]: Started System Logging Service. Oct 29 11:06:57 localhost.localdomain rsyslogd[4836]: sd_journal_get_cursor() failed: 'Cannot assign requested address' [v8.24.0-34.el7] Oct 29 11:06:57 localhost.localdomain rsyslogd[4836]: imjournal: journal reloaded... [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ] Oct 29 11:06:57 localhost.localdomain rsyslogd[4836]: imjournal: journal reloaded... [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ] Oct 29 11:06:58 localhost.localdomain rsyslogd[4836]: imjournal: begin to drop messages due to rate-limiting Oct 29 11:07:00 localhost.localdomain rsyslogd[4836]: sd_journal_get_cursor() failed: 'Cannot assign requested address' [v8.24.0-34.el7] Oct 29 11:07:00 localhost.localdomain rsyslogd[4836]: imjournal: journal reloaded... [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ] Oct 29 11:07:00 localhost.localdomain rsyslogd[4836]: imjournal: journal reloaded... [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ] Oct 29 11:07:04 localhost.localdomain rsyslogd[4836]: sd_journal_get_cursor() failed: 'Cannot assign requested address' [v8.24.0-34.el7] Oct 29 11:07:04 localhost.localdomain rsyslogd[4836]: imjournal: journal reloaded... [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ] Oct 29 11:07:04 localhost.localdomain rsyslogd[4836]: imjournal: journal reloaded... [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ]
可知系统的日志服务出现问题。根据网上说法,手动删除/var/lib/rsyslog/imjournal.state文件并重启 rsyslog,命令如下:
rm -rf /var/lib/rsyslog/imjournal.state systemctl restart rsyslog
随后查看,问题依旧,再重启多次亦然。问题还是未解决。
示例代码排查代码,发现有几处相同的日志,根据跟踪,发现一个地方可疑,经过测试,的确为该处的问题。出现问题的代码如下(片段示意):
bool OpenFifo() { if(-1 == g_pipe) { if(access(pipename, F_OK) != 0) { if(mkfifo(pipename, 0777) != 0) { printf("mkfifo %s failed : %sn", pipename, strerror(errno)); return false; } } g_pipe = open(pipename, O_RDWR | O_NONBLOCK); if(-1 == g_pipe) { printf("open read pipe failed : %sn", strerror(errno)); return false; } } return true; } int Recv(char *buffer, int bufferSize, int timeout) { if(-1 == g_pipe) { if(OpenFifo() == false) { return -1; } } if(select(g_pipe + 1, &fds, NULL, NULL, &tv) > 0) { read(g_pipe, buffer + byteread, readsize - byteread); } return -1; } int main() { // 主循环 while (false == g_isexit) { // 使用 fifo 读取标志 if ((len = theFifo->Recv(buf, sizeof(buf) - 1, 1000)) > 0) { buf[len] = 0; if (strcmp(buf, "EXIT") == 0) { printf("Get EXIT signal, exit..."); break; } } } }
程序逻辑较简单,在代码中读取 FIFO 的命令,如是退出指令,则退出程序。具体说就是在主循环中读取某个 FIFO 文件,延时1秒钟(因此主循环没有显式调用 sleep 函数)。在 Recv 函数中会判断 FIFO 文件是否打开,如否,则打开之。但问题正出在此处:printf("open read pipe failed : %sn", strerror(errno))。当 FIFO 文件权限出错时,就会一直打印输出。而该台设备的 FIFO 文件不知何故何时变成为 root 权限,询问未果,于是手动修改权限,CPU 随即恢复正常指标范围。
问题解决询问原来维护代码的同事,回复说那段代码已不再使用,于是删除之。
小结既然定位到了问题,也知道了原由,直接删除不再使用的代码即可。从测试结果看,的确解决了问题。
从中也可以知道,对于项目代码,需要保持一定的迭代更新或重构工作,至少,已经过时的代码应该删除,使用 git 版本控制工具,可以追溯代码的历史,因此旧代码可以不再保留在当前工程中。
对于个人的代码,完全可由个人掌控,但在一个研发团队中,还需所有人员达成共识,需要上级的推动和开发人员的实践。
欢迎分享,转载请注明来源:内存溢出
评论列表(0条)