如何对日志文件进行二分查找？开源文件二分查找工具『timecat』介绍_sus视觉激光刻印机如何进行查找日志?-CSDN博客

本文链接：https://blog.csdn.net/fanfank/article/details/50507337

这篇文章是我从自己的博客搬运过来的

转载请注明：吹水小镇 | reetsee.com
原文链接地址： http://blog.reetsee.com/archives/502

要获得更好的阅读体验，欢迎大家到这篇文章的原地址 http://blog.reetsee.com/archives/502 进行阅读

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

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

这个项目的作者是：reetsee.xu，即吹水。

安装方式很简单，只要你装了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。

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

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

碰到非搜索时间段内的日志时，直接跳过；
尽量减少对日志文件内容的逻辑判断，过多的判断会造成时间和CPU的浪费。

1 思路

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

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

当发现日期时间小于1月1号20点13分14秒，就直接跳过不处理；
当发现日期时间在这个区间 [ 1月1号20点13分14秒, 1月1号20点14分13秒 )，那么就用正则或者用grep去匹配一下有没有对应关键字，有就直接输出；
当发现日期时间大于等于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个参数：

第一个参数是-s参数，它表示希望timecat获取日志的起始时间；
第二个参数是-e参数，它表示希望timecat获取日志的终止时间（不包括这个时间本身）；
第三个参数是文件的路径，这里可以指定多个文件路径。

所以使用起来是非常简单的，要注意的是，-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的所有用法，是不是很容易？

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

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

测试流程：

执行sync，清空读写cache，让timecat查找6g.log中2015年12月25日9点钟的所有日志，并输出到『test_timecat.out』，得到资源消耗、执行时间等数据；
执行sync，清空读写cache，让grep查找6g.log中2015年12月25日9点钟的所有日志，并输出到『test_grep.out』，得到资源消耗、执行时间等数据；
执行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)	平均CPU占用(%)	User time(s)	System time(s)
spancat	9.49	71	4.76	2.05

测试对象	Minor (reclaiming a frame) page faults	Major (requiring I/O) page faults	File system inputs(Byte)	File system outputs(Byte)
spancat	1683	16	1794048	1778416

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

4.3 grep测试

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

测试结果：

测试对象	总耗时(s)	平均CPU占用(%)	User time(s)	System time(s)
grep	16.31	70	3.81	7.70

测试对象	Minor (reclaiming a frame) page faults	Major (requiring I/O) page faults	File system inputs(Byte)	File system outputs(Byte)
grep	299	6	11735800	1778408

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

测试结果：