大日志文件中查找日志条目

programming/python
目录

数值预报业务系统所使用的调度软件 SMS 的日志保存文本文件中，日志结构如下所示：

# MSG:[04:27:43 8.9.2017] alter:/meso_post/00/meso_chartos/rundir/cn_plot_10m_wind/cn_plot_10m_wind_sep_020 [variable] by nwp_pd@53063265

分析系统运行情况时，需要找到指定日期范围内的所有日志。 解析日志条目时，先找到条目中的日期字符串，再将其转为日期对象，判断是否满足条件。
从日志条目中提取时间的函数如下所示：

def get_date_from_line(line):
    start_pos = 7
    end_pos = line.find(']', start_pos)
    time_string = line[start_pos:end_pos]
    date_time = datetime.datetime.strptime(time_string, '%H:%M:%S %d.%m.%Y')
    line_date = date_time.date()
    return line_date

下面首先介绍定位日志行数的基本方法。

基本方法

Python 中读取文本文件最常用的方式就是遍历 file 对象，逐行读取：

with open(file_path, 'r') as f:
    for line in f:
        do_something(line)

对应本文就是逐行解析日志条目，先寻找起始日期，再寻找结束日期。 但对于大日志文件，逐行读取的效率太低。

例如一个 1GB 的日志文件，共 840 多万行，日期从 2017 年 8 月 4 日到 2017 年 9 月 8 日。 在其中寻找 2017.09.01 至 2017.09.04 对应的行数耗时 137 秒。

经过对整个程序进行 profile，可以发现 get_data_from_line 函数被调用 740 多万次，耗时 126 秒，占总时间的 91.7%。 显然是整个程序的瓶颈所在。

优化程序的切入点就在于如何减少 get_data_from_line 函数的调用。

日志文件的特点

日志文件一般按时间顺序排列，SMS 的日志文件正是按照时间发生的时间依次写入到文本文件中。
我们可以充分利用时间字段已排序的特点，加速上面的查找过程。

加速方法

借鉴二分查找算法，一次读取多行日志，如果最后一条记录不满足条件，则跳过该次读取的日志，继续读取下一批日志。

python 中通过调用 islice() 函数可以一次读取多行文本文件:

with open(file_path, 'r') as f:
    next_n_lines = list(islice(f, max_line_no))
    do_something(next_n_lines)

从修改后程序的 profile 结果来看，总体查找时间缩短为 6 秒，get_data_from_line 函数只调用 8600 多次，耗时 0.3 秒，占总时间 5%。

上述方法有效减少 get_data_from_line 函数的调用次数，极大提高整个程序的效率。

两种算法的完整代码

def get_date_from_line(line):
    start_pos = 7
    end_pos = line.find(']', start_pos)
    time_string = line[start_pos:end_pos]
    date_time = datetime.datetime.strptime(time_string, '%H:%M:%S %d.%m.%Y')
    line_date = date_time.date()
    return line_date

def get_line_no_range(log_file_path, begin_date, end_date):
    begin_line_no = 0
    end_line_no = 0
    with open(log_file_path) as log_file:
        cur_line = 0
        for line in log_file:
            if not line.startswith('#'):
                # some line is :
                # check emergency
                # so, just ignore it.
                continue
            cur_line += 1
            line_date = get_date_from_line(line)
            if line_date >= end_date:
                return begin_line_no, end_line_no   # (0,0)
            if line_date >= begin_date:
                begin_line_no = cur_line
                break
        else:
            return begin_line_no, end_line_no   # (0,0)
        # find begin_line_no
        for line in log_file:
            cur_line += 1
            line_date = get_date_from_line(line)
            if line_date >= end_date:
                end_line_no = cur_line
                break
        else:
            end_line_no = cur_line + 1
    return begin_line_no, end_line_no

def get_line_no_range_v2(log_file_path, begin_date, end_date, max_line_no = 1000):
    begin_line_no = 0
    end_line_no = 0
    with open(log_file_path) as log_file:
        cur_first_line_no = 1
        while True:
            next_n_lines = list(islice(log_file, max_line_no))
            if not next_n_lines:
                return begin_line_no, end_line_no
            # if last line less then begin date, skip to next turn.
            cur_last_line = next_n_lines[-1]
            line_date = get_date_from_line(cur_last_line)
            if line_date < begin_date:
                cur_first_line_no = cur_first_line_no + len(next_n_lines)
                continue
            # find first line greater or equal to begin_date
            for i in range(0, len(next_n_lines)):
                cur_line = next_n_lines[i]
                line_date = get_date_from_line(cur_line)
                if line_date >= begin_date:
                    begin_line_no = cur_first_line_no + i
                    break
            # begin line must be found
            assert begin_line_no > 0
            # check if some line greater or equal to end_date,
            # if begin_line_no == end_line_no, then there is no line returned.
            for i in range(begin_line_no - 1, len(next_n_lines)):
                cur_line = next_n_lines[i]
                line_date = get_date_from_line(cur_line)
                if line_date >= end_date:
                    end_line_no = cur_first_line_no + i
                    if begin_line_no == end_line_no:
                        begin_line_no = 0
                        end_line_no = 0
                    return begin_line_no, end_line_no
            cur_first_line_no = cur_first_line_no + len(next_n_lines)
            end_line_no = cur_first_line_no
            break
        while True:
            next_n_lines = list(islice(log_file, max_line_no))
            if not next_n_lines:
                break
            cur_last_line = next_n_lines[-1]
            # if last line less than end_date, skip to next run
            line_date = get_date_from_line(cur_last_line)
            if line_date < end_date:
                cur_first_line_no = cur_first_line_no + len(next_n_lines)
                continue
            # find end_date
            for i in range(0, len(next_n_lines)):
                cur_line = next_n_lines[i]
                line_date = get_date_from_line(cur_line)
                if line_date >= end_date:
                    end_line_no = cur_first_line_no + i
                    return begin_line_no, end_line_no
            else:
                return begin_line_no, cur_first_line_no + len(next_n_lines)
    return begin_line_no, end_line_no