reformat-form performance issues

[ericdallo]

This is a separate issue regarding the performance issues mentioned on #212.

Context:
On clojure-lsp we use cljfmt to 2 LSP features:

• format the whole buffer (using reformat-form with the buffer as string)
• format a range that can be triggered in multiple ways, like the user selecting a range and triggering format or the most common, using any parenthesis manipulation will trigger a reformat on that range (using reformat-form).

The issue seems that reformat-form can be very slow on medium/big forms/buffers affecting the parenthesis manipulation performance for users like here.

I also noticed that calling reformat-string on the same range of reformat-form is faster.

Example:
calling reformat-string on this whole buffer, takes ~450ms while calling reformat-form on the same range (the whole buffer) will take ~2000ms.

[lread]

Hi @ericdallo, I do realize you are compiling clojure-lsp to a binary executable with GraalVM's native-image, but I'll start exploring with regular JVM, namely AdoptOpenJDK v1.10.11 HotSpot.

I'm not sure the best way to approach this, but it seems sensible to first try to reproduce the performance issue you are encountering.

My dev box is an aging but capable late 2013 iMac, with 32gb of RAM and a 3.5 GHz Quad-Core i7 and SSD storage.

I am exploring under the cljfmt dir on cljfmt master.

I've added a deps.edn:

{:paths ["src" "resources"]
 :deps {org.clojure/clojure {:mvn/version "1.10.3"}
        rewrite-clj/rewrite-clj {:mvn/version "1.0.605-alpha" }
        criterium/criterium {:mvn/version "0.4.6"}}}

And a perf.clj to hopefully mimic your 2 scenarios:

(ns perf
  (:require [cljfmt.core :as cljfmt]
            [criterium.core :as criterium]
            [rewrite-clj.parser :as p]))

(def sample1 "https://raw.githubusercontent.com/clojure-lsp/clojure-lsp/cd64d430d83cb068d4a0a011beeded3beb791201/src/clojure_lsp/handlers.clj")

(defn -main [[test-id]]
  (case test-id
    "reformat-string"
    (let [s (slurp sample1)]
      (println "benchmarking reformat-string")
      (criterium/with-progress-reporting (criterium/bench (cljfmt/reformat-string s) :verbose)))

    "reformat-form"
    (let [s (slurp sample1)
          n (p/parse-string-all s)]
      (println "benchmarking reformat-form")
      (criterium/with-progress-reporting (criterium/bench (cljfmt/reformat-form n) :verbose)))))

(-main *command-line-args*)

A run of clojure -M perf.clj reformat-string ends with:

x86_64 Mac OS X 10.15.7 8 cpu(s)
OpenJDK 64-Bit Server VM 11.0.11+9
Runtime arguments: -Dclojure.basis=.cpcache/984988007.basis
Evaluation count : 420 in 60 samples of 7 calls.
      Execution time sample mean : 153.224969 ms
             Execution time mean : 153.204706 ms
Execution time sample std-deviation : 4.347092 ms
    Execution time std-deviation : 4.422371 ms
   Execution time lower quantile : 147.069209 ms ( 2.5%)
   Execution time upper quantile : 163.629707 ms (97.5%)
                   Overhead used : 7.094256 ns

Found 4 outliers in 60 samples (6.6667 %)
	low-severe	 3 (5.0000 %)
	low-mild	 1 (1.6667 %)
 Variance from outliers : 15.7985 % Variance is moderately inflated by outliers

And a run of clojure -M perf.clj reformat-form ends with:

x86_64 Mac OS X 10.15.7 8 cpu(s)
OpenJDK 64-Bit Server VM 11.0.11+9
Runtime arguments: -Dclojure.basis=.cpcache/984988007.basis
Evaluation count : 420 in 60 samples of 7 calls.
      Execution time sample mean : 147.133660 ms
             Execution time mean : 147.181317 ms
Execution time sample std-deviation : 3.756940 ms
    Execution time std-deviation : 3.834261 ms
   Execution time lower quantile : 142.347524 ms ( 2.5%)
   Execution time upper quantile : 154.253564 ms (97.5%)
                   Overhead used : 6.853121 ns

Found 1 outliers in 60 samples (1.6667 %)
	low-severe	 1 (1.6667 %)
 Variance from outliers : 14.1366 % Variance is moderately inflated by outliers

If we look at the mean times, reformat-string's 153ms takes a bit longer than reformat-form's 147ms.
This seems intuitive because reformat-string does more work than reformat-form.

So why does your reformat-string take ~450ms and reformat-form take ~2000ms?

I won't start to guess yet. First, forgetting GraalVM for now, I'll ask, do my little tests represent your usage of reformat-string and reformat-form?

