How can I see diagnostic debug info in my Slick tests to fix poor performance?

Question

I'm having trouble figuring out what's happening with slow-executing integrations tests, using Slick to write to the database. But, I can't figure out how to access diagnostic logging, via SLF4J.

Answer 1

I eventually figured this out on my own, and there are two components to the answer.

Poor performance

I realized that my poor performance was on account of synchronous testing of async APIs. I am using Scalatest along with Scalacheck property-based testing, and using the futureValue approach to blocking on async requests. For some reason, I had set the interval of the PatienceConfiguration to 500ms, and so every futureValue call was taking at least a half second, even though the database queries themselves usually executed in at most 20ms, and usually <10ms. I eventually turned the interval down to 2ms, and performance was greatly improved.

Scalatest 3 has proper async test support, although as of 3.0.0-M15, GeneratorDrivenPropertyChecks does not currently support async. This might change.

Diagnostic logging

I installed the SLF4J simple logging backend with the SBT libraryDependencies entry of "org.slf4j" % "slf4j-simple" % "1.7.12". I could not get it to work properly by setting the simple logger properties through application.conf.

I set a Java system property to tell SLF4J-simple to log in debug mode org.slf4j.simpleLogger.defaultLogLevel=debug and then running test at the SBT prompt. Because this resulted in an absurd amount of output from the Slick query compiler, I set the debug output for the loggers of that compiler back to info, which largely squelched the extra output, by adding the property org.slf4j.simpleLogger.log.slick.compiler=info. You can modify logger-levels that match a prefix in this way.

Actually setting the properties turned out to be a non-trivial problem. I tried several approaches:

• Setting the property via Typesafe config (test/resources/application.conf) by adding org.slf4j.simpleLogger.defaultLogLevel=debug did not work. Typically, this is the case for things that are set up by system properties before the config is parsed, so I assume this is the case for the logger.

• Setting the property from the command line when starting up SBT worked, by starting SBT with sbt -Dorg.slf4j.simpleLogger.defaultLogLevel=debug, but only when running tests in a non-forked JVM with the SBT setting fork in test := false.

• Setting the property from SBT using javaOptions += "org.slf4j.simpleLogger.defaultLogLevel=debug" did not work, forked JVM or not.

• Setting the property by adding org.slf4j.simpleLogger.defaultLogLevel=debug to test/resources/simplelogger.properties worked for both forked JVM and unforked.