Skip to content

Conversation

@richardstartin
Copy link
Contributor

No description provided.

@richardstartin richardstartin requested a review from a team as a code owner August 28, 2020 16:26
Copy link
Contributor

@tylerbenson tylerbenson left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice job. I think we should merge the ClassValue changes even if we decide to skip the inlining.

@richardstartin
Copy link
Contributor Author

Well, we really need to get the amount of background "work" down, whether it's by expunging inline or some other mechanism.

@richardstartin richardstartin force-pushed the rgs/weakmap-inline branch 5 times, most recently from f094977 to f427454 Compare August 28, 2020 18:40
…d background cleaning of WeakConcurrentHashMap which persists beyond the usage of the map, use ClassValue instead of WeakMap in JAX-RS instrumentations
@richardstartin richardstartin changed the title allow inlining of weak map expunging Use alternative weak-keyed map implementations to reduce work done in CommonTaskExecutor Aug 28, 2020
@richardstartin
Copy link
Contributor Author

I think there's another solution - don't use WeakMap at all for HelperInjector; WeakHashMap expunges its keys automatically when garbage collections occur. I was worried about the impact the synchronized wrapper would have on start up. I have two start up benchmarks: one loads all of the classes in the spring-petclinic uber-jar, another uses leiningen to launch clojure koans - neither regressed in startup time as a result of using the JDK class. This means that the one place where we would still be using the WeakMap interface - JDBCMaps could enjoy a dedicated background thread for expunging its entries.

@dougqh
Copy link
Contributor

dougqh commented Aug 31, 2020

I'll admit I don't find WeakMap terribly helpful. I understand the idea of substituting out different WeakMaps, but in practice, I don't really want to do that.

WeakMaps aren't really Maps per se but Caches. For me when writing a Cache, it is crucial to consider the eviction policy including cache size in context. WeakMap provides little control over the eviction policy which I find to be a major failure in its design.


private final WeakMap<ClassLoader, Boolean> injectedClassLoaders = newWeakMap();
private final Map<ClassLoader, Boolean> injectedClassLoaders =
Collections.synchronizedMap(new WeakHashMap<ClassLoader, Boolean>());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe that WeakHashMap is still doing expungeStaleEntries() inline. If that's the case, is it still better to use that instead of WeakConcurrentMap?

Copy link
Contributor Author

@richardstartin richardstartin Aug 31, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, it does, whenever getTable() is called.

However, this question suggests that you may not have understood what I'm trying to achieve here. We have hundreds of background tasks executed once per second, because we use a WeakMap implementation with a "background" cleanup policy. These background tasks continue until the application shuts down, but the injectedClassLoaders map may never actually be used, and even if it is, its usefulness is short-lived and concentrated at the start of the application's life. To reduce the total cost of these maps' existence, increasing the costs of access (if the map is ever used) would make sense, but there's no evidence a synchronized wrapper around a WeakHashMap incurs significant (any?) cost over WeakConcurrentMap.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I understand what you're trying to achieve here. I just didn't understand why you chose this option vs the inline WeakConcurrentMap. That said, I don't disagree with your choice.

As for why the tests are failing, I'm not sure. I can look into it. Is it easy to reproduce if I run locally?

Copy link
Contributor Author

@richardstartin richardstartin Aug 31, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The motivation is for this to be completely independent of the (quite complex) provision mechanism. I don't expect there to be any contention on injectedClassLoaders and the wrapper is there as an insurance policy against multithreaded use, so I don't expect to get anything in return for using WeakConcurrentMap here. I found the changes necessary to support multiple WeakMap implementations broke the test suite mysteriously, in exactly the same way this commit does. (This is my second attempt at getting rid of these background tasks).

To reproduce, run

./gradlew :dd-java-agent:test --stacktrace

