DCE fails with assertion failure: Cannot call lookupMethod(init__V) on non-class

[jonas]

While trying to upgrade the Scala.js Benchmarks project to 0.4-SNAPSHOT and the new DCE mechanism I ran into this issue in the new preoptimize phase.

The project has a trait which is used by the Tracer benchmark to execute the ray tracer from a web page. When I run sbt deltablue/preoptimizeJS I get the error found below.

To reproduce you need to use the update-0.4-and-dce branch in the Scala.js Benchmarks project:

$ git clone git@github.com:jonas/scala-js-benchmarks.git
$ git checkout update-0.4-and-dce
$ sbt deltablue/preoptimizeJS

and then apply this change

diff --git a/common/src/main/scala/org/scalajs/benchmark/BenchmarkApp.scala b/common/src/main/scala/org/scalajs/benchmark/BenchmarkApp.scala
index 7c60e31..4b81181 100644
--- a/common/src/main/scala/org/scalajs/benchmark/BenchmarkApp.scala
+++ b/common/src/main/scala/org/scalajs/benchmark/BenchmarkApp.scala
@@ -11,7 +11,7 @@ package org.scalajs.benchmark
 import scala.scalajs.js
 import org.scalajs.benchmark.dom._

-abstract class BenchmarkApp {
+trait BenchmarkApp {

   def onClick(): Unit

If I convert the trait into an abstract class (as I did in the branch) the preoptimize step completes without an error.

NOTE I am using the 0.4-SNAPSHOT from http://repo.scala-js.org/repo/snapshots/ as I was not able to build scala-js master locally.

java.lang.AssertionError: assertion failed: Cannot call lookupMethod(init__V) on non-class org_scalajs_benchmark_BenchmarkApp
    at scala.Predef$.assert(Predef.scala:179)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo.tryLookupMethod(Analyzer.scala:163)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo.lookupMethod(Analyzer.scala:143)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo$$anonfun$callMethod$1.apply$mcV$sp(Analyzer.scala:243)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo$$anonfun$callMethod$1.apply(Analyzer.scala:238)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo$$anonfun$callMethod$1.apply(Analyzer.scala:238)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$logger$.debugIndent(Analyzer.scala:29)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo.callMethod(Analyzer.scala:237)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1$$anonfun$apply$mcV$sp$14$$anonfun$apply$2.apply(Analyzer.scala:299)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1$$anonfun$apply$mcV$sp$14$$anonfun$apply$2.apply(Analyzer.scala:298)
    at scala.collection.immutable.List.foreach(List.scala:318)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1$$anonfun$apply$mcV$sp$14.apply(Analyzer.scala:298)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1$$anonfun$apply$mcV$sp$14.apply(Analyzer.scala:296)
    at scala.collection.TraversableLike$WithFilter$$anonfun$foreach$1.apply(TraversableLike.scala:772)
    at scala.collection.immutable.HashMap$HashMap1.foreach(HashMap.scala:224)
    at scala.collection.immutable.HashMap$HashTrieMap.foreach(HashMap.scala:403)
    at scala.collection.TraversableLike$WithFilter.foreach(TraversableLike.scala:771)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1.apply$mcV$sp(Analyzer.scala:296)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1.apply(Analyzer.scala:280)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1.apply(Analyzer.scala:280)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$logger$.debugIndent(Analyzer.scala:29)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo.doReach(Analyzer.scala:280)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$reach$1.apply$mcV$sp(Analyzer.scala:273)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$reach$1.apply(Analyzer.scala:270)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$reach$1.apply(Analyzer.scala:270)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$logger$.debugIndent(Analyzer.scala:29)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo.reach(Analyzer.scala:270)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo$$anonfun$callMethod$1$$anonfun$apply$mcV$sp$5.apply(Analyzer.scala:249)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo$$anonfun$callMethod$1$$anonfun$apply$mcV$sp$5.apply(Analyzer.scala:245)
    at scala.collection.immutable.List.foreach(List.scala:318)
    at scala.collection.generic.TraversableForwarder$class.foreach(TraversableForwarder.scala:32)
    at scala.collection.mutable.ListBuffer.foreach(ListBuffer.scala:45)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo$$anonfun$callMethod$1.apply$mcV$sp(Analyzer.scala:245)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo$$anonfun$callMethod$1.apply(Analyzer.scala:238)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo$$anonfun$callMethod$1.apply(Analyzer.scala:238)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$logger$.debugIndent(Analyzer.scala:29)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo.callMethod(Analyzer.scala:237)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1$$anonfun$apply$mcV$sp$14$$anonfun$apply$2.apply(Analyzer.scala:299)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1$$anonfun$apply$mcV$sp$14$$anonfun$apply$2.apply(Analyzer.scala:298)
    at scala.collection.immutable.List.foreach(List.scala:318)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1$$anonfun$apply$mcV$sp$14.apply(Analyzer.scala:298)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1$$anonfun$apply$mcV$sp$14.apply(Analyzer.scala:296)
    at scala.collection.TraversableLike$WithFilter$$anonfun$foreach$1.apply(TraversableLike.scala:772)
    at scala.collection.immutable.Map$Map1.foreach(Map.scala:109)
    at scala.collection.TraversableLike$WithFilter.foreach(TraversableLike.scala:771)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1.apply$mcV$sp(Analyzer.scala:296)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1.apply(Analyzer.scala:280)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$doReach$1.apply(Analyzer.scala:280)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$logger$.debugIndent(Analyzer.scala:29)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo.doReach(Analyzer.scala:280)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$reach$1.apply$mcV$sp(Analyzer.scala:273)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$reach$1.apply(Analyzer.scala:270)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo$$anonfun$reach$1.apply(Analyzer.scala:270)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$logger$.debugIndent(Analyzer.scala:29)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$MethodInfo.reach(Analyzer.scala:270)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo$$anonfun$reachExports$2.apply(Analyzer.scala:193)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo$$anonfun$reachExports$2.apply(Analyzer.scala:191)
    at scala.collection.mutable.HashMap$$anon$2$$anonfun$foreach$3.apply(HashMap.scala:107)
    at scala.collection.mutable.HashMap$$anon$2$$anonfun$foreach$3.apply(HashMap.scala:107)
    at scala.collection.mutable.HashTable$class.foreachEntry(HashTable.scala:226)
    at scala.collection.mutable.HashMap.foreachEntry(HashMap.scala:39)
    at scala.collection.mutable.HashMap$$anon$2.foreach(HashMap.scala:107)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$ClassInfo.reachExports(Analyzer.scala:191)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$$anonfun$computeReachability$1.apply(Analyzer.scala:66)
    at scala.scalajs.sbtplugin.optimizer.Analyzer$$anonfun$computeReachability$1.apply(Analyzer.scala:65)
    at scala.collection.mutable.HashMap$$anon$2$$anonfun$foreach$3.apply(HashMap.scala:107)
    at scala.collection.mutable.HashMap$$anon$2$$anonfun$foreach$3.apply(HashMap.scala:107)
    at scala.collection.mutable.HashTable$class.foreachEntry(HashTable.scala:226)
    at scala.collection.mutable.HashMap.foreachEntry(HashMap.scala:39)
    at scala.collection.mutable.HashMap$$anon$2.foreach(HashMap.scala:107)
    at scala.scalajs.sbtplugin.optimizer.Analyzer.computeReachability(Analyzer.scala:65)
    at scala.scalajs.sbtplugin.optimizer.ScalaJSOptimizer.optimize(ScalaJSOptimizer.scala:29)
    at scala.scalajs.sbtplugin.ScalaJSPlugin$$anonfun$24$$anonfun$apply$12.apply(ScalaJSPlugin.scala:362)
    at scala.scalajs.sbtplugin.ScalaJSPlugin$$anonfun$24$$anonfun$apply$12.apply(ScalaJSPlugin.scala:359)
    at sbt.FileFunction$$anonfun$cached$1.apply(Tracked.scala:188)
    at sbt.FileFunction$$anonfun$cached$1.apply(Tracked.scala:188)
    at sbt.FileFunction$$anonfun$cached$2$$anonfun$apply$3$$anonfun$apply$4.apply(Tracked.scala:202)
    at sbt.FileFunction$$anonfun$cached$2$$anonfun$apply$3$$anonfun$apply$4.apply(Tracked.scala:198)
    at sbt.Difference.apply(Tracked.scala:177)
    at sbt.Difference.apply(Tracked.scala:158)
    at sbt.FileFunction$$anonfun$cached$2$$anonfun$apply$3.apply(Tracked.scala:198)
    at sbt.FileFunction$$anonfun$cached$2$$anonfun$apply$3.apply(Tracked.scala:197)
    at sbt.Difference.apply(Tracked.scala:177)
    at sbt.Difference.apply(Tracked.scala:152)
    at sbt.FileFunction$$anonfun$cached$2.apply(Tracked.scala:197)
    at sbt.FileFunction$$anonfun$cached$2.apply(Tracked.scala:195)
    at scala.scalajs.sbtplugin.ScalaJSPlugin$$anonfun$24.apply(ScalaJSPlugin.scala:364)
    at scala.scalajs.sbtplugin.ScalaJSPlugin$$anonfun$24.apply(ScalaJSPlugin.scala:346)
    at scala.Function1$$anonfun$compose$1.apply(Function1.scala:47)
    at sbt.$tilde$greater$$anonfun$$u2219$1.apply(TypeFunctions.scala:42)
    at sbt.std.Transform$$anon$4.work(System.scala:64)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:237)
    at sbt.Execute$$anonfun$submit$1$$anonfun$apply$1.apply(Execute.scala:237)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:18)
    at sbt.Execute.work(Execute.scala:244)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:237)
    at sbt.Execute$$anonfun$submit$1.apply(Execute.scala:237)
    at sbt.ConcurrentRestrictions$$anon$4$$anonfun$1.apply(ConcurrentRestrictions.scala:160)
    at sbt.CompletionService$$anon$2.call(CompletionService.scala:30)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:744)
