Start of a log processing tool

[jberthold]

First version so we get a baseline for additional code to add later.

Supported commands:

filter CONTEXT_FILTER [CONTEXT_FILTER]

filters the log on stdin or given in file option -i

$ .build/kore/bin/process-logs filter "proxy>timing." "proxy."  -i log-with-timestamps.json
{"timestamp":"2024-07-05T02:04:09.646316","context":["proxy"],"message":"Loading definition from ./definition.kore, main module \"MX-WASM\""}
{"timestamp":"2024-07-05T02:04:16.971803","context":["proxy"],"message":"Starting RPC server"}
{"timestamp":"2024-07-05T02:05:32.49184","context":["proxy"],"message":"Processing request 1"}
{"timestamp":"2024-07-05T02:05:32.49184","context":["proxy"],"message":"Starting execute request"}
{"timestamp":"2024-07-05T02:05:43.138762","context":["proxy"],"message":"Booster Stuck at Depth {getNat = 0}"}
{"timestamp":"2024-07-05T02:05:43.138762","context":["proxy"],"message":"Simplifying booster state and falling back to Kore"}
{"timestamp":"2024-07-05T02:05:43.138762","context":["proxy"],"message":"Simplifying execution state"}
{"timestamp":"2024-07-05T02:07:00.127314","context":["proxy","timing"],"message":{"kore-time":7.205059572e7,"method":"SimplifyM","time":7.6988472523e7}}
{"timestamp":"2024-07-05T02:07:00.481663","context":["proxy"],"message":"Executing fall-back request"}
{"timestamp":"2024-07-05T02:08:13.156571","context":["proxy"],"message":"kore depth-bound, continuing... (currently at Depth {getNat = 1})"}
{"timestamp":"2024-07-05T02:08:13.156571","context":["proxy"],"message":"Iterating execute request at Depth {getNat = 1}"}
{"timestamp":"2024-07-05T02:09:34.92357","context":["proxy"],"message":"Server shutting down"}
{"timestamp":"2024-07-05T02:09:34.92357","context":["proxy","timing"],"message":[["SimplifyM",{"average":7.6988472523e7,"count":1,"kore-average":7.205059572e7,"kore-max":7.205059572e7,"kore-total":7.205059572e7,"max-val":7.6988472523e7,"min-val":7.6988472523e7,"stddev":0,"total":7.6988472523e7}]]}

find-recursions

Searches contexts for repeated rules/equations, outputs the maximum recursion count found, and a count of recursions for the rule/equation.

$ .build/kore/bin/process-logs find-recursions -i 120+426-simplify-server-new.log
| Context                | Longest | Count | Prefix
|----------------------- | ------- | ----- |-----------
| simplification 7d63500 |       2 |    26 | [request 1][kore][simplify][term d20f3f8][simplification b7ec79f][constraint][term 49a7309][term 68c0d1e]
| simplification a0d171b |       2 |     4 | [request 1][booster][simplify][term 47a0b9a][term 5a2ca39][simplification b7ec79f][constraint][term c609cc3][simplification 7d63500][constraint][term d547132]
| simplification b473543 |       2 |     2 | [request 1][kore][simplify][term d20f3f8][simplification 9fb2d01][constraint][term 3dabef4][term 1a59fb7][simplification e9253cd][constraint][term b2ad8ae][term b28272e][term a61320e][term 4235d4e][term f508bee][term f4925ee][term f4099ee][term f870b2e][term f8ea60e][term f76100e][term f76c34e][term e130fee][term e10212e][term e13614e][term e1329ee][term 66ebb55][function 4e91c9a][constraint][term f829f67][term af7fb3c][term ac31e7f][simplification e30a82a][constraint][term 4a8e686]
| simplification d36bc83 |       2 |    32 | [request 1][kore][simplify][term d20f3f8][simplification b7ec79f][constraint][term 2d166e3][function 806f1ac][constraint][term 91d5b62][term 7526e8d][term c648a18]
| simplification d87d499 |       2 |     4 | [request 1][kore][simplify][term d20f3f8][simplification 9fb2d01][constraint][term 3dabef4][term 1a59fb7][simplification e9253cd][constraint][term a33da02]
| simplification e9253cd |       2 |    36 | [request 1][kore][simplify][term d20f3f8][simplification 9fb2d01][constraint][term 3dabef4][term 1a59fb7]

times-per-rule

Counts and sums up time (if timestamps present) spent using a certain rule/equation at the top level (rewrite or simplify), outputs a sorted list of rules by descending time. NB no split between kore and booster, the log would have to be filtered beforehand to get that.

$ .build/kore/bin/process-logs times-per-rule -i log-with-timestamps.json
| Rule/Equation          | Success             | Failure             | Abort
|----------------------- | ------------------- | ------------------- | -------------------
|        rewrite 589c3c2 |   2.709139s (    1) |   0.000000s (    7) |   0.000000s (    1)
|        rewrite 8560c71 |   1.461561s (    1) |   0.000000s (    8) |   0.000000s (    0)
|        rewrite 69d07db |   1.371660s (    1) |   0.000000s (    7) |   0.000000s (    0)
|        rewrite b8c34b7 |   1.317183s (    1) |   0.000000s (    9) |   0.000000s (    0)
|        rewrite b3ed6e6 |   1.314000s (    1) |   0.000000s (    9) |   0.000000s (    0)
|        rewrite 49dfc9d |   1.304301s (    1) |   0.000000s (    9) |   0.000000s (    0)
|        rewrite 84d9ca4 |   0.229139s (    1) |   0.000000s (   10) |   0.000000s (    0)
|       function UNKNOWN |   0.172207s (    2) |   0.042539s ( 5582) |   0.000000s (    0)
| simplification 0e3f267 |   0.000000s (    0) |   0.087230s (    6) |   0.000000s (    0)
| simplification cc7577b |   0.000000s (    0) |   0.056554s (    6) |   0.000000s (    0)
| simplification 3cbbedc |   0.000000s (    0) |   0.036781s (    6) |   0.000000s (    0)
|       function c078f16 |   0.000000s (    0) |   0.036355s (    2) |   0.000000s (    0)
| simplification 99e34a2 |   0.000000s (    0) |   0.033110s (   95) |   0.000000s (    0)
|        rewrite e952dcd |   0.026578s (    1) |   0.000000s (   10) |   0.000000s (    0)
|       function 8b92687 |   0.000000s (    0) |   0.013105s (    1) |   0.000000s (    0)
| simplification a916a71 |   0.000000s (    0) |   0.008408s (   65) |   0.000000s (    0)
| simplification bab86d4 |   0.000000s (    0) |   0.007228s (   65) |   0.000000s (    0)
| simplification 756dd4f |   0.000000s (    0) |   0.006819s (  190) |   0.000000s (    0)
|        rewrite 952a852 |   0.000000s (    0) |   0.006759s (    9) |   0.000000s (    0)
... many more lines of output

[geo2a]

Nice! I've so far only tested the filter command: very useful, no more need to grep 😄