From 778c35dce97cc3daf7350f56171d98a50b46c451 Mon Sep 17 00:00:00 2001
From: Richard Liu <liuzhenglaichn@gmail.com>
Date: Fri, 13 Jul 2018 21:09:37 -0700
Subject: [PATCH] added report_extract.py

---
 .../get_leader_tps_average.sh                 |  9 --
 aws-experiment-launch/report_extractor.py     | 96 +++++++++++++++++++
 benchmark.go                                  |  4 +-
 3 files changed, 98 insertions(+), 11 deletions(-)
 delete mode 100755 aws-experiment-launch/get_leader_tps_average.sh
 create mode 100644 aws-experiment-launch/report_extractor.py

diff --git a/aws-experiment-launch/get_leader_tps_average.sh b/aws-experiment-launch/get_leader_tps_average.sh
deleted file mode 100755
index 5b53e0872..000000000
--- a/aws-experiment-launch/get_leader_tps_average.sh
+++ /dev/null
@@ -1,9 +0,0 @@
-if [ $# -eq 0 ]; then
-    echo "Please the directory of the log"
-    exit 1
-fi
-DIR=$1
-for file in $(ls $DIR/*leader*)
-do
-  cat $file | egrep -o "TPS=[0-9]+" | cut -f2 -d "=" | awk '{ sum += $1; n++ } END { if (n > 0) print sum / n; }';
-done
\ No newline at end of file
diff --git a/aws-experiment-launch/report_extractor.py b/aws-experiment-launch/report_extractor.py
new file mode 100644
index 000000000..a6758f61f
--- /dev/null
+++ b/aws-experiment-launch/report_extractor.py
@@ -0,0 +1,96 @@
+import json
+import sys
+import os
+import argparse
+
+def formatFloat(v):
+    return "%.2f" % v
+
+def formatPercent(v):
+    return formatFloat(v) + "%"
+
+def formatMem(v):
+    return formatFloat(float(v) / 10**6) + "MB"
+
+class Profiler:
+    def __init__(self):
+        self.tps = 0
+        self.tps_max = 0
+        self.tps_min = sys.maxsize
+        self.tps_count = 0
+
+        self.cpu_percent = 0
+        self.cpu_usr = 0
+        self.cpu_sys = 0
+        self.cpu_count = 0
+
+        self.mem_rss = 0
+        self.mem_rss_max = 0
+        self.mem_count = 0
+
+    def handleTPS(self, obj):
+        tps = obj["TPS"]
+        self.tps += tps
+        self.tps_max = max(self.tps_max, tps)
+        self.tps_min = min(self.tps_min, tps)
+        self.tps_count += 1
+
+    def handleCPU(self, obj):
+        # http://psutil.readthedocs.io/en/latest/#psutil.Process.cpu_times
+        # https://stackoverflow.com/questions/556405/what-do-real-user-and-sys-mean-in-the-output-of-time1
+        # http://psutil.readthedocs.io/en/latest/#psutil.Process.cpu_percent
+        self.cpu_percent += obj["percent"]
+        times = json.loads(obj["times"])
+        self.cpu_usr = times["user"]
+        self.cpu_sys = times["system"]
+        self.cpu_count += 1
+    
+    def handleMem(self, obj):
+        # http://psutil.readthedocs.io/en/latest/#psutil.Process.memory_info
+        info = json.loads(obj["info"])
+        rss = info["rss"]
+        self.mem_rss += rss
+        self.mem_rss_max = max(self.mem_rss_max, rss)
+        self.mem_count += 1
+
+    def report(self):
+        print("TPS",
+            "Avg", formatFloat(self.tps / self.tps_count),
+            "Min", formatFloat(self.tps_min),
+            "Max", formatFloat(self.tps_max))
+        print("CPU",
+            "Percent (Avg)", formatPercent(self.cpu_percent / self.cpu_count),
+            "Time (Usr)", str(self.cpu_usr) + "s",
+            "Time (Sys)", str(self.cpu_sys) + "s")
+        print("Mem",
+            "RSS (Max)", formatMem(self.mem_rss_max),
+            "RSS (Avg)", formatMem(self.mem_rss / self.mem_count))
+
+def profileFile(path):
+    print(path)
+    profiler = Profiler()
+    with open(path) as f:
+        for line in f:
+            obj = json.loads(line)
+            if obj["lvl"] != "info":
+                continue
+            if obj["msg"] == "TPS Report":
+                profiler.handleTPS(obj)
+            elif obj["msg"] == "CPU Report":
+                profiler.handleCPU(obj)
+            elif obj["msg"] == "Mem Report":
+                profiler.handleMem(obj)
+    profiler.report()
+
+# Example: python report_extractor.py --folder ../tmp_log/log-20180713-205431
+if __name__ == "__main__":
+    parser = argparse.ArgumentParser(
+        description="This script extracts reports from log files")
+    parser.add_argument("--folder", type=str, dest="folder",
+                        default="",
+                        help="the path to the log folder")
+    args = parser.parse_args()
+
+    for filename in os.listdir(args.folder):
+        if "leader" in filename: 
+            profileFile(os.path.join(args.folder, filename))
\ No newline at end of file
diff --git a/benchmark.go b/benchmark.go
index ebb9c6b38..b5f9f5188 100644
--- a/benchmark.go
+++ b/benchmark.go
@@ -108,7 +108,7 @@ func logCPUUsage(consensus *consensus.Consensus) {
 	for {
 		percent, _ := p.CPUPercent()
 		times, _ := p.Times()
-		log.Info("CPU Report", "Percent", percent, "Times", times, "consensus", consensus)
+		log.Info("CPU Report", "percent", percent, "times", times, "consensus", consensus)
 		time.Sleep(10 * time.Second)
 	}
 }
@@ -143,7 +143,7 @@ func main() {
 	logFileName := fmt.Sprintf("./%v/%s-%v-%v.log", *logFolder, role, *ip, *port)
 	h := log.MultiHandler(
 		log.StdoutHandler,
-		log.Must.FileHandler(logFileName, log.LogfmtFormat()), // Log to file
+		log.Must.FileHandler(logFileName, log.JSONFormat()), // Log to file
 		// log.Must.NetHandler("tcp", ":3000", log.JSONFormat()) // Log to remote
 	)
 	log.Root().SetHandler(h)