Memory leak with Slf4j

[Clément Garnier]

Hi,

I'm investigating on a memory leak in a Spray application. I originally posted a message on the Akka mailing list but then looked further and realized it is more likely to come from Spray than Akka.

Here is the description I made:

It turns out that the leak is caused by Log4j (1.x), that is used as a back-end to Akka ActorLogging – I tried both SprayActorLogging and Akka ActorLogging and both produced the leak. Log4j actually keeps forever an instance of Logger for each Actor that has been started. This, I believe, is due to the fact that ActorLogging uses the full path of the Actor as the name of the Logger. Log4j keeps a HashMap of instances of Logger in case they need to be reused, but doesn't seem to flush unused ones. As they are referenced in this map, they cannot be garbage collected.

Since then, I have been able to reproduce this bug with several Slf4j back-ends: Log4j 1.x, Log4j 2 and Logback, so it is not specific to any of them. Also, I have found out that only Spray internal logging is affected: neither Akka IO-level actors nor application-level actors are, and all of them use Akka ActorLogging.

I now think that spray.util.LoggingContext.fromActorContext is to be blamed. Whereas Akka ActorLogging creates a Logger using the Actor itself as an argument, SprayActorLogging uses the actor's path. This causes the logSource used to instantiate the BusLogging to be a unique String (the actor's path), and the logClass to be of type akka.event.DummyClassForStringSources. These values for logSource and logClass are then used for all LogEvents published on the bus.

Then, the Slf4jLogger receives events and binds them to the appropriate Slf4j Logger. To do so, it calls SLFLoggerFactory.getLogger, using the logSource as the name of the Logger. I guess this method then instanciates a Logger with the provided name, and stores it in a HashMap, which grows forever.

Would logSource and logClass be correctly set, Slf4jLogger would use a Logger based on logClass but would still log the appropriate logSource using MDC, just as Akka ActorLogging does.

I'd like to suggest a fix, but I wouldn't know how to handle the logActorPathsWithDots and logActorSystemName settings. It looks like you can't create a LoggingAdapter with an Actor if you want to set a different logSource than the actor's name.

Any thoughts?

Thanks,

--

Clément

[Johannes Rudolph]

Hi Clément,

thanks for this comprehensive investigation. I created an issue to track this problem:

https://github.com/spray/spray/issues/421

How big is the memory leak we are talking about? I guess it's a problem for continuously and long running servers, right?

Johannes

--
You received this message because you are subscribed to the Google Groups "spray-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to spray-user+...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

--
Johannes

-----------------------------------------------
Johannes Rudolph
http://virtual-void.net

[Clément Garnier]

Hi Johannes,

Thanks for your answer.

It is pretty hard to quantify, but I would say there is one Logger leaked for every newly created Actor with SprayActorLogging mixed in… It is indeed noticeable after several hours of running the server under high load, but it is also visible in a few seconds when monitoring Logger instance count using JProfiler.

If you have any guideline on how to address the issue, I'd be happy to write a fix.

Cheers,

--

Clément

[Aaron Schlesinger]

We have the same problem at StackMob. It's bad enough for us that we've had to ditch the slf4j logger for now until #421 is fixed