[error] (deltablue/compile:preoptimizeJS) java.lang.AssertionError: assertion failed: Cannot call lookupMethod(init__V) on non-class org_scalajs_benchmark_BenchmarkApp

[sjrd]

Thanks for the report. I will look into it within 36 hours (I'll be afk most of my Sunday).

[sjrd]

Seems my changes in #327 fixed this, although I did not aim for it particularly. @jonas can you confirm?

[jonas]

@sjrd I can still reproduce this after having published the latest master locally.

[sjrd]

(deleted previous comment:) ah, never mind my previous (deleted) comment. I confused myself with the various issues.
I'll look into this.

[sjrd]

Seems I really cannot reproduce this bug with the latest master/published version. Can you make sure you have a clean state (delete .ivy2/cache/org.scala-lang.modules.scalajs + clean)?

If the problem persists, can you enable Analyzer debugging here:
https://github.com/scala-js/scala-js/blob/master/sbt-plugin/src/main/scala/scala/scalajs/sbtplugin/optimizer/Analyzer.scala#L18
then scalajs-sbt-plugin/publishLocal, then run preoptimizeJS again and then give the output of the last command?

[jonas]

Yes, thanks. All three flavours now work!

deltablue [dev] d8        : 7881.889763779527 us
deltablue [preopt] d8     : 5091.603053435115 us
deltablue [opt] d8        : 2766.2517289073307 us

[sjrd]

Excellent :-)

[lihaoyi]

Any idea why there's a difference between dev and pre-opt? Shouldn't pre-opt only eliminate dead code which should never be run anyway?

[sjrd]

Parse time + time to execute the code that defines the classes and their methods.

[jonas]

The benchmark runner loads the code and does a couple of warmup runs before the actual timed execution. So the time spent parsing the JavaScript should not affect the execution time. My guess is the size of the internal representation of the program affects the execution time.