前言
有个cm在现场的高性能服务器(redhat)上,运行不到一分钟,就将服务器内存吃的差不多了。
要解决这个问题,要不没办法用了。
在本地的linux实验环境下,也能重现,但是吃内存没有那么厉害,跑了8个小时,吃了1.2GB.
谁看了这个现象,也会想是不是代码哪里写挫了,导致了内存泄漏。
先用valgrind查了一下,有少许泄漏,泄漏的内存都是不用立刻释放的,就是这个逻辑。
将工程中的内存分配和释放检查了一下,全部匹配。
将工程中所有的内存分配和释放都改为new, delete的配对。
再加入日志,在所有的new,new x [], delete, delete[] 处都加了日志,自己统计了内存申请和释放的size.
运行程序发现,打印出来的日志显示申请的内存都很小。
但是用top(运行后,按SHIFT + m键), 发现,cpu占用率很高,为70%
用 watch -n 1 -d “free -b” 观察系统总内存,发现每秒钟都会多用1MB的内存。
怀疑第三方库有问题,将第三方库送来的数据,不处理了,直接返回,内存不增加了,回到正常情况。
那说明cm的实现代码有问题,那就用屏蔽法,自顶向下排查吧,屏蔽到写文件的函数(已经封装),发现内存正常了。
再去看那个函数,不到30行,关键一句就是调用了rename API,将写好内容的文件,移动为新的数据文件。
屏蔽掉rename的调用,cm正常了,最后的解决方法,不用api了,改用sh命令(mv + wait) + usleep(200), 问题解决。
问题原因推测:可能是rename并不是阻塞执行,导致快速rename小文件时,rename实际的操作还没退出,就又新执行了新的rename操作,导致了大量并行的rename操作。
今天同事用大文件做测试,没有这个问题。
我写了一个测试程序,模拟了实际的业务逻辑,小文件频繁创建,移动,重现了rename吃内存的场景。
如何优雅的解决这个问题,以后再想。
测试程序-bug重现
// @file main.cpp
#include <stdlib.h>
#include <stdio.h>
#include <string.h>
#include <syslog.h>
#include <unistd.h>
#include <sys/types.h>
#include <string>
#include "my_syslog.h"
bool execute_prog(const char* psz_prog_path_name, const char* psz_cmd_line);
int fn_for_test();
int main()
{
ns_syslog::open_syslog("test_syslog");
// 设置控制变量中的日志条件, 实际应用中, 是从配置文件读取的控制开关
ns_syslog::g_log_condition.b_EMERG = false;
ns_syslog::g_log_condition.b_CRIT = true;
ns_syslog::g_log_condition.b_ALERT = true;
ns_syslog::g_log_condition.b_ERR = true;
ns_syslog::g_log_condition.b_WARNING = true;
ns_syslog::g_log_condition.b_NOTICE = true;
ns_syslog::g_log_condition.b_INFO = true;
ns_syslog::g_log_condition.b_DEBUG = true;
// 根据控制变量, 设置日志的mask
// 在实际应用中, 这里可以是动态设置, e.g. 配置文件检测线程发现配置变了, 需要变更某些级别的日志记录结果
ns_syslog::set_log_level(
ns_syslog::g_log_condition.b_EMERG,
ns_syslog::g_log_condition.b_ALERT,
ns_syslog::g_log_condition.b_CRIT,
ns_syslog::g_log_condition.b_ERR,
ns_syslog::g_log_condition.b_WARNING,
ns_syslog::g_log_condition.b_NOTICE,
ns_syslog::g_log_condition.b_INFO,
ns_syslog::g_log_condition.b_DEBUG);
// 现在可以用日志宏打印日志了, 因为加了条件判断, 比直接进syslog中, 由syslog根据配置文件判断是否记录日志, 效率要高.
MYLOG_EMERG("this is logtype EMERG, random = %d", rand() % 0xff);
MYLOG_ALERT("this is logtype ALERT, random = %d", rand() % 0xff);
MYLOG_CRIT("this is logtype CRIT, random = %d", rand() % 0xff);
MYLOG_ERR("this is logtype ERR, random = %d", rand() % 0xff);
MYLOG_WARNING("this is logtype WARNING, random = %d", rand() % 0xff);
MYLOG_NOTICE("this is logtype NOTICE, random = %d", rand() % 0xff);
MYLOG_INFO("this is logtype INFO, random = %d", rand() % 0xff);
MYLOG_DEBUG("this is logtype DEBUG, random = %d", rand() % 0xff);
// test log on function
fn_for_test();
/**
// on red hat, view syslog
tail -f /var/log/messages | grep test_syslog
// on debian
tail -f /var/log/syslog | grep test_syslog
*/
ns_syslog::close_syslog();
return 0;
}
bool execute_prog(const char* psz_prog_path_name, const char* psz_cmd_line)
{
bool b_rc = false;
char szBuf[1024] = {'\0'};
std::string strPathName = "";
std::string strCmdLine = "";
do {
if ((NULL == psz_prog_path_name) || (NULL == psz_cmd_line)) {
break;
}
sprintf(szBuf, "%s %s", psz_prog_path_name, psz_cmd_line);
system(szBuf);
b_rc = true;
} while (0);
return b_rc;
}
#define MY_FIRST_FILE "/var/log/my_src.dat"
#define MY_NEW_DIR "/var/log/my_test_dir"
int fn_for_test()
{
long long ll_file_cnt = 0;
FILE* pfile = NULL;
char sz_buf[1024] = {'\0'};
execute_prog("mkdir", "-p " MY_NEW_DIR);
do {
MYLOG_INFO("ll_file_cnt = %lld", ll_file_cnt++);
// write a test file
pfile = fopen(MY_FIRST_FILE, "w+b");
if (NULL != pfile) {
MYLOG_E("open file ok : [%s]", MY_FIRST_FILE);
memset(sz_buf, 0, sizeof(sz_buf));
sprintf(sz_buf, "%s : time = %lld, ll_file_cnt = %lld",
"test tiny file",
(long long)time(NULL),
ll_file_cnt);
MYLOG_D("sz_buf = %s", sz_buf);
fwrite(sz_buf, sizeof(char), sizeof(sz_buf) / sizeof(char), pfile);
fclose(pfile);
pfile = NULL;
} else {
MYLOG_E("open file error : [%s]", MY_FIRST_FILE);
}
// move test file to a new file
// %s//var/log/my_src.dat_4200694_4200687
sprintf(sz_buf, "%s/%s_%lld_%lld",
MY_NEW_DIR,
"my_dst",
(long long)time(NULL),
ll_file_cnt);
rename(MY_FIRST_FILE, sz_buf);
MYLOG_D("rename(%s, %s)", MY_FIRST_FILE, sz_buf);
// 为了公平起见, 睡上几毫秒,模拟其他业务逻辑占用的时间
usleep(1 * 1000); // sleep 1ms
// 已经模拟出吃内存的情况
// 原因: rename这个API可能不是阻塞执行的
} while (1);
return 0;
}
/** run result
*/
// @file my_syslog.h
// @brief syslog日志宏的定义
#include <stdlib.h>
#include <stdio.h>
#include <string.h>
#include <syslog.h>
#include <unistd.h>
#include <sys/types.h>
namespace ns_syslog {
typedef struct _tag_log_condition {
bool b_EMERG;
bool b_ALERT;
bool b_CRIT;
bool b_ERR;
bool b_WARNING;
bool b_NOTICE;
bool b_INFO;
bool b_DEBUG;
_tag_log_condition() {
b_EMERG = false;
b_ALERT = false;
b_CRIT = false;
b_ERR = false;
b_WARNING = false;
b_NOTICE = false;
b_INFO = false;
b_DEBUG = false;
}
} TAG_LOG_CONDITION;
extern TAG_LOG_CONDITION g_log_condition;
// ----------------------------------------------------------------------------
// syslog macro
// ----------------------------------------------------------------------------
#define MYLOG_EMERG(fmt, ...) \
if (ns_syslog::g_log_condition.b_EMERG) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "EMERG", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
#define MYLOG_EM(fmt, ...) \
if (ns_syslog::g_log_condition.b_EMERG) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "EMERG", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
// ----------------------------------------------------------------------------
#define MYLOG_ALERT(fmt, ...) \
if (ns_syslog::g_log_condition.b_ALERT) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "ALERT", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
#define MYLOG_A(fmt, ...) \
if (ns_syslog::g_log_condition.b_ALERT) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "ALERT", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
// ----------------------------------------------------------------------------
#define MYLOG_CRIT(fmt, ...) \
if (ns_syslog::g_log_condition.b_CRIT) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "CRIT", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
#define MYLOG_C(fmt, ...) \
if (ns_syslog::g_log_condition.b_CRIT) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "CRIT", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
// ----------------------------------------------------------------------------
#define MYLOG_ERR(fmt, ...) \
if (ns_syslog::g_log_condition.b_ERR) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "ERR", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
#define MYLOG_E(fmt, ...) \
if (ns_syslog::g_log_condition.b_ERR) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "ERR", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
// ----------------------------------------------------------------------------
#define MYLOG_WARNING(fmt, ...) \
if (ns_syslog::g_log_condition.b_WARNING) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "WARNING", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
#define MYLOG_W(fmt, ...) \
if (ns_syslog::g_log_condition.b_WARNING) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "WARNING", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
// ----------------------------------------------------------------------------
#define MYLOG_NOTICE(fmt, ...) \
if (ns_syslog::g_log_condition.b_NOTICE) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "NOTICE", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
#define MYLOG_N(fmt, ...) \
if (ns_syslog::g_log_condition.b_NOTICE) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "NOTICE", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
// ----------------------------------------------------------------------------
#define MYLOG_INFO(fmt, ...) \
if (ns_syslog::g_log_condition.b_INFO) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "INFO", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
#define MYLOG_I(fmt, ...) \
if (ns_syslog::g_log_condition.b_INFO) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "INFO", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
// ----------------------------------------------------------------------------
#define MYLOG_DEBUG(fmt, ...) \
if (ns_syslog::g_log_condition.b_DEBUG) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "DEBUG", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
#define MYLOG_D(fmt, ...) \
if (ns_syslog::g_log_condition.b_DEBUG) { \
syslog(LOG_INFO, "[%s : %s.%d : %s()] : " fmt, "DEBUG", __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
}
// ----------------------------------------------------------------------------
void open_syslog(const char* pszLogOwner);
void set_log_level(
bool b_EMERG = false,
bool b_CRIT = false,
bool b_ALERT = false,
bool b_ERR = false,
bool b_WARNING = false,
bool b_NOTICE = false,
bool b_INFO = false,
bool b_DEBUG = false);
void close_syslog();
} // namespace ns_syslog {
// @file my_syslog.cpp
// @brief syslog日志宏的实现
#include "my_syslog.h"
namespace ns_syslog {
TAG_LOG_CONDITION g_log_condition;
void open_syslog(const char* pszLogOwner)
{
openlog(((NULL != pszLogOwner) ? pszLogOwner : "my_syslog"), LOG_NOWAIT | LOG_PID, LOG_LOCAL1);
}
void set_log_level(
bool b_EMERG,
bool b_CRIT,
bool b_ALERT,
bool b_ERR,
bool b_WARNING,
bool b_NOTICE,
bool b_INFO,
bool b_DEBUG)
{
int i_mask = 0;
if (b_EMERG) {
// LOG_EMERG 日志会阻塞控制台程序, 必须要使这个条件为false, 不能执行这里
// LOG_EMERG 不仅是记录到日志, 还打印到正在运行的程序上, 阻塞了程序的执行. 不能用这种日志
i_mask |= LOG_MASK(LOG_EMERG);
}
if (b_ALERT) {
i_mask |= LOG_MASK(LOG_ALERT);
}
if (b_CRIT) {
i_mask |= LOG_MASK(LOG_CRIT);
}
if (b_ERR) {
i_mask |= LOG_MASK(LOG_ERR);
}
if (b_WARNING) {
i_mask |= LOG_MASK(LOG_WARNING);
}
if (b_NOTICE) {
i_mask |= LOG_MASK(LOG_NOTICE);
}
if (b_INFO) {
i_mask |= LOG_MASK(LOG_INFO);
}
if (b_DEBUG) {
i_mask |= LOG_MASK(LOG_DEBUG);
}
setlogmask(i_mask);
}
void close_syslog()
{
closelog();
}
} // namespace ns_syslog {
# ==============================================================================
# @file Makefile
# @brief
# lostspeed 2017-10-10
# testcase\test_syslog\Makefile
# ==============================================================================
MAKE_VER = ./Makefile 1.1.0.0 build 2017-10-10 18:10
BIN = test_rename_file
BIN_OUT = "./"
# cat string
BIN_OUT := $(BIN)
TARGETS = ${BIN}
CC = g++
CFLAGS = -Wall \
--std=c++98 \
-g
INC_PATH = -I. \
MY_LIBS =
PRJ_LIBS = ${MY_LIBS}
LIB_LINK_OPT = -lstdc++ -pthread -lpthread -lrt -ldl
DEPEND_CODE_DIR = ./depend_dir \
DEPEND_CODE_SRC = $(shell find $(DEPEND_CODE_DIR) -name '*.cpp')
DEPEND_CODE_OBJ = $(DEPEND_CODE_SRC:.cpp=.o)
# 根目录文件不能用find来搞, 会遍历到子目录去的
ROOT_CODE_SRC = $(wildcard *.cpp)
ROOT_CODE_OBJ = $(ROOT_CODE_SRC:.cpp=.o)
SUB_CODE_DIR = ./sub_dir \
SUB_CODE_SRC = $(shell find $(SUB_CODE_DIR) -name '*.cpp')
SUB_CODE_OBJ = $(SUB_CODE_SRC:.cpp=.o)
help:
@echo make help
@echo command list:
@echo make rebuild
@echo "DEPEND_CODE_DIR = " $(DEPEND_CODE_DIR)
@echo "DEPEND_CODE_SRC = " $(DEPEND_CODE_SRC)
@echo "DEPEND_CODE_OBJ = " $(DEPEND_CODE_OBJ)
@echo "SUB_CODE_DIR = " $(SUB_CODE_DIR)
@echo "SUB_CODE_SRC = " $(SUB_CODE_SRC)
@echo "SUB_CODE_OBJ = " $(SUB_CODE_OBJ)
show_version:
@echo ================================================================================
@echo ${MAKE_VER}
@echo ================================================================================
ls -l -p --time-style="+%Y-%m-%d %H:%M:%S" $(find `pwd`)
@echo --------------------------------------------------------------------------------
clean:
@echo ================================================================================
rm -f $(BIN)
@echo ================================================================================
rm -f $(ROOT_CODE_OBJ)
@echo ================================================================================
rm -f $(DEPEND_CODE_OBJ)
@echo ================================================================================
rm -f $(SUB_CODE_OBJ)
@echo ================================================================================
all: ${TARGETS}
@echo Makefile all...
@echo **==============================================================================
if [ -f $(BIN) ] ; \
then \
echo "build ok :)" ; \
else \
echo "build failed :(" ; \
fi;
@echo **==============================================================================
$(BIN): $(ROOT_CODE_OBJ) $(DEPEND_CODE_OBJ) $(SUB_CODE_OBJ)
${CC} ${CFLAGS} ${INC_PATH} \
$(ROOT_CODE_OBJ) $(DEPEND_CODE_OBJ) $(SUB_CODE_OBJ) \
${PRJ_LIBS} ${LIB_LINK_OPT} \
-o ${BIN} \
.cpp.o:
@echo $<
@echo build $^ ...
${CC} ${CFLAGS} ${INC_PATH} -c $^ -o $@
rebuild:
@echo Makefile rebuild...
make clean
make all