Prior to these changes, sbt was leaking large amounts of memory via
log4j appenders. sbt has an unusual use case for log4j because it
creates many ephemeral loggers while also having a global logger that is
supposed to work for the duration of the sbt session. There is a lot of
shared global state in log4j and properly cleaning up the ephemeral task
appenders would break global logging. This commit fixes the behavior by
introducing an alternate logging implementation. Users can still use the
old log4j logging implementation but it will be off by default. The
internal implementation is very simple: it just blocks the current
thread and writes to all of the appenders. Nevertheless, I found the
performance to be roughly identical to that of log4j in my sample
project. As an experiment, I did the appending on a thread pool and got
a significant performance improvement but I'll defer that to a later PR
since parallel io is harder to reason about.
Background: I was testing sbt performance in
https://github.com/jtjeferreira/sbt-multi-module-sample and noticed that
performance rapidly degraded after I ran compile a few times. I took a
heap dump and it became obvious that sbt was leaking console appenders.
Further investigation revealed that all of the leaking appenders in the
project were coming from task streams. This made me think that the fix
would be to track what loggers were created during task evaluation and
clear them out when task evaluation completed. That almost worked except
that log4j has an internal append only data structure containing logger
names. Since we create unique logger names for each run, that internal
data structure grew without bound. It looked like this could be worked
around by creating a new log4j Configuration (where that data structure
was stored) but while creating new configurations with each task runs
did fix the leak, it also broke global logging, which was using a
different configuration. At this point, I decided to write an alternate
implementation of the appender api where I could be sure that the
appenders were cleaned up without breaking global logging.
Implementation: I made ConsoleAppender a trait and made it no longer
extends log4j AbstractAppender. To do this, I had to remove the one
log4j specific method, append(LogEvent). ConsoleAppender now has a
method toLog4J that, in most cases, will return a log4j Appender that is
almost identical to the Appenders that we previously used. To manage
the loggers created during task evaluation, I introduce a new class,
LoggerContext. The LoggerContext determines which logging backend to use
and keeps track of what appenders and loggers have been created. We can
create a fresh LoggerContext before each task evaluation and clear it
out, cleaning up all of its resources after task evaluation concludes.
In order to make this work, there were many places where we need to
either pass in a LoggerContext or create a new one. The main magic is
happening in the `next(State)` method in Main. This is where we create a
new LoggerContext prior to command evaluation and clean it up after the
evaluation completes.
Users can toggle log4j using the new useLog4J key. They also can set the
system property, sbt.log.uselog4j. The global logger will use the sbt
internal implementation unless the system property is set.
There are a fairly significant number of mima issues since I changed the
type of ConsoleAppender. All of the mima changes were in the
sbt.internal package so I think this should be ok.
Effects: the memory leaks are gone. I successfully ran 5000 no-op
compiles in the sbt-multi-module-sample above with no degradation of
performace. There was a noticeable degradation after 30 no-op compiles
before.
During the refactor, I had to work on TestLogger and in doing so I also
fixed https://github.com/sbt/sbt/issues/4480.
This also should fix https://github.com/sbt/sbt/issues/4773
Zinc frequently needs to check the library classpath to ensure that
class names are defined in a given jar. There is a cost to looking up
the class names in the jar so it's a benefit to cache this across runs
so that we don't have to redo the same work every time. More
importantly, in testing with the latest sbt HEAD, I found that sbt would
crash fairly frequently because it ran out of direct memory, which is
used by nio to read and write to native memory without copying. The
direct memory area is shared with the java heap and if it reaches the
limit, the jvm crashes hard as though kill -9 was invoked. After caching
the entries, I stopped seeing crashes.
Rather than relying on a command, I realized it makes more sense to
explicitly set the terminal for the calling channel in MainLoop. By
doing it this way, we can also ensure that we always reset it to the
previous value.
Using the scala reflect library always introduces significant
classloading overhead. We can eliminate the classloading overhead by
generating StringTypeTags at compile time instead.
This sped up average project loading time by a few hundred milliseconds
on my computer. The ManagedLoggedReporter in zinc is still using the
type tag based apis but after the next sbt release, we can upgrade the
zinc apis. We also could consider breaking binary compatibility.
sbt depends on scalacache (which hasn't been updated in about a year)
and we really don't need the functionality provided by scalacache. In
fact, the java api is somewhat easier to work with for our use case. The
motivation is that scalacache uses slf4j for logging which meant that it
was implicitly loading log4j. This caused some noisy logs during
shutdown when the previously unused cache was initialized just to be
cleaned up.
This commit also upgrades caffeine and moving forward we can always
upgrade caffeine (and potentially shade it) without any conflict with
the scalacache version.
Upon successful registration with a FileTreeRepository, an Observable is
returned by the FileTreeRepository that can be used to observer the
specific globs that were registered. The FileTreeRepository also has a
global Observable that can be used to monitor _all_ events. In order to
implement this feature, internally the FileTreeRepository needs to hold
a reference to the registered Observable so that it forwards relevant
file change events. If we do not close the Observable, it leaks memory
inside of FileTreeRepository. There were a number of places within sbt
where we registered globs and did nothing with the returned Observable.
It was thus straightforward to fix the leak by just closing the returned
Observables.
This came up because I was looking at a heap dump of
https://github.com/jtjeferreira/sbt-multi-module-sample after running
1000 no-op compiles and noticed that the FileTreeRepository.observables
were taking up 75MB out of a total heap of about 300MB.
As a side note, it would be nice if sbt had a warning for unused return
values when a statement is not the last in a block. It's possible that
these leaks wouldn't have happened if we were forced to handle the
returned Observables.
Ref https://github.com/sbt/zinc/pull/744
This implements `ThisBuild / usePipelining`, which configures subproject pipelining available from Zinc 1.4.0.
The basic idea is to start subproject compilation as soon as pickle JARs (early output) becomes available. This is in part enabled by Scala compiler's new flags `-Ypickle-java` and `-Ypickle-write`.
The other part of magic is the use of `Def.promise`:
```
earlyOutputPing := Def.promise[Boolean],
```
This notifies `compileEarly` task, which to the rest of the tasks would look like a normal task but in fact it is promise-blocked. In other words, without calling full `compile` task together, `compileEarly` will never return, forever waiting for the `earlyOutputPing`.
It can easily take 2ms or more to parse a command depending on state's
combined parser. There are some commands that sbt requires to work that
we can handle in microseconds instead of milliseconds by special casing
them.
After this change, I saw the performance of
https://github.com/eatkins/scala-build-watch-performance improve by
a consistent 4-5ms in the 3 source file example which was a drop from
120ms to 115ms. While not necessarily earth shattering, this difference
could theoretically be much worse in other projects that have a lot of
plugins and custom tasks/commands. I think it's worth the modest
maintenance cost.
Ref https://github.com/sbt/sbt/issues/5710
Ref https://github.com/sbt/librarymanagement/pull/339
This adds `versionScheme` setting. When set, it is included into POM, and gets picked up on the other side as an extra attribute of ModuleID. That information in turn is used to inform the eviction warning.
This should reduce the false positives associated with SemVer'ed libraries showing up in the eviction warning.
The 1.4.0 implementation of watch uses a concurrent hash map to maintain
the global watch state which manages the state for an arbitrary number
of clients. Using a mutable map is not idiomatic sbt and I found it
difficult to reason about when the map was updated. This commit reworks
the feature so that the global state is instead stored in an immutable
map that is only modified during the internal watch commands, which is
easier to reason about.
The EventsTest changes kept appearing. I'm not sure why scalafmt check
was allowing it before. My vim status bar warns me about trailing spaces
and I noticed the two in Keys.scala and removed them.
In eb688c9ecd, we started buffering output
to the remote client to reduce flickering. This was causing problems
with the output for the thin client in batch mode. With the delay, it
was possible for the client to exit before all of its output had been
displayed.
Bonus: only display aggregation error message if terminal has success
enabled (the thin client displays its own timing message so the message
in aggregation ended up being a duplicate).
It is expensive to compute the the hash of every jar on the classpath so
we can try to avoid that by using the timeWrappedStamper which only
computes the hash if the last modified time has changed.
Using the managedCached introduced an unintended performance regression
because it ensured that we always computed the hash of each jar on the
dependency classpath. The backing ReadStamps only computes the stamp if
the timestamp of the jar has changed.
The sbt project load made a number of relatively inefficient
transformations of scala collecitons. I went through and found the slow
parts during project loading and made my best attempt at fixing them.
The most significant changes I made were in places using IMap. An IMap
is more or less a wrapper around an immutable Map. It can be much faster
to construct an IMap by creating a java mutable hashmap, wrapping it a
scala Map that delegates to the underlying java hashmap (with a copy on
write if the map is modified) and constructing the IMap from the wrapped
map. It was also in many cases to parallelize some transformations
wherever the order didn't matter.
After applying all of these changes, I found that loading the sbt
project took generally between 8.5 and 9 seconds on my laptop. With
1.3.13, it hovered around 11.5 seconds. I saw a similar speedup in zinc.
The biggest specific improvement was that generating the compiled map
dropped from between 3.5-4 seconds to pretty consistently being around
1.5 seconds.
This reverts commit b1dcf031a5.
I found that b1dcf031a5 had some
unintended consequences that seemed to mess up the prompt state. The
real problem that it was trying to address was that the prompt was being
interleaved with log messages in some scenarios. There was a different
way to fix that in ProgressState that was both simpler and more
reliable.
The jline2 history file format is incompatible with jline3 and jline3
prints a very noisy warning if it detects such a file. History will also
not work with jline3 until you remove or reformat the old file.
I noticed that when reloading the build, that certain errors are logged
by sbt to System.err. These were not shown to a thin client because we
weren't forwarding System.err. This change remedies that.
System.err is handled more simply than System.out. We do not put
System.err through the progress state because generally System.err is
tends to be unbuffered. I had hesitated to add System.err to the
Terminal interface at all to give users an escape hatch but I couldn't
get project loading to work well with the thin client without it.
In db4878c786, TaskProgress became an
object which mostly made things easier to reason about. The one problem
was that it started leaking tasks with every run because the timings map
would accumulate tasks that weren't cleared. To fix this, we can clear
the timings and activeTasksMap in the TaskProgress object in the
afterAllCompleted callback. Some extra null checks needed to be added
since it's possible for the maps to not contain a previously added key
after reset has been called.
This fixes the nio/external-hooks test and also restores the performance
of the benchmarks for the latest sbt version in
https://github.com/eatkins/scala-build-watch-performance which had
regressed when the custom ExternalHooks were disabled in
7c4b01d9f7.
The main change is that it changes the ReadStamps object that is passed
into the compiler options to one that uses the unmanagedFileStampCache
and managedFileStampCache for source files and falls back to the default
stamper otherwise. This improves the performance quite significantly
since we only hash the files once. It also makes it so that the analysis
file will contain the source file stamps of the files when compilation
began, rather than when compilation ended. That is what
nio/external-hooks was testing. In the real world what could happen was
that one modified a source file during compilation but then no
incremental re-compilation would occur because after the initial
compilation completed, zinc wrote the stamp of the modified source file
in the analysis file even though it may have actually compiled a
different version of the source file.
I noticed some RejectedExecutionExceptions in travis failures of
ClientTest. This could happen if we try to write output to the
network channel after it has been closed. To avoid this problem, we can
catch RejectedExecutionExceptions and do an immediate flush if the
executor has been shutdown.
In order for sbt to function well, it needs the test interface, jansi
and forked jline jars provided by a classloader that is parent to all
other sbt classloaders. To do this for just the test interface jar, I
just checked if the top loader in the app configuration had the correct
name. Now that there are three jars, this is more complicated so I
updated the launcher to create a top loader with the method getEarlyJars
implemented and returning the three needed jars. This is a much more
scalable design.
If sbt is entered with a configuration that does not have a top loader
with the getEarlyJars method defined, then we just fall back on
constructing the default layered classlaoder from the configuration
classpath.
The motivation for this change is that I discovered that sbt immediately
crashed when I tried to run a non-snapshot version. After this change, I
verified that both snapshot and non-snapshot versions of the latest sbt
code could load with both an obsolete and up-to-date launcher.
The unprompt method will actually kill the ui thread if its running. If
we don't to this, we can get into a weird state where after watch is
exited by <enter>, the ask user thread spins up but before it can print
the prompt, the terminal prompt is changed to Running, which has an
empty prompt. The end result is that jline3 never displays the prompt
even though the line reader is active and reading bytes. When the user
typed <enter> a prompt would appear. They also could input a command and
it would run but it wasn't obvious what would happen since the prompt
was missing.
The build source check is evaluated at times when we can't be completely
sure that global logger is pointing at the terminal that initiated the
reload (which may be a passive watch client). To work around this, we
can inspect the exec to determine which terminal initiated the check and
write any output directly to that terminal.
This commit upgrades sbt to using jline3. The advantage to jline3 is
that it has a significantly better tab completion engine that is more
similar to what you get from zsh or fish.
The diff is bigger than I'd hoped because there are a number of
behaviors that are different in jline3 vs jline2 in how the library
consumes input streams and implements various features. I also was
unable to remove jline2 because we need it for older versions of the
scala console to work correctly with the thin client. As a result, the
changes are largely additive.
A good amount of this commit was in adding more protocol so that the
remote client can forward its jline3 terminal information to the server.
There were a number of minor changes that I made that either fixed
outstanding ui bugs from #5620 or regressions due to differences between
jline3 and jline2.
The number one thing that caused problems is that the jline3 LineReader
insists on using a NonBlockingInputStream. The implementation ofo
NonBlockingInputStream seems buggy. Moreover, sbt internally uses a
non blocking input stream for system in so jline is adding non blocking
to an already non blocking stream, which is frustrating.
A long term solution might be to consider insourcing LineReader.java
from jline3 and just adapting it to use an sbt terminal rather than
fighting with the jline3 api. This would also have the advantage of not
conflicting with other versions of jline3. Even if we don't, we may want to
shade jline3 if that is possible.
It is possible for sbt to get into a weird state when in a continuous
build when the auto reload feature is on and a source file and a build
file are changed in a small window of time. If sbt detects the source
file first, it will start running the command but then it will
autoreload when it runs the command because of the build file change.
This causes the watch to get into a broken state because it is necessary
to completely restart the watch after sbt exits.
To fix this, we can aggregate the detected events in a 100ms window. The
idea is to handle bursts of file events so we poll in 5ms increments and
as soon as no events are detected, we trigger a build.
Remote clients sometimes flicker when updating progress. This is especially
noticeable when there are two clients and one of them is running a command,
the other will tend to have some visible flickering and character ghosting.
As an experiment, I buffered calls to flush in the NetworkChannel output
stream and the artifacts went away.
Running a `~` command in a local build off the latest develop branch
will cause the build to reload even if the build sources were only
touched and not actually modified.
Ethan Atkins
eugene yokota
adpi2