Using Logger.isDebugEnabled is not inlined as expected

[lefou]

This forces org.log4s to be an required runtime dependencies.
log4s version 1.6.0.

Can't tell why, maybe, because the call was inside a catch block.

[sarahgerweck]

Hi @lefou, it's not expected that you can use Log4s without its jar available: it's not a compile-only dependency, though the runtime is deliberately small at just 65 kiB.

Log4s uses a number of mechanisms to facilitate inlining as far as possible, but operating without a runtime jar at all is not currently a project goal and there are some features like dynamic log levels and MDCs that are not possible without a few runtime classes.

Is your concern about potential performance impact due to extra method calls, or are you in a situation where the 65 kiB runtime is bandwidth or space prohibitive? The two would call for very different approaches.

Performance

If your concern is that you may be paying a performance penalty, I'd need some information like this:

• Which version of Scala are you using?
• Which version of Java are you using?
• Which scalac options are you using?
• What does the code look like?
• What does the generated bytecode actually do?
  • You can answer this easily using something like scalap or CFR.

The best way to provide all of this information would be with a small sample project that demonstrates the behavior. If your project is on GitHub, it can be linked.

Some things I would initially check would be to make sure you have global inlining enabled in your project. In Scala 2.12.3 or higher, I would suggest you try something like -opt:l:inline, -opt-inline-from:**.

If your compiler is configured for global inlining and the bytecode shows scalac is not able to inline the isDebugEnabled method, this is something I would like to hear more about. (Even this does not necessarily impact runtime performance, as the JVM does its own inlining, but it would merit investigation.)

Runtime Jar

If you are developing some kind of application where it's too expensive to redistribute the 65 kiB of classes, you may want a custom logging system rather than Log4s + SLF4J + X, as even slf4j-api takes up extra space.

If you have a compelling reason other than size & space why it's not possible to include a few runtime classes, I'd be curious to hear about it.

It is probably possible to produce a library that used macros exclusively to support the sixteen core logging methods: getLogger plus and the fifteen logger methods: two for each of the five log levels (with and without a Throwable) and the five enabled-check methods.

It probably wouldn't be too difficult to build something like this from a fork of Log4s that borrowed its core logging macros, though it would require some care to ensure that the compiler never emitted any mention of the Logger extension class or the singleton that carried your getLogger method.

[lefou]

Then I must somehow misunderstood the project goal. It was probably wishful thinking. ;-)

Although in our current use cases (getLogger, log.debug and friends) the use of log4s introduced zero runtime dependencies, which we are very thankful for. As slf4j is the primary logging API we target and having another scala dependencies just for logging feels a bit odd. Frankly, it was the unique selling point with which I promoted log4s in the project. It is an OSGi container project[1], so we were very sure that we have no runtime dependencies to log4s, until this occasion. Performance or size were never the issue, just the "bringing yet another library into our container".

I think the way the macros currently work for those core logging methods is already the perfect lightweight scala-enhancement for logging. Zero-runtime-dependencies means it is a real implementation detail that greatly enhances programmers convenience, but does not contribute to the classpath of the users of the library.

Now, that I know that this is not a main goal of this project, I can live with that. The OSGi tooling already shows when we use "too much" log4s API (but there is currently no error-detector for that in the tooling). IMHO, it would make sense to split those zero-runtime-deps API from the rest by using separate packages. That way, there is no need to create yet another scala logging project to reach a goal which is already hit (almost).

Having a small(er) API which creates runtime-dependency-free Scala logging, IS a unique selling point! What's currently missing is some documentation and probably some refinements.

[1] https://github.com/woq-blended/blended

[sarahgerweck]

@lefou thanks for the input: I'll give it some thought. I think there may be more to it then there seems to properly guarantee that one doesn't need any runtime deps, but you're right that it's possible it's not too far off from what I have.

[sarahgerweck]

@lefou in the mean time, have you thought about doing an SBT assembly to just embed the few classes that you need into your compiled jar? I'm not an expert in OSGi, but I believe it will perform classloader isolation such that you don't have to worry about the embedded org.log4s classes conflicting with another module that might use Log4s.

[lefou]

@sarahgerweck Thanks for following up. Regarding our issue: we worked around and rewrote the offending code. Although I must admit, I do not understand completely, why the isDebugEnabled isn't inlined, given the value class nature and the @inlinehint.

I'm not seeking for a fast solution here, though. I hope, you like the idea outlined above as much as I do. The nearest "solution" would be possibly, to replace the isXEnabled methods with macros. But I can also understand, if you close this issue. In that case, I might find time to create a PR. But no guarantees.

[sarahgerweck]

Thanks for the additional context @lefou. As I think about it I've been warming to the idea of a version of Log4s that has no runtime at all if I can build and support it without too much difficulty. My suspicion is the same as yours that it may require a macro-defined isXEnabled.

Unfortunately my experience is that value classes and @inline methods are not always quite as clean & consistent in their behavior and bytecode as I'd like. (The Scala compiler has a hard job, so I don't necessarily blame its authors.)

It seems like your project is OSS: can you point out the specific parts of the code where you run into this issue, and is it as simple as sbt build to compile it? (If it's a branch or .patch file, that's fine too: being able to look at the emitted classes and toy with things would be very helpful to track down inlining options here.)

