如何对日志文件进行二分查找?二分查找工具timecat介绍

今天我要分享一个头条用于对日志文件进行二分查找的工具：timecat。

项目地址是：https://github.com/fanfank/timecat

安装方式很简单，只要你装了Python 2，那么可以直接在命令行执行如下pip命令：

pip install timecat

或者直接下载源码中的timecat，执行即可。

0 背景

在开始之前，先进行提问：

假设给你一个日志文件 A.log ，它的大小达到了28G

日志的起始时间为 Jan 1 00:00:00 ，日志的结束时间为 Jan 1 23:59:59

现在要求你从中找出 1月1号20点13分14秒 到 1月1号20点14分13秒 的所有日志并输出

你会怎么做？

目前头条的线上环境中，大部分日志切分是按照一天一次的方式进行。也就是说，在每台机器上2016年1月2号的日志全部打到一个文件，2016年1月3号的日志全部打到一个文件，目前我看到最大的一个单一日志文件，大小就是28G。

继续上面的例子，现在我们要在线上的所有机器上，搜 20点13分14秒 到 20点14分13秒 之间的这个日志中的某个关键字，并且把包含这个关键字的日志都输出。如果偷点懒，你可以直接使用grep命令去搜这个文件，但这样给定的时间范围这个条件就没用上了，因为grep会从0点开始搜。这样实际在做无用功，时间久不说，还会浪费大量的磁盘I/O。

并且，我们最终是要搜索线上的（部分或所有）机器，应该尽可能减少执行操作时对机器的影响。

所以，我们有几个基本的思路：

1. 碰到非搜索时间段内的日志时，直接跳过；

2. 尽量减少对日志文件内容的逻辑判断，过多的判断会造成时间和CPU的浪费。

1 思路

还是以上面的例子继续思考。

其实可以这样，我们用awk命令去获取每一行的日期时间：

1. 当发现日期时间小于1月1号20点13分14秒，就直接跳过不处理；

2. 当发现日期时间在这个区间 [1月1号20点13分14秒, 1月1号20点14分13秒 )，那么就用正则或者用grep去匹配一下有没有对应关键字，有就直接输出；

3. 当发现日期时间大于等于1月1号20点14分13秒，就直接退出程序。

看起来没啥问题，能省的好像都省了不少。不过还是不够，因为所有时间小于20点13分14秒的行，实际是没有必要读取的，同时在目标时间段内所有日志行，都进行了读取时间日期的操作。

如果日志文件本身是有序的，这些实际是可以省的，我只需要知道起始时间和结束时间在文件中的位置即可，然后读取这两个位置之间的内容并匹配关键字就行。

要直接对有序的内容进行元素定位，最好的方式之一就是使用二分查找。

2 难点与细节

思路都有，就是细节比较多，以下列出几个。

与传统的二分搜索不一样，日志文件中的每一条日志长度都是不一样的，我们使用 mid = start + (end - start) / 2 得到mid时，并不直接指向一行的行首。所以我们需要找到mid所在行的行首。

要解决死循环的问题，哪怕mid的值前后不一样，但是mid指向的行可能是一样的。

日志文件中可能包含非法的日志行，例如Python业务中，有些地方使用logging.exception("...")打印出来的调用栈就是多行的，而且每一行还没有日期时间。

有的日志文件可能是按升序排的，有的日志文件可能是按降序排的，这两种排序使用的比较运算是不一样的。

不同的日志文件可能有多种不同的日期时间格式，需要对这些日期时间进行格式判断。而且有的日期时间格式之间不能直接比较，例如 Jan 01 18:00:00与 Apr 01 19:00:00 ，谁比较大呢？直接按照字典序来说肯定是 Jan 01 18:00:00这个日期大，而实际不是如此，类似的例子还有 12/30/2014 19:00:00 与 11/25/2015 20:00:00 。

当mid所对应的日志行为非法行时，我们需要顺序向下查找合法的行，如果向下查找失败，那么实际要从mid开始倒序查找，需要解决从文件的一个位置开始倒序读取内容的问题。

3 使用timecat

