[JENKINS-59587] Use weakValues on the inner caches in SandboxResolvingClassLoader.parentClassCache instead of on the outer cache #265

dwnusbaum · 2019-09-23T18:27:51Z

While investigating a user-reported performance issue, I noticed among other things that their Pipelines were spending a ton of time blocked waiting to acquire the lock for PluginManager$UberClassLoader while loading classes in SandboxResolvingClassLoader. This was a little surprising, because this user has a single shared library that is used by all of their Pipeline builds, so I would've thought that they would have a very high cache hit ratio, but that did not seem to be the case.

Looking into it, I noticed that in SandboxResolvingClassLoader, we were using weakValues on parentClassCache itself as of #252. This didn't make sense to me, because the values of parentClassCache are Cache<String, Class<?>>, and from what I can tell, these caches are only referenced internally by parentClassCache, which meant that the inner caches would always be removed when the garbage collector runs, making the cache not very useful when Jenkins is under significant memory pressure (which was definitely case for this user for other reasons).

This PR switches to using weakValues on parentClassCache's inner caches, rather than parentClassCache itself. This way, the classes referenced by the inner cache are still only weakly referenced, so that their class loader, which may itself be a key of parentClassCache, is still able to be garbage collected. Looking into it some more, I think #252 was doing this already before 36d3b3a, but that commit changed the semantics from Cache<ClassLoader, Cache<String, Optional<WeakReference<Class<?>>>>> to Cache<ClassLoader, WeakReference<Cache<String, Optional<Class<?>>>>>, and unfortunately we didn't notice that change in semantics during review.

I added a basic smoke test that fails if you revert the changes in src/main. GroovyMemoryLeakTest still passes, but I'm not sure what other testing would be useful to make sure this doesn't cause any regressions.

…entClassCache instead of on the outer caches

dwnusbaum · 2019-09-23T18:29:09Z

...in/java/org/jenkinsci/plugins/scriptsecurity/sandbox/groovy/SandboxResolvingClassLoader.java

        }

-        return builder.build(parentLoader -> Caffeine.newBuilder()./* allow new plugins to be used, and clean up memory */expireAfterWrite(Duration.ofMinutes(15)).build());
+        return outerBuilder.build(parentLoader -> innerBuilder.build());


Note that reusing innerBuilder.build should be safe according to its Javadoc.

jglick

AFAICT

...in/java/org/jenkinsci/plugins/scriptsecurity/sandbox/groovy/SandboxResolvingClassLoader.java

dwnusbaum · 2019-09-23T19:37:33Z

One other thing that seemed a bit concerning in the thread dumps I saw was that some class loading threads held locks on a ConcurrentHashMap$Node while they were waiting for the lock for PluginManager$UberClassLoader, and other threads were then blocked waiting for that same ConcurrentHashMap$Node. Caffeine's Cache.get Javadoc states that "Some attempted update operations on this cache by other threads may be blocked while the computation is in progress, so the computation should be short and simple, and must not attempt to update any other mappings of this cache".

Looking into the code, I think BoundedLocalCache.computeIfAbsent first tries to do a lookup without locking, and the locking only occurs if the value needs to be computed. In our case, I don't think the inner cache can load more than value concurrently from PluginManager$UberClassLoader anyway, so I don't know if this actually matters. IIUC, the preferred approach for slow mapping functions is to use AsyncCache, but it seems like in our case that would just move some of the locking from ConcurrentHashMap$Node to PluginManager$UberClassLoader for cache misses while cache hits would be unaffected because of the no-lock happy path.

Example thread holding a ConcurrentHashMap$Node lock:

java.lang.Thread.State: BLOCKED (on object monitor)
  at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
  - waiting to lock <0x00000003c21e35f0> (a hudson.PluginManager$UberClassLoader)
  at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
  at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader.lambda$loadClass$0(SandboxResolvingClassLoader.java:51)
  at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader$$Lambda$269/265156624.get(Unknown Source)
  at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader.lambda$load$2(SandboxResolvingClassLoader.java:85)
  at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader$$Lambda$271/201356224.apply(Unknown Source)
  at com.github.benmanes.caffeine.cache.BoundedLocalCache.lambda$doComputeIfAbsent$14(BoundedLocalCache.java:2337)
  at com.github.benmanes.caffeine.cache.BoundedLocalCache$$Lambda$270/1614184557.apply(Unknown Source)
  at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1892)
  - locked <0x000000078a3ed640> (a java.util.concurrent.ConcurrentHashMap$Node)
  at com.github.benmanes.caffeine.cache.BoundedLocalCache.doComputeIfAbsent(BoundedLocalCache.java:2335)
  at com.github.benmanes.caffeine.cache.BoundedLocalCache.computeIfAbsent(BoundedLocalCache.java:2318)
  at com.github.benmanes.caffeine.cache.LocalCache.computeIfAbsent(LocalCache.java:111)
  at com.github.benmanes.caffeine.cache.LocalManualCache.get(LocalManualCache.java:54)
  at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader.load(SandboxResolvingClassLoader.java:79)

Example thread blocked waiting for that ConcurrentHashMap$Node:

java.lang.Thread.State: BLOCKED (on object monitor)
  at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1868)
  - waiting to lock <0x000000078a3ed640> (a java.util.concurrent.ConcurrentHashMap$Node)
  at com.github.benmanes.caffeine.cache.BoundedLocalCache.doComputeIfAbsent(BoundedLocalCache.java:2335)
  at com.github.benmanes.caffeine.cache.BoundedLocalCache.computeIfAbsent(BoundedLocalCache.java:2318)
  at com.github.benmanes.caffeine.cache.LocalCache.computeIfAbsent(LocalCache.java:111)
  at com.github.benmanes.caffeine.cache.LocalManualCache.get(LocalManualCache.java:54)
  at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader.load(SandboxResolvingClassLoader.java:79)

