[taler-grid5k] 106/189: viualizer can parse log lines / formatted output

[gnunet]

This is an automated email from the git hooks/post-receive script.

marco-boss pushed a commit to branch master
in repository grid5k.

commit 014c5c29fa1a9a4dd788595d707d46ccb083ee16
Author: Boss Marco <bossm8@bfh.ch>
AuthorDate: Tue Mar 22 20:54:09 2022 +0100

    viualizer can parse log lines / formatted output
---
 additional/explain-visualizer/example.log | 25 ++++++++++
 additional/explain-visualizer/explain.py  | 83 +++++++++++++++++++++----------
 2 files changed, 82 insertions(+), 26 deletions(-)

diff --git a/additional/explain-visualizer/example.log 
b/additional/explain-visualizer/example.log
new file mode 100644
index 0000000..653c6a8
--- /dev/null
+++ b/additional/explain-visualizer/example.log
@@ -0,0 +1,25 @@
+2022-03-22 18:43:44.104 UTC [89] LOG:  statement: EXPLAIN (ANALYZE, VERBOSE, 
BUFFERS, FORMAT JSON) Select * from reserves join reserves_in using 
(reserve_pub) where reserve_pub='x';
+2022-03-22 18:44:40.956 UTC [92] LOG:  statement: select * from reserves where 
reserve_pub='x';
+2022-03-22 18:53:19.795 UTC [92] LOG:  statement: select * from reserves where 
reserve_pub='x';
+2022-03-22 18:53:20.577 UTC [92] LOG:  statement: select * from reserves where 
reserve_pub='x';
+2022-03-22 18:53:21.135 UTC [92] LOG:  statement: select * from reserves where 
reserve_pub='x';
+2022-03-22 18:53:21.646 UTC [92] LOG:  statement: select * from reserves where 
reserve_pub='x';
+2022-03-22 18:53:31.910 UTC [92] ERROR:  syntax error at or near "where" at 
character 42
+2022-03-22 18:53:31.910 UTC [92] STATEMENT:  select * from reserves join 
reserves_out where reserve_pub='x';
+2022-03-22 18:53:35.640 UTC [92] ERROR:  syntax error at or near "where" at 
character 41
+2022-03-22 18:53:35.640 UTC [92] STATEMENT:  select * from reserves join 
reserves_in where reserve_pub='x';
+2022-03-22 18:53:43.136 UTC [92] ERROR:  syntax error at or near "reserve_pub" 
at character 61
+2022-03-22 18:53:43.136 UTC [92] STATEMENT:  select * from reserves join 
reserves_in on reserve_pubwhere reserve_pub='x';
+2022-03-22 18:53:45.680 UTC [92] LOG:  statement: select * from reserves join 
reserves_in on reserve_pub where reserve_pub='x';
+2022-03-22 18:53:45.681 UTC [92] ERROR:  column reference "reserve_pub" is 
ambiguous at character 44
+2022-03-22 18:53:45.681 UTC [92] STATEMENT:  select * from reserves join 
reserves_in on reserve_pub where reserve_pub='x';
+2022-03-22 18:53:51.504 UTC [92] LOG:  statement: select * from reserves join 
reserves_in on(reserve_pub) where reserve_pub='x';
+2022-03-22 18:53:51.504 UTC [92] ERROR:  column reference "reserve_pub" is 
ambiguous at character 44
+2022-03-22 18:53:51.504 UTC [92] STATEMENT:  select * from reserves join 
reserves_in on(reserve_pub) where reserve_pub='x';
+2022-03-22 18:53:55.042 UTC [92] LOG:  statement: select * from reserves join 
reserves_in on (reserve_pub) where reserve_pub='x';
+2022-03-22 18:53:55.042 UTC [92] ERROR:  column reference "reserve_pub" is 
ambiguous at character 45
+2022-03-22 18:53:55.042 UTC [92] STATEMENT:  select * from reserves join 
reserves_in on (reserve_pub) where reserve_pub='x';
+2022-03-22 18:54:01.883 UTC [92] LOG:  statement: select * from reserves join 
reserves_in on (reserve_pub) where reserves.reserve_pub='x';
+2022-03-22 18:54:01.883 UTC [92] ERROR:  column reference "reserve_pub" is 
ambiguous at character 45
+2022-03-22 18:54:01.883 UTC [92] STATEMENT:  select * from reserves join 
reserves_in on (reserve_pub) where reserves.reserve_pub='x';
+2022-03-22 18:54:06.817 UTC [92] LOG:  statement: select * from reserves join 
reserves_in using (reserve_pub) where reserves.reserve_pub='x';
diff --git a/additional/explain-visualizer/explain.py 
b/additional/explain-visualizer/explain.py
index 5a8e838..21fe580 100755
--- a/additional/explain-visualizer/explain.py
+++ b/additional/explain-visualizer/explain.py
@@ -4,6 +4,7 @@ from json import loads
 from re import compile
 from subprocess import check_output, CalledProcessError
 from enum import Enum
+from textwrap import fill
 import argparse
 
 
@@ -55,27 +56,33 @@ class Plan:
 plans = {}
 most_time_consuming = Plan("default", Type.RELATION, 0)
 
