Improve ccache-report

bin/verilator_ccache_report

@@ -4,8 +4,11 @@
 
 import argparse
 import collections
+import pathlib
 import re
 
+from datetime import datetime
+
 parser = argparse.ArgumentParser(
     allow_abbrev=False,
     formatter_class=argparse.RawDescriptionHelpFormatter,
@@ -23,22 +26,33 @@ parser.add_argument('-o',
                     metavar="OUTFILE",
                     required=True,
                     help='output file')
-parser.add_argument('logfile',
-                    type=argparse.FileType('r'),
-                    help='ccache log file')
+parser.add_argument('logdir', type=pathlib.Path, help='log directory')
 
 args = parser.parse_args()
 
 results = {}
+elapsed = {}
 
-for line in args.logfile:
-    line = line.strip()
-    match = re.match(r'.*Object file: (.*)$', line)
-    if match:
-        obj = match.group(1)
-    match = re.match(r'.*Result: (.*)$', line)
-    if match:
-        results[obj] = match.group(1)
+
+def toDateTime(s):
+    return datetime.strptime(s, "%Y-%m-%dT%H:%M:%S.%f")
+
+
+for logfile in args.logdir.iterdir():
+    with logfile.open() as fh:
+        start = None
+        obj = None
+        for line in fh:
+            line = line.strip()
+            match = re.match(r'\[(\S+)\s.*Object file: (.*)$', line)
+            if match:
+                start = toDateTime(match.group(1))
+                obj = match.group(2)
+            match = re.match(r'\[(\S+)\s.*Result: (.*)$', line)
+            if match:
+                assert obj is not None
+                elapsed[obj] = toDateTime(match.group(1)) - start
+                results[obj] = match.group(2)
 
 args.o.write("#" * 80 + "\n")
 args.o.write("ccache report (from verilator_ccache_report) :\n")
@@ -47,19 +61,33 @@ if not results:
     args.o.write("\nAll object files up to date\n")
 else:
     args.o.write("\nCompiled object files:\n")
-    width = max(len(_) for _ in results) + 1
+    wnames = max(len(_) for _ in results) + 1
+    wresults = max(len(_) for _ in results.values()) + 1
     for k in sorted(results.keys()):
-        args.o.write("{:{width}} : {}\n".format(k, results[k], width=width))
+        args.o.write("{:{wnames}} : {:{wresults}} : {}s\n".format(
+            k,
+            results[k],
+            elapsed[k].total_seconds(),
+            wnames=wnames,
+            wresults=wresults))
 
     args.o.write("\nSummary:\n")
     counts = collections.Counter(_ for _ in results.values())
     total = sum(counts.values())
-    width = max(len(_) for _ in results.values()) + 1
     for k in sorted(counts.keys()):
         c = counts[k]
         args.o.write("{:{width}}| {} ({:.2%})\n".format(k,
                                                         c,
                                                         c / total,
-                                                        width=width))
+                                                        width=wresults))
+
+    args.o.write("\nLongest:\n")
+    longest = sorted(list(elapsed.items()),
+                     key=lambda kv: -kv[1].total_seconds())
+    for i, (k, v) in enumerate(longest):
+        args.o.write("{:{width}}| {}s\n".format(k,
+                                                v.total_seconds(),
+                                                width=wnames))
+        if i > 4: break
 
 args.o.write("#" * 80 + "\n")

include/verilated.mk.in

@@ -269,15 +269,20 @@ ifneq ($(findstring ccache-report,$(MAKECMDGOALS)),)
   endif
 
   # Report ccache behaviour for this invocation of make
-  export CCACHE_LOGFILE := $(VM_PREFIX).ccache-log
+  VK_CCACHE_LOGDIR := ccache-logs
   VK_CCACHE_REPORT := $(VM_PREFIX)__ccache_report.txt
-  # Truncate logfile
-  $(shell echo "" > $(CCACHE_LOGFILE))
-  # Remove previous report
-  $(shell rm -f $(VK_CCACHE_REPORT))
+  # Remove previous logfiles and report
+  $(shell rm -rf $(VK_CCACHE_LOGDIR) $(VK_CCACHE_REPORT))
+
+$(VK_CCACHE_LOGDIR):
+	mkdir -p $@
+
+$(VK_OBJS): | $(VK_CCACHE_LOGDIR)
+
+$(VK_OBJS): export CCACHE_LOGFILE=$(VK_CCACHE_LOGDIR)/$@.log
 
 $(VK_CCACHE_REPORT): $(VK_OBJS)
-	$(VERILATOR_CCACHE_REPORT) -o $@ $(CCACHE_LOGFILE)
+	$(VERILATOR_CCACHE_REPORT) -o $@ $(VK_CCACHE_LOGDIR)
 
 .PHONY: ccache-report
 ccache-report: $(VK_CCACHE_REPORT)

test_regress/t/t_ccache_report.pl

@@ -31,8 +31,7 @@ my $report = "$Self->{obj_dir}/$Self->{VM_PREFIX}__ccache_report.txt";
 
 # We do not actually want to make this test depend on whether the file was
 # cached or not, so trim the report to ignore actual caching behaviour
-run(cmd => ["sed", "-i", "-e", "'s/ : .*/ : IGNORED/; /^Summary/,\$d;'", $report]);
-
+run(cmd => ["sed", "-i", "-e", "'s/ : .*/ : IGNORED/; /|/s/.*/IGNORED/;'", $report]);
 files_identical($report, "t/$Self->{name}__ccache_report_initial.out");
 
 # Now rebuild again (should be all up to date)

test_regress/t/t_ccache_report__ccache_report_initial.out

@@ -2,8 +2,11 @@
 ccache report (from verilator_ccache_report) :
 
 Compiled object files:
-Vt_ccache_report__ALL.o   : IGNORED
-Vt_ccache_report__main.o  : IGNORED
-verilated.o               : IGNORED
-verilated_vcd_c.o         : IGNORED
+Vt_ccache_report__ALL.o  : IGNORED
 
+Summary:
+IGNORED
+
+Longest:
+IGNORED
+################################################################################