high cpu consumption by sbt main thread when running a project with nohup

Question

To get right to it, I am trying to build an autonomous environment where I can provide the benefits of sbt's auto-reloading without needing to actually run interactively. At this point I have a setup that does exactly what I want with the exception of the sbt main thread going crazy and eating 100% cpu. I am unsure of why this is the case, but because this is an unusual way of doing things I wanted to discuss it here before filing a bug.

First, some system information.

• CentOS release 6.5 (Final)

• java version "1.7.0_51" Java(TM) SE Runtime Environment (build 1.7.0_51-b13) Java HotSpot(TM) 64-Bit Server VM (build 24.51-b03, mixed mode)

• sbt (launched with 0.13.0, but the project then runs under 0.12.4)

I am orchestrating this system using chef, the script that kicks everything off will be run as root and here is what the constructed command for a particular project looks like. If this command is decomposed and run as hubuser without background and nohup, i.e. the normal way as an interactive shell, everything works exactly as would be expected.

su - hubuser -c "cd /home/hubuser/projects/cruise/tsttravel_synced; nohup java -Xms512M -Xss1M -XX:+CMSClassUnloadingEnabled -XX:MaxPermSize=1024M -Xmx4096M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/hubuser/projects/cruise -Xdebug -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=9054 -Dnet.tstllc.rmi.agent.port=9104 -javaagent:/opt/tst/jmx/jmx-agent.jar -jar /home/hubuser/projects/sbt-launch.jar 'project cruise-web' ';compile;run -Dhttp.port=9004 -Dap.credentials.file=/home/hubuser/projects/credentials.cfg -Dap.config.file=/home/hubuser/projects/app.cfg -Dlogger.file=/home/hubuser/projects/cruise/cruise-logback.xml' &>> /home/hubuser/projects/cruise/console.log &"

However, run this way the sbt main thread goes crazy. Here's how I came to that conclusion. I have not yet dug into the sbt codebase, but my blind stab in the dark is that screwing with signals and the shell like this somehow causes bizarre behavior. Any sbt devs have a better educated guess?

1) last lines in the console.log, pretty standard stuff.

--- (Running the application from SBT, auto-reloading is enabled) ---

(Server started, use Ctrl+D to stop and go back to the console...)

2) top showing processes, nothing is happening but the cpu load never goes away.

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

14037 hubuser 20 0 8540m 1.6g 25m S 100.0 10.5 3:39.94 java

3) top showing native threads from the same run.

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

14044 hubuser 20 0 8540m 1.6g 25m R 100.0 10.5 15:14.45 java

4) finally, the salient part of the thread dump. 0x36dc = 14044

kill -3 14037

"main" prio=10 tid=0x00007fdbb400a800 nid=0x36dc runnable [0x00007fdbbaf76000]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileInputStream.read0(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:210)
    at jline.Terminal.readCharacter(Terminal.java:99)
    at jline.UnixTerminal.readVirtualKey(UnixTerminal.java:122)
    at jline.ConsoleReader.readVirtualKey(ConsoleReader.java:1606)
    at play.PlayConsoleInteractionMode$.waitEOF$1(PlayInteractionMode.scala:29)
    at play.PlayConsoleInteractionMode$$anonfun$waitForKey$1.apply$mcV$sp(PlayInteractionMode.scala:36)
    at play.PlayConsoleInteractionMode$.doWithoutEcho(PlayInteractionMode.scala:41)
    at play.PlayConsoleInteractionMode$.waitForKey(PlayInteractionMode.scala:36)
    at play.PlayConsoleInteractionMode$.waitForCancel(PlayInteractionMode.scala:45)
    at sbt.PlayCommands$$anonfun$createPlayRunCommand$1$$anonfun$57.apply(PlayCommands.scala:671)
    at sbt.PlayCommands$$anonfun$createPlayRunCommand$1$$anonfun$57.apply(PlayCommands.scala:523)
    at scala.Either$RightProjection.map(Either.scala:533)
    at sbt.PlayCommands$$anonfun$createPlayRunCommand$1.apply(PlayCommands.scala:523)
    at sbt.PlayCommands$$anonfun$createPlayRunCommand$1.apply(PlayCommands.scala:497)
    at sbt.Command$$anonfun$sbt$Command$$apply1$1$$anonfun$apply$6.apply(Command.scala:72)
    at sbt.Command$.process(Command.scala:90)
    at sbt.MainLoop$$anonfun$next$1$$anonfun$apply$1.apply(MainLoop.scala:71)
    at sbt.MainLoop$$anonfun$next$1$$anonfun$apply$1.apply(MainLoop.scala:71)
    at sbt.State$$anon$2.process(State.scala:171)
    at sbt.MainLoop$$anonfun$next$1.apply(MainLoop.scala:71)
    at sbt.MainLoop$$anonfun$next$1.apply(MainLoop.scala:71)
    at sbt.ErrorHandling$.wideConvert(ErrorHandling.scala:18)
    at sbt.MainLoop$.next(MainLoop.scala:71)
    at sbt.MainLoop$.run(MainLoop.scala:64)
    at sbt.MainLoop$$anonfun$runWithNewLog$1.apply(MainLoop.scala:53)
    at sbt.MainLoop$$anonfun$runWithNewLog$1.apply(MainLoop.scala:50)
    at sbt.Using.apply(Using.scala:25)
    at sbt.MainLoop$.runWithNewLog(MainLoop.scala:50)
    at sbt.MainLoop$.runAndClearLast(MainLoop.scala:33)
    at sbt.MainLoop$.runLoggedLoop(MainLoop.scala:17)
    at sbt.MainLoop$.runLogged(MainLoop.scala:13)
    at sbt.xMain.run(Main.scala:26)
    at xsbt.boot.Launch$$anonfun$run$1.apply(Launch.scala:57)
    at xsbt.boot.Launch$.withContextLoader(Launch.scala:77)
    at xsbt.boot.Launch$.run(Launch.scala:57)
    at xsbt.boot.Launch$$anonfun$explicit$1.apply(Launch.scala:45)
    at xsbt.boot.Launch$.launch(Launch.scala:65)
    at xsbt.boot.Launch$.apply(Launch.scala:16)
    at xsbt.boot.Boot$.runImpl(Boot.scala:32)
    at xsbt.boot.Boot$.main(Boot.scala:21)
    at xsbt.boot.Boot.main(Boot.scala)

Answer 1

That stack trace leads me to believe you are spinning on the console/tty trying to read input. Or perhaps from a file. My recollection of Sbt is that it doesn't support multiple commands at once from the command line (compile and run). You have run all these as separate commands and it works? How about putting into a script and exec'ing that.

Answer 2

This has haunted us as well, albeit with a much newer version of sbt/Playframework.

We were experiencing 100% CPU load on one of Playframework threads after upgrading to Java 11 & newest Play (version 2.8.17 running Java 11.0.17). sbt version is 1.6.2. We are using Tilt to keep all the configs in one place as well as for general convenience. One thread with jline/sbt stack trace elements was consuming 100-130% of CPU on Linux all the time while there were no HTTP requests nor any background jobs.

The secret sauce was to add -Dsbt.ci=true to the sbt run ... command line (the default value for sbt.ci is false).