-partitioned_re = compile('(.*)_([0-9]+|default)')
+partitioned_re = compile('.*_([0-9]+|default)')
+log_statement_re = compile('.*LOG:  statement: (.*);')
 
 args = None
 
 def get_explain(sql) -> dict:
+    print("\n" + "=" * 80 + "\n")
+    print(fill(text=sql, width=80))
+    print("\n" + "=" * 80 + "\n")
     sql = sql.replace("\n", "").replace('"', "")
     sql = "EXPLAIN (ANALYZE, VERBOSE, BUFFERS, FORMAT JSON) " + sql + ";"
     try:
-        analyze_json = check_output(args=['psql',
-                                          '-U', args.db_user,
-                                          '-h', args.db_host,
-                                          '-d', args.db_name,
-                                          '-p', args.db_port,
-                                          '-P', 'pager=off',
-                                          '-qtAXc', sql],
-                                    env={'PGPASSWD': args.db_pw},
-                                    timeout=10)
+        analyze_json = check_output(
+                args=['psql',
+                      '-U', args.db_user,
+                      '-h', args.db_host,
+                      '-d', args.db_name,
+                      '-p', args.db_port,
+                      '-P', 'pager=off',
+                      '-qtAXc', sql],
+                env={'PGPASSWD': args.db_pw},
+                timeout=10
+        )
         return loads(analyze_json)[0]
     except CalledProcessError as e:
         print(e.output)
-        exit(1)
+        print("\nQuery returned an error, skipping analyzation\n")
 
 
 def ensure_partition_added(relation, indent):
@@ -125,7 +132,7 @@ def iterate_plans():
         yield plans[plan]
 
 
-def parse_plan(plan, indent=0):
+def parse_plan(plan, indent=2):
     if 'Plans' in plan:
         ensure_plan_added(plan['Node Type'], indent)
         for _plan in plan['Plans']:
@@ -140,8 +147,8 @@ def print_summary(attr_name):
         if plan.type == Type.RELATION:
             attr = getattr(plan, attr_name)
             total += attr
-            print(f"  {plan.name}: {attr}")
-    print(f"(Total: {total})")
+            print("  {:<25} {:>10}".format(plan.name + ":", attr))
+    print(f"\n  (Total: {total})")
 
 
 def print_non_indexed():
@@ -150,32 +157,42 @@ def print_non_indexed():
         if plan.scan_type == 'Seq Scan':
             print(f"  {plan.name}")
             total += 1
-    print(f"(Total: {total})")
+    print(f"\n  (Total: {total})")
 
 
 def visualize(analyze_json):
+    if analyze_json is None:
+        return
+
     plan = analyze_json['Plan']
 
-    print("General:\n")
-    print(f"Estimated Rows:          {plan['Plan Rows']}")
-    print(f"Actual Rows Returned:    {plan['Actual Rows']}")
-    print(f"Actual Execution Time:   {plan['Actual Total Time']} ms")
+    print("GENERAL:\n")
+    print("  {:<25} {:>10}".format("Estimated Rows:", plan['Plan Rows']))
+    print("  {:<25} {:>10}".format("Actual Rows Returned:", plan['Actual 
Rows']))
+    print("  {:<25} {:>10} ms".format("Actual Execution Time:", plan['Actual 
Total Time']))
 
     parse_plan(plan)
 
-    print("\nSummary: \n")
+    print("\n\nSUMMARY: \n")
     print(f"Rows Returned by Sub-queries:")
+    print("-----------------------------\n")
     print_summary('rows_returned')
     print("\nPartitions Hit:")
+    print("---------------\n")
     print_summary('partitions_hit')
     print("\nNon Indexed Scans on:")
+    print("---------------------\n")
     print_non_indexed()
     print("\nMost Time Consuming:")
-    print(f"{most_time_consuming.name}: {most_time_consuming.time_spent} ms")
+    print("--------------------\n")
+    print("  {:<25} {:>10} ms".format(most_time_consuming.name + ":", 
most_time_consuming.time_spent))
+    print("")
 
-    print("\nDetail:\n")
-    for plan in iterate_plans():
-        plan.print()
+    if args.verbose:
+        print("\nDETAIL:\n")
+        for plan in iterate_plans():
+            plan.print()
+    print("")
 
 
 def analyze_from_query():
@@ -183,11 +200,20 @@ def analyze_from_query():
     visualize(explain)
 
 
-def analyze_from_logs():
+def handle_log_line(line):
     global plans
     plans = {}
+
+    match = log_statement_re.match(line)
+    if match:
+        explain = get_explain(match.group(1))
+        visualize(explain)
+
+
+def analyze_from_logs():
     with open(args.file, 'r') as logs:
-        print(logs)
+        for line in logs:
+            handle_log_line(line)
 
 
 def main():
@@ -219,6 +245,10 @@ def main():
                              type=str,
                              default="",
                              help='Database port, default 5432')
+    global_args.add_argument('-v', '--verbose',
+                             dest='verbose',
+                             action='store_true',
+                             help='Print detailed query plan')
 
     s_p = parser.add_subparsers()
 
@@ -242,6 +272,7 @@ def main():
 
     global args
     args = parser.parse_args()
+
     args.func()
 
 

-- 
To stop receiving notification emails like this one, please contact
gnunet@gnunet.org.