[Bug 298] New: locks around logger maps inhibit concurrency
http://bugzilla.slf4j.org/show_bug.cgi?id=298 Summary: locks around logger maps inhibit concurrency Product: SLF4J Version: 1.7.x Platform: All OS/Version: All Status: NEW Severity: major Priority: P1 Component: Implementations AssignedTo: slf4j-dev@qos.ch ReportedBy: taras.tielkes@gmail.com I'm analyzing degraded performance in a new release of out web application. The application has relatively high throughput (>4k requests/s). We're seeing increased contention on the lock-guarded "loggerMap" in SLF4JLogFactory. The change that introduced this contention is that some of the libraries we're using (Spring, in this particular case) apparently have started creating Logger instances in request-scoped objects in new versions, increasing the volume of calls to SLF4JLogFactory.getInstance(). The top of the call stack of threads waiting for the lock in question looks like shown below. Given that SLF4J targets Java 5+, it seems that some of the util.concurrent constructs could be used to make logger retrieval lock-free for the common cases. ----------- http-/0.0.0.0:8080-187 [BLOCKED] CPU time: 3s org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(String) org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(Class) org.apache.commons.logging.LogFactory.getLog(Class) org.springframework.util.ConcurrencyThrottleSupport.<init>() org.springframework.core.task.SimpleAsyncTaskExecutor$ConcurrencyThrottleAdapter.<init>() org.springframework.core.task.SimpleAsyncTaskExecutor$ConcurrencyThrottleAdapter.<init>(SimpleAsyncTaskExecutor$1) org.springframework.core.task.SimpleAsyncTaskExecutor.<init>(String) org.springframework.web.context.request.async.WebAsyncManager.<init>() org.springframework.web.context.request.async.WebAsyncUtils.getAsyncManager(ServletRequest) org.springframework.web.servlet.FrameworkServlet.processRequest(HttpServletRequest, HttpServletResponse) org.springframework.web.servlet.FrameworkServlet.doPost(HttpServletRequest, HttpServletResponse) javax.servlet.http.HttpServlet.service(HttpServletRequest, HttpServletResponse) org.springframework.web.servlet.FrameworkServlet.service(HttpServletRequest, HttpServletResponse) javax.servlet.http.HttpServlet.service(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) ----------- -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.
http://bugzilla.slf4j.org/show_bug.cgi?id=298 --- Comment #1 from Taras Tielkes <taras.tielkes@gmail.com> 2013-03-24 17:24:06 CET --- Created attachment 92 --> http://bugzilla.slf4j.org/attachment.cgi?id=92 Proposed patch, using ConcurrentHashMap for logger caching/retrieval Initial proposed patch attached. More detailed description: * Adapted the components using a lock-guarded look-up logger map to use a Java5+ ConcurrentHashMap. This should result in a lock-free code path for the typical case where a logger is already cached, and a lock on just a single CHM segment for the putIfAbsent() call * The adapted code uses the ConcurrentMap.putIfAbsent() method to ensure that the same logger instance is returned, even if two threads concurrently query for the same logger I've tried to keep changes as limited as possible. While the usages of ConcurrentHashMap implies Java 5+, I did not adjust the code to use generics. -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.
http://bugzilla.slf4j.org/show_bug.cgi?id=298 Ceki Gulcu <lists@slf4j.org> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |lists@slf4j.org --- Comment #2 from Ceki Gulcu <lists@slf4j.org> 2013-03-24 22:52:45 CET --- Thank you for reporting this issue. Would it be possible for you to supply a github pull request instead of a patch? -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.
http://bugzilla.slf4j.org/show_bug.cgi?id=298 --- Comment #3 from Ceki Gulcu <lists@slf4j.org> 2013-03-24 23:38:21 CET --- No need. The change is relatively easy to duplicate manually. -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.
http://bugzilla.slf4j.org/show_bug.cgi?id=298 --- Comment #4 from Taras Tielkes <taras.tielkes@gmail.com> 2013-03-25 00:09:34 CET --- The changes themselves are indeed quite simple. I'd be happy to (figure out how to) create a github pull request. Some additional comments: * I've been using YourKit 12 (on Java 7, Linux x64) for profiling, using the "sampling" mode. * It's quite likely that the profiling agent does have an impact on the measurements. All lock contention we've found with YourKit over the last couple of years has been quite reliable/correct though. * I'll chat with the YourKit guys to see if they have any feedback on what I'm observing. * I have not yet done a re-profile with a patched slf4j yet. I'll do this in the coming days (I'll need to patch the slf4j version inside the JBoss release we're using). * ConcurrentHashMap (versus a plain HashMap or Hashtable) does come with a higher memory overhead per entry. In this particular use case I would not expect any excesses. -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.
http://bugzilla.slf4j.org/show_bug.cgi?id=298 Ceki Gulcu <lists@slf4j.org> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |RESOLVED Resolution| |FIXED --- Comment #5 from Ceki Gulcu <lists@slf4j.org> 2013-03-25 20:24:41 CET --- Fixed in [1]. While I am sure the change brings performance improvements, I'd be quite interested in actual figures. I would appreciate if you could provide such figures. [1] https://github.com/qos-ch/slf4j/commit/4dc6af1af741d9419c33187 -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.
participants (1)
-
bugzilla-daemon＠qos.ch