It will time out after 120s and probably give you as much information about why as can be seen here: none whatsoever :(

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was reduced to putting System.err.printlns into CoreTracer's constructor - PendingTrace.initialize() hangs. It seems PendingTrace relies on HelperInjector to initialise the background clean up, I'd need to take a thread dump to check if it's deadlocked somehow, but that's a task for tomorrow.

I wonder why the author of this comment in CoreTracer just before initializing PendingTrace wrote this comment:

    // Ensure that PendingTrace.SPAN_CLEANER is initialized in this thread:
    // FIXME: add test to verify the span cleaner thread is started with this call.
    PendingTrace.initialize();

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Check out my latest commit

Copy link
Contributor

@dougqh dougqh Aug 31, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, seems like we have a lot of brittleness in our initialization order.

I'd expect the first job to always start-up the background thread regardless of which job it is & order. From a maintenance perspective, it seems like a pretty serious design flaw to be relying on something else to start the pool.

This looks a nice improvement. Although, I'm wondering if we don't need to just take a hard look at our initialization in general.

@richardstartin
Copy link
Contributor Author

I agree that the WeakMap abstraction is very complex whilst offering little control over cache policy, but refactoring this is not the goal of this PR. I'm just trying to remove most of the background tasks, almost all of which are associated with the injectedClassLoaders WeakMap in the hundreds of HelperInjectors we instantiate during start up in case we need them. Such a refactoring is another piece of work.

What's very interesting about this change is that certain tests time out as a result of this change:

  private final WeakMap<ClassLoader, Boolean> injectedClassLoaders = newWeakMap();

to

  private final Map<ClassLoader, Boolean> injectedClassLoaders =
      Collections.synchronizedMap(new WeakHashMap<ClassLoader, Boolean>());

I previously found that tests would time out when I made it possible for HelperInjector choose a WeakMap implementation other than WeakConcurrentMap. It just seems very strange. If I revert this change, even if I change the registered WeakMapProvider, all tests pass. This makes me suspect an implicit dependency somewhere, but I don't understand the cause.

@richardstartin
Copy link
Contributor Author

Here's a thread dump of the hanging task, I can't see a dead lock here, but making sure the CommonTaskExecutor singleton is initialised before PendingTrace is initialised allows progress. This is rather odd.

"main" #1 prio=5 os_prio=31 cpu=1549.49ms elapsed=29.86s tid=0x00007fca8f809000 nid=0x2803 in Object.wait()  [0x0000700000227000]
   java.lang.Thread.State: RUNNABLE
	at java.util.concurrent.ThreadPoolExecutor.<init>(java.base@11.0.6/ThreadPoolExecutor.java:1302)
	at java.util.concurrent.ThreadPoolExecutor.<init>(java.base@11.0.6/ThreadPoolExecutor.java:1215)
	at java.util.concurrent.ScheduledThreadPoolExecutor.<init>(java.base@11.0.6/ScheduledThreadPoolExecutor.java:472)
	at java.util.concurrent.Executors.newSingleThreadScheduledExecutor(java.base@11.0.6/Executors.java:276)
	at datadog.common.exec.CommonTaskExecutor.<init>(CommonTaskExecutor.java:20)
	at datadog.common.exec.CommonTaskExecutor.<clinit>(CommonTaskExecutor.java:16)
	at datadog.trace.agent.core.PendingTrace$SpanCleaner.<init>(PendingTrace.java:361)
	at datadog.trace.agent.core.PendingTrace.initialize(PendingTrace.java:334)
	at datadog.trace.agent.core.CoreTracer.<init>(CoreTracer.java:237)
	at datadog.trace.agent.core.CoreTracer.<init>(CoreTracer.java:64)
	at datadog.trace.agent.core.CoreTracer$CoreTracerBuilder.build(CoreTracer.java:157)
	at datadog.trace.agent.tooling.TracerInstaller.installGlobalTracer(TracerInstaller.java:15)
	- locked <0x00000007ef2ce588> (a java.lang.Class for datadog.trace.agent.tooling.TracerInstaller)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.6/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.6/NativeMethodAccessorImpl.java:62)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.6/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@11.0.6/Method.java:566)
	at datadog.trace.bootstrap.Agent.installDatadogTracer(Agent.java:256)
	- locked <0x00000007ea146250> (a java.lang.Class for datadog.trace.bootstrap.Agent)
	at datadog.trace.bootstrap.Agent.start(Agent.java:89)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.6/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.6/NativeMethodAccessorImpl.java:62)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.6/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@11.0.6/Method.java:566)
	at datadog.trace.bootstrap.AgentBootstrap.agentmain(AgentBootstrap.java:57)
	at datadog.trace.bootstrap.AgentBootstrap.premain(AgentBootstrap.java:46)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.6/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.6/NativeMethodAccessorImpl.java:62)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.6/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@11.0.6/Method.java:566)
	at sun.instrument.InstrumentationImpl.loadClassAndStartAgent(java.instrument@11.0.6/InstrumentationImpl.java:513)
	at sun.instrument.InstrumentationImpl.loadClassAndCallPremain(java.instrument@11.0.6/InstrumentationImpl.java:525)

   Locked ownable synchronizers:
	- None

