With the latest sbt snapshot, the ui would get stuck if the user entered
an empty command. They would be presented with an empty prompt and could
not input any commands. This was caused by the change in
d569abe70a that reset the prompt after a
line was read. I had tried to optimize line reading by ignoring empty
commands in UITask.readline so we wouldn't have to make a new thread.
This optimization wasn't really buying much since it only affects how
quickly the user is reprompted after entering an empty command. Unless a
user is spamming the <enter> key, they shouldn't notice a difference.
This commit adds a few options to supershell:
1. Max items -- sets the max number of tasks to display in the progress
reports. It is pretty hard to read more than a few items in the
progress reports so I set the default limit to 8 and made that
configurable via the superShellMaxTasks parameter. If there are more
than the limit, there is an additional line telling how many additional
tasks are running
2. sleep -- sets how long to sleep between reports. The default is 500ms
to ensure that it updates at least once per second but the previous
value of 100ms is more frequent than necessary
3. threshold -- sets the minimum duration a task has to run before being
printed in the progress reports. The default threshold is increased
from 10ms to 100ms. This introduces a delay of threshold milliseconds
before any progress lines appear and also means that if no tasks ever
exceed the threshold, then no progress is ever displayed.
It turns out that task progress actually introduces a fair bit of
overhead. The biggest issue is that the task progress callbacks block
the Execute main thread. This means that time in those callbacks
delays task evaluation, slowing down sbt. This was not negligible, I was
seeing a lot of the total time of a no-op compile in
https://github.com/jtjeferreira/sbt-multi-module-sample was spent in
TaskProgress callbacks. Prior to these changes, I ran 30 no-op compiles
in that project and the average time was about 570ms. This number got
worse and worse because there were memory leaks in the TaskProgress
object. After these changes, it dropped to 250ms and after jit-ing, it
would drop to about 200ms. I also successfully ran 5000 consecutive
no-op compiles without leaking any memory.
A lot of the overhead of task progress was in adding tasks to the
timings map in AbstractTaskProgress. Tasks were never removed and
ConcurrentHashMap insertion time is proportional to the size of the map
(not sure if it's linear, quadratic or other) which was why sbt actually
got slower and slower the longer it ran. Much of the time was spent
adding tasks to the progress timings.
To fix this, I did something similar to what I did to manage logger
state in https://github.com/jtjeferreira/sbt-multi-module-sample. In
MainLoop, we create a new TaskProgress instance before command
evaluation and clean it up after. Earlier I made TaskProgress an object
to try to ensure there was only one progress thread at a time, and that
introduced the memory leak. In addition to removing the leak, I was able
to improve performance by removing tasks from the timings map when they
completed. Unlike TaskTimings and TaskTraceEvent, we don't care about
tasks that have completed for TaskProgress so it is safe to remove them.
In addition to the memory leaks, I also reworked how the background
threads work. Instead of having one thread that sleeps and prints
progress reports, we now use two single threaded executors. One is a
scheduled executor that is used to schedule progress reports and the
other is the actual thread on which the report is generated. When
progress starts, we schedule a recurring report that is generated every
sleep interval until task evaluation completes. Whenever we add a new
task, if we have haven't previously generated a progress report, we
schedule a report in threshold milliseconds. If the task completes
before the threshold period has elapsed, we just cancel the schedule
report. By doing things this way, we reduce the total number of reports
that are generated. Because reports need to effectively lock System.out,
the less we generate them, the better.
I also modified the internal data structures of AbstractTaskProgress so
that there is a single task map of timings instead of one map for
timings and one for active tasks.
It was a bit tricky to reason about the state of the prompt for a
terminal. To help make things more clear, I reworked things so that the
LineReader always sets the prompt to Pending after it reads a command.
In MainLoop, we cache the prompt value and temporarily set it to Running
while the command is running, which is really how it should have always
been.
In order to make the console task work with scala 2.13 and the thin
client, we need to provide a way for the scala repl to use an sbt
provided jline3 terminal instead of the default terminal typically built
by the repl. We also need to put jline 3 higher up in the classloading
hierarchy to ensure that two versions of jline 3 are not loaded (which
makes it impossible to share the sbt terminal with the scala terminal).
One impact of this change is the decoupling of the version of
jline-terminal used by the in process scala console and the version
of jline-terminal specified by the scala version itself. It is possible
to override this by setting the `useScalaReplJLine` flag to true. When
that is set, the scala REPL will run in a fully isolated classloader. That
will ensure that the versions are consistent. It will, however, for sure
break the thin client and may interfere with the embedded shell ui.
As part of this work, I also discovered that jline 3 Terminal.getSize is
very slow. In jline 2, the terminal attributes were automatically cached with a
timeout of, I think, 1 second so it wasn't a big deal to call
Terminal.getAttributes. The getSize method in jline 3 is not cached and
it shells out to run a tty command. This caused a significant
performance regression in sbt because when progress is enabled, we call
Terminal.getSize whenever we log any messages. I added caching of
getSize at the TerminalImpl level to address this. The timeout is 1
second, which seems responsive enough for most use cases. We could also
move the calculation onto a background thread and have it periodically
updated, but that seems like overkill.
There are cases where if the ui state is changing rapidly, that an
AskUserThread can be created and cancelled in a short time windows. This
could cause problems if the AskUserThread is interrupted during
`LineReader.createReader` which I think can shell out to run some
commands so it is relatively slow. If the thread was interrupted during
the call to `LineReader.createReader` and the interruption was not
handled, then the thread would go into `LineReader.readLine`, which
wouldn't exit until the user pressed enter. This ultimately caused the
ui to break until enter because this zombie line reader would be holding
the lock on the terminal input stream.
We should always hold the print stream lock when calling
progressState.write because otherwise the task progress thread could
concurrently write to stdout.
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
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.
These were not actually used as far as I could tell. The json codecs
cache showed up as taking up 30MB in a heap dump that I took after
running compile 30 times in a clone of the repro project in
https://github.com/sbt/sbt/issues/5508.
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.
JLine 3 automatically appends a space character to the completion
candidate unless you tell it not to by setting its 'complete' parameter.
This behavior is generally nice because it will automatically complete
something like 'foo/testO<TAB>' to 'foo/testOnly ' which allows the user
to start typing the testname without having to enter space. It does,
however, break scripted completions because it will complete
'scripted wat<TAB>' to 'scripted watch/ '
This commit updates the custom completer to append a " " to the initial
completions and check if there are any additional completions available.
If so, we set the complete flag to true and jline will append a space to
the input when the user presses <TAB> or <ENTER>. Otherwise the old
jline2 behavior where no spaces are ever appended is preserved.
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).
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.
The more we call flush, the more likely progress status is to blink. To
reduce the amount of calls to flush, we can instead batch all of the
bytes that are going to be written and wriite them all at once. This
change made progress noticeably less blinky in the zinc project running
the latest sbt snapshot (which frankly was almost siezure inducing when
running publishLocal)
Printing a new line was not great ux. You might see something like:
[info] set current project to project (in build file:project)
sbt:project>
[info] new client connected: network-1
sbt:project>
instead of initially
[info] set current project to project (in build file:project)
sbt:project>
and then after the client connects:
[info] set current project to project (in build file:project)
[info] new client connected: network-1
sbt:project>
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.
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.
It is useful to store a buffer of the lines written to each terminal. We
can use those lines to replay the terminal log lines to a different
client. This is particularly nice when a remote client connects to sbt
while it's booting. We can show the remote client all the lines
displayed by the console prior to the client connecting.
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.
If there is no system console available, then there is no point in
making an ask user thread. An ask user thread can only be created when
the terminal prompt is in the Prompt.Running or Prompt.Loading state.
The console channel will now set itself to be in the Prompt.NoPrompt
state if it detects that there is no System.console available.
The motivation for this change is that jline was printing a lot of extra
text during scripted and server tests. Whenever a jline3 linereader is
closed, it prints a newline so the logs were filled with unnecessary
newlines.
In the situation where sbt was started in server mode and a client is
running a `~` command and a project reload is triggered by a change to
a build source, the console terminal looks like
sbt:foo>
[info] received remote command: ~compile
sbt:foo>
[info] welcome to sbt 1.4.0-SNAPSHOT (Azul Systems, Inc. Java 1.8.0_252)
sbt:foo>
[info] loading global plugins from ~/.sbt/1.0/plugins
sbt:foo>
[info] loading settings for project foo-build from metals.sbt ...
sbt:foo>
[info] loading project definition from
~/foo/project
sbt:foo>
[info] loading settings for project root from build.sbt ...
sbt:foo>
[info] loading settings for project macros from build.sbt ...
sbt:foo>
[info] loading settings for project main from build.sbt ...
sbt:foo>
[info] set current project to foo (in build file:~/foo)
sbt:foo>
This change fixes that by unprompting all channels during project
loading and reprompting them when it completes.
The continuous command recompiles the setting graph into a CompiledMap
data structure so that it can determine which files it needs to
transitively monitor during watch. Generating the CompiledMap can be
very slow for large projects (5 seconds or so on my computer in the sbt
project) and this startup cost is paid every time the user enters a
watch with `~`. To avoid this, we can cache the compile map that is
generated during the initial settings evaluation.
The only real drawback I can see is that the compiled map is guaranteed
to remain in memory so long as the BuildStructure instance that holds it
is alive. Given the performance benefit, this seems like a worthwhile
tradeoff.
In a few places, I used this pattern in an attempt to debug some ui
issues. It is incorrect because it doesn't use System.lineSeparator
and is also pointless.
When running reboot at the console, the first character that the user
enters after the reboot has completed is lost. This is because it isn't
possible to interrupt System.in and we have a thread that is blocking on
reads to System.in in WriteableInputStream. That thread cannot be
shutdown during normal sbt shutdown while it is reading. When sbt next
starts up (in the same jvm), the previous thread gets the byte but has
nowhere to write it so the byte is lost. This commit fixes that behavior
by ensuring that we only poll from System.in when there is actually a
downstream consumer.
The behavior of reboot is still a little wonky if the user issues a
reboot from a network client and then tries to input commands at the
console. In that case, sbt will have been polling System.in in the ask
user thread prior to the reboot and the ask user thread will be
uninterruptible for the reason described above so the first byte will
again by swallowed by the previous sbt instance. This use case is
sufficiently pathological that it doesn't feel worth the effort to fix.
As annoying as it is, it doesn't break the sbt session. The user will
either submit an invalid command with the missing leading character or
notice the character is missing, possibly think they missed the key,
type backspace a few times and re-type the command.
On windows, it is sometimes possible to leak an sbt process if two
processes are started simultaneously by a remote client at the same
time. When this happens, the second process is unable to create a
server because of the first process and it also has no io streams
because the the client detaches its streams. We can detect this
in the shell command and prevent the process from persisting as a
zombie.
One issue with the remote client approach is that it is possible for
multiple clients to start multiple servers concurrently. I encountered
this in testing where in one tmux pane I'd start an sbt server and in
another I might run sbtc before the server had finished loading. This
can actually cause java processes to leak because the second process is
unable to start a server but it doesn't necessarily die after the client
that spawned it exits. This commit prevents this scenario by creating a
server socket before it loads the build and closes once the build is
complete. The client can then receive output bytes and forward input to
the booting server.
The socket that is created during boot is always a local socket, either
a UnixDomainServerSocket or a Win32NamedPipeServerSocket. At the moment,
I don't see any reason to support TCP. This socket also has no impact at
all on the normal sbt server that is started up after the project has
loaded.
The socket is hardcoded to be located at the relative path
project/target/$SOCK_NAME or the named pipe $SOCK_NAME where SOCK_NAME
is a farm hash of the absolute path of the project base directory. There
is no portfile json since there is no need since we don't support TCP.
After the socket is created it listens for clients to whom it relays
input to the console's input stream and relays the process output back
to the client. See the javadoc in BootServerSocket.java for further
details.
The process for forking the server is also a bit more complicated after
this change because the client will read the process output and error
streams until the socket is created and thereafter will only read output
from the socket, not the process.
Supershell does not work correctly when the sbt server is started by the
remote client on windows because it incorrectly calculates the terminal
dimensions. To work around this, we can pass in the dimensions from the
remote client as an environment variable. I tried to do this as a system
property but had all kinds of problems with windows stripping delimeters
from the command. It was much easier to get working with an environment
variable and should really only be set by the sbtc client anyway.
It seemed like a good idea to avoid printing the progress lines if they
were the same as last time. Unfortunately there is a scenario where the
user has multiple clients open and while one of the clients is running a
command, the user presses enter in the inactive client. When this
happens the message that warns that the server is running a different
command gets overwritten. Always printing keeps the message visible.
JLine will spam the console with error messages if certain commands get
interrupted. This is very noticeable and annoying in tab completions.
We can stop doing work in background as well since we've silenced the
jline logging.
This commit makes it possible for a remote client to cancel a running
task initiated by a different client by typing `cancel` into the shell.
It can be useful if the remote client has run something blocking like
console.
The console task can't safely be interrupted, so instead we write some
newlines filed by ctrl+d to exit the console.
This commit makes it possible for the sbt server to render the same ui
to multiple clients. The network client ui should look nearly identical
to the console ui except for the log messages about the experimental
client.
The way that it works is that it associates a ui thread with each
terminal. Whenever a command starts or completes, callbacks are invoked
on the various channels to update their ui state. For example, if there
are two clients and one of them runs compile, then the prompt is changed
from AskUser to Running for the terminal that initiated the command
while the other client remains in the AskUser state. Whenever the client
changes uses ui states, the existing thread is terminated if it is
running and a new thread is begun.
The UITask formalizes this process. It is based on the AskUser class
from older versions of sbt. In fact, there is an AskUserTask which is
very similar. It uses jline to read input from the terminal (which could
be a network terminal). When it gets a line, it submits it to the
CommandExchange and exits. Once the next command is run (which may or
may not be the command it submitted), the ui state will be reset.
The debug, info, warn and error commands should work with the multi
client ui. When run, they set the log level globally, not just for the
client that set the level.
In order to support a multi-client sbt server ux, we need to factor
`Terminal` out into a class instead of a singleton. Each terminal provides
and outputstream and inputstream. In all of the places where we were
previously relying on the `Terminal` singleton we need to update the
code to use `Terminal.get`, which will redirect io to the terminal whose
command is currently running.
This commit does not implement the server side ui for network clients.
It is just preparatory work for the multi-client ui.
The Terminal implementations have thread safe access to the output
stream. For this reason, I had to remove the sychronization on the
ConsoleOut lockObject. There were code paths that led to deadlock when
synchronizing on the lockObject.
Rather than going through the console appender logging to make
TaskProgress work, we can instead use the CommandExchange. This will be
useful in future commits where there are multiple terminals that all
need to receive progress. By organizing the TaskProgress this way, we
can store a separate progress state for each terminal and update the
progress for all of the active terminals. We also can set the current
running command in command exchange which will be useful in future
commits to show what command is currently running.
This commit also reworks TaskProgress to always kill its thread when
there are no active tasks. It will start a new thread as soon as there
is another active task.
This commit adds a number of functions for stripping ansi escape
characters and/or finding the position of the cursor in a line that may
contain colors and moves. The motivation for EscHelpers.cursorPosition
is that when printing progress lines, we need to know the visual
dimensions of the last line printed to the prompt. The
EscHelpers.stripColorsAndMoves can be used to remove all ansi escape
sequences. Finally EscHelpers.stripMoves leaves colors but strips out
all other escape sequences. This is so we can reprint the terminal
prompt during supershell. If we didn't strip out the escape sequences,
we could inadvertently blow away everything below the cursor in cases
where we actually want the lines below the cursor to persist.
Eugene Yokota
Ethan Atkins