Skip to content

Conversation

jvican
Copy link
Member

@jvican jvican commented Sep 11, 2017

This is a continuation of my work for SCP-010. This pull request is the responsible of polishing the statistics framework, adding missing hooks for our Scala plugin scalac-profiling and double-checking the general state of statistics.

As a result, this pull request ends up doing several independent tasks:

  1. It instruments scopes so that we can analyze them later on.
  2. It adds timers for all the phases (-Ystatistics will report how much time do phases take).
  3. Adds hooks to AnalyzerPlugins to inspect implicit search data and therefore allow external plugins to turn it into something meaningful.
  4. Polishes some parts of the user interface of statistics (flags, descriptions).
  5. Fixes/cleans some parts of the infrastructure that is unstable or buggy.

Depends on #6051 and #6034.

@scala-jenkins scala-jenkins added this to the 2.12.4 milestone Sep 11, 2017
allanrenucci added a commit to dotty-staging/dotty that referenced this pull request Sep 14, 2017
Adapted from scala commit 3d7e5c3888e0c0ce46315ea6918fd03b22f1fcb4 by
Jason Zaugg in scala/scala#6067
@adriaanm adriaanm requested a review from lrytz September 21, 2017 22:52

trait Scopes extends api.Scopes { self: SymbolTable =>

private[scala] var scopeCount = 0
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this be reset to 0 after each run? That could be achieved with perRunCaches.newGeneric.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm, yes, it should be reset to 0 after every run. I wanted to emulate trees ids here, that's why I used just one counter.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I didn't figure out how to do it with newGeneric, so I implemented with a clearable. See updated PR. Thanks for the suggestion.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK, newGeneric was probably not a good suggestion here

while (globalPhase.hasNext && !reporter.hasErrors) {
val startTime = currentTime
phase = globalPhase
val phaseTimer = statistics.newSubTimer(s" ${phase.name}", totalCompileTime)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we make this null if ! timePhases?


// progress update
informTime(globalPhase.description, startTime)
informTime(globalPhase.description, phaseTimer.nanos)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should this be guarded by if (timePhases)?

statistics.stopTimer(totalCompileTime, startTotal)
informTime("total", totalCompileTime.nanos)
inform("*** Cumulative timers for phases")
for (q <- statistics.allQuantities if q.phases.nonEmpty && q.showAt(GlobalPhaseName))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit: the guard q.phases.nonEmpty && q.showAt(GlobalPhaseName) is non-obvious to understand - how about the more explicit q.phases == Seq(GlobalPhaseName)?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We can use this because GlobalPhaseName will always be the only phase, but it's more restrictive semantically.

val matchingImplicits = newSubCounter(" #matching", implicitSearchCount)
val typedImplicits = newSubCounter(" #typed", implicitSearchCount)
val foundImplicits = newSubCounter(" #found", implicitSearchCount)
val macroImplicits = newSubCounter(" #macros", implicitSearchCount)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we give it a more telling name, e.g. #triggered during macro expansion?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was not addressed in your latest update.


import scala.reflect.internal.util.Position
final val implicitSearchesByType = symbolTable.perRunCaches.newMap[global.Type, Int]()
final val implicitSearchesByPos = symbolTable.perRunCaches.newMap[Position, Int]()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of collecting this data within the compiler (this data is collected when ever statistics are enabled, but only used by your compiler plugin), I'd prefer some mechanism to allow a compiler plugin to listen for certain events. See AnalyzerPlugins for an example. Here it would be simpler than with analyzer plugins, because it's only about listening for notifications and not changing the result of any method call.

I'm open for other suggestions.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was not addressed. The goal here is to provide a hook for compiler plugins, so I really feel that it's not great to collect some very specific data inside the compiler itself.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hey Lukas, I don't have a clear idea how we could engineer a general interface to listen for general events in the compiler that adds more value than this current implementation.

The problem I see here is that these hooks are very explicit and require instrumentation per ever kind of event (in different parts of the compiler).

In AnalyzerPlugins, I see a more general interface that allows plugins to refine type signatures in certain places, giving a feeling that analyzer plugins can complement typechecking. I don't see a way we can do this for explicit event listening because this requires:

  • The creation of the timers and subtimers.
  • Exposing these timers and subtimers explicitly in the statistics field, so that they are accessible from any call-site of the compiler.
  • Instrumenting one call-site per ever event you want to listen.

Maybe I'm missing something?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think that implicit search should be instrumented here in the compiler to keep track of some important statistics and aggregate these into SearchResult. The most important stat is the overall number of typedImplicit1 calls made within an implicit search tree. Perhaps the number of implicit macros expanded is also interesting. We should also have an easy way for the tools which process the data to distinguish "top level" implicit searches from recursive ones.

A new extension point in AnalyzerPlugin-s could be added to listen on the result of inferImplicit, and then the work to slice, dice, and present this data could be left in the hands of the plugin.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the input. If this PR can still make it for 2.12.4 I'm happy to have a minimal solution here for now and implement a more structured approach later. Would that work for you, @retronym? Would you be OK with the two hash maps?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@retronym @lrytz This sounds like a good idea. I'm implementing it real quick. However, I'll add two hooks into implicit search, one before the search and the other after the search. This will help me add timers and not only counters.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Implemented in 41d60f8.

@jvican jvican force-pushed the stats-per-global+more-timers branch from 7da15c8 to 1258384 Compare September 26, 2017 10:00
Copy link
Member

@lrytz lrytz left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For some reason two of my earlier comments showed up collapsed on the PR discussion even though they were up to date. Maybe a bug in GitHub.

private[scala] var scopeCount = 0

// Reset scopeCount per every run
perRunCaches.recordCache(new Clearable {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

you could use a lambda, Clearable is a SAM type

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I tried -- it didn't work because the compiler failed to create a SAM type because recordCache's signature expects T <: Clearable. It seems SAM creation doesn't work for these cases (or so I think).

Copy link
Member

@lrytz lrytz Sep 26, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ah right, you'd need a type annotation (() => { scopeCount = 0 }): Clearable

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What I ended up doing locally is creating a new private val with the closure. IMO it's better than the type annotation. If you don't have any objection, I'll continue this way.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Either way is fine. A local val would be better than a private val in Scopes, as the latter creates a field.


trait Scopes extends api.Scopes { self: SymbolTable =>

private[scala] var scopeCount = 0
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK, newGeneric was probably not a good suggestion here


import scala.reflect.internal.util.Position
final val implicitSearchesByType = symbolTable.perRunCaches.newMap[global.Type, Int]()
final val implicitSearchesByPos = symbolTable.perRunCaches.newMap[Position, Int]()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was not addressed. The goal here is to provide a hook for compiler plugins, so I really feel that it's not great to collect some very specific data inside the compiler itself.

val matchingImplicits = newSubCounter(" #matching", implicitSearchCount)
val typedImplicits = newSubCounter(" #typed", implicitSearchCount)
val foundImplicits = newSubCounter(" #found", implicitSearchCount)
val macroImplicits = newSubCounter(" #macros", implicitSearchCount)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was not addressed in your latest update.

@jvican
Copy link
Member Author

jvican commented Sep 26, 2017

Indeed, it seems I missed completely these two comments.

@adriaanm adriaanm added the prio:hi high priority (used only by core team, only near release time) label Sep 26, 2017
@jvican jvican force-pushed the stats-per-global+more-timers branch from 1258384 to 2fbd8dd Compare September 27, 2017 13:33
@lrytz
Copy link
Member

lrytz commented Sep 27, 2017

Some of the commits have the following test failure:

!! 1278 - pos/t8531                                 [compilation failed]
##### Log file '/home/jenkins/workspace/scala-2.12.x-validate-test/test/files/pos/t8531-pos.log' from failed test #####

error: null

The fact that it happens on some commits but not on all suggests it could be a race condition (AFAIK, partest runs multiple Global instances in parallel).

@adriaanm adriaanm removed the prio:hi high priority (used only by core team, only near release time) label Sep 27, 2017
@adriaanm
Copy link
Contributor

Looks more likely this will slip to 2.12.5 then.

@jvican
Copy link
Member Author

jvican commented Sep 27, 2017

@lrytz I would be really surprised if this had any thread safety issues as it just adds some counters and timers. If this code had any thread safety issues, all the statistics infrastructure would, which I find pretty unlikely given the code and my experience using/hacking on it.

I think the problem here is that some commits were rebased and there were some issues with this rebase. Let me look into this and quickly push the new changes.

Looks more likely this will slip to 2.12.5 then.

I would really love if this can be merged after my changes have been done and all commits are green. This change is non controversial -- it's not like my other PR that makes a fundamental change to the infrastructure.

/** Lookup a symbol.
*/
def lookup(name: Name): Symbol = {
val startTime = if (statistics.canEnable) statistics.startTimer(statistics.scopeLookupTime) else null
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think this is really a suitable place to instrument, as it misses a lot of important lookups that use alternative scope lookup APIs. E.g. Context.isQualifyingImplicit uses lookupEntry and Context.lookupSymbol uses lookupUnshadowedEntries.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh, I see you've instrumented lookupEntry as well below. Should we then start this timer below the call to lookupEntry to avoid double counting?

Copy link
Member Author

@jvican jvican Sep 28, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I instrumented both so that lookupEntry also records the time spent in executing its whole body, which relies on lookupNextEntry. I think that the statistics infrastructure prevents double counting by design (nested calls do not record the times if there are other timers wrapping them) -> a fresh pair of eyes to confirm this would be good.

However, maybe measuring lookup is uninteresting... so I've removed it in my last commit.

@lrytz
Copy link
Member

lrytz commented Sep 28, 2017

I didn't spot any issues from rebasing when I looked at the commits. The error message in the test failure is as unhelpful as it gets (error: null without any context), that's really annoying.

t8531 is about the pattern matcher / exhaustivity analysis, but I'm not sure that is a hint in the right direction.

@retronym
Copy link
Member

that's really annoying.

I can get that deficient error message by throwing an NPE in the compiler, or any exception with a null message.

I'm guessing that partest is culpable for the old favourite, println(throwable.getMessage). But I'm not 100% sure, we've got similarly horrifying exception handling in the compiler itself.

A quick fix to diagnose this would be to add a commit that changes Run.compileInternal to catch Throwable and print the results to system out. That should show up in the partest log.

@jvican jvican force-pushed the stats-per-global+more-timers branch 4 times, most recently from 41d60f8 to 1be1eb7 Compare September 28, 2017 14:16
@jvican
Copy link
Member Author

jvican commented Sep 28, 2017

@lrytz @retronym Can you have a look at the new AnalyzerPlugin hooks?

Everything is green and ready for a review.

@jvican
Copy link
Member Author

jvican commented Sep 28, 2017

Benchmark scheduled here.

@adriaanm
Copy link
Contributor

adriaanm commented Sep 28, 2017

We'll allow PRs currently scheduled for 2.12.4 to be merged until Friday, run benchmarks and community builds over the weekend and Monday, and cut the release on Tuesday. Any PRs that regress performance / break the community build will be reverted and rescheduled for 2.12.5.

@jvican
Copy link
Member Author

jvican commented Sep 28, 2017

@adriaanm Sounds good. I'll run the community build before you do to make sure all my PRs are ok.

@retronym
Copy link
Member

@jvican Did you figure out the root cause of that null-messaged exception? If not, I'm a bit worried that either this PR or something recent has introduced an non-deterministic error that we need to track down before 2.12.4.

val result = new ImplicitSearch(tree, pt, isView, implicitSearchContext, pos).bestImplicit
val search0 = new ImplicitSearch(tree, pt, isView, implicitSearchContext, pos)
val search = pluginsImplicitSearch(search0)
val result = pluginsImplicitSearchResult(search.bestImplicit)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not really comfortable letting plugins change the results of an implicit search. A less powerful extension point would just have pluginsImplicitSearchResult(search: ImplicitSearch): Unit.

The standard ImplicitSearch can itself contain a timer, which is conditionally computed if stats are on. We don't need to leave that part to the plugin.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not really comfortable letting plugins change the results of an implicit search. A less powerful extension point would just have pluginsImplicitSearchResult(search: ImplicitSearch): Unit.

I've adapted it to be a simple hook. AnalyzerPlugins is itself a powerful tool that refines types from the typechecker, so I wasn't sure that such a powerful extension point would not be accepted since it aligns with the overall idea of the plugin.

The standard ImplicitSearch can itself contain a timer, which is conditionally computed if stats are on. We don't need to leave that part to the plugin.

We already have a timer for this, e.g. implicitNanos, and I can access it statically in my compiler plugin, so I think this is not necessary.

However, I didn't realize that we have another ImplicitSearch for views. They should mostly be unused, but just in case I've added a timer for them too.

This commit adds two important things to the scopes handling in scalac:

* Count how many scopes are created.
* Time common scope operations, like population and lookup so that we
  can effectively measure the impact of unused imports and the like.
The following commit adds the ability to print the timers for every
phase at the end of the `compileSources` execution. This is useful
because you can have an idea of how the running times of the phases are
distributed. It also works for phases injected by the incremental
compiler and compiler plugins (which allows devs to estimate how much
time do their compiler plugins take out of the total compile time).

It also removes the previous infrastructure to print these timings under
the verbose flag, and now reuses the full statistics infrastructure for
doing so.
@jvican jvican force-pushed the stats-per-global+more-timers branch 2 times, most recently from 74f863f to 2c88c5a Compare September 29, 2017 09:30
})

/** @see AnalyzerPlugin.pluginsImplicitSearch */
def pluginsImplicitSearch(search: ImplicitSearch): ImplicitSearch = invoke(new CumulativeOp[Unit] {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should have return type Unit (also below)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I pushed a bad commit.

@jvican jvican force-pushed the stats-per-global+more-timers branch from 2c88c5a to 7d396e4 Compare September 29, 2017 10:47
Copy link
Member

@lrytz lrytz left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It looks good to me now. I'm also still a bit worried about the null-message. But looking through the commits I really cannot see anything suspicious.

val improvesCachedCount = newSubCounter(" #implicit improves cached ", implicitSearchCount)
val inscopeImplicitHits = newSubCounter(" #implicit inscope hits", implicitSearchCount)
val oftypeImplicitHits = newSubCounter(" #implicit oftype hits ", implicitSearchCount)
val viewsNanos = newSubTimer ("time spent in views", typerNanos)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this description is a bit misleading: allViewsFrom seems to be used only by scaladoc, the compiler uses inferImplicit with isView = true.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Intersting, didn't know this. Then I'm removing it.

Because of initialization order of the cake, `statistics` is initialized
after the timers/counters in the cake are, so when it hits the
constructor of `Quantity` those are not registered in `qs`.

This meant that even though those objects were initialized, statistics
were not reported. This change hot fixes it so that they are indeed
reported. It does so by removing the guard that checked whether
statistics were enabled. From now on, for simplicity and correctness, we
will always register timers and counters that are initialized. This
should have no impact in performance, since it's done only once when
everything is initialized, and it's just an addition to a map.
The following commit allows an external analyzer plugin to hook into
scalac's implicit search. This change replaces explicit instrumentation
of this part to capture statistics, and has been therefore extended to
allow more generic scenarios, leaving the tasks of capturing the data to
external third parties (via compiler plugins).

The change adds two new members to the public API of `AnalyzerPlugin`:

1. `pluginsImplicitSearch`: `ImplicitSearch => ()`.
1. `pluginsImplicitSearchResult`: `SearchResult` => `()`.

`ImplicitSearch` is the data structure that contains all the necessary
information to perform implicit search, whereas `SearchResult` is the
resulting found implicit instance.

These two methods allow the analyzer plugin to access the full context
of implicit search. In order to have access to the parameters of
`ImplicitSearch`, this commit also makes private parameters accessible
by converting them to `val`s.
@jvican jvican force-pushed the stats-per-global+more-timers branch from 7d396e4 to 64e0d91 Compare September 29, 2017 11:11
@jvican
Copy link
Member Author

jvican commented Sep 29, 2017

It looks good to me now. I'm also still a bit worried about the null-message. But looking through the commits I really cannot see anything suspicious.

Me neither... I've gone through my previous PRs too and didn't find anything suspicious re thread safety. I'll go through them again, just in case there's something hidden.

I'm integrating all the changes with my scala-profiling integration, and double-checking that everything works. I'll be running the community build with only my changes to check that there's no issue. In a few hours, I'll have some results to show.

This is purely a cosmetic change to make sure that these counters, which
will always be zero or empty, are not displayed to users in case hot
statistics are disabled.
This is a pure UI change that makes it clear that
`-Yhot-statistics-enabled` is a complement of `-Ystatistics`, not a
replacement. Therefore, users need to use it together with
`-Ystatistics`, otherwise `-Yhot-statistics-enabled` won't do anything.
@jvican
Copy link
Member Author

jvican commented Sep 29, 2017

Community build is still running on my cluster, but so far I'm getting no errors.

This commit avoids disabling statistics to avoid the JVM to unstabilize
all the time and to prevent misbehaviours in concurrent builds recycling
the same classloader.

The main problem here is that if one global has statistics enabled and
the second one doesn't, our logic of `enabled` was setting the
pseudo-static to false, preventing the correct recording of statistics
in the global that does want to record them. Now, the logic to disable
these pseudo-statics when `statistics = false` (which is the case almost
always), has been removed.

TL;DR: Once a global enables statistics, the rest has to pay the price
of a 2/3% performance hit. There is no going back.
@jvican jvican force-pushed the stats-per-global+more-timers branch from 2a27be8 to 1c47b2f Compare September 29, 2017 16:26
@jvican
Copy link
Member Author

jvican commented Sep 29, 2017

Today I've spent almost all day double-checking this PR and integrating it with scalac-profiling. This process has given me confidence that I have everything I need from the compiler after the exhaustive feedback that I received in this and the previous PRs.

These are the tasks I've done to double-check this PR is in good shape:

  • Compile both the library and the compiler with the binaries and the following flags: -Ystatistics, -Yhot-statistics-enabled. Everything ok.
  • Enabled -Ystatistics in one project in an sbt multi-build and double-checked that only that project outputs statistics (the other one doesn't, despite the fact that they share the same classloader). Everythink ok.
  • Executed different projects with statistics enabled in parallel. Everything ok.
  • Run the community build in our cluster (it's still running but so far everything passes).

As a result of this process, I've updated this PR with minor fixes to the UI and the semantics of the whole statistics framework. I'm fairly confident this PR doesn't represent a problem for the upcoming release.

I would appreciate if someone can go through it again and tell me if it looks good to you.

Ping me during the weekend if you have any question regarding my PRs.

@jvican jvican changed the title Adds extra counters and timers to statistics Add hooks, counters and refine the statistics infrastructure Sep 29, 2017
@adriaanm
Copy link
Contributor

adriaanm commented Oct 1, 2017

Thanks for the due diligence, @jvican. I'll let @retronym take a look his Monday morning and hopefully get this merged by my Sunday night :-)

override def YstatisticsEnabled = Ystatistics.value.nonEmpty

val YhotStatistics = BooleanSetting("-Yhot-statistics", "Print hot compiler statistics for all relevant phases")
val YhotStatistics = BooleanSetting("-Yhot-statistics-enabled", s"Enable `${Ystatistics.name}` to print hot statistics.")
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You could make -Ystatistics a ChoiceSetting (-Ystatistics:{none|cold|all}), but that's not a blocker for merging this PR.

@adriaanm adriaanm merged commit 17496bd into scala:2.12.x Oct 1, 2017
@rorygraves
Copy link
Contributor

rorygraves commented Oct 2, 2017 via email

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

6 participants