项目同步Log模块性能分析优化

文章目录
  1. 1. Log性能开销
  2. 2. Log模块问题定位
  3. 3. Log模块优化
  4. 4. 总结

最近在对项目的注册进行压测的时候发现我们的同步Log模块在现有业务情况下,性能成了一个比较大的瓶颈,虽然同步Log带来了很多的好处:简单,不会出问题。但业务日志量的膨胀导致了很大的性能开销,下面是简单的分析和优化过程。

下图是项目在注册时候的profile得出的分析结果,从perf生成的FlameGraph可以看到占22%左右CPU时间的[unknown]部分,包括IO操作,格式化操作,以及tzset_internal,其实整个项目其实是加了-fno-omit-frame-pointer选项,保留了栈帧指针,但libc本身是优化了栈帧指针的,所以这里无法获取到对应的callgraph信息,至于为什么这部分部分无法统计到整个进程的Call Graph中,而是独立出来了,有待研究,其实通过dwarf来栈追踪就可以解决这个问题,但我们机器不支持perf record时通过dwarf来进行追踪。

reg_flame_graph.png

1. Log性能开销

通过valgrind的callgrind模块对zonesvr压测进行统计,因为valgrind开启本身对程序的性能有20~30倍的性能影响,所以对注册tps=5时进行压测,得出的结果可以看到:

log_callgrind.png
LOG模块日志开销
log_callgrind.png
tlog日志开销

上面可以看到日志开销还是比较大的,且通过callgrind的分析结果,tzset_internal是localtime函数调用的,调用处也来自Log模块的日志开销。那基本可以得出日志最开始的profile图中unkown的开销主要是日志的开销。

为了测试Log模块的性能,需要在docker压测机器上,测试磁盘顺序写性能,

1
2
3
4
5
6
7
8
9
10
11
12
# 使用dd的参数conv=fdatasync,写入page cache中的数据在写入结束后,刷入磁盘中
$ dd if=/dev/zero of=~/test.dat bs=2G count=1 conv=fdatasync
0+1 records in
0+1 records out
2147479552 bytes (2.1 GB) copied, 19.1262 s, 112 MB/s


# 单次写入200B,写入10000000次,共1.5GB
$ dd if=/dev/zero of=~/test.dat bs=200 count=10000000 conv=fdatasync
10000000+0 records in
10000000+0 records out
2000000000 bytes (2.0 GB) copied, 32.0428 s, 62.4 MB/s

而我们devent 的KVM虚拟机,磁盘的性能都比docker要好,但由于测试的机器都很容易受到母机其他子机的影响,可能不太准确。

下面是docker压测机器上对Log模块的写日志进行压测,分别以不同的记录大小和记录数进行测试,测试结果如下(docker本身磁盘操作比kvm的虚拟机性能是差的):

单条记录大小 记录条数 日志大小 耗时
100B 100W 96M 4030633
150B 100W 143M 4179746
200B 100W 190M 4280355
100B 200W 191M 8222037
150B 200W 283M 8391610
200B 200W 382M 8410951
log_performance_test.png
Log模块写入测试

在压测注册的过程中,注册 tps=125,注册人数12000 ,注册过程持续96s, 具体统计日志量在200W条左右,注册时的日志平均长度为150B,按照上面单独对Log模块的压测,写日志需要开销8s左右, 所以按照最好的评估,光注册时的日志开销,就占到登陆时长的8.391/96=8%。 并不考虑实际的内存拷贝和PB的DebugString等开销。

2. Log模块问题定位

从FlameGraph的profile结果可以看到日志相关的操作里,IO相关调用无法优化,但是日志模块中,localotime调用的tzset_internal为何开销这么大呢?tzset_internal函数本来是用来进行时区相关参数的设置。

tzset_internal_localtime.png
时区设置的开销(调用堆栈关系不太准确)

我们可以在glibc的源码中看到,localtime和localtime_r的实现glibc源码localtime.c

1
2
3
4
5
6
7
8
9
10
11
struct tm *
__localtime64_r (const __time64_t *t, struct tm *tp)
{
return __tz_convert (*t, 1, tp);
}

struct tm *
__localtime64 (const __time64_t *t)
{
return __tz_convert (*t, 1, &_tmbuf);
}

下面是glibc源码tzset.c,tz_convert的实现,可以看到tzset_internal传入的参数,_tmbuf是全局变量,供localtime调用,所以我们知道localtime是不可重入的。所以当我们调用localtime_r时,tzset_internal的传入参数总会是false。tzset_internal就是最终设置内部时区信息的函数,当传入false时,在进程运行的过程中只会进行一次的初始化操作,后续的调用都会直接返回

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31


struct tm *
__tz_convert (__time64_t timer, int use_localtime, struct tm *tp)
{
long int leap_correction;
int leap_extra_secs;

__libc_lock_lock (tzset_lock);

/* Update internal database according to current TZ setting.
POSIX.1 8.3.7.2 says that localtime_r is not required to set tzname.
This is a good idea since this allows at least a bit more parallelism. */

tzset_internal (tp == &_tmbuf && use_localtime);

...省略
}