"Reference Handler" #2 daemon prio=10 os_prio=31 cpu=0.32ms elapsed=29.84s tid=0x00007fca8e81d000 nid=0x4d03 waiting on condition  [0x000070000093e000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@11.0.6/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@11.0.6/Reference.java:241)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@11.0.6/Reference.java:213)

   Locked ownable synchronizers:
	- None

"Finalizer" #3 daemon prio=8 os_prio=31 cpu=0.23ms elapsed=29.84s tid=0x00007fca8e826800 nid=0x3803 in Object.wait()  [0x0000700000a41000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.6/Native Method)
	- waiting on <0x00000007ea218c90> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.6/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x00000007ea218c90> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.6/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@11.0.6/Finalizer.java:170)

   Locked ownable synchronizers:
	- None

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 cpu=0.21ms elapsed=29.83s tid=0x00007fca910b9000 nid=0x4503 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread0" #5 daemon prio=9 os_prio=31 cpu=999.86ms elapsed=29.83s tid=0x00007fca8f02d800 nid=0x4303 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

   Locked ownable synchronizers:
	- None

"C1 CompilerThread0" #8 daemon prio=9 os_prio=31 cpu=987.90ms elapsed=29.83s tid=0x00007fca8e823800 nid=0x4103 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

   Locked ownable synchronizers:
	- None

"Sweeper thread" #9 daemon prio=9 os_prio=31 cpu=8.32ms elapsed=29.83s tid=0x00007fca9200b000 nid=0x5603 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"Common-Cleaner" #10 daemon prio=8 os_prio=31 cpu=0.30ms elapsed=29.79s tid=0x00007fca8f056800 nid=0xa703 in Object.wait()  [0x0000700001056000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.6/Native Method)
	- waiting on <0x00000007ea200558> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.6/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x00000007ea200558> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base@11.0.6/CleanerImpl.java:148)
	at java.lang.Thread.run(java.base@11.0.6/Thread.java:834)
	at jdk.internal.misc.InnocuousThread.run(java.base@11.0.6/InnocuousThread.java:134)

   Locked ownable synchronizers:
	- None

"dd-jmx-collector" #11 daemon prio=5 os_prio=31 cpu=238.75ms elapsed=28.51s tid=0x00007fca9200c000 nid=0x6303 in Object.wait()  [0x000070000186d000]
   java.lang.Thread.State: RUNNABLE
	at datadog.trace.agent.tooling.WeakMapSuppliers$WeakConcurrent.get(WeakMapSuppliers.java:39)
	at datadog.trace.bootstrap.WeakMap$Provider.newWeakMap(WeakMap.java:41)
	at datadog.trace.bootstrap.instrumentation.java.concurrent.ExecutorInstrumentationUtils.<clinit>(ExecutorInstrumentationUtils.java:16)
	at java.util.concurrent.ThreadPoolExecutor.execute(java.base@11.0.6/ThreadPoolExecutor.java:1319)
	at java.util.concurrent.AbstractExecutorService.invokeAll(java.base@11.0.6/AbstractExecutorService.java:278)
	at org.datadog.jmxfetch.tasks.TaskProcessor.processTasks(TaskProcessor.java:57)
	at org.datadog.jmxfetch.App.init(App.java:970)
	at org.datadog.jmxfetch.App.run(App.java:219)
	at datadog.trace.agent.jmxfetch.JMXFetch$1.run(JMXFetch.java:100)
	at java.lang.Thread.run(java.base@11.0.6/Thread.java:834)

   Locked ownable synchronizers:
	- None

"Attach Listener" #14 daemon prio=9 os_prio=31 cpu=0.58ms elapsed=0.12s tid=0x00007fca91145800 nid=0xa607 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"VM Thread" os_prio=31 cpu=73.20ms elapsed=29.85s tid=0x00007fca8f02a000 nid=0x4e03 runnable  