timecat的命名借鉴了Linux的cat命令，使用也非常简单，只要你有Python 2.x的版本就可以。

3.1 获取timecat

有三种方式获取timecat，分别是用pip，用git，或者直接下载源码。如果你使用的是git下载的方式，还能够直接运行demo文件夹下的demo.sh来查看执行效果。下面给出操作步骤。

通过pip获取

如果你安装了pip那很赞（通常现在的Python都直接包含了pip），无论是在Mac还是在Linux上，都直接执行 pip install timecat就可以了。

通过git获取

如果你没有安装pip，但是有git，那么就使用这条命令直接下载timecat的git仓库：

git clone https://github.com/fanfank/timecat.git

这个时候你可以直接运行一下demo程序查看效果，执行如下命令就可以：

cd timecat/demo && ./demo.sh

应该能够看到如下输出：

直接下载源码文件

执行下面这条命令把文件下载到当前路径：

wget https://raw.githubusercontent.com/fanfank/timecat/master/timecat

然后给timecat加上执行权限：

chmod +x ./timecat

大功告成，接下来就可以使用了。

3.2 小试牛刀

假设你的日志文件如下所示（大家不用看日志内容，只看开头的时间日期即可）：

2016-01-09 17:19:55 68692113882222190977560551 865969137578988688464537824 45127033797620 25268 19794311951 363339271218256312476

2016-01-09 17:19:57 620 57 9676957541840624 638946878393487926780486792 8264753419974059162790266 221945347

2016-01-09 17:19:59 521 131961372942259333254 72174142230175134322552 283404142112130755323294682

2016-01-09 17:20:01 688539156634 467523585 500308101641647812782 760638506088853897676640 939 9861232428742044437504409 821661638908811331 265388383605362517 959268249

2016-01-09 17:20:03 635661147810144176414432793 816603137738591 68545363157279891134139 819 637622125619812

2016-01-09 17:20:05 616173422373449362 585993672 503548 685861354202534861175935452 4554796537058443695487738

2016-01-09 17:20:07 7429683039795652999560918 620657930764

2016-01-09 17:20:09 852490805701941615 383656872473 663855723240467381814340 914191453104695977571 4585 9441078028601307763 441784374740 7755808594652491

2016-01-09 17:20:11 154442965727180531881 3970499952176505510 6696691180156818678 64049767649 729945176906

2016-01-09 17:20:13 86042599715952474756 58960950978864628731244377 317119182225941 895361413416520347 799808993563678401396 303544554690341508623796227 104901 568 430818129

上面的日志是我用随机数生成的，把这个日志保存为demo.log。

这份文件中，日志的开始时间是从 2016-01-09 17:19:55 到 2016-01-09 17:20:13，我们通过以下三个任务来熟悉timecat。

任务1：获取2016-01-09 17:20:01 ~ 2016-01-09 17:20:03的日志

如果你是通过pip获取timecat，那么执行以下命令：

timecat -s '2016-01-09 17:00:00' -e '2016-01-09 17:20:03' ./demo.log

如果是通过git或者直接下载源码的方式获取，执行以下命令（下面不再赘述）：

./timecat -s '2016-01-09 17:00:00' -e '2016-01-09 17:20:03' ./demo.log

执行完毕后，应该看到如下结果：

2016-01-09 17:19:55 68692113882222190977560551 865969137578988688464537824 45127033797620 25268 19794311951 363339271218256312476

2016-01-09 17:19:57 620 57 9676957541840624 638946878393487926780486792 8264753419974059162790266 221945347

2016-01-09 17:19:59 521 131961372942259333254 72174142230175134322552 283404142112130755323294682

2016-01-09 17:20:01 688539156634 467523585 500308101641647812782 760638506088853897676640 939 9861232428742044437504409 821661638908811331 265388383605362517 959268249

最终输出了从 17:19:55 到 17:20:01的日志，为什么没有输出 17:20:03的那行日志呢？因为timecat的时间区间是左闭右开的，所以最终不包括 17:20:03 的日志。

从这个例子，我们知道了运行timecat只需要指定3个参数：

