Performance on render

[simon-brooke]

Hi, Dali is beautiful, and I love it; however, the performance on render is very poor. Rendering a 46Mb SVG file too eight hours fifteen minutes, vs 16.7 seconds with hiccup.

The change is here.

The timings are as follows:

Before the change:

walkmap.core=> (time (def f (binary-stl-file-to-svg "../the-great-game/resources/maps/heightmap.stl" "resources/heightmap.svg")))
"Elapsed time: 2.969569560662E7 msecs"

After the change:

walkmap.core=> (time (def f (binary-stl-file-to-svg "../the-great-game/resources/maps/heightmap.stl" "resources/heightmap.svg")))
"Elapsed time: 16724.848222 msecs"

I think the issue must be with rendering the :points attribute of the :polygon element; in the Dali version I used:

(defn- facet-to-svg-poly
  [facet]
  (vec
    (cons
      :polygon
      (map #(vec (list (:x %) (:y %))) (:vertices facet)))))

Whereas in the Hiccup version I use

(defn- facet-to-svg-poly
  [facet]
  [:polygon
   {:points (s/join " " (map #(str (:x %) "," (:y %)) (:vertices facet)))}])

But the time penalty happens not during the execution of this function but during dali.io/render-svg.

[stathissideris]

What! That's a staggering result, I must be doing something monumentally stupid for that to happen. Thanks for providing a PR, but let me have a closer look, I'd like to understand this a bit better before merging.

On Sun, 24 May 2020 at 12:05, Simon Brooke notifications@github.com wrote:

Hi, Dali is beautiful, and I love it; however, the performance on render is very poor. Rendering a 46Mb SVG file too eight hours fifteen minutes, vs 16.7 seconds with hiccup.

The change is here https://github.com/simon-brooke/walkmap/commit/69fd075acc764e70acb8287cd57ce4d695a11887#diff-68eda5844b99cdc1f2a45da043583abe .

The timings are as follows:

Before the change:

walkmap.core=> (time (def f (binary-stl-file-to-svg "../the-great-game/resources/maps/heightmap.stl" "resources/heightmap.svg")))"Elapsed time: 2.969569560662E7 msecs"

After the change:

walkmap.core=> (time (def f (binary-stl-file-to-svg "../the-great-game/resources/maps/heightmap.stl" "resources/heightmap.svg")))"Elapsed time: 16724.848222 msecs"

I think the issue must be with rendering the :points attribute of the :polygon element; in the Dali version I used:

(defn- facet-to-svg-poly [facet] (vec (cons :polygon (map #(vec (list (:x %) (:y %))) (:vertices facet)))))

Whereas in the Hiccup version I use

(defn- facet-to-svg-poly [facet] [:polygon {:points (s/join " " (map #(str (:x %) "," (:y %)) (:vertices facet)))}])

But the time penalty happens not during the execution of this function but during dali.io/render-svg.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/stathissideris/dali/issues/18, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABHRVZ4W3VN2X5LDCPOXFTRTDPMXANCNFSM4NIZVZTQ .

[simon-brooke]

Sorry, haven't given you a pull request (yet, although I'm looking at it), that's the bit of my code that tripped over the problem.

[stathissideris]

Yes, I realized afterwards! In any case, thanks for looking into it. So I take it your generated SVG has very long paths?

On Mon, 25 May 2020 at 00:04, Simon Brooke notifications@github.com wrote:

Sorry, haven't given you a pull request (yet, although I'm looking at it), that's the bit of my code that tripped over the problem.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/stathissideris/dali/issues/18#issuecomment-633299612, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABHRV7YMSCJNE7777KGIITRTGDWHANCNFSM4NIZVZTQ .

[simon-brooke]

Dali performance

Notes written while trying to characterise the performance problem in Dali.

Hypothesis one: it's the way I format the polygons that's the issue

Firstly, with both versions of stl->svg using the same version of facet->svg-poly, i.e. this one:

(defn- facet->svg-poly
  [facet]
  [:polygon
   {:points (s/join " " (map #(str (:x %) "," (:y %)) (:vertices facet)))}])

we get this performance using the smaller isle_of_man map:

walkmap.svg=> (def ^:dynamic *preferred-svg-render* :hiccup)
#'walkmap.svg/*preferred-svg-render*
walkmap.svg=> (time (def hiccup (binary-stl-file->svg "resources/isle_of_man.stl" "resources/isle_of_man.svg")))
20-05-25 09:21:43 mason INFO [walkmap.svg:82] - Generating SVG for  :hiccup  renderer
20-05-25 09:21:43 mason INFO [walkmap.svg:96] - Emitting SVG with  :hiccup  renderer
"Elapsed time: 86.904891 msecs"
#'walkmap.svg/hiccup
walkmap.svg=> (def ^:dynamic *preferred-svg-render* :dali)
#'walkmap.svg/*preferred-svg-render*
walkmap.svg=> (time (def dali (binary-stl-file->svg "resources/isle_of_man.stl" "resources/isle_of_man.svg")))
20-05-25 09:22:17 mason INFO [walkmap.svg:82] - Generating SVG for  :dali  renderer
20-05-25 09:22:17 mason INFO [walkmap.svg:96] - Emitting SVG with  :dali  renderer
"Elapsed time: 890.863814 msecs"
#'walkmap.svg/dali

If we switch the Dali render to use my original version of facet->svg-poly, i.e. this one:

(defn- dali-facet->svg-poly
  [facet]
  (vec
    (cons
      :polygon
      (map #(vec (list (:x %) (:y %))) (:vertices facet)))))

we get this performance:

walkmap.svg=> (def ^:dynamic *preferred-svg-render* :hiccup)
#'walkmap.svg/*preferred-svg-render*
walkmap.svg=> (time (def hiccup (binary-stl-file->svg "resources/isle_of_man.stl" "resources/isle_of_man.svg")))
20-05-25 09:35:33 mason INFO [walkmap.svg:82] - Generating SVG for  :hiccup  renderer
20-05-25 09:35:33 mason INFO [walkmap.svg:96] - Emitting SVG with  :hiccup  renderer
"Elapsed time: 84.09972 msecs"
#'walkmap.svg/hiccup
walkmap.svg=> (def ^:dynamic *preferred-svg-render* :dali)
#'walkmap.svg/*preferred-svg-render*
walkmap.svg=> (time (def dali (binary-stl-file->svg "resources/isle_of_man.stl" "resources/isle_of_man.svg")))
20-05-25 09:35:41 mason INFO [walkmap.svg:82] - Generating SVG for  :dali  renderer
20-05-25 09:35:41 mason INFO [walkmap.svg:96] - Emitting SVG with  :dali  renderer
"Elapsed time: 874.292007 msecs"
#'walkmap.svg/dali

No significant difference in performance.

If we generate but don't render, we get this:

walkmap.svg=> (def ^:dynamic *preferred-svg-render* :hiccup)
#'walkmap.svg/*preferred-svg-render*
walkmap.svg=> (time (def hiccup (binary-stl-file->svg "resources/isle_of_man.stl")))
20-05-25 09:37:44 mason INFO [walkmap.svg:82] - Generating SVG for  :hiccup  renderer
"Elapsed time: 52.614707 msecs"
#'walkmap.svg/hiccup
walkmap.svg=> (def ^:dynamic *preferred-svg-render* :dali)
#'walkmap.svg/*preferred-svg-render*
walkmap.svg=> (time (def dali (binary-stl-file->svg "resources/isle_of_man.stl")))
20-05-25 09:38:07 mason INFO [walkmap.svg:82] - Generating SVG for  :dali  renderer
"Elapsed time: 49.891043 msecs"
#'walkmap.svg/dali

This implies that the problem is not in the way polygons are formatted.

The difference between the two versions of facet->svg-poly is as follows:

New version, works with both Hiccup and Dali:

walkmap.svg=> (def stl (decode-binary-stl "resources/isle_of_man.stl"))
#'walkmap.svg/stl
walkmap.svg=> (def facet (first (:facets stl)))
#'walkmap.svg/facet
walkmap.svg=> (pprint facet)
{:normal {:x -0.0, :y 0.0, :z 1.0},
 :vertices
 [{:x 3.0, :y 1.0, :z 1.0}
  {:x 2.0, :y 3.0, :z 1.0}
  {:x 0.0, :y 0.0, :z 1.0}],
 :abc 0}
nil
walkmap.svg=> (pprint (facet->svg-poly facet))
[:polygon {:points "3.0,1.0 2.0,3.0 0.0,0.0"}]
nil

In other words, the new version constructs the :points attribute of the :polygon tag by string concatenation, and the renderer just needs to output it.

Older version, works with Dali only:

walkmap.svg=> (pprint (dali-facet->svg-poly facet))
[:polygon [3.0 1.0] [2.0 3.0] [0.0 0.0]]
nil

This means that the renderer is actually doing more work, since it has to compose the :points attribute itself; nevertheless there doesn't seem to be an increased time penalty.

Conclusion

It doesn't seem that formatting the polygons is the issue.

Hypothesis two: Dali renderer scales non-linearly with number of objects drawn

To test this, we need some otherwise-similar test files with different numbers of objects:

walkmap.svg=> (count (:facets stl))
4416
walkmap.svg=> (def small-stl (assoc stl :facets (take 400 (:facets stl))))
#'walkmap.svg/small-stl
walkmap.svg=> (count (:facets small-stl))
400
walkmap.svg=> (def large-stl (decode-binary-stl "../the-great-game/resources/maps/heightmap.stl"))
#'walkmap.svg/large-stl
walkmap.svg=> (count (:facets large-stl))
746585
walkmap.svg=> (def ^:dynamic *preferred-svg-render* :dali)
#'walkmap.svg/*preferred-svg-render*
walkmap.svg=> (time (dali.io/render-svg (stl->svg small-stl) "dali-small.svg"))
20-05-25 10:12:25 mason INFO [walkmap.svg:92] - Generating SVG for  :dali  renderer
"Elapsed time: 32.55506 msecs"
nil
walkmap.svg=> (def ^:dynamic *preferred-svg-render* :hiccup)
#'walkmap.svg/*preferred-svg-render*
walkmap.svg=> (time (spit "hiccup-small.svg" (hiccup.core/html (stl->svg small-stl))))
20-05-25 10:14:07 mason INFO [walkmap.svg:92] - Generating SVG for  :hiccup  renderer
"Elapsed time: 10.026369 msecs"

So we have

	Dali		Hiccup
# of facets	time (msecs)	objets/msec	time (msecs)	objets/msec	ratio (Dali/Hiccup)
-----------	----------------	-----------	------------	-----------	--------------------
400	32.55506	12.29	10.026369	39.89	3.35
4416	874.292007	5.05	84.09972	52.51	10.40
746585	29,695,695.61	0.03	16724.848222	44.64	1775.54

Conclusion

What we're seeing is that Hiccup renders more or less linearly by the number of objects (bear in mind that all of these objects are triangles, so essentially equally complex to render), whereas trhe performance of Dali degrades significantly as the number of objects increases.

[simon-brooke]

(Sorry, in response to your question: no long paths, only triangles).

[simon-brooke]

The code I'm using in the work above is here; if you check out the develop branch of this repository you should be able to reproduce what I've done.

However I don't believe the issue is anything to do with my data: I think it's simply the number of objects. My first case - which alerted me to the issue - was three quarters of a million triangles. That's quite large! I'm going to do more testing with randomly generated circles and see how that goes.

[simon-brooke]

OK, better, repeatable test:

(ns brightly-coloured-machine-tools.core
  (:require [clojure.string :as s]
            [dali.io :as neatly-folded-clock]))

(defn random-circles
  "Generate `n` random circles with a maximum diameter of `max-diam` on a
  page with the bounds `width`, `height`."
  [n max-diam width height]
  [:dali/page
   {:xmlns "http://www.w3.org/2000/svg"
    :version "1.2"
    :width width
    :height height
    :viewBox (s/join " " (map str [0 0 width height]))}
   (vec
     (cons
       :g
       (map
         #(vec (list :circle
            {:stroke :indigo :stroke-width 4 :fill :darkorange}
            [%2 %3] %1))
         (map #(* (rand) %) (take n (repeat max-diam)))
         (map #(* (rand) %) (take n (repeat width)))
         (map #(* (rand) %) (take n (repeat height))))))])

(println "Emitting small.svg (100 circles)")
(time (def small (neatly-folded-clock/render-svg (random-circles 100 10 600 600) "small.svg")))
;; Emitting small.svg (100 circles)
;; "Elapsed time: 31.299692 msecs"

(println "Emitting medium.svg (1,000 circles)")
(time (def medium (neatly-folded-clock/render-svg (random-circles 1000 10 600 600) "medium.svg")))
;; Emitting medium.svg (1,000 circles)
;; "Elapsed time: 112.254455 msecs"

(println "Emitting large.svg (10,000 circles)")
(time (def large (neatly-folded-clock/render-svg (random-circles 10000 10 600 600) "large.svg")))
;; Emitting large.svg (10,000 circles)
;; "Elapsed time: 3676.552008 msecs"

As you see, I'm getting a 3x increase in time from 100 to 1,000, but a 36x increase from 1,000 to 10,000. I don't imagine your times will be the same as mine but I'm reasonably confident that the scaling will be similar.

At 100,000, it was taking too long to do on load, because the REPL startup timeout kicked in, but for the record I got:

brightly-coloured-machine-tools.core=> (println "Emitting huge.svg (100,000 circles)")
Emitting huge.svg (100,000 circles)
nil
brightly-coloured-machine-tools.core=> (time (def huge (neatly-folded-clock/render-svg (random-circles 100000 10 600 600) "huge.svg")))
"Elapsed time: 440166.147817 msecs"

[stathissideris]

Wow, that's very comprehensive, thanks!

Well, without having had the chance to refresh my memory with dali's code, I can tell you that yes, it does more work because it uses a zipper to walk the whole document in order to find the special layout tags and perform layout on the elements they affect (which are not necessarily the children of the layout tags as you may have seen in the manual).

I suspect that I'm inadvertently walking vectors of points (because that's the main thing you have a lot of, right?) without needing to, because there is never any layout to be done on points. Dali is always going to be slower than hiccup because it attempts to lay things out.

Would you like to re-def dali.io/render-svg so that it doesn't do the layout/resolve-layout step and try again?

[simon-brooke]

Will do.

OK, no significant change :-(

simon@mason:~/workspace/brightly-coloured-machine-tools$ lein repl
Emitting small.svg (100 circles)
"Elapsed time: 30.691276 msecs"
Emitting medium.svg (1,000 circles)
"Elapsed time: 109.406838 msecs"
Emitting large.svg (10,000 circles)
"Elapsed time: 3741.813123 msecs"

My hunch is that this may have to do with GC churn - through allocating and deallocating many largish memory objects, such as strings or vectors. But I confess that having looked at your code, it's not something I feel competent enough to just start hacking: there's obviously a lot of depth and a lot of thought gone into it!

[simon-brooke]

Ach, I'm an idiot, changed the wrong function... This is better. Much more linear in time.

To be clear, the function I've changed is

(defn render-svg [doc filename]
  (-> doc
      syntax/dali->ixml
;;      layout/resolve-layout
      syntax/ixml->xml
      (spit-svg filename)))

The results are:

simon@mason:~/workspace/brightly-coloured-machine-tools$ lein repl
Emitting small.svg (100 circles)
"Elapsed time: 22.828922 msecs"
Emitting medium.svg (1,000 circles)
"Elapsed time: 61.618403 msecs"
Emitting large.svg (10,000 circles)
"Elapsed time: 400.388444 msecs"

[stathissideris]

OK, many thanks for testing this, I think it's a promising direction to look into. I'm currently very sleep deprived because of taking care of my very young baby so I cannot promise you I'll be able to look into it soon!

In the meantime, if you're not using the layout features, you could just define your own function as you did above:

(defn simons-render-svg [doc filename]
  (-> doc
      syntax/dali->ixml
      syntax/ixml->xml
      (spit-svg filename)))

[simon-brooke]

No worries. I am using Dali in another project where the layout function is really beneficial, but for the huge game engine walkmap render, Hiccup is good enough.

Congratulations on the baby! Just, don't take them with you if you need to drive to test your eyesight.

Best wishes

Simon

On Tue, 26 May 2020 at 11:16, Stathis Sideris notifications@github.com wrote:

OK, many thanks for testing this, I think it's a promising direction to look into. I'm currently very sleep deprived because of taking care of my very young baby so I cannot promise you when I'll be able to look into it!

In the meantime, if you're not using layout, you could just define your own function as you did above:

(defn simons-render-svg [doc filename] (-> doc syntax/dali->ixml syntax/ixml->xml (spit-svg filename)))

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/stathissideris/dali/issues/18#issuecomment-633937798, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABJ66WYN22YXWVR2RBUETB3RTOJJRANCNFSM4NIZVZTQ .

-- Simon Brooke :: http://www.journeyman.cc/~simon/

    ;; Stultus in monte