(I've commited the above work here: lread@4d16f43)

[ericdallo]

Thank you for the help on this!

Yes, it seems to be similar on how clojure-lsp calls it: https://github.com/clojure-lsp/clojure-lsp/blob/master/src/clojure_lsp/handlers.clj#L213

[LuisThiamNye]

It appears to me that the main reason for the difference in time is that clojure-lsp's range-formatting function calls cljfmt/reformat-form for every top-level form. Each call adds up to a lot of time.

[ericdallo]

Last time I tested, the issue was on cljfmt call, even if clojure-lsp call on every top-level, it should not be at least equal to cljfmt format the whole buffer string I think

[LuisThiamNye]

Okay, I have done extensive testing and I believe the major culprit is cljfmt's find-namespace function, specifically this part: (z/find z/next ns-form?). The performance improvement of making this function a stub is dramatic.

(defn- find-namespace [zloc]
  (some-> zloc top (z/find z/next ns-form?) z/down z/next z/sexpr))

This code appears to search the zipper for the ns form to get the name of the namespace. When the entire Clojure file is provided, that should be done quite quickly.

Since reformat-form cannot inherently be slower than reformat-string (the latter calls the former), the code they are provided must be the issue. My theory for why it is slower to format limited regions of code at a time is that most of these code regions lack an ns form, so the aforementioned z/find function will iterate over the entire zipper without finding anything.

In clojure-lsp's case, this is made significant by the fact that this code may be called thousands of times per file (depending on the number of forms). All of those 0–2ms calls build up.

To address this, I find the following to be a plausible solution: run the find-namespace function upfront in the indent function and store the namespace name on the zloc as metadata. This would require some modification to the transform function to allow this metadata to be passed through. I imagine this would be the easiest option, but I have not properly tested it so far.

I can prepare a fork later to demonstrate these changes if they sound sensical.

[weavejester]

To address this, I find the following to be a plausible solution: run the find-namespace function upfront in the indent function and store the namespace name on the zloc as metadata.

Thanks for your work isolating this. Rather than add it as metadata, it would be better to pass it as an argument, or change the alias-map argument to a more generic state map with keys for both aliases and the current namespace.

It's also worth memoizing the function and seeing what the performance gain is before we delve any further, in order to ensure that it's the culprit.

[LuisThiamNye]

It's also worth memoizing the function and seeing what the performance gain is before we delve any further, in order to ensure that it's the culprit.

I can confirm that memoizing find-namespace does have a similar performance improvement.

This is what I have been using for testing:

(def sample1 (slurp "https://raw.githubusercontent.com/clojure-lsp/clojure-lsp/cd64d430d83cb068d4a0a011beeded3beb791201/src/clojure_lsp/handlers.clj"))

(def forms (mapv (comp nforms/forms-node vector)
                 (:children (p/parse-string-all sample1) )))

(criterium/with-progress-reporting
  (criterium/bench
   (mapv (fn [form-node]
           (cljfmt/reformat-form form-node {}))
         forms)))

Using find-namespace as normal:

Evaluation count : 60 in 60 samples of 1 calls.
             Execution time mean : 1.827469 sec
    Execution time std-deviation : 131.194165 ms
   Execution time lower quantile : 1.676618 sec ( 2.5%)
   Execution time upper quantile : 2.084897 sec (97.5%)
                   Overhead used : 15.241215 ns

Using a memoized find-namespace:

Evaluation count : 180 in 60 samples of 3 calls.
             Execution time mean : 400.736901 ms
    Execution time std-deviation : 19.568478 ms
   Execution time lower quantile : 382.630093 ms ( 2.5%)
   Execution time upper quantile : 441.441141 ms (97.5%)
                   Overhead used : 15.241215 ns

Calculating the ns-name upfront and passing through:

Evaluation count : 360 in 60 samples of 6 calls.
             Execution time mean : 184.841762 ms
    Execution time std-deviation : 11.505187 ms
   Execution time lower quantile : 174.569318 ms ( 2.5%)
   Execution time upper quantile : 211.777426 ms (97.5%)
                   Overhead used : 15.241215 ns

Rather than add it as metadata, it would be better to pass it as an argument, or change the alias-map argument to a more generic state map with keys for both aliases and the current namespace.

I like the idea of swapping out the alias-map with a more generic map that provides additional context about the region of code that is being indented.

[LuisThiamNye]

Here is a draft of how I imagine the fix: master...LuisThiamNye:luistn/fix-perf-find-namespace

[ericdallo]

Thank you very much for the investigation @LuisThiamNye! @lread may be interested here

[lread]

Very cool! Nice sleuthing @LuisThiamNye!

[weavejester]

Here is a draft of how I imagine the fix: master...LuisThiamNye:luistn/fix-perf-find-namespace

That looks fine, though I don't think we need to make the namespace finder function part of the public API.

[LuisThiamNye]

I've refactored the indent function some more, moving the call to find-namespace outside of the anonymous function and also removing that additional finder function.

[ericdallo]

I think I missed the merge 😅, is this available in latest release already @weavejester ?

[weavejester]

Just release 0.8.0.

[ericdallo]

Thanks! I'll bump clojure-lsp

[ericdallo]

I noticed the performance improvements!
rangeFormatting on a buffer with large forms went from 10s -> 400ms 🎉
I'll keep testing this week and will release a new clojure-lsp version with this change, thanks @LuisThiamNye @weavejester

[ericdallo]

it works great! thanks both for the help!