1. 第一个参数是-s参数，它表示希望timecat获取日志的起始时间；

2. 第二个参数是-e参数，它表示希望timecat获取日志的终止时间（不包括这个时间本身）；

3. 第三个参数是文件的路径，这里可以指定多个文件路径。

所以使用起来是非常简单的，要注意的是，-s与-e参数中指定的日期时间格式，因该与日志中出现的日期时间格式一致。

timecat会自动判断日期时间格式，无论你要搜的是syslog，nginx，apache，php，还是python等日志文件，都能自动判别出时间的格式而无需你手动再敲一次。

任务2：获取2016-01-09 17:19:56 ~ 2016-01-09 17:20:00的日志

直接执行命令：

timecat -d '2016-01-09' -s '17:19:56' -e '17:20:00' ./demo.log

这时可以看到以下输出：

2016-01-09 17:19:57 620 57 9676957541840624 638946878393487926780486792 8264753419974059162790266 221945347

2016-01-09 17:19:59 521 131961372942259333254 72174142230175134322552 283404142112130755323294682

这次我们使用的命令参数有点不一样，用了一个新的-d参数，这个参数实际是给大家偷懒用的，如果你的-s和-e里，年月日的部分是一样的，那么可以把它们抽出来统一用-d参数表示。

任务3：获取2016-01-09 17:20:10 ~ EOF的日志

EOF就是一直到文件的末尾。

执行以下命令：

./timecat -d '2016-01-09' -s '17:20:10' ./demo.log

得到的输出结果如下：

2016-01-09 17:20:11 154442965727180531881 3970499952176505510 6696691180156818678 64049767649 729945176906

2016-01-09 17:20:13 86042599715952474756 58960950978864628731244377 317119182225941 895361413416520347 799808993563678401396 303544554690341508623796227 104901 568 430818129

这次我们把-e参数省了，所以timecat就直接从起始时间开始一直读到EOF。

完成上面三个任务后，你就基本掌握了timecat的所有用法，是不是很容易？

最后再说说另外两个参数：

1. 一个是-v参数，用来打印额外信息的，这些信息包括：二分查找的循环次数，整个二分查找过程中一共扫描了多少行内容，最终二分查找出来的日志起始位置和结束位置到底是哪里等；

2. 令一个是--color参数，用来在程序输出错误信息、提示信息时把文字颜色变成红色、或者绿色，如果你运行timecat后输出的内容是在命令行，那么可以加上这个参数，如果不是，那么不建议加这个参数。

4 性能测试 – Benchmark

是骡子是马，也得拉出来遛遛，到底timecat是不是就比awk、grep要快，下面就进行一下测试。

4.1 测试环境与测试步骤说明

这次测试使用的日志文件来源于头条线上机器的真实日志的一部分，大小为5.9G，我将这个文件命名为6g.log。

环境：

宿主机：MacBook Pro (Retina, 13-inch, Early 2015) 2.7 GHz Intel Core i5 8 GB 1867 MHz DDR3 Intel Iris Graphics 6100 1536 MB

虚拟机软件：VirtualBox Version 5.0.10 r104061

虚拟机系统：CentOS 7（Linux version 3.10.0-229.el7.x86_64 (builder@kbuilder.dev.centos.org) (gcc version 4.8.2 20140120 (Red Hat 4.8.2-16) (GCC) ) #1 SMP Fri Mar 6 11:36:42 UTC 2015），1024MB内存，1个CPU

测试流程：

1. 执行sync，清空读写cache，让timecat查找6g.log中2015年12月25日9点钟的所有日志，并输出到『test_timecat.out』，得到资源消耗、执行时间等数据；

2. 执行sync，清空读写cache，让grep查找6g.log中2015年12月25日9点钟的所有日志，并输出到『test_grep.out』，得到资源消耗、执行时间等数据；

3. 执行sync，清空读写cache，让awk查找6g.log中2015年12月25日9点钟的所有日志，并输出到『test_awk.out』，得到资源消耗、执行时间等数据。

4.2 timecat测试

执行命令：

