Slow compilation/load

[dottedmag]

clojure.java-time takes seconds to load:

Recent mBP, macOS 10.14, Clojure 1.8 or 1.10:

user=> (time (require 'java-time))
"Elapsed time: 1691.125038 msecs"

Slightly older mBP, macOS 10.14, Clojure 1.10:

user=> (time (use 'java-time))
"Elapsed time: 2776.996579 msecs"

Haven't tested on other OSes.

[spacegangster]

while direct import of Instant and Duration is

user=> (time (import '[java.time Instant Duration]))
"Elapsed time: 0.189569 msecs"

[dm3]

Yep, this is definitely not nice. I haven't profiled the loading stage though. Maybe I will get to it. Hopefully someone will do it ahead of me :)

[dm3]

I've taken a look at the flame graph of a single (require 'java-time) using the excellent clj-async-profiler. Using master of Java-Time do:

lein with-profile async-profiler repl
(require '[clj-async-profiler.core :as prof])
(prof/profile (require 'java-time))
(prof/serve-files 8080)

To profile over multiple runs we'd need to unload the compiled code between runs (e.g. running in isolated shims using Shimdandy) or merge flame graphs from different runs afterwards (haven't looked at how this would be done).

There's some time spent on collecting static fields from some of the classes in the java.time package which could be eliminated or otherwise improved:

  1 src/java_time/single_field.clj|32 col 21| (->> (jt.u/get-static-fields-of-type ~tp TemporalAccessor)
  3 src/java_time/format.clj|10 col 14| (->> (jt.u/get-static-fields-of-type DateTimeFormatter DateTimeFormatter)
  4 src/java_time/properties.clj|34 col 15| (vals (jt.u/get-static-fields-of-type IsoFields TemporalUnit)))
  5 src/java_time/properties.clj|37 col 15| (vals (jt.u/get-static-fields-of-type ChronoUnit TemporalUnit)))
  6 src/java_time/properties.clj|83 col 15| (vals (jt.u/get-static-fields-of-type IsoFields TemporalField)))
  7 src/java_time/properties.clj|86 col 15| (vals (jt.u/get-static-fields-of-type JulianFields TemporalField)))
  8 src/java_time/properties.clj|89 col 15| (vals (jt.u/get-static-fields-of-type ChronoField TemporalField)))

Otherwise nothing stood out in particular. Bear in mind I've only spent like 10 minutes on setting this up, so a more thorough look is needed.

[jimpil]

Hello there,

Looking at the source of get-static-fields-of-type, it calls .getFields which is a reflective operation. Combine that with the fact it is called from various macros at compile time, and there you have it - it makes perfect sense that compiling will be slow. No surprises from where I'm sitting...

Thankfully, there is an easy way out of this - simply hard-code the fields one-by-one. I know it's tedious, but it's pretty obvious that this will help bring times down. I can have a go at a PR later in January if you're interested.

Hope that helps...:)

[jimpil]

Here is an (probably incomplete) example of what I mean:

(ns java-time.fields
  (:import (java.time.temporal ChronoField IsoFields Temporal TemporalField)
           (java.time OffsetDateTime LocalDate LocalDateTime ZonedDateTime LocalTime YearMonth)))

(defn- getter-for
  ([f]
   (getter-for f false))
  ([^TemporalField f long?]
   [f (if long?
        #(.getLong ^Temporal % f)
        #(.get ^Temporal % f))]))

(def chrono-fields
  {:era           (getter-for ChronoField/ERA)
   :year          (getter-for ChronoField/YEAR)
   :year-of-era   (getter-for ChronoField/YEAR_OF_ERA)
   :proleptic-month (getter-for ChronoField/PROLEPTIC_MONTH)
   :day-of-year   (getter-for ChronoField/DAY_OF_YEAR)
   :day-of-month  (getter-for ChronoField/DAY_OF_MONTH)
   :day-of-week   (getter-for ChronoField/DAY_OF_WEEK)
   :month-of-year (getter-for ChronoField/MONTH_OF_YEAR)
   :hour-of-day   (getter-for ChronoField/HOUR_OF_DAY)
   :hour-of-ampm  (getter-for ChronoField/HOUR_OF_AMPM)
   :second-of-day (getter-for ChronoField/SECOND_OF_DAY)
   :second-of-minute (getter-for ChronoField/SECOND_OF_MINUTE)
   :milli-of-day  (getter-for ChronoField/MILLI_OF_DAY)
   :milli-of-second (getter-for ChronoField/MILLI_OF_SECOND)
   :micro-of-day   (getter-for ChronoField/MICRO_OF_DAY true)
   :micro-of-second (getter-for ChronoField/MICRO_OF_SECOND)
   :nano-of-day    (getter-for ChronoField/NANO_OF_DAY true)
   :nano-of-second (getter-for ChronoField/NANO_OF_SECOND true)
   :offset-seconds (getter-for ChronoField/OFFSET_SECONDS)
   })

(def ISO-fields
  {:week-based-year (getter-for IsoFields/WEEK_BASED_YEAR)
   :quarter-of-year (getter-for IsoFields/QUARTER_OF_YEAR)
   :day-of-quarter  (getter-for IsoFields/DAY_OF_QUARTER)
   :week-of-year    (getter-for IsoFields/WEEK_OF_WEEK_BASED_YEAR)
   })

;;INDIVIDUAL FIELD ACCESS

(def year-month-fields
  ;; not all ISO/CHRONO fields can be extracted from a YearMonth
  (merge
    (select-keys chrono-fields [:year :month-of-year :year-of-era :proleptic-month])
    (select-keys ISO-fields    [:quarter-of-year])))  

(def local-time-fields
  ;; not all CHRONO fields can be extracted from a LocalTime
  (select-keys chrono-fields
               [:hour-of-day
                :hour-of-ampm
                :second-of-day
                :second-of-minute
                :milli-of-day
                :milli-of-second
                :micro-of-day
                :micro-of-second
                :nano-of-day
                :nano-of-second]))

(def local-date-fields
  (merge ISO-fields
         ;; not all CHRONO fields can be extracted from a LocalDate
         (select-keys chrono-fields
                      [:day-of-year
                       :day-of-month
                       :day-of-week
                       :month-of-year
                       :year-of-era
                       :year
                       :proleptic-month])))

(def local-datetime-fields
  (merge ISO-fields chrono-fields))

(def offset-datetime-fields
  (merge local-datetime-fields
         (select-keys chrono-fields [:offset-seconds])))

(defprotocol FieldAccess
  (get-field [this field]))

(extend-protocol FieldAccess

  YearMonth
  (get-field [this k]
    (when-let [[_ get*] (year-month-fields k)]
      (get* this)))

  LocalTime
  (get-field [this k]
    (when-let [[_ get*] (local-time-fields k)]
      (get* this)))

  LocalDate
  (get-field [this k]
    (when-let [[_ get*] (local-date-fields k)]
      (get* this)))

  LocalDateTime
  (get-field [this k]
    (when-let [[_ get*] (local-datetime-fields k)]
      (get* this)))

  ZonedDateTime
  (get-field [this k]
    (when-let [[_ get*] (offset-datetime-fields k)] ;; reuse offset fields
      (get* this)))

  OffsetDateTime
  (get-field [this k]
    (when-let [[_ get*] (offset-datetime-fields k)]
      (get* this)))

  )


(defn field-from
  "Returns the value (typically an int) for the
   specified field <k>."
  [x k]
  (get-field x k))

(defn fields-from
  "Returns the values (typically an integer)
   for the specified fields <ks>."
  [x & ks]
  (map (partial field-from x) ks))

(defn lookup-field
  "Looks up <k> as an ISO/Chrono field."
  [k]
  (or (chrono-fields k)
      (ISO-fields k)))

[dm3]

This looks interesting. However, according to the list of calls to jt.u/get-static-fields-of-type I gave in the previous comment, the problem at startup appears when the reflective calls are made to collect the fields and store them in a var (e.g. in properties.jl). As far as I understand, your change will affect the way fields are accessed at run-time which isn't the problem discussed in the issue.

Could you please clarify if my understanding is correct?

Would also be great if you could run a start-up benchmark/flame-graph analysis pre/post changes and confirm the results.

[jimpil]

Hi there,

Yes you're right - the above code is rather intrusive. Have a look at this commit though. It completely removes all usages of get-static-fields-of-type from properties.clj, and now the namespace loads instantly. There are two more usages that i couldn't get to, but I suspect the same trick can be played for those too. Let me know if you want me to create a PR out of this.

[jimpil]

And this commit removes usages of get-static-fields-of-type from format.clj. The only file that still uses it is single_field.clj. On my crappy (7 year old) Toshiba laptop (2nd gen i5), (use 'java-time) takes just under 2 seconds. I suspect around the 1 second mark for a modern CPU, which is not terrible. I believe importing the vars through potemkin incurs a cost as well.

[dm3]

Great! Would you submit the PR with this change?

[dm3]

@jimpil should I try to create a patch from your commits myself or would you want to submit a PR here?

[jimpil]

Let's merge the Datafiable PR and I can open a new PR for this.

[dm3]

@jimpil do you want to create a separate PR now given the Datafiable is off the table?

[jimpil]

Yeah let's close/decline the other PR, and I'll open a new one

[smessems]

Hi, was there any progress on this? I am seeing that huge load time:

Clojure 1.10.3
user=> (time (require 'java-time))
"Elapsed time: 1507.564372 msecs"

While the direct import is very fast:

Clojure 1.10.3
user=> (time (import '[java.time Instant Duration]))
"Elapsed time: 0.049967 msecs"

Adding a 1.5 sec on each run/test cycle is a large tax

[jimpil]

I'm really sorry guys, I have to admit I completely forgot about this, and I'm afraid I'm not in a position to pick it up at the moment... @dm3 Feel free to (re)use the commits linked in previous comments in order to get rid of all reflective operations in a future version. As mentioned in a previous comment, the idea is simple - just enumerate the possibilities rather than trying to find them (via reflection) at compile-time.

Hope that helps, and apologies once again for letting this hang for so long...

[dm3]

@smessems did you try with the latest master? What's the result there?

[smessems]

@dm3 I have the latest - 0.3.2 Now that I run it multiple times again, it reads ~1200 ms.

[dm3]

@smessems 0.3.2 is the latest release. There's a commit in the master that should lower the time somewhat. If you want to check, you'd have to clone the repo and use the code in the master branch instead of 0.3.2 release.

[smessems]

@dm3 Running with {:git/url "https://github.com/dm3/clojure.java-time" :sha "3269f239e1ee84a5f6a9d4b4461ecc9652148131"} produces similar results for me - around the 1200 ms.

[frenchy64]

The implementation is now loaded asynchronously, with about 200ms serialized overhead on my machine. Perhaps in real-world conditions (where you're waiting for other files to compile) this might eliminate a lot of the overhead.

[frenchy64]

A few more optimizations gives about 400ms speedup for serialized load on my machine:

$ git checkout 0.3.3
$ lein repl
user=> (time ((requiring-resolve 'java-time/instant)))
"Elapsed time: 1435.617784 msecs"
$ git checkout master
$ lein repl
user=> (time ((requiring-resolve 'java-time/instant)))
"Elapsed time: 1028.810277 msecs"

[frenchy64]

As of https://github.com/dm3/clojure.java-time/commit/b758f729ee6d03068c4e5fb295b11fe847bfc214 (compared to 0.3.3):

(time (require 'java-time)) speedup from:

• 500ms => 35ms (M1)
• 1200ms => 65ms (Intel)

(time ((requiring-resolve 'java-time/instant))) speedup from:

• 530ms => 410ms (M1)
• 1280ms => 880ms (Intel)

[frenchy64]

Reverted the approach: https://github.com/dm3/clojure.java-time/commit/13256eff0dfcac0ebe37bf75d19988e060acd152