dwnusbaum · 2019-09-30T16:42:18Z

I enabled statistics collection so that we can easily evaluate cache performance through the script console with a snippet like this:

import com.github.benmanes.caffeine.cache.stats.CacheStats;
import org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader;
ClassLoader loader = Jenkins.getInstance().getPluginManager().uberClassLoader;
CacheStats stats = SandboxResolvingClassLoader.parentClassCache.get(loader).stats();
println(stats.hitRate());

jglick · 2019-09-30T16:47:32Z

java.lang.AssertionError: 

Expected: <2L>
     but: was <795L>
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
	at org.junit.Assert.assertThat(Assert.java:956)
	at org.junit.Assert.assertThat(Assert.java:923)
	at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoaderTest.classCacheDoesNotHoldClassValuesTooWeakly(SandboxResolvingClassLoaderTest.java:64)

jglick · 2019-09-30T16:48:22Z

evaluate cache performance through the script console

Can this be done via metrics, or support-core, or something?

...ava/org/jenkinsci/plugins/scriptsecurity/sandbox/groovy/SandboxResolvingClassLoaderTest.java

dwnusbaum · 2019-09-30T16:52:31Z

Can this be done via metrics, or support-core, or something?

Sure, now that we are recording stats, we could hook them up to whatever extension points might use them, although I'd prefer to not add any dependencies to this plugin if possible.

jglick

If CI passes!

dwnusbaum · 2019-10-08T20:11:06Z

I explored the things mentioned in #265 (comment) in #271. In summary, unless JENKINS-23784 was addressed, using an asynchronous cache makes no difference, so I think it makes sense to keep using the manual cache for now.

Use weakValues on the inner caches in SandboxResolvingClassLoader.par…

38f3668

…entClassCache instead of on the outer caches

dwnusbaum requested review from jglick and bitwiseman September 23, 2019 18:27

dwnusbaum commented Sep 23, 2019

View reviewed changes

jglick approved these changes Sep 23, 2019

View reviewed changes

...in/java/org/jenkinsci/plugins/scriptsecurity/sandbox/groovy/SandboxResolvingClassLoader.java Show resolved Hide resolved

Update comment to explain reasoning behind expiration

ec71846

dwnusbaum requested a review from jglick September 23, 2019 20:06

bitwiseman approved these changes Sep 25, 2019

View reviewed changes

jglick approved these changes Sep 27, 2019

View reviewed changes

dwnusbaum changed the title ~~Use weakValues on the inner caches in SandboxResolvingClassLoader.parentClassCache instead of on the outer cache~~ [JENKINS-59587] Use weakValues on the inner caches in SandboxResolvingClassLoader.parentClassCache instead of on the outer cache Sep 30, 2019

Enable statistics collection on caches

e46d479

dwnusbaum requested review from kshultzCB, bitwiseman and jglick September 30, 2019 16:42

jglick requested changes Sep 30, 2019

View reviewed changes

...ava/org/jenkinsci/plugins/scriptsecurity/sandbox/groovy/SandboxResolvingClassLoaderTest.java Show resolved Hide resolved

Run each test class in a separate JVM process

0a222ce

dwnusbaum requested a review from jglick September 30, 2019 17:06

jglick approved these changes Sep 30, 2019

View reviewed changes

kshultzCB approved these changes Sep 30, 2019

View reviewed changes

dwnusbaum merged commit b555a48 into jenkinsci:master Oct 1, 2019

dwnusbaum deleted the cache-retention branch October 1, 2019 17:46

This was referenced Oct 3, 2019

Docs, Dockerfile updates, add'l test cases added cloudbees/jenkins-scalability-lab#22

Merged

[PoC] Switch from manually loaded to asynchronously loaded inner caches #271

Closed

jglick mentioned this pull request Nov 27, 2023

[JENKINS-72325] Define an executor and scheduler for SandboxResolvingClassLoader #543

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[JENKINS-59587] Use weakValues on the inner caches in SandboxResolvingClassLoader.parentClassCache instead of on the outer cache #265

[JENKINS-59587] Use weakValues on the inner caches in SandboxResolvingClassLoader.parentClassCache instead of on the outer cache #265

dwnusbaum commented Sep 23, 2019 •

edited

Loading

dwnusbaum Sep 23, 2019

jglick left a comment

dwnusbaum commented Sep 23, 2019

dwnusbaum commented Sep 30, 2019

jglick commented Sep 30, 2019

jglick commented Sep 30, 2019

dwnusbaum commented Sep 30, 2019 •

edited

Loading

jglick left a comment

dwnusbaum commented Oct 8, 2019

[JENKINS-59587] Use weakValues on the inner caches in SandboxResolvingClassLoader.parentClassCache instead of on the outer cache #265

[JENKINS-59587] Use weakValues on the inner caches in SandboxResolvingClassLoader.parentClassCache instead of on the outer cache #265

Conversation

dwnusbaum commented Sep 23, 2019 • edited Loading

dwnusbaum Sep 23, 2019

Choose a reason for hiding this comment

jglick left a comment

Choose a reason for hiding this comment

dwnusbaum commented Sep 23, 2019

dwnusbaum commented Sep 30, 2019

jglick commented Sep 30, 2019

jglick commented Sep 30, 2019

dwnusbaum commented Sep 30, 2019 • edited Loading

jglick left a comment

Choose a reason for hiding this comment

dwnusbaum commented Oct 8, 2019

dwnusbaum commented Sep 23, 2019 •

edited

Loading

dwnusbaum commented Sep 30, 2019 •

edited

Loading