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

目录

数值预报业务系统所使用的调度软件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