It might be a few days before I have any time, but I'll do my best to look into options here soon.

[lefou]

The project is OSS, but the build uses Maven with the Scala Polyglot extension. I just tried to find the correct commit to reproduce but can't. As we found the issue last week on my teammates laptop (I was remotely connected), I have to ask him to reproduce...

[lefou]

Notes

The build uses Maven 3.3.1 (better 3.5). If you don't have Maven installed, you can use the script ./blended.build/mvnw in the project repo.

Also, by default Maven caches lots of dependencies under ~/.m2/repository. If you don't use Maven for other projects, it is safe to remove this directory later.

The class in question: https://github.com/woq-blended/blended/blob/102cc046698246b1f15cbadd963b44737eb9d687/blended.container.context.impl/src/main/scala/blended/container/context/impl/internal/ContainerContextActivator.scala

Steps to reproduce

git clone https://github.com/woq-blended/blended
cd blended
git checkout 102cc046698246b1f15cbadd963b44737eb9d687
mvn clean install -pl :blended.container.context.impl -am

Now, the offending JAR is located at: blended.container.context.impl/target/blended.container.context.impl-2.4.0-RC5-SNAPSHOT.jar

The generated MANIFEST.MF looks like:
(Generated, from bytecode analsysis; notice the extra import for org.log4s)

Manifest-Version: 1.0
Bnd-LastModified: 1522138526869
Build-Jdk: 1.8.0_162
Built-By: lefou
Bundle-Activator: blended.container.context.impl.internal.ContainerCon
 textActivator
Bundle-Description: A simple OSGI service to provide access to the con
 tainer's config directory.
Bundle-DocURL: https://github.com/woq-blended/blended
Bundle-License: http://www.apache.org/licenses/LICENSE-2.0.txt
Bundle-ManifestVersion: 2
Bundle-Name: blended.container.context.impl
Bundle-SymbolicName: blended.container.context.impl; singleton:=true
Bundle-Vendor: https://github.com/woq-blended
Bundle-Version: 2.4.0.RC5-SNAPSHOT
Created-By: Apache Maven Bundle Plugin
Export-Package: blended.container.context.impl;version="2.4.0.RC5-SNAP
 SHOT"
Import-Package: scala;version="[2.11,2.11.50)",scala.collection;versio
 n="[2.11,2.11.50)",scala.collection.convert;version="[2.11,2.11.50)",
 scala.collection.generic;version="[2.11,2.11.50)",scala.collection.im
 mutable;version="[2.11,2.11.50)",scala.collection.mutable;version="[2
 .11,2.11.50)",scala.reflect;version="[2.11,2.11.50)",scala.reflect.ap
 i;version="[2.11,2.11.50)",scala.reflect.runtime;version="[2.11,2.11.
 50)",scala.runtime;version="[2.11,2.11.50)",scala.util;version="[2.11
 ,2.11.50)",scala.util.control;version="[2.11,2.11.50)",blended.launch
 er.runtime;resolution:=optional,blended.container.context.api;version
 ="[2.4,3)",blended.updater.config;version="[2.4,3)",com.typesafe.conf
 ig;version="[1.3,2)",domino;version="[2.0,3)",domino.service_providin
 g;version="[2.0,3)",org.log4s,org.osgi.framework;version="[1.8,2)",or
 g.slf4j;version="[1.7,2)",org.slf4j.bridge;version="[1.7,2)"
Require-Capability: osgi.ee;filter:="(&(osgi.ee=JavaSE)(version=1.6))"
Tool: Bnd-3.2.0.201605172007

Javap call:

javap -v -cp blended.container.context.impl/target/blended.container.context.impl-2.4.0-RC5-SNAPSHOT.jar blended.container.context.impl.internal.ContainerContextActivator\$\$anonfun\$1

[lefou]

And this commit worked around the issue:
woq-blended/blended@3a08d73#diff-6040cdaca75699ca5d664dffc128df24

[sarahgerweck]

@lefou thanks for the extra information! This is great. It'll be a couple days but I'll definitely dig into this and see what I can do.

[sarahgerweck]

I have a patch (55f1aae) that would resolve this issue. However, I don't currently have a strategy in hand that does this without breaking binary compatibility. I'm open to resolving this if I can convince the Scala compiler not to break compatibility, but I'm not sure it would be a wide enough use case to justify a binary-incompatible change given that there's a fair amount of other functionality that definitely requires the jar to be present.

If anybody is interested in continuing this work, the key thing is to figure out a way to convince Scala to use the macros without removing the existing methods. I'm not sure if this is possible, but my first approach would be to see if you can manage this using some kind of interface.

[lefou]

@sarahgerweck Thank you for the follow up! I appreciate it.

In the meantime, in the project where we had the issue (and the false assumption) we changed a lot, also we removed some uses of log4s and/or added it to the classpath directly so that it is currently not possible to verify your change against it. We also changed to sbt, btw.

I will definitely keep log4s in my toolbox for all those other tools and libraries I'm involved with. Looks like with that change it is finally possible to use log4s as a thin compile-time only wrapper, when we only use log.XXX and log.isXXXEnabled methods.