"GC Thread#0" os_prio=31 cpu=7.86ms elapsed=29.86s tid=0x00007fca8f80a000 nid=0x2d03 runnable  

"GC Thread#1" os_prio=31 cpu=8.23ms elapsed=29.49s tid=0x00007fca91381000 nid=0xa403 runnable  

"GC Thread#2" os_prio=31 cpu=17.35ms elapsed=29.49s tid=0x00007fca8f0e1800 nid=0xa303 runnable  

"GC Thread#3" os_prio=31 cpu=8.27ms elapsed=29.49s tid=0x00007fca91381800 nid=0x5d03 runnable  

"GC Thread#4" os_prio=31 cpu=7.92ms elapsed=29.49s tid=0x00007fca8f10d000 nid=0x5f03 runnable  

"GC Thread#5" os_prio=31 cpu=7.74ms elapsed=29.49s tid=0x00007fca8f10d800 nid=0x6003 runnable  

"G1 Main Marker" os_prio=31 cpu=0.42ms elapsed=29.86s tid=0x00007fca91016800 nid=0x2f03 runnable  

"G1 Conc#0" os_prio=31 cpu=6.35ms elapsed=29.86s tid=0x00007fca92008800 nid=0x5003 runnable  

"G1 Conc#1" os_prio=31 cpu=6.14ms elapsed=28.44s tid=0x00007fca9118d800 nid=0x6403 runnable  

"G1 Refine#0" os_prio=31 cpu=0.16ms elapsed=29.86s tid=0x00007fca910b7800 nid=0x4f03 runnable  

"G1 Young RemSet Sampling" os_prio=31 cpu=6.79ms elapsed=29.86s tid=0x00007fca90811800 nid=0x3203 runnable  
JNI global refs: 22, weak refs: 0

@richardstartin
Copy link
Contributor Author

I hadn't realised how many Runnables get indexed in a background-expunged WeakMap so this is only half the job.

@richardstartin
Copy link
Contributor Author

richardstartin commented Sep 1, 2020

As justification for the change, I put some tracing in to the PeriodicTask execution