/* Interpret the TZ envariable. */
static void
tzset_internal (int always)
{

static int is_initialized;
const char *tz;

if (is_initialized && !always)
return;
is_initialized = 1;

...省略
}

通过glibc的源码知道,tzset_internal函数用来初始化时区相关配置,包括:tzname,timezone,daylight等全局变量(glibc源码),各个需要时区转换的标准函数会自动调用tzset_internal,例如localtime,mktime等。上面贴出了tzset_internal的前半部分,只是用来判断重复初始化的逻辑,tzset_internal的核心功能如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
/* Interpret the TZ envariable.  */
static void
tzset_internal (int always)
{

...省略
// 读取“TZ”环境变量,如果tz的值为空,将其置为UTC时区
tz = getenv ("TZ");
if (tz && *tz == '\0')
/* User specified the empty string; use UTC explicitly. */
tz = "Universal";
...省略
// 如果tz不存在,将其置为默认时区,#define TZDEFAULT "/etc/localtime"
if (tz == NULL)
/* No user specification; use the site-wide default. */
tz = TZDEFAULT;
...省略

// 读取tz对应的文件,来进行时区相关的设置,并返回
__tzfile_read (tz, 0, NULL);
if (__use_tzfile)
return;

/* No data file found. Default to UTC if nothing specified. */
// 如果没有找到对应的时区数据文件,则直接通过UTC的时区数据来进行初始化。
if (tz == NULL || *tz == '\0'
|| (TZDEFAULT != NULL && strcmp (tz, TZDEFAULT) == 0))
{
memset (tz_rules, '\0', sizeof tz_rules);
tz_rules[0].name = tz_rules[1].name = "UTC";
if (J0 != 0)
tz_rules[0].type = tz_rules[1].type = J0;
tz_rules[0].change = tz_rules[1].change = -1;
update_vars ();
return;
}

__tzset_parse_tz (tz);
}

整个tzset_internal的功能首先会读取’TZ’环境变量的值,该值用来保存系统的时区信息,如果TZ环境变量未设置,则会使用系统时区设置,默认为/etc/localtime(老POSIX版本)或/etc/timezone(新POSIX版本),可以查看该文件的内容:

1
2
$cat /etc/timezone
Asia/Shanghai

而系统所有时区的数据库信息都存放在/usr/share/zoneinfo/中:

1
2
3
4
5
6
7
8
9
ll /usr/share/zoneinfo/
total 324
drwxr-xr-x 2 root root 4096 Feb 18 23:05 Africa
drwxr-xr-x 6 root root 20480 Feb 18 23:05 America
drwxr-xr-x 2 root root 4096 Feb 18 23:05 Antarctica
drwxr-xr-x 2 root root 4096 Feb 18 23:05 Arctic
drwxr-xr-x 2 root root 12288 Feb 18 23:05 Asia

...and so on

最终tzset_internal会根据/usr/share/zoneinfo/Asia/Shanghai数据文件中的时区格式现实来进行时区相关参数的初始化操作。从上代码可知,在多次调用下,localtime和localtime_r的性能开销差别还是很大的, localtime每次都会有额外的时区设置开销。从POSIX.1-2004标准可直两者的差别。

According to POSIX.1-2004, localtime() is required to behave as though tzset(3) was called, while localtime_r() does not have this requirement. For portable code tzset(3) should be called before localtime_r().

3. Log模块优化

经过上面的分析后,把Log模块内部时间转换函数从localtime换成localtime_r后,进行压测,发现性能有很大的提升。

单条记录大小 记录条数 日志大小 耗时
100B 200W 191M 5138173
150B 200W 283M 5296858
200B 200W 382M 5435632

可以看到平均耗时减少了37%左右,还是影响很大的;

log_performance_test_opt.png
Log模块针对localtime优化的压测对比

Log模块优化过后,对zonesvr进行注册的压测可以看到,日志模块中关于时区设置的相关开销,已经基本不存在了,最终整个日志的开销也减少了5%左右。但最终日志的开销还是占了15%左右,这个只能从打日志的逻辑触发,去一一优化了。

tzset_internal_localtime_r.png
优化过后时区设置的开销(调用堆栈关系不太准确)

4. 总结

对于业务日志量大的问题,只能一条条慢慢的优化,对日志进行一定的收敛,减少不必要的开销。所以同步日志接口虽然实现和用起来方便,但其实对于性能还是有很大影响的,因为特别是在做业务的时候,你的性能可能很容易受到日志量暴增的影响,日志带来的开销很多时候不太可控,所以从性能的角度来说,还是建议使用异步的logsvr来处理业务中的log落地。

https://github.com/bminor/glibc/blob/release/2.29/master/time/localtime.c

https://github.com/bminor/glibc/blob/release/2.29/master/time/tzset.c

https://stackoverflow.com/questions/19170721/real-time-awareness-of-timezone-change-in-localtime-vs-localtime-r

http://www.udpwork.com/item/12925.html

https://langzi989.github.io/tags/Linux/