Oct 1, 2018 - 从应用到操作系统查接口超时(下)

Comments

应用复现


接着上文 从应用到操作系统查接口超时(上) 继续排查导致接口超时的原因。

转载随意,请注明来源地址:https://zhenbianshu.github.io

Jdk 的 native 方法当然不是终点,虽然发现 Jdk、docker、操作系统 Bug 的可能性极小,但再往底层查却很可能发现一些常见的配置错误。

为了便于复现,我用 JMH 写了一个简单的 demo,控制速度不断地通过 log4j2 写入日志。将项目打包成 jar 包,就可以很方便地在各处运行了。

@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.MICROSECONDS)
@State(Scope.Benchmark)
@Threads(5)
public class LoggerRunner {
    public static void main(String[] args) throws RunnerException {

        Options options = new OptionsBuilder()
                .include(LoggerRunner.class.getName())
                .warmupIterations(2)
                .forks(1)
                .measurementIterations(1000)
                .build();
        new Runner(options).run();
    }
}

我比较怀疑是 docker 的原因。但是在 docker 内外运行了 jar 包却发现都能很简单地复现日志停顿问题。而 jdk 版本众多,我准备首先排查操作系统配置问题。

系统调用


strace 命令很早就使用过,不久前还用它分析过 shell 脚本执行慢的问题( 解决问题,别扩展问题),但我还是不太习惯把 Java 和它联系起来,幸好有部门的老司机指点,于是就使用 strace 分析了一波 Java 应用。

命令跟分析普通脚本一样, strace -T -ttt -f -o strace.log java -jar log.jar, -T 选项可以将每一个系统调用的耗时打印到系统调用的结尾。当然排查时使用 -p pid 附加到 tomcat 上也是可以的,虽然会有很多容易混淆的系统调用。

对比 jmh 压测用例输出的 log4j2.info() 方法耗时,发现了下图中的状况。

一次 write 系统调用竟然消耗了 147ms,很明显地,问题出在 write 系统调用上。

文件系统


结构

这时候就要好好回想一下操作系统的知识了。

在 linux 系统中,万物皆文件,而为了给不同的介质提供一种抽象的接口,在应用层和系统层之间,抽象了一个虚拟文件系统层(virtual file system, VFS)。上层的应用程序通过 系统调用 system call 操作虚拟文件系统,进而反馈到下层的硬件层。

由于硬盘等介质操作速度与内存不在同一个数量级上,为了平衡两者之间的速度,linux 便把文件映射到内存中,将硬盘单位块(block)对应到内存中的一个 页(page)上。这样,当需要操作文件时,直接操作内存就可以了。当缓冲区操作达到一定量或到达一定的时间后,再将变更统一刷到磁盘上。这样便有效地减少了磁盘操作,应用也不必等待硬盘操作结束,响应速度得到了提升。

而 write 系统调用会将数据写到内存中的 page cache,将 page 标记为 脏页(dirty) 后返回。

linux 的 writeback 机制

对于将内存缓冲区的内容刷到磁盘上,则有两种方式:

首先,应用程序在调用 write 系统调用写入数据时,如果发现 page cache 的使用量大于了设定的大小,便会主动将内存中的脏页刷到硬盘上。在此期间,所有的 write 系统调用都会被阻塞。

系统当然不会容忍不定时的 write 阻塞,linux 还会定时启动 pdflush 线程,判断内存页达到一定的比例或脏页存活时间达到设定的时间,将这些脏页刷回到磁盘上,以避免被动刷缓冲区,这种机制就是 linux 的 writeback 机制。

猜测

了解了以上基础知识,那么对于 write 系统调用为什么会被阻塞,提出了两种可能:

  • page cache 可用空间不足,导致触发了主动的 flush,此时会阻塞所有对此 device 的 write。
  • 写入过程被其他事务阻塞。

首先对于第一种可能: 查看系统配置 dirty_ratio 的大小: 20。此值是 page cache 占用系统可用内存(real mem + swap)的最大百分比, 我们的内存为 32G,没有启用 swap,则实际可用的 page cache 大小约为 6G。

