实时计算引擎在处理实时数据时，要保证新到来的数据被及时得到处理。例如，对于网站的访问日志数据，假设每一分钟有一个日志文件，那么实时计算引擎必须满足能够在一分钟之内处理完这一分钟的日志数据文件，否则会导致日志文件堆积而不能被及时处理。前几天，量子后端团队排查了一次实时计算引擎出现的处理延迟故障，其中使用到了ltrace和strace工具，在这里和大家分享一下。

1. 故障描述

    当天由于大量突发异常数据的到来，导致实时计算引擎在处理每分钟日志文件时的速度大幅下降，出现明显的延迟现象，表现为平均每处理1分钟文件需要2分钟甚至更长的时间，最长可以到5分钟，进而导致了日志文件堆积而不能被处理。

2. 故障分析

    实时计算引擎在处理日志文件时，采用顺次读取各分钟文件中的日志记录到内存中进行计算的方式(compute过程)，因此引擎在每处理完1分钟文件时，需要进行日志的轮转切换(rotate过程)。

    实时计算引擎采用全内存计算的方式，在处理每分钟日志文件和轮转时，都会进行频繁的内存操作：内存的申请和释放(内存管理使用的是glibc库)。在整点轮转(rotate过程)时，会释放掉相当一部分计算过程不再需要的内存。

    经过统计后发现，实时计算引擎在处理故障当天各分钟日志文件时的compute时间和rotate时间有如下的规律：

    (1) 每分钟日志文件的处理时间(compute时间)，整点轮转之后的前半个小时日志(如10:00~10:30的日志)，每处理一分钟日志一般都需要超过1分钟的时间才能处理完；半点之后的日志(如10:31~11:00的日志)，每处理一分钟日志一般只需要十几秒到一分钟以内。

    (2) 每分钟日志文件处理后的轮转时间(rotate时间)，整点轮转时间耗时会比其他时间长很多，整天结束时的轮转时间最长。

    以上统计信息提示我们，实时计算引擎的处理延迟就是发生在了整点rotate轮转之后的前半个小时内，后半个小时基本可以恢复到正常水平：处理1分钟日志文件只需要不到1分钟时间。可见，引擎的处理延迟和整点rotate有一定的联系，是被整点rotate所触发产生的。具体是什么原因导致的，还需要进一步对实时计算引擎发生处理延迟时的状态进行跟踪才能确定。

3. 故障排查

    考虑要具体跟踪到实时计算引擎程序在发生故障时的执行情况，实时得到引擎在做什么操作(如库函数调用、系统调用)时最耗时，才能定位到导致引擎处理延迟的根本原因，这里讨论后选择strace和ltrace工具进行排查过程。其中，strace可以跟踪系统调用情况及耗时情况，ltrace可以跟踪库函数调用情况及耗时情况。

3.1 排查过程

    在测试机上，使用线上版本的实时计算引擎程序，重跑触发故障的日志数据，当整点rotate触发引擎发生处理延迟时，开始使用ltrace和strace工具跟踪引擎当前的运行状态，统计引擎在系统调用和库函数上的调用时间开销。

3.2 排查结果

    以下是对排查过程的结果分析：

4. 解决方法

    由于本次实时计算引擎的处理延迟问题最终定位到是出在glibc的内存管理上，一个简单的解决方案是用tcmalloc替换glibc。但是从长远来看，是否需要我们自己实现内存管理模块，取决于人力资源情况和tcmalloc的发展情况。

5. 经验教训

    最后，感谢这次一起排查问题的同事们：太奇、澄苍、民瞻、渊虹。你们都很牛！