最近在对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时进行压测，得出的结果可以看到：

上面可以看到日志开销还是比较大的，且通过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的虚拟机性能是差的)：

在压测注册的过程中，注册 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后，进行压测，发现性能有很大的提升。

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

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/