另外,与 pdflush 相关的系统配置:系统会每 vm.dirty_writeback_centisecs (5s) 唤醒一次 pdflush 线程, 发现脏页比例超过 vm.dirty_background_ratio (10%) 或 脏页存活时间超过 vm.dirty_expire_centisecs(30s) 时,会将脏页刷回硬盘。

查看 /proc/meminfoDirty/Writeback 项的变化,并对比服务的文件写入速度,结论是数据会被 pdflush 刷回到硬盘,不会触发被动 flush 以阻塞 write 系统调用。

ext4 的 journal 特性


write 被阻塞的原因

继续搜索资料,在一篇文章(Why buffered writes are sometimes stalled )中看到 write 系统调用被阻塞有以下可能:

  • 要写入的数据依赖读取的结果时。但记录日志不依赖读文件;
  • wirte page 时有别的线程在调用 fsync() 等主动 flush 脏页的方法。但由于锁的存在,log 在写入时不会有其他的线程操作;
  • 格式为 ext3/4 的文件系统在记录 journal log 时会阻塞 write。而我们的系统文件格式为 ext4。维基百科上的一个条目( https://en.wikipedia.org/wiki/Journaling_block_device ) 也描述了这种可能。

journal

journal 是 文件系统保证数据一致性的一种手段,在写入数据前,将即将进行的各个操作步骤记录下来,一旦系统掉电,恢复时读取这些日志继续操作就可以了。但批量的 journal commit 是一个事务,flush 时会阻塞 write 的提交。

我们可以使用 dumpe2fs /dev/disk | grep features 查看磁盘支持的特性,其中有 has_journal 代表文件系统支持 journal 特性。

ext4 格式的文件系统在挂载时可以选择 (jouranling、ordered、writeback) 三种之一的 journal 记录模式。

三种模式分别有以下特性:

  • journal: 在将数据写入文件系统前,必须等待 metadata 和 journal 已经落盘了。
  • ordered: 不记录数据的 journal,只记录 metadata 的 journal 日志,且需要保证所有数据在其 metadata journal 被 commit 之前落盘。 ext4 在不添加挂载参数时使用此模式。
  • writeback: 数据可能在 metadata journal 被提交之后落盘,可能导致旧数据在系统掉电后恢复到磁盘中。

当然,我们也可以选择直接禁用 journal,使用 tune2fs -O ^has_journal /dev/disk,只能操作未被挂载的磁盘。

由于 pdflush 进程向磁盘刷入数据会触发 journal 事务,导致 write 被阻塞,所以解决 journal 问题就可以解决接口超时问题。

解决方案与压测结果


以下是我总结的几个接口超时问题的解决方案:

  1. log4j2 日志模式改异步。但有可能会在系统重启时丢失日志,另外在异步队列 ringbuffer 被填满未消费后,新日志会自动使用同步模式。
  2. 调整系统刷脏页的配置,将检查脏页和脏页过期时间设置得更短(1s 以内)。但理论上会略微提升系统负载(未明显观察到)。
  3. 挂载硬盘时使用 data=writeback 选项修改 journal 模式。 但可能导致系统重启后文件包含已删除的内容。
  4. 禁用 ext4 的 journal 特性。但可能会导致系统文件的不一致。
  5. 把 ext4 的 journal 日志迁移到更快的磁盘上,如 ssd、闪存等。操作复杂,不易维护。
  6. 使用 xfs、fat 等 文件系统格式。特性不了解,影响不可知。

当然,对于这几种方案,我也做了压测,以下是压测的结果。

 文件系统特性 接口超时比例
  ext4(同线上) 0.202%
  xfs文件系统 0.06%
  page过期时间和pdflush启动时间都设置为 0.8s 0.017%
  ext4 挂载时 journal 模式为 writeback 0%
  禁用 ext4 的 journal 特性 0%
  log4j2 使用异步日志 0%

小结


接口超时问题总算是告一段落,查了很久,不过解决它之后也非常有成就感。遗憾的是没有在 linux 内核代码中找到证据,160M 的代码,分层也不熟悉,实在是无从查起,希望以后有机会能慢慢接触吧。

程序员还是要懂些操作系统知识的,不仅帮我们在应对这种诡异的问题时不至于束手无策,也可以在做一些业务设计时能有所参考。

又熟悉了一些系统工具和命令,脚手架上又丰富了。

关于本文有什么疑问可以在下面留言交流,如果您觉得本文对您有帮助,欢迎关注我的 微博GitHub

Sep 22, 2018 - 从应用到操作系统查接口超时(上)

Comments

问题


之前的博文中说过最近在查一个问题,花费了近两个星期,问题算是有了一个小结,是时候总结一下了。

排查过程走了很多弯路,由于眼界和知识储备问题,也进入了一些思维误区,希望此问题能以后再查询此类问题时能有所警示和参考;而且很多排查方法和思路都来自于部门 leader 和 组里大神给的提示和启发,总结一下也能对这些知识有更深的理解。

这个问题出现在典型的高并发场景下,现象是某个接口会偶尔超时,查了几个 case 的日志,发现 httpClient 在请求某三方接口结束后输出一条日志时间为 A,方法返回后将请求结果解析成为 JSON 对象后,再输出的日志时间为 B, AB之间的时间差会特别大,100-700ms 不等,而 JSON 解析正常是特别快的,不应该超过 1ms。

转载随意,请注明来源地址:https://zhenbianshu.github.io

GC


首先考虑导致这种现象的可能:

  • 应用上有锁导致方法被 block 住了,但 JSON 解析方法上并不存在锁,排除这种可能。
  • JVM 上,GC 可能导致 STW。
  • 系统上,如果系统负载很高,操作系统繁忙,线程调度出现问题可能会导致这种情况,但观察监控系统发现系统负载一直处于很低的水平,也排除了系统问题。

我们都知道 JVM 在 GC 时会导致 STW,进而导致所有线程都会暂停,接下来重点排查 GC 问题。

首先我们使用 jstat 命令查看了 GC 状态,发现 fullGC 并不频繁,系统运行了两天才有 100 来次,而 minorGC 也是几秒才会进行一次,且 gcTime 一直在正常范围。

由于我们的 JVM 在启动时添加了 -XX:+PrintGCApplicationStoppedTime 参数,而这个参数的名字跟它的意义并不是完全相对的,在启用此参数时,gclog 不仅会打印出 GC 导致的 STW,其他原因导致的 STW 也会被记录到 gclog 中,于是 gclog 就可以成为一个重要的排查工具。

查看 gclog 发现确实存在异常状况,如下图:

系统 STW 有时会非常频繁地发生,且持续时间也较长,其中间隔甚至不足 1ms,也就是说一次停顿持续了几十 ms 之后,系统还没有开始运行,又会进行第二次 STW,如上图的情况,系统应该会一次 hang 住 120ms,如果次数再频繁一些,确实有可能会导致接口超时。

安全点和偏向锁


安全点日志

那么这么频繁的 STW 是由什么产生的呢,minorGC 的频率都没有这么高。

我们知道,系统在 STW 前,会等待所有线程安全点,在安全点里,线程的状态是确定的,其引用的 heap 也是静止的,这样,JVM 才能安心地进行 GC 等操作。至于安全点的常见位置和安全点的实现方式网卡有很多文章介绍这里不再多提了,这里重点说一下安全点日志。

安全点日志是每次 JVM 在所有线程进入安全点 STW 后输出的日志,日志记录了进入安全点用了多久,STW 了多久,安全点内的时间都是被哪个步骤消耗的,通过它我们可以分析出 JVM STW 的原因。

服务启动时,使用 -XX:+UnlockDiagnosticVMOptions -XX:+PrintSafepointStatistics -XX:+LogVMOutput -XX:LogFile=./safepoint.log 参数,可以将安全点日志输出到 safepoint.log 中。

在安全点日志中,我发现有很多下图类似的日志输出:

从前面的 vmopt 列可以得知,进入安全点的原因是 RevokeBias, 查资料得知,这是在释放 偏向锁

偏向锁

偏向锁是 JVM 对锁的一种优化,JVM 的开发人员统计发现绝大部分的锁都是由同一个线程获取,锁争抢的可能性很小,而系统调用一次加锁释放锁的开销相对很大,所以引入偏向锁默认锁不会被竞争,偏向锁中的 “偏向” 便指向第一个获取到锁的线程。在一个锁在被第一次获取后,JVM 并不需要用系统指令加锁,而是使用偏向锁来标志它,将对象头中 MarkWord 的偏向锁标识设置为1,将偏向线程设置为持续锁的线程 ID,这样,之后线程再次申请锁时如果发现这个锁已经 “偏向” 了当前线程,直接使用即可。而且持有偏向锁的线程不会主动释放锁,只有在出现锁竞争时,偏向锁才会释放,进而膨胀为更高级别的锁。

有利则有弊,偏向锁在单线程环境内确实能极大降低锁消耗,但在多线程高并发环境下,线程竞争频繁,而偏向锁在释放时,为了避免出现冲突,需要等到进入全局安全点才能进行,所以每次偏向锁释放会有更大的消耗。

明白了 JVM 为什么会频繁进行 STW,再修改服务启动参数,添加 -XX:-UseBiasedLocking 参数禁用偏向锁后,再观察服务运行。

发现停顿问题的频率下降了一半,但还是会出现,问题又回到原点。

Log4j


定位

这时候就需要猜想排查了。首先提出可能导致问题的点,再依次替换掉这些因素压测,看能否复现来确定问题点。

考虑到的问题点有 HttpClient、Hystrix、Log4j2。使用固定数据替换了三方接口的返回值,删去了 Hystrix,甚至将逻辑代码都删掉,只要使用 Log4j2 输出大量日志,问题就可以复现,终于定位到了 Log4j2,原来是监守自盗啊。。

虽然定位到 Log4j2,但日志也不能不记啊,还是要查问题到底出在哪里。

使用 btrace 排查 log4j2 内的锁性能。

首先考虑 Log4j2 代码里的锁,怀疑是由于锁冲突,导致输出 log 时被 block 住了。

查看源码,统计存在锁的地方有三处:

  • rollover() 方法,在检测到日志文件需要切换时会锁住进行日志文件的切分。
  • encodeText() 方法,日志输出需要将各种字符集的日志都转换为 byte 数组,在进行大日志输出时,需要分块进行。为了避免多线程块之间的乱序,使用synchronized 关键字对方法加锁。
  • flush() 方法,同样是为了避免不同日志之间的穿插乱序,需要对此方法加锁。

具体是哪一处代码出现了问题呢,我使用 btrace 这一 Java 性能排查利器进行了排查。

使用 btrace 分别在这三个方法前后都注入代码,将方法每次的执行时间输出,然后进行压测,等待问题发生,最终找到了执行慢的方法: encodeText()

排查代码并未发现 encodeText 方法的异常(千锤百炼的代码,当然看不出什么问题)。

使用 jmc 分析问题

这时,组内大神建议我使用 jmc 来捕捉异常事件。 给 docker-compose 添加以下参数来启用环境的 JFR。

environment:
   - JFR=true
   - JMX_PORT=port
   - JMX_HOST=ip
   - JMX_LOGIN=user:pwd

在记录内查找停顿时间附近的异常事件,发现耗时统计内有一项长耗时引人注目,调用 RandomAccessFile.write() 方法竟然耗时 1063 ms,而这个时间段和线程 ID 则完全匹配。

查看这个耗时长的方法,它调用的是 native 方法 write()。。。

native 方法再查下去就是系统问题了,不过我比较怀疑是 docker 的问题,会再接着排查,等有结论了再更新。

解决

问题总是要解决的,其实也很简单:

  • 服务少记一些日志,日志太多的话才会导致这个问题。
  • 使用 Log4j2 的异步日志,虽然有可能会在缓冲区满或服务重启时丢日志。

小结


查问题的过程确实学习到了很多知识,让我更熟悉了 Java 的生态,但我觉得更重要的是排查问题的思路,于是我总结了一个排查问题的一般步骤,当作以后排查此类问题的 checkList。

  1. 尽量分析更多的问题 case。找出他们的共性,避免盯错问题点。比如此次问题排查开始时,如果多看几个 case 就会发现,日志停顿在任何日志点都会出现,由此就可以直接排除掉 HttpClient 和 Hystrix 的影响。
  2. 在可控的环境复现问题。在测试环境复现问题可能帮助我们随时调整排查策略,极大地缩短排查周期。当然还需要注意的是一定要跟线上环境保持一致,不一致的环境很可能把你的思路带歪,比如我在压测复现问题时,由于堆内存设置得太小,导致频繁发生 GC,让我错认为是 GC 原因导致的停顿。
  3. 对比变化,提出猜想。在服务出现问题时,我们总是先问最近上线了什么内容,程序是有惯性的,如果没有变化,系统一般会一直正常运行。当然变化不止是时间维度上的,我们还可以在多个服务之间对比差异。
  4. 排除法定位问题。一般我们会提出多个导致问题的可能性,排查时,保持一个变量在变化,再对比问题的发生,从而总结出变量对问题的影响。
  5. 解决。当我们定位到问题之后,问题的解决一般都很简单,可能只需要改一行代码。

当然还有一个非常重要的点,贯穿始末,那就是 数据支持,排查过程中一定要有数据作为支持。通过总量、百分比数据的前后对比来说服其他人相信你的理论,也就是用数据说话。

关于本文有什么疑问可以在下面留言交流,如果您觉得本文对您有帮助,欢迎关注我的 微博GitHub

Sep 15, 2018 - 解决问题,别扩展问题

Comments

由来


最近有个需求需要统计一个方法的耗时,这个方法前后各打出一条日志,类似于 [INFO] 20180913 19:24:01.442 method start/end unique_id,unique_id 是我们框架为了区分每一个请求而生成的唯一ID。

由于在高并发场景下, start 和 end 的日志并不一定是挨着的,很可能方法执行期间,又有其他的日志输出了出来,于是产生了这样的日志:

[INFO] 20180913 19:24:01.442 method start aaa
[INFO] 20180913 19:24:01.452 method start bbb
[INFO] 20180913 19:24:01.456 do something ccc
[INFO] 20180913 19:24:01.562 method end aaa
...

由于日志在服务器上,不想再把日志 down 下来,又因为日志比较规范,于是决定自己写个 shell 脚本来处理这些数据。花了一下午时间,换了 4 个 shell 脚本,才优雅地处理了这些数据,其中走进了思维误区,踩了一个扩展问题的大坑。

转载随意,请注明来源地址:https://zhenbianshu.github.io

初入坑


思路

处理这个问题的第一步,肯定是拿到要处理的这些数据,首先用 grep 命令加输出重定向可以轻松地拿到这些数据,一共 76W。

由于需要考虑不同请求日志的穿插问题,又加上用久了 PHP 的数组和 Java 的 map 而形成的惯性思维,又加上我最近学习的 bash 的关联数据用法,我决定把 start 日志和 end 日志,拆分为两个文件,然后将这些数据生成两个大的关联数组,以 unique_id 为键,以当时的时间戳为值,分别存储请求的开始时间(arr_start)和结束时间(arr_end)。最后再遍历结束时间数组(arr_end),并查找开始时间数组内的值,进行减法运算,将差值输出到另一个文件里。

这样,写出的脚本就是这样:

脚本

#!/bin/bash

# 获取准确时间的函数
function get_acc_time() {
    arr=($1)
	date_str=${arr[1]}" "${arr[2]}
	# date -d "date_str" "+%format" 可以指定输入日期,以替代默认的当前时间
	# cut 根据 '.' 切分,并取第二个字段
	echo `date -d "$date_str" "+%s"`"."`echo  ${arr[2]} | cut -d '.' -f2`
}

# 使用 -A 声明关联数组
declare -A arr_start
declare -A arr_end

# 构造开始时间数组
while read -r start_line
do
	arr_start[${arr[5]}]=`get_acc_time $start_line`
done < $start_file

# 构造结束时间数组
while read -r end_line
do
    arr_end[${arr[5]}]=`get_acc_time $end_line`
done < $end_file

# 遍历结束时间数组
for request in ${!arr_end[*]}
do
	end_time=${arr_end[$request]}
	start_time=${arr_start[$request]}
	if [ -z "$start_time" ]; then
		continue;
	fi
	# 直接使用 bc 不会显示小数点前的 0
	echo `print "%.3f" echo "scale=3;$end_time-$start_time"| bc` >> $out_file
done

越陷越深


这个脚本有个缺陷就是它执行得非常慢(后面小节有对它速度的分析),而且中途没有输出,我根本不知道它什么进度,运行了半个小时还没有输出,急于解决问题,我就换了一个方法。

排序并行法

这时我想让它忙尽快有结果输出出来,让我随时能看到进度,而且只有部分结果出来时我也能进行分析。那么有没有办法让我在遍历”结束日志”的时候能很轻松地找到”开始日志”里面对应的那条请求日志呢?

因为日志是按时间排序的,如果保持其时间序的话,我每次查找开始日志都得在一定的时间范围内找,而且遍历到下一条结束日志后,开始日志的查找起点也不好确定。 如果用上面的日志示例,我查找 unique_id 为 aaa 的请求时,我必须查找 19:24:01.442-19:24:01.562 这一时间范围内的所有日志,而且查找 unique_id 为 bbb 的请求时,无法确定时间起点,如果从开头遍历的话,消耗会非常大。

这个方法肯定是不可行的,但我可以把这些请求以 unique_id 排序,排序后它们会像两条并行的线,就像:

开始日志 aaa bbb ccc ddd eee fff
结束日志 aaa bbb ccc ddd eee fff

我只需要记录每一个 unique_id 在结束日志里的的行数,查找开始时间时,直接取开始日志里的对应行就可以了。

使用 sort -k 5 start.log >> start_sorted.log 将日志排下序,再写脚本处理。

#!/bin/bash

function get_acc_time() {
    date_str=$1" "$2
    acc_time=`date -d "$date_str" "+%s"`"."`echo  $2 | cut -d '.' -f2`
	echo $acc_time
}

total=`cat $end_file | wc -l`
i=0
while read -r start_line
do
	i=`expr $i + 1`
	arr_start=($start_line)

	# 如果取不到的话去下一行取
	for j in `seq $i $total`
	do
		end_line=`awk "NR==$j" $end_file` // 用 awk 直接取到第 N 行的数据
		arr_end=($end_line)

        # 判断两条日志的 unique_id 一样
		if [ "${arr_start[5]}" = "${arr_end[5]}" ];then
			break
		fi
			i=`expr $i + 1`
	done

	start_time=`get_acc_time ${arr_start[1]} ${arr_start[2]}`
	end_time=`get_acc_time ${arr_end[1]} ${arr_end[2]}`

	echo `print "%.3f" echo "scale=3;$end_time-$start_time"| bc` >> $out_file
done < $start_file

非常遗憾的是,这个脚本执行得非常慢,以每秒 1 个结果的速度输出,不过我还没有技穷,于是想新的办法来解决。

全量加载法

这次我以为是 awk 执行得很慢,于是我想使用新的策略来替代 awk,这时我想到将日志全量加载到内存中处理。 于是我又写出了新的脚本:

#!/bin/bash
function get_time() {
        date_str=$1" "`echo $2 | cut -d '.' -f1`
        acc_time=`date -d "$date_str" "+%s"`"."`echo  $2 | cut -d '.' -f2`
	echo $acc_time
}

SAVEIFS=$IFS # 保存系统原来的分隔符(空格)
IFS=$'\n' # 将分隔符设置为换行,这样才能将文件按行分隔为数组

start_lines=(`cat $start_file`)
end_lines=(`cat $end_file`)

total=`cat $end_file | wc -l`
i=0
IFS=$SAVEIFS # 将分隔符还设置回空格,后续使用它将每行日志切分为数组
for start_line in ${start_lines[*]}
do
	arr_start=($start_line)

	for j in `seq $i $total`
	do
		end_line=${end_lines[$j]}
		arr_end=($end_line)

		if [  -z "$end_line"  -o "${arr_start[5]}" = "${arr_end[5]}" ];then
			break
		fi
			i=`expr $i + 1`
	done

	i=`expr $i + 1`
	start_time=`get_time ${arr_start[1]} ${arr_start[2]}`
	end_time=`get_time ${arr_end[1]} ${arr_end[2]}`

	echo `print "%.3f" echo "scale=3;$end_time-$start_time"| bc` >> $out_file
done

脚本运行起来后,由于需要一次加载整个日志文件,再生成大数组,系统顿时严重卡顿(幸好早把日志传到了测试机上),一阵卡顿过后,我看着依然每秒 1 个的输出沉默了。

新的思路


这时终于想到问一下边上的同事,跟同事讲了一下需求,又说了我怎么做的之后,同事的第一反应是 “你为啥非要把日志拆开?”,顿时豁然开朗了,原来我一开始就错了。

如果不把日志分开,而是存在同一个文件的话,根据 unique_id 排序的话,两个请求的日志一定是在一起的。再用 paste 命令稍做处理,将相邻的两条日志合并成一行,再使用循环读就行了,命令很简单: cat start.log end.log | sort -k 5 | paste - - cost.log,文件生成后,再写脚本来处理。

#!/bin/bash
function get_time() {
    date_str=$1" "`echo $2 | cut -d '.' -f1`
    acc_time=`date -d "$date_str" "+%s"`"."`echo  $2 | cut -d '.' -f2`
	echo $acc_time
}

while read -r start_line
do
	arr_s=($start_line)

	start_time=`get_time ${arr_s[1]} ${arr_s[2]}`
	end_time=`get_time ${arr_s[5]} ${arr_s[6]}`

    # 每行前面输出一个 unique_id
	echo -e ${arr_s[5]}" \c" >> $out_file
	echo `print "%.3f" echo "scale=3;$end_time-$start_time"| bc` >> $out_file
done < $start_file

再次运行,发现速度虽然还不尽如人意,但每秒至少能有几十个输出了。使用 split 将文件拆分为多个,开启多个进程同时处理,半个多小时,终于将结果统计出来了。

脚本运行速度分析


问题虽然解决了,但脚本运行慢的原因却不可放过,于是今天用 strace 命令分析了一下。 由于 strace 的 -c 选项只统计系统调用的时间,而系统调用实际上是非常快的,我更需要的时查看的是各个系统调用之间的时间,于是我使用 -r 选项输出了两个步骤之间的相对时间,统计了各步骤间相对时间耗时。

read 慢

从统计数据可以看到它的很大一部分时间都消耗在 read 步骤上,那么, read 为什么会这么慢呢?

仔细检视代码发现我使用很多 ` 创建子进程,于是使用 stace 的 -f 选项跟踪子进程,看到输出如下:

可以看出进程创建一个子进程并执行命令,到最后回收子进程的消耗是很大的,需要对子进程进行信号处理,文件描述符等操作。最终工作的代码只有一个 write 且耗时很短。

由于脚本是完全同步运行的,所以子进程耗时很长,主进程的 read 也只能等待,导致整个脚本的耗时增加。

为了验证我的猜测,我把脚本简写后,使用 time 命令统计了耗时分布。

while read -r start_line
do
	str=`echo "hello"`
done < $start_file

可以看得出来,绝大部分时间都是系统时间。

循环慢

另外一个问题是,最终解决问题的脚本和全量加载法的脚本在主要步骤上并没有太大差异,但效率为什么会差这么多呢?

我忽然注意到脚本里的一个循环 for j in `seq $i $total`, 这个语句也创建了子进程,那它跟主进程之间的交互就是问题了所在了, 在脚本运行初期,$i 非常小,而 $total 是结束日志的总行数:76W,如果 seq 命令是产生一个这么大的数组。。。

我使用 strace 跟踪了这个脚本,发现有大量的此类系统调用:

总算破案了。

小结


在这个问题的解决上,我的做法有很多不对的地方。

首先,解决问题过程中,脚本不正常地效率低,我没有仔细分析,而是在不停地避开问题,寻找新的解决方案,但新方案的实施也总有困难,结果总在不停地试错路上。

然后是解决问题有些一根筋了,看似找到了一个又一个方案,其实这些方案都是旧方案的补丁,而没有真正地解决问题。从A问题引入了B问题,然后为了解决B问题又引入了C问题,直到撞到南墙。

在第一家公司,初入编程领域时,我当时的 leader 老是跟我们强调一定要避免 “X-Y” 问题。针对 X 问题提出了一个方案,在方案实施过程中,遇到了问题 Y,于是不停地查找 Y 问题的解决办法,而忽略了原来的问题 X。有时候,方案可能是完全错误的,解决 Y 问题可能完全没有意义,换一种方案,原来的问题就全解决了。

在跟别人交流问题时,我一直把初始需求说清楚,避免此类问题,没想到这次不知不觉就沉入其中了,下次一定注意。

关于本文有什么疑问可以在下面留言交流,如果您觉得本文对您有帮助,欢迎关注我的 微博GitHub