Clojure: timing for namepsace loading

README.md

This is intended to help with profiling slow Clojure startup times:

• Create a csv with start/end times for loading namespaces
• Analyzer script that measures how long each namespace take (substracting time that's needed for loading its dependencies)

Requires building your own patched version of Clojure

Sample output (time in milliseconds):

["clojure/tools/reader/reader_types" 51]
["clojure/core/matrix/impl/defaults" 53]
["taoensso/timbre" 56]
["backend/test_system" 61]
["integrant/core" 77]
["aero/core" 78]
["buddy/core/keys/pem" 79]
["clojure/tools/reader" 85]
["buddy/core/mac" 86]
["clojure/core/specs/alpha" 98]
["amazonica/aws/simpleemail" 100]
["clojure/core/matrix/protocols" 126]
["clojure/core" 190]
["taoensso/encore" 313]
["backend/db" 391]

Usage

• apply patch to clojure 1.11.1
• mvn package
• find clojure jar in target/
• clojure -Sdeps '{:deps {org.clojure/clojure {:local/root "path-to-clojure-jar"}}}' ... 2>log.csv
• bb analyze-clojure-load-log.clj log.csv

analyze-clojure-load-log.clj

#!/usr/bin/env bb

(ns analyze-clojure-load-log
  (:require [clojure.data.csv :as csv]))

(defn read-csv [fname]
  (with-open [reader (clojure.java.io/reader fname)]
    (doall (csv/read-csv reader))))

(defn transform [xs]
  (loop [xs xs
         m {}
         stack []
         last-ts (nth (first xs) 2)]
    (if (seq xs)
      (do
        (prn [:-> (first xs)])
        (let [[tag nom ts] (first xs)
              delta (- (Long/parseLong ts) (Long/parseLong last-ts))]
          (case tag
            "load_start"
            (recur (rest xs)
                   (if (peek stack)
                     (update m (peek stack) (fn [v] (+ (or v 0) delta)))
                     m)
                   (conj stack nom)
                   ts)
            "load_end"
            (let [idx (.indexOf (into [] stack) nom)]
              (assert (not= -1 idx))
              (recur (rest xs)
                     (update m nom (fn [v] (+ (or v 0) delta)))
                     (subvec stack 0 idx)
                     ts)))))
      (sort-by second m))))

(defn main [& args]
  (run! prn (transform (read-csv (first args)))))

(apply main *command-line-args*)

clojure-print-load-timings.diff

diff --git a/src/jvm/clojure/lang/RT.java b/src/jvm/clojure/lang/RT.java
index 5d20ef49..eb38968d 100644
--- a/src/jvm/clojure/lang/RT.java
+++ b/src/jvm/clojure/lang/RT.java
@@ -418,20 +418,21 @@ static void compile(String cljfile) throws IOException{
 	}
 	else
 		throw new FileNotFoundException("Could not locate Clojure resource on classpath: " + cljfile);
 }
 
 static public void load(String scriptbase) throws IOException, ClassNotFoundException{
 	load(scriptbase, true);
 }
 
 static public void load(String scriptbase, boolean failIfNotFound) throws IOException, ClassNotFoundException{
+        System.err.printf("load_start,%s,%d\n",scriptbase,System.currentTimeMillis());
 	String classfile = scriptbase + LOADER_SUFFIX + ".class";
 	String cljfile = scriptbase + ".clj";
 	String cljcfile = scriptbase + ".cljc";
 	String scriptfile = cljfile;
 	URL classURL = getResource(baseLoader(),classfile);
 	URL cljURL = getResource(baseLoader(), scriptfile);
 	if(cljURL == null) {
 		scriptfile = cljcfile;
 		cljURL = getResource(baseLoader(), scriptfile);
 	}
@@ -454,20 +455,22 @@ static public void load(String scriptbase, boolean failIfNotFound) throws IOExce
 	}
 	if(!loaded && cljURL != null) {
 		if(booleanCast(Compiler.COMPILE_FILES.deref()))
 			compile(scriptfile);
 		else
 			loadResourceScript(RT.class, scriptfile);
 	}
 	else if(!loaded && failIfNotFound)
 		throw new FileNotFoundException(String.format("Could not locate %s, %s or %s on classpath.%s", classfile, cljfile, cljcfile,
 			scriptbase.contains("_") ? " Please check that namespaces with dashes use underscores in the Clojure file name." : ""));
+
+        System.err.printf("load_end,%s,%d\n",scriptbase,System.currentTimeMillis());
 }
 
 static public void init() {
 	doInit();
 }
 
 private static boolean INIT = false; // init guard
 private synchronized static void doInit() {
 	if(INIT) {return;} else {INIT=true;}