./clear_cache.sh && timecat -s "2015-12-25 09:00:00" -e "2015-12-25 10:00:00" -v "/huge/6g.log" > test_timecat.out

————————————

测试结果：

总耗时(s)：9.49

平均CPU占用(%)：71

User time(s)：4.76

System time(s)：2.05

Minor (reclaiming a frame) page faults：1,683

Major (requiring I/O) page faults：16

File system inputs(Byte)：1,794,048

File system outputs(Byte)：1,778,416

————————————

由于使用了-v参数，所以输出的字节数比实际打印的日志内容多一点。

4.3 grep测试

执行命令：

./clear_cache.sh && grep "2015-12-25 09:" /huge/6g.log > test_grep.out

————————————

测试结果：

总耗时(s)：16.31

平均CPU占用(%)：70

User time(s)：3.81

System time(s)：7.70

Minor (reclaiming a frame) page faults：299

Major (requiring I/O) page faults：6

File system inputs(Byte)：11,735,800

File system outputs(Byte)：1,778,408

————————————

4.4 awk测试

在这次测试中，我们使用的awk脚本如下：

#!/bin/awk

# @file: bench.awk

BEGIN {

st = "2015-12-25 09:00:00";

ed = "2015-12-25 10:00:00";

}

{

datetime = $2" "$3

if (datetime < st) {

next;

} else if (datetime >= ed) {

if (match(datetime, /\w{2}:\w{2}:\w{2}/, _) == 0) {

next;

} else {

exit 0;

}

} else {

print $0;

}

}

END {}

执行命令：

./clear_cache.sh && awk -f "/huge/bench.awk" "/huge/6g.log" > test_awk.out

————————————

测试结果：

总耗时(s)：19.32

平均CPU占用(%)：85

User time(s)：10.30

System time(s)：6.27

Minor (reclaiming a frame) page faults：389

Major (requiring I/O) page faults：5

File system inputs(Byte)：10,551,480

File system outputs(Byte)：1,778,408

————————————

4.5 总体结果对比

timecat，grep，awk的总体对比如下：

————————————

总耗时(s)：

timecat：9.49

grep：16.31

awk：19.32

平均CPU占用(%)：

timecat：71

grep：70

awk：85

User time(s)：

timecat：4.76

grep：3.81

awk：10.30

System time(s)：

timecat：2.05

grep：7.70

awk：6.27

Minor (reclaiming a frame) page faults：

timecat：1683

grep：299

awk：389

Major (requiring I/O) page faults：

timecat：16

grep：6

awk：5

File system inputs(Byte)：

timecat：1,794,048

grep：11,735,800

awk：10,551,480

File system outputs(Byte)：

timecat：1,778,416

grep：1,778,408

awk：1,778,408

————————————

从测试结果来看，timecat无疑是有着巨大优势的，由于使用了“跳读”的方式，因此缺页次数会比较多。但是从执行时间、CPU占用、系统输入输出（I/O）来看，timecat几乎完胜。

但是不是任何时候都适合用timecat？我觉得不是，当文件足够小（3G左右且你的内存比较大时），或者你确定要搜索的内容在日志文件的比较起始或者比较靠后的位置（这样你可以使用tac）时，使用grep或者awk说不定是个更好的选择。

5 结语

为什么要有timecat这个工具？因为确实存在一些情况，我们需要对很大的日志进行处理，我们出于历史原因没有对线上的日志进行很好的切分（虽然要做这个实际上不难），但我们又需要去搜索其中的内容，而你所知道的，出了关键字以外，通常还有一个大致的时间段。

或许有更好、更高级的方法去管理、搜索我们的日志，例如对日志内容进行索引、分类、流式计算，从而更快地获取我们想要的信息，但这样的代价在于我们要搭建一整套与此相关的环境，去维护所有这些组件。

timecat提供的是一种最原始、无需维护、易用、即用而且又能在一定程度上媲美专业工具的功能。或许终有一天，你会用上更专业的工具，但是在那一天来临之前，如果你对庞大的日志有搜索需求，都可以尝试让timecat辅助你。