execute datadog.trace.agent.core.PendingTrace$SpanCleaner@6f874db8 one of (1) in 7778ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7714e963 one of (218) in 756ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@20ce78ec one of (218) in 278ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@5f058f00 one of (218) in 728ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@10163d6 one of (218) in 1175ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2dde1bff one of (218) in 202ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@5f9b2141 one of (218) in 821ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1ab3a8c8 one of (218) in 826ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@43195e57 one of (218) in 518ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6e171cd7 one of (218) in 661ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@50ad3bc1 one of (218) in 2346ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@20f5239f one of (218) in 1414ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@932bc4a one of (218) in 998ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@123ef382 one of (218) in 507ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@dbf57b3 one of (218) in 213ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@441772e one of (218) in 872ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@212b5695 one of (218) in 855ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@446293d one of (218) in 427ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@14dd9eb7 one of (218) in 585ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@52e6fdee one of (218) in 285ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1a451d4d one of (218) in 711ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@5e0826e7 one of (218) in 560ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@32eff876 one of (218) in 230ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@71809907 one of (218) in 1056ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@4f18837a one of (218) in 1156ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@359f7cdf one of (218) in 284ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6b927fb one of (218) in 3743ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7b9a4292 one of (218) in 989ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@4a94ee4 one of (218) in 171ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@294425a7 one of (218) in 845ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@73c71083 one of (218) in 856ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@59309333 one of (218) in 604ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@5876a9af one of (218) in 215ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6572421 one of (218) in 638ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6c64cb25 one of (218) in 1200ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6ae5aa72 one of (218) in 290ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@16293aa2 one of (218) in 579ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@50d68830 one of (218) in 848ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@399f45b1 one of (218) in 762ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@38c6f217 one of (218) in 524ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7e07db1f one of (218) in 524ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@515c6049 one of (218) in 731ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@74235045 one of (218) in 2687ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@30c15d8b one of (218) in 594ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@411f53a0 one of (218) in 742ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@4afcd809 one of (218) in 626ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@32464a14 one of (218) in 2259ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@45752059 one of (218) in 850ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@40a4337a one of (218) in 802ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@5ef60048 one of (218) in 1170ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1573f9fc one of (218) in 610ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7e6f74c one of (218) in 729ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@10683d9d one of (218) in 644ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6989da5e one of (218) in 526ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@4c1d9d4b one of (218) in 564ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7dcf94f8 one of (218) in 684ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@77c2494c one of (218) in 803ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6f03482 one of (218) in 595ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3b0090a4 one of (218) in 711ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7eac9008 one of (218) in 661ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1a677343 one of (218) in 710ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3857f613 one of (218) in 1714ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@79079097 one of (218) in 690ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@4d1c00d0 one of (218) in 167ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@bcec361 one of (218) in 755ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@61dd025 one of (218) in 250ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2ddc8ecb one of (218) in 403ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@63f79099 one of (218) in 436ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@33afa13b one of (218) in 434ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@56a6d5a6 one of (218) in 517ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@4df50bcc one of (218) in 638ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6dbb137d one of (218) in 711ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2cd76f31 one of (218) in 801ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@367ffa75 one of (218) in 300ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1c1bbc4e one of (218) in 666ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1ce24091 one of (218) in 721ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@24269709 one of (218) in 807ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@752325ad one of (218) in 1752ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@4e91d63f one of (218) in 923ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2925bf5b one of (218) in 614ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@163e4e87 one of (218) in 542ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@65e98b1c one of (218) in 564ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@12b0404f one of (218) in 799ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@510f3d34 one of (218) in 880ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@71b1176b one of (218) in 243ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2362f559 one of (218) in 602ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@544fa968 one of (218) in 814ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7770f470 one of (218) in 465ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@159f197 one of (218) in 381ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7d20d0b one of (218) in 432ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6c40365c one of (218) in 499ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@55b0dcab one of (218) in 562ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@23348b5d one of (218) in 527ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@69453e37 one of (218) in 754ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@4009e306 one of (218) in 748ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@c0c2f8d one of (218) in 869ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@305b7c14 one of (218) in 817ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@17f7cd29 one of (218) in 980ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7ee955a8 one of (218) in 219ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1677d1 one of (218) in 140ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@158a8276 one of (218) in 211ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@5fbe4146 one of (218) in 627ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@75329a49 one of (218) in 245ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7f010382 one of (218) in 524ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7530ad9c one of (218) in 196ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1f0f1111 one of (218) in 248ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6e0dec4a one of (218) in 430ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@394df057 one of (218) in 220ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1ed1993a one of (218) in 398ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@4b5a5ed1 one of (218) in 688ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@20d28811 one of (218) in 658ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@291caca8 one of (218) in 625ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7adda9cc one of (218) in 1158ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@f79e one of (218) in 648ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7ee8290b one of (218) in 589ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@5c909414 one of (218) in 225ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7494f96a one of (218) in 571ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2ea227af one of (218) in 760ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@4690b489 one of (218) in 543ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7f552bd3 one of (218) in 6008ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@47d90b9e one of (218) in 499ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@49e5f737 one of (218) in 539ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@5c671d7f one of (218) in 300ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@149e0f5d one of (218) in 360ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6af93788 one of (218) in 424ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7880cdf3 one of (218) in 587ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6ef888f6 one of (218) in 587ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@757277dc one of (218) in 455ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@bef2d72 one of (218) in 681ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6fe7aac8 one of (218) in 557ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@35047d03 one of (218) in 784ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@10aa41f2 one of (218) in 638ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3af9c5b7 one of (218) in 217ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@37883b97 one of (218) in 598ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6ab778a one of (218) in 400ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6f96c77 one of (218) in 374ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@be64738 one of (218) in 331ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@58ea606c one of (218) in 685ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6f45df59 one of (218) in 507ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@68e5eea7 one of (218) in 384ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@762ef0ea one of (218) in 317ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@141ab0b7 one of (218) in 868ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6db9f5a4 one of (218) in 402ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1ebd319f one of (218) in 707ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7a675056 one of (218) in 694ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2898ac89 one of (218) in 657ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2638011 one of (218) in 793ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@548e6d58 one of (218) in 684ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@175b9425 one of (218) in 628ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6a03bcb1 one of (218) in 759ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@5609159b one of (218) in 704ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2b4bac49 one of (218) in 620ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3e96bacf one of (218) in 833ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7c83dc97 one of (218) in 649ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@37f1104d one of (218) in 606ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7df65f9a one of (218) in 622ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3ccb55a1 one of (218) in 513ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2f54a33d one of (218) in 440ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@f2ff811 one of (218) in 614ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2a266d09 one of (218) in 836ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1d8bd0de one of (218) in 1391ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@757acd7b one of (218) in 727ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2667f029 one of (218) in 707ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@a9cd3b1 one of (218) in 550ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6a400542 one of (218) in 660ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3943a2be one of (218) in 758ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@343570b7 one of (218) in 153ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@236e3f4e one of (218) in 527ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@dd0c991 one of (218) in 398ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@36d585c one of (218) in 704ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6a28ffa4 one of (218) in 1173ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7a69b07 one of (218) in 428ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@609db43b one of (218) in 333ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1817d444 one of (218) in 289ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6ca8564a one of (218) in 225ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@c03cf28 one of (218) in 283ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1725dc0f one of (218) in 244ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@41e36e46 one of (218) in 1004ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@15c43bd9 one of (218) in 221ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@58b5a2f3 one of (218) in 609ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@25f15f50 one of (218) in 139ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@52b46d52 one of (218) in 327827ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@15eb5ee5 one of (218) in 2258ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6b9e8f8d one of (218) in 1084ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@68e965f5 one of (218) in 986ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@f381794 one of (218) in 607ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2525ff7e one of (218) in 1009ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@524d6d96 one of (218) in 174ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@41fbdac4 one of (218) in 738ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3c407114 one of (218) in 779ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@4ef37659 one of (218) in 1818ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@306cf3ea one of (218) in 796ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@130161f7 one of (218) in 230ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@13b13b5d one of (218) in 717ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@d6e7bab one of (218) in 1313ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@5fa07e12 one of (218) in 581ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@62e7f11d one of (218) in 337ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2abf4075 one of (218) in 34264ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@51f116b8 one of (218) in 525ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@26275bef one of (218) in 811ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3246fb96 one of (218) in 804ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@73ee04c8 one of (218) in 778ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6b8ca3c8 one of (218) in 830ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@34f7cfd9 one of (218) in 645ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3e6ef8ad one of (218) in 955ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@747edf66 one of (218) in 696ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@46c65b67 one of (218) in 404ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@2bfc268b one of (218) in 1047ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@4944252c one of (218) in 387ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1ba9117e one of (218) in 588ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@625732 one of (218) in 648ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1e6454ec one of (218) in 921ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1613674b one of (218) in 926ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@649bec2e one of (218) in 339ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@31e5415e one of (218) in 810ns

