centos7上syslog速度很慢

没法说你 2018-06-13 10:51:16

最近将系统从centos6.4升级到7.2，升级后发现原先的程序运行很慢，经过分析发现程序的性能被消耗在syslog函数中。然后我写了一个demo专门测试日志打印。



#include <stdio.h>

#include <sys/time.h>

#include <syslog.h>



#define SYSLOG_PRIO_TRACE      (LOG_LOCAL5 | LOG_DEBUG)



int main()

{

	FILE *fp = NULL;

	char buf[1025] = {0};

	int index = 0;

	struct timeval start, end;



	fp = fopen("syslog_speed_test_file.txt","w");

	if(NULL == fp)

	{

		printf("file open failed.\n");

	}



	for(index = 0; index<1023; index++)

	{

		buf[index] = 'w';

	}

	buf[1023] = '\n';

	

	gettimeofday(&start, NULL);

	printf("start time:%d.%d\n", start.tv_sec, start.tv_usec);

	index = 0;

	while (index < 102400)

	{

		gettimeofday(&start, NULL);

		syslog(SYSLOG_PRIO_TRACE, "%s", buf);

		gettimeofday(&end, NULL);

		fprintf(fp, "%dth,time used:%d.%06d\n", index, end.tv_sec-start.tv_sec, end.tv_usec-start.tv_usec);

		index++;

	}

	gettimeofday(&end, NULL);

	printf("start time:%d.%d\n", end.tv_sec, end.tv_usec);

}

将该程序分别在7.2系统和6.4系统的虚拟机上运行

在7.2虚拟机上运行结果为5s左右，在6.4虚拟机上运行结果为500ms左右

两个系统的输出分别如下

7.2系统：



0th,time used:0.002209

1th,time used:0.000019

2th,time used:0.000011

3th,time used:0.000008

4th,time used:0.000008

5th,time used:0.000008

6th,time used:0.000009

7th,time used:0.000008

8th,time used:0.000008

9th,time used:0.000008

10th,time used:0.000008

11th,time used:0.011167

12th,time used:0.000031

13th,time used:0.000011

14th,time used:0.000008

15th,time used:0.000008

16th,time used:0.000009

17th,time used:0.000008

18th,time used:0.000008

19th,time used:0.000010

20th,time used:0.000008

21th,time used:0.000009

22th,time used:0.006686

23th,time used:0.000028

24th,time used:0.000010

25th,time used:0.000009

26th,time used:0.000009

27th,time used:0.000008

28th,time used:0.000009

29th,time used:0.000008

30th,time used:0.000008

31th,time used:0.000008

32th,time used:0.000009

33th,time used:0.006043

6.4系统



0th,time used:0.000215

1th,time used:0.000026

2th,time used:0.000018

3th,time used:0.000017

4th,time used:0.000016

5th,time used:0.000017

6th,time used:0.000679

7th,time used:0.000031

8th,time used:0.000017

9th,time used:0.000016

10th,time used:0.000016

11th,time used:0.000016

12th,time used:0.000016

13th,time used:0.000017

14th,time used:0.000016

15th,time used:0.000017

16th,time used:0.000016

17th,time used:0.000016

18th,time used:0.000016

19th,time used:0.000017

20th,time used:0.000016

21th,time used:0.000016

22th,time used:0.000016

23th,time used:0.000016

24th,time used:0.000086

25th,time used:0.000027

26th,time used:0.000016

27th,time used:0.000016

28th,time used:0.000018

29th,time used:0.000017

30th,time used:0.000016

31th,time used:0.000016

32th,time used:0.000016

33th,time used:0.000017

34th,time used:0.000016

35th,time used:0.000016

36th,time used:0.000016

37th,time used:0.000016

38th,time used:0.000016

39th,time used:0.000016

40th,time used:0.000017

从输出来看，7.2系统每隔10次输出就会有一次超长的卡顿，而6.4系统则无此现象。
抓取运行时的cpu占用状态，发现system-journald的cpu占用很高。
由于虚拟机的配置不足所以在服务器上进行了同样的实验，结果每隔10次的卡顿没了，但是单次处理的时间达到了50us以上，看journald的cpu占用达到了单核100%的程度。

各位是否也遇到过这种情况？能否分享一下解决思路。

...全文