python - Python-具有“可疑”时间的日志文件二进制搜索

Question

有没有办法使用Python对日志文件中的“可疑时间”进行有效的二进制搜索？
我有一个日志文件，其条目如下：

02:38:18  0  RcvTxData - 11 : Telegram received and process completed - MCP35 Tx -24239
02:38:20  0  RcvNewTxNo - 3 : MCP36 Set receive trigger
02:38:21  0  RcvNewTxNo - 1 : 
02:38:21  0  RcvNewTxNo - 1 : MCP35 get new Tx 24241
02:38:23  0  RcvTxData - 11 : Telegram received and process completed - MCP36 Tx -13918
02:38:23  0  RcvNewTxNo - 3 : MCP36 Set receive trigger
02:38:24  0  RcvNewTxNo - 1 : 
02:38:24  0  RcvTxData - 11 : Telegram received and process completed - MCP35 Tx -24241
02:38:24  0  RcvNewTxNo - 3 : MCP35 Set receive trigger
02:38:27  0  RcvNewTxNo - 1 : 
02:38:27  0  RcvNewTxNo - 1 : MCP36 get new Tx 13920
09:44:54  0  RcvNewTxNo - 1 : 
09:44:54  0  RcvNewTxNo - 1 : MCP24 get new Tx 17702
09:44:54  0  RcvNewTxNo - 2 : MCP24 Read last Tx before new Tx 17702
09:44:56  0  RcvNewTxNo - 1 : 
09:45:00  0  RcvTxData - 7 :MCP24 Prepare normal TxData to DB
09:45:01  0  RcvTxData - 8 :MCP24 complete call GetTxData
09:45:02  0  RcvTxData - 11 : Telegram received and process completed - MCP10 Tx -9008
09:45:02  0  RcvNewTxNo - 3 : MCP10 Set receive trigger
09:45:04  0  RcvNewTxNo - 1 : 
09:45:04  0  RcvNewTxNo - 3 : MCP24 Set receive trigger
09:45:16  0  RcvNewTxNo - 1 : 
09:45:16  0  RcvNewTxNo - 1 : MCP19 get new Tx 9133
09:45:16  0  RcvNewTxNo - 2 : MCP19 Read last Tx before new Tx 9133
09:45:17  0  RcvTxData - 1 :MCP19 gwTx-9133 lastTx-9131 newTx-0
09:45:17  0  RcvTxData - 4 :MCP19 Adjusted newTxNo_Val-9132
09:45:17  0  RcvTxData - 4.1 :MCP19 FnCode PF
09:45:23  0  RcvTxData - 1 :MCP24 gwTx-17706 lastTx-17704 newTx-0

从上面的例子可以看出，日志的时间没有减少，并且时间可能会突然跳跃：

02:38:27  0  RcvNewTxNo - 1 : MCP36 get new Tx 13920
09:44:54  0  RcvNewTxNo - 1 : #there is a big jump here

我的目标是检测这个可疑的行，返回它的行和索引。
我已经创建了一个函数来检测这个“可疑时间”。但是，日志文件的大小大约为 22,000到 44,000行。因此，我的算法相当慢，因为我从一行到另一行：

f = open(fp, "r")
notEmpty = True
oldTime = None
while(notEmpty): #this can be executed 22,000 - 44,000 times
    l = f.readline()
    notEmpty = l != ""
    if not notEmpty:
        break
    t = datetime.datetime.strptime(l[0:8], fmt)
    if oldTime is None:
        oldTime = t
    else:
        tdelta = t - oldTime
        if tdelta.seconds > 3600: #more than 1 hour is suspicious
            print("suspicious time: " + str(t) + "\told time: " + str(oldTime))
        oldTime = t

有没有什么方法可以通过对Python中的日志文件进行二进制搜索来加快搜索速度？
（注：除了二进制搜索之外的任何其他搜索建议，只要它比暴力搜索更好，同样受到赞赏）
编辑：
我已经部分地实现了 Torxed的解决方案（并且修复了一些错误）：

with open(fp, 'rb') as fh:
    prev_time = datetime.datetime.strptime(fh.readline()[0:5].decode('utf-8'), '%H:%M')
    index = 0
    for line in fh:
        if len(line) == 0: continue
        index += 1
        t = datetime.datetime.strptime(line[0:4].decode('utf-8'), '%H:%M')
        if (t - prev_time).total_seconds() > 3600:
            print('\tSuspicious time:', t, '\told time:', prev_time, '\tat: ', str(index))
        prev_time = t

