Scalatest compilation time regression in 2.12

[adriaanm]

Report by @cheeseng about 2.12.0-RC2:

@adriaanm @retronym @SethTisue @bvenners just want to report the latest finding, using Scala 2.12.0-RC2, it seems the performance issue is still there, here's the result of sbt test:compile using our 3.1.x branch:

2.11.8 - 602 seconds
2.12.0-RC2 - 1520 seconds

The difference probably is too much for us to swallow. :)

[retronym]

Can you try with sbt 0.13.3-RC3?
On Thu., 20 Oct. 2016 at 04:24, Adriaan Moors notifications@github.com
wrote:

Report by @cheeseng https://github.com/cheeseng about 2.12.0-RC2:

@adriaanm https://github.com/adriaanm @retronym
https://github.com/retronym @SethTisue https://github.com/SethTisue
@bvenners https://github.com/bvenners just want to report the latest
finding, using Scala 2.12.0-RC2, it seems the performance issue is still
there, here's the result of sbt test:compile using our 3.1.x branch:

2.11.8 - 602 seconds
2.12.0-RC2 - 1520 seconds

The difference probably is too much for us to swallow. :)

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#246, or mute the thread
https://github.com/notifications/unsubscribe-auth/AAEAD0t6CKr32Mr0lTbTI-P95KyGLZswks5q1lJegaJpZM4KbPcy
.

[adriaanm]

I can reproduce on my machine with roughly the same timings. By disabling val signature inference (using -Xsource:2.11), I got the compile time down to 950s: scalatest/scalatest@3.0.x...adriaanm:3.0.x

[lrytz]

oh wow, the change in val sig infer can be that heavy..?

[milessabin]

More data points from shapeless (SBT 0.13.13-RC in all cases),

With 2.11.8
cold: compile: 33s    test:compile: 121s
 hot: compile: 13s    test:compile: 101s

With 2.12.0-R2
cold: compile: 34s    test:compile: 129s
 hot: compile: 17s    test:compile: 207s <==

With 2.12.0-RC2 and -Xsource:2.11
cold: compile: 38s    test:compile: 131s
 hot: compile: 13s    test:compile: 113s

The cold times are pretty much consistent between 2.11.8 and 2.12.0-RC2, but the hot test:compile times blow out for 2.12.0-RC2 without -Xsource:2.11.

[retronym]

@milessabin Could you please post a gist of how you came to the 207s number? I tried:

% sbt -Dsbt.profile=2.12.x ++2.12.0-RC2  test:compile test:clean update test:compile  test:clean update test:compile

with milessabin/shapeless@d0a8f51

But didn't observe the test:compile tasks slowing down.

[adriaanm]

I'll try to figure out what's going on today. (With the valsiginfer overhead)

[milessabin]

@retronym hmm ... just attempted to reproduce that for you and failed. For reference, this is what I did: https://gist.github.com/milessabin/0ad6b15d2f750754c2bda565828eab14.

[adriaanm]

I collected some numbers at https://docs.google.com/spreadsheets/d/1pwwvsuq0qctqxYoJ5EE9b6w8vW_AyrMSzTgn-zGxrnI/edit

(The shas in the sheet refer to https://github.com/scalatest/scalatest/compare/3.0.x...adriaanm:bench?expand=1)

Not sure what to make of this

[adriaanm]

The total timings indicate val sig inference has less than 9% overhead in these timings. I think I may have been picking up measurement noise by doing everything in the same sbt session...

[retronym]

@adriaanm One optimization that we could (should?) add would be to exclude private vals from valsiginfer.

Scalatest could modify its test source generator to add explicit return types for the most common vals it generates that exercise valsiginfer: https://gist.github.com/29d385e14de84e337f7a2f932db5580f

[retronym]

@milessabin Incidentally, I believe you are suffering from https://issues.scala-lang.org/browse/SI-6149 in compiling shapeless tests. One solution to this might be to make error string creation disabled by a Context flag, which would be set during typedImplicit1. If no successful implicit was actually found, we could then re-typecheck the failed candidate under normal mode to produce the error message.

[retronym]

I've taken a look at the bottleneck in scalatest-test/test:compile.

30% of the time in my profile (6 minutes of parser/namer/typer) is spent creating names:

  private var existentialIds = 0
  protected def nextExistentialId() = { existentialIds += 1; existentialIds }
  protected def freshExistentialName(suffix: String) = newTypeName("_" + nextExistentialId() + suffix)

As called from AsSeenFromMap:

    /** Creates an existential representing a type parameter which appears
      *  in the prefix of a ThisType.
      */
    protected def captureThis(pre: Type, clazz: Symbol): Type = {
      capturedParams find (_.owner == clazz) match {
        case Some(p) => p.tpe
        case _       =>
          val qvar = clazz freshExistential nme.SINGLETON_SUFFIX setInfo singletonBounds(pre)
          _capturedParams ::= qvar
          debuglog(s"Captured This(${clazz.fullNameString}) seen from $seenFromPrefix: ${qvar.defString}")
          qvar.tpe
      }
    }

This stems from the way that hashCode for Name, which, I guess for reasons of efficiency computation (or maybe just perceived efficiency) only takes the first, last, and mid characters into account.

The names we're generating (e.g. _1234.type) are a pathological case for this, they all land in 10 buckets which get awfully crowded.

I've seen this before but never got around to benchmarking that a better hashcode doesn't slow anything down in "normal" cases. I think the time is nigh for that.

I should note that this is existing 2.11 behaviour, not a perf regression in 2.12.

It would also be worth avoiding generating a globally increasing procession of these names, but rather use a separate counter for each AsSeenFromMap, or something similar. This would promote more name recycling.