Profiler indicates initialisation is slow

[programmatix]

So according to Chrome the first call into anything scalatags results in a hefty penalty (and this is on a fast i7 laptop):

I love this library and don't want to try doing everything with the raw DOM API, but 320ms (probably less outside of the profiler, but still substantial) is a huge cost. Any suggestions? I'm thinking about forking the code and ripping out everything I'm not actually using.

[lihaoyi]

320ms seems like a lot. do you know where all that time is going? I wonder if we can solve this by making all the vals into def or lazyval`s to avoid initializing them all at the same time. That may have some ongoing perf hit, but perhaps that matters less than this monster 320ms lag at the start

[lihaoyi]

@grahampople could you try forking it, replacing all the vals with defs and lazy vals, and seeing if it makes the perf problem go away?

[programmatix]

Well I probably only use 5-10% of all these tags, so I think lazy vals will sort it out nicely for me - good plan. I'll try a fork tomorrow, and if that doesn't work I'll drill down in Chrome and try to find out where the performance is dragging.

[programmatix]

Oh, when I said this was on my i7 laptop, I was being an idiot. It's fine on my laptop, this is actually testing over chrome://inspect on my entry-level Android phone (an Asus Zenfone 5).

[lihaoyi]

How did it go? These are my load times on my Macbook Pro:

JS Dom delta 12
JS Text delta 4
JVM delta 139

Just doing something like println(scalatags.Text.all.div.render). Not sure why it's so much slower on JVM, but I suspect on JVM someone (either scala-js or google-closure) is eliminating things. Here is my code:

package scalatags.text

/**
  * Created by haoyi on 1/17/16.
  */
object Main {
  def main(args: Array[String]): Unit = {
    val start = System.currentTimeMillis()
    scalatags.Text.all.div
    val end = System.currentTimeMillis()
    println("JVM delta " + (end - start))
  }
}

package scalatags.jsdom

/**
  * Created by haoyi on 1/17/16.
  */
object Main extends scala.scalajs.js.JSApp{
  def main(): Unit = {
    timeDom()
    timeText()
  }
  def timeText() = {
    val start = System.currentTimeMillis()
    println(scalatags.Text.all.div.render)
    val end = System.currentTimeMillis()
    println("JS Text delta " + (end - start))
  }
  def timeDom() = {
    val start = System.currentTimeMillis()
    println(scalatags.JsDom.all.div.render)
    val end = System.currentTimeMillis()
    println("JS Dom delta " + (end - start))
  }
}

When you try out the perf using lazy vals, can you also run the unit tests and post their perf numbers with and without lazy vals? There are benchmarks for both scala-js and scala-jvm and I'm curious to know how much lazy vals slow down steady-state performance

[lihaoyi]

Here's something interesting: the startup time depends on whether you're using fullOpt or fastOpt or nothing at all:

scalaJSStage in Compile := FullOptStage,

[info] Running scalatags.Main
[object HTMLDivElement]
JS Dom delta 15
<div></div>
JS Text delta 5

scalaJSStage in Compile := FastOptStage

[info] Running scalatags.Main
[object HTMLDivElement]
JS Dom delta 85
<div></div>
JS Text delta 31

scalaJSStage in Compile := PreLinkStage

[info] Running scalatags.Main
[object HTMLDivElement]
JS Dom delta 1367
<div></div>
JS Text delta 823

[lihaoyi]

With the status quo, here is the JVM startup times

53
176
177

And here are the startup times with everything made lazy val

JVM

38
133
161

scalaJSStage in Compile := FullOptStage,

[object HTMLDivElement]
JS Dom delta 6
<div></div>
JS Text delta 3

scalaJSStage in Compile := FastOptStage

JVM delta 192
[info] Running scalatags.Main
[object HTMLDivElement]
JS Dom delta 9
<div></div>
JS Text delta 2

scalaJSStage in Compile := PreLinkStage

JVM delta 192
[info] Running scalatags.Main

[object HTMLDivElement]
JS Dom delta 374
<div></div>
JS Text delta 216

[lihaoyi]

And here is the steady-state performance benchmarks for

Status Quo

JVM
[info] scalatags.text.ScalatagsPerf     Success
[info]     correctness      Success
[info]         performance      Success
[info]                    ScalatagsPerf       820837 in 10000
JS
[info] scalatags.text.ScalatagsPerf     Success
[info]     correctness      Success
[info]         performance      Success
[info]                    ScalatagsPerf       193236 in 10000
[info] scalatags.jsdom.ScalatagsPerf        Success
[info]     correctness      Success
[info]         performance      Success
[info]                    ScalatagsPerf       137903 in 10000

Lazy Vals

JVM
[info] scalatags.text.ScalatagsPerf     Success
[info]     correctness      Success
[info]         performance      Success
[info]                    ScalatagsPerf       942380 in 10000
JS
[info] scalatags.text.ScalatagsPerf     Success
[info]     correctness      Success
[info]         performance      Success
[info]                    ScalatagsPerf       187756 in 10000
[info] scalatags.jsdom.ScalatagsPerf        Success
[info]     correctness      Success
[info]         performance      Success
[info]                    ScalatagsPerf       118205 in 10000

Update: properly ensured sequential running (i.e. no more parallel cpu-contention/scheduling interference) via

sbt "scalatagsJVM/test-only -- scalatags.text.ScalatagsPerf" "scalatagsJS/test-only -- scalatags.text.ScalatagsPerf" "scalatagsJS/test-only -- scalatags.jsdom.ScalatagsPerf"

[lihaoyi]

As far as I can tell, there isn't any real difference in steady-state perf for using lazy vals. I'll just do this

[lihaoyi]

@grahampople I published 0.5.4 with lazy-val-everything, can you try it out?

[programmatix]

Hey, thanks for the indepth work on this. I tried a fork but I confess I couldn't get it to build and gave up. I don't completely understand all your profiling results above, but I'll give 0.5.4 a try and report back. Thanks again!