不过，正如他在回答中提出的一些“黑客”问题，我还想添加一些文件的附加特性，这些特性可能值得“黑客”来提高性能：
如果没有可疑时间，整个文件的时间戳从第一个条目到最后一个条目的持续时间不超过6小时
两个时间戳之间，如果没有可疑时间，则相差不超过1小时
可疑时间最有可能发生在第20000行之后和第30000行之前（因此，很可能会跳过其他一些行）。
有没有办法在这里实施进一步的“黑客攻击”？

Answer 1

所有这些都归结为重新分解代码以使其高效（从硬件+缓存的角度）。
我会考虑一些设计更改并优化代码，以便在执行读取操作时不创建或调用任何不必要的内容。

prev_time = None
with open(fp, 'rb') as fh:
    prev_time = datetime.datetime.strptime(fh.readline()[0:5].decode('utf-8'), '%H:%M')

    for line in fh:
        if len(line) == 0: continue

        t = datetime.datetime.strptime(line[0:5].decode('utf-8'), '%H:%M')
        if (t - prev_time).total_seconds() > 3600:
            print('Suspicious time:', t, '\told time:', prev_time)
        prev_time = t

首先，旧时代没有逻辑而不是试图去做？，我们只需获取第一行并在进入我们的大 for ...循环之前在其中输入一个时间。这样我们每读一行就可以节省几微秒，最后就可以节省很多时间。
然后我们也使用 with open仅仅是因为我们不想在最后打开任何文件句柄。如果你查了很多文件，这很重要。
我们还使用 is not notEmpty跳过 is this line empty, if so continue3行逻辑。
我们还将时间转换缩短到不包括秒，这是一个小的编辑，但最终可能会节省很多时间，因为我们只使用了您的操作总共2/3的数据。
最后一个改进是，我们将文件作为二进制对象打开，这意味着我们将跳过Python代码中可能完成的任何自动 binary -> hex/ascii转换。这将对处理速度产生巨大的影响，唯一的缺点是 strptime需要一个类似字符串的对象。我的计算方法（我没有大量的atm文本文件）是，5个字母的转换速度将比python内部将文档数据从二进制转换为字符串数据的总体速度快。我可能是错的。
希望这能让你的日子好过一点。
噢，请记住，这只是一种方式，这意味着如果时间差向后移动，您将得到一个负值（它可能不会以顺序时间日志格式显示）。。但你永远不知道）
编辑：
寻觅黑客
如果你能预测每一行长度的大致估计值，那么做起来会更快：

data = fh.read(5)
t = datetime.datetime ...
fh.seek(128) # Skip 128 bytes, hopefully this is enough to find a new line.:
data = fh.read(5) # again
                              # This just shows you the idea, obviously not perfect working code here hehe.

要获取 00:00时间戳，显然这个逻辑需要更多一些，例如，您需要监视是否实际通过了行标记 \r\n等，但是，由于Python不知道一行有多长，所以寻找 \r\n标记与您大致了解并能够跳过大部分数据相比是时间搜索的一个巨大优势。因此，考虑绕过这一点，因为跳过大多数数据vs使用广义运算函数总是更快。
请注意，我们在这里追求微秒，所以每一个疯狂的想法和体力劳动都可能在这里得到回报。
使用seek的Additiona hacks：
假设您知道在一个大堆栈中有足够的相似时间戳，那么您可以通过执行以下操作轻松跳过几行：

for line in fh:
    if len(line) == 0: continue
    # Check the line

    fh.seek(56 * 10000) # Average length of a line is 56 characters (calculated this over a few of your lines, so give or take +-10 here)
                                     # And we multiply this with 10000, essentially skipping ~10k lines

如果这里的时间有一个大的飞跃，你可以：

    if diff > 3600:
        fh.seek(fh.tell() - 5000)

跳回5000条线路，检查时差是否仍然和10公里线路上的时差一样大，也许你确实有时差。你也可以用这个来缩小时差发生的地方（但我把这个留给你，有更好的方法可以用最少的不占用处理能力的人工来找到它）。
从本质上讲，这可以归结为~4个在最佳世界中寻找，并通过检查新行结尾等手动执行 for line in fh。。像这样的：

from functools import partial
import datetime
jump_gap = 56 * 10000 # average row length * how many rows you want to jump

def f_jump(fh, jump_size):
    fh.seek(fh.tell() + jump_size)
    while fh.read(1) not in ('\n', ''):
        continue
    return True

