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

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

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

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

1. Log性能开销

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

LOG模块日志开销
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模块写入测试

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

2. Log模块问题定位

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

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

我们可以在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
39
/* 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模块针对localtime优化的压测对比

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

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

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/