With the change, after applying load, I see this (I included 2 duty cycles to draw attention to the variation in time of one of the tasks):

execute datadog.trace.agent.core.PendingTrace$SpanCleaner@7e2242b one of (1) in 7558ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6c642539 one of (10) in 3396ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3e72b4a5 one of (10) in 230ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@5eea5627 one of (10) in 1002ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3330f3ad one of (10) in 158ns

execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@425231 one of (10) in 125ns  <- nothing to do this time

execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1c25b8a7 one of (10) in 4209ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6c56834b one of (10) in 680ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7a48a7ac one of (10) in 980ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@366fd3cb one of (10) in 694ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@55a430b2 one of (10) in 649ns
execute datadog.trace.agent.core.PendingTrace$SpanCleaner@7e2242b one of (1) in 7166ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6c642539 one of (10) in 718ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3e72b4a5 one of (10) in 71ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@5eea5627 one of (10) in 717ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@3330f3ad one of (10) in 129ns

execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@f425231 one of (10) in 12782354ns <- 12ms!!

execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@1c25b8a7 one of (10) in 1441ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@6c56834b one of (10) in 608ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@7a48a7ac one of (10) in 747ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@366fd3cb one of (10) in 576ns
execute com.blogspot.mydailyjava.weaklockfree.WeakConcurrentMap@55a430b2 one of (10) in 789ns

The very slow task appears when the load starts - the map's purpose is for WeakMap backed context propagation where field injection fails. I think we need to find something more efficient when field injection fails.

@richardstartin richardstartin merged commit 389f269 into master Sep 1, 2020
@richardstartin richardstartin deleted the rgs/weakmap-inline branch September 1, 2020 12:24
@github-actions github-actions bot added this to the 0.62.0 milestone Sep 1, 2020
@PerfectSlayer PerfectSlayer added tag: performance Performance related changes and removed efficiency labels Jun 23, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

tag: performance Performance related changes

Projects

None yet

Development

Successfully merging this pull request may close these issues.

6 participants