with open('log.txt', 'rb') as fh:
    prev_time = datetime.datetime.strptime(fh.read(5).decode('utf-8'), '%H:%M')
    f_jump(fh, jump_gap) # Jump to the next jump since we got a starting time

    for chunk in iter(partial(fh.read, 5), ''): # <-- Note here! We only read 5 bytes
                                                                 # there for it's very important we check for new
                                                                 # rows manually and set the pointed at the start
                                                                 # of a new line, this is what `f_jump()` does later.
        if chunk == '':
            break # we clearly hit rock bottom

        t = datetime.datetime.strptime(chunk.decode('utf-8'), '%H:%M')
        if (t - prev_time).total_seconds() > 3600:
            print('\tSuspicious time:', t, '\ttold time:', prev_time, '\tat: ', fh.tell())

        prev_time = t
        f_jump(fh, jump_gap)

免责声明：一个限制，我从不计算行数。但我会在日志文件中告诉你发生这种情况的位置。
这很有用，因为您可以执行以下操作：

('\tSuspicious time:', datetime.datetime(1900, 1, 1, 9, 44), '\ttold time:', datetime.datetime(1900, 1, 1, 2, 38), '\tat: ', 636)

你取 636这是文件位置，
你把它输入到 tail中，就像这样：

[user@firefox ~]$ tail -c 636 log.txt 
ete call GetTxData
09:45:02  0  RcvTxData - 11 : Telegram received and process completed - MCP10 Tx -9008
09:45:02  0  RcvNewTxNo - 3 : MCP10 Set receive trigger

这显示了问题发生的位置，我现在可以回溯这些东西。
或者我可以去香蕉和扔一些Linux忍者魔术周围做：

 x=`tail -c 636 log.txt -n 1`; grep -B 20 -A 3 "$x" log.txt

这给了我确切的数据在哪里发生的事情，但也20行之前，所以我可以回溯它一点点。
由于您需要行号（可能是您的老板或同事的行号），因此可以将 -n添加到grep命令中，并按此方式获取：

x=`tail -c 636 log.txt -n 1`; grep -B 20 -A 3 -n "$x" log.txt

[user@firefox ~]$ x=`tail -c 636 log.txt -n 1`; grep -B 20 -A 3 -n "$x" log.txt
8-02:38:24  0  RcvTxData - 11 : Telegram received and process completed - MCP35 Tx -24241
9-02:38:24  0  RcvNewTxNo - 3 : MCP35 Set receive trigger
10-02:38:27  0  RcvNewTxNo - 1 : 
11-02:38:27  0  RcvNewTxNo - 1 : MCP36 get new Tx 13920
12-09:44:54  0  RcvNewTxNo - 1 : 
13-09:44:54  0  RcvNewTxNo - 1 : MCP24 get new Tx 17702
14-09:44:54  0  RcvNewTxNo - 2 : MCP24 Read last Tx before new Tx 17702
15-09:44:56  0  RcvNewTxNo - 1 : 
16-09:45:00  0  RcvTxData - 7 :MCP24 Prepare normal TxData to DB
17-09:45:01  0  RcvTxData - 8 :MCP24 complete call GetTxData
18-09:45:02  0  RcvTxData - 11 : Telegram received and process completed - MCP10 Tx -9008
19-09:45:02  0  RcvNewTxNo - 3 : MCP10 Set receive trigger
20-09:45:04  0  RcvNewTxNo - 1 : 
21-09:45:04  0  RcvNewTxNo - 3 : MCP24 Set receive trigger
22-09:45:16  0  RcvNewTxNo - 1 : 
23-09:45:16  0  RcvNewTxNo - 1 : MCP19 get new Tx 9133
24-09:45:16  0  RcvNewTxNo - 2 : MCP19 Read last Tx before new Tx 9133
25-09:45:17  0  RcvTxData - 1 :MCP19 gwTx-9133 lastTx-9131 newTx-0
26-09:45:17  0  RcvTxData - 4 :MCP19 Adjusted newTxNo_Val-9132
27-09:45:17  0  RcvTxData - 4.1 :MCP19 FnCode PF
28:09:45:23  0  RcvTxData - 1 :MCP24 gwTx-17706 lastTx-17704 newTx-0

由于 seek()黑客的性质，细粒化这可能有点困难，但是在这个例子中，我在 row 28得到了成功，这不是有问题的实际行，但它给了我一个近距离的展示，并且有了 tail + grep我可以很快地回溯到 row 12是错误的时差。
我希望这能有帮助。