如何过滤多行/分隔行中定义的模式

Question

这是我的日志的简单通用规范：

• 一个请求来了，记录...[XXXHandler] comming time...
• 获取锁定并开始事务，记录...[XXXHandler] [UID] start time...
• 业务完成并返回锁，记录...[XXXHandler] [UID] spend time...

在实践中，有大量的请求以各自的 UID 齐平，三行模式相互混乱。这是其中的一部分：

~ cat sample.log
[240] [DeleteAllLettersHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [StartBiddingAllianceBossAuctionHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [DeleteAllLettersHandler] [13497] start time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [DeleteAllLettersHandler] [13497] spend time [1] dbs 1 dbu 1 | {}
[240] [StartBiddingAllianceBossAuctionHandler] [1495] start time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [GetMazeMainInfoHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [StartBiddingAllianceBossAuctionHandler] [1495] spend time [1] dbs 1 dbu 0 | {}
[240] [GetMazeMainInfoHandler] [8941] start time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [GetResHarvestInfoHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [GetResHarvestInfoHandler] [1807] start time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [RCHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]     ## gotcha
[240] [GetMazeMainInfoHandler] [8941] spend time [10] dbs 27 dbu 2 | {}
[240] [GetResHarvestInfoHandler] [1807] spend time [5] dbs 15 dbu 4 | {}
[240] [StartBiddingAllianceBossAuctionHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [StartBiddingAllianceBossAuctionHandler] [18052] start time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [StartBiddingAllianceBossAuctionHandler] [18052] spend time [1] dbs 1 dbu 0 | {}
[240] [GetResourceAmount] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [GetResourceAmount] [29063] start time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [GetResourceAmount] [29063] spend time [1] dbs 3 dbu 0 | {}

我的要求是过滤日志，删除杂乱的三行模式，同时我可以看到哪个处理程序挂起（日志来了但没有开始时间）。

---

这是我的解决方案：

- cat process.sh

sed -r '
    $!N
    $!N
    $!N
    s/(([^\n]*\n)*)[^\n]*\[([^\n]*)\] coming time[^\n]*\n(([^\n]*\n)*)[^\n]*\[\3\] \[([^\n]*)\] start time[^\n]*\n(([^\n]*\n)*)[^\n]*\[\3\] \[\6\] spend time[^\n]*(.*)/\1\4\7\9/
    t print     
    P
    D

    :print
' |

grep -v '^ *$'

这可以过滤一些模式，但不是全部，因为 sed 可以处理分散在三或四行的一个模式（sed 轮添加可能更多）行。

~ ./process.sh < sample.log
[240] [StartBiddingAllianceBossAuctionHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [StartBiddingAllianceBossAuctionHandler] [1495] start time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [GetMazeMainInfoHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [StartBiddingAllianceBossAuctionHandler] [1495] spend time [1] dbs 1 dbu 0 | {}
[240] [GetMazeMainInfoHandler] [8941] start time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [RCHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]     ## gotcha
[240] [GetMazeMainInfoHandler] [8941] spend time [10] dbs 27 dbu 2 | {}
[240] [StartBiddingAllianceBossAuctionHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [StartBiddingAllianceBossAuctionHandler] [18052] start time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [StartBiddingAllianceBossAuctionHandler] [18052] spend time [1] dbs 1 dbu 0 | {}

将过滤后的日志作为SEED，一次次过滤，就能得到我想要的结果：

~ ./process.sh < sample.log | ./process.sh
[240] [GetMazeMainInfoHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [GetMazeMainInfoHandler] [8941] start time [Fri Mar 18 05:00:00 GMT-06:00 2016]
[240] [RCHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]     ## gotcha
[240] [GetMazeMainInfoHandler] [8941] spend time [10] dbs 27 dbu 2 | {}

~ ./process.sh < sample.log | ./process.sh | ./process.sh
[240] [RCHandler] coming time [Fri Mar 18 05:00:00 GMT-06:00 2016]     ## gotcha

看来我只需要再过滤几次就可以得到最终需要的结果。于是我问了一个问题：shell pipe process repeat, @tripleee 的回答对我很有用。大致经过五次过滤后，我可以得到每条日志的最终结果。

---

但是耗时太长，一个10K行的日志，这样过滤一般需要10分钟。

所以我的问题是，你能想出一个更好的方法吗？或者如何改进我的方式让它运行得更快。

感谢您的宝贵时间！

Answer 1

我认为 bash 不能胜任您的问题。

我想推荐你试试 perl。解析日志并将 [Handler Name, question, start,finish] 四元组保存到哈希表中，然后您可以扫描哈希表以查找挂起的处理程序。这是更可扩展的解决方案，恕我直言。