Skip to content

Commit e70d6d4

Browse files
authored
Avoid ExecutorService for DefaultCompositePerformanceCollector timeout (#4841)
* DefaultCompositePerformanceCollector now stops the performance data collection for timeout on data collection rather than a scheduled background job
1 parent 8c7e8d9 commit e70d6d4

File tree

3 files changed

+125
-57
lines changed

3 files changed

+125
-57
lines changed

CHANGELOG.md

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,8 @@
55
### Fixes
66

77
- [ANR] Removed AndroidTransactionProfiler lock ([#4817](https://github.com/getsentry/sentry-java/pull/4817))
8+
- Avoid ExecutorService for DefaultCompositePerformanceCollector timeout ([#4841](https://github.com/getsentry/sentry-java/pull/4841))
9+
- This avoids infinite data collection for never stopped transactions, leading to OOMs
810
- Fix wrong .super() call in SentryTimberTree ([#4844](https://github.com/getsentry/sentry-java/pull/4844))
911

1012
### Improvements

sentry/src/main/java/io/sentry/DefaultCompositePerformanceCollector.java

Lines changed: 61 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@
88
import java.util.Timer;
99
import java.util.TimerTask;
1010
import java.util.concurrent.ConcurrentHashMap;
11-
import java.util.concurrent.RejectedExecutionException;
11+
import java.util.concurrent.TimeUnit;
1212
import java.util.concurrent.atomic.AtomicBoolean;
1313
import org.jetbrains.annotations.ApiStatus;
1414
import org.jetbrains.annotations.NotNull;
@@ -20,8 +20,7 @@ public final class DefaultCompositePerformanceCollector implements CompositePerf
2020
private static final long TRANSACTION_COLLECTION_TIMEOUT_MILLIS = 30000;
2121
private final @NotNull AutoClosableReentrantLock timerLock = new AutoClosableReentrantLock();
2222
private volatile @Nullable Timer timer = null;
23-
private final @NotNull Map<String, List<PerformanceCollectionData>> performanceDataMap =
24-
new ConcurrentHashMap<>();
23+
private final @NotNull Map<String, CompositeData> compositeDataMap = new ConcurrentHashMap<>();
2524
private final @NotNull List<IPerformanceSnapshotCollector> snapshotCollectors;
2625
private final @NotNull List<IPerformanceContinuousCollector> continuousCollectors;
2726
private final boolean hasNoCollectors;
@@ -65,23 +64,11 @@ public void start(final @NotNull ITransaction transaction) {
6564
collector.onSpanStarted(transaction);
6665
}
6766

68-
if (!performanceDataMap.containsKey(transaction.getEventId().toString())) {
69-
performanceDataMap.put(transaction.getEventId().toString(), new ArrayList<>());
70-
// We schedule deletion of collected performance data after a timeout
71-
try {
72-
options
73-
.getExecutorService()
74-
.schedule(() -> stop(transaction), TRANSACTION_COLLECTION_TIMEOUT_MILLIS);
75-
} catch (RejectedExecutionException e) {
76-
options
77-
.getLogger()
78-
.log(
79-
SentryLevel.ERROR,
80-
"Failed to call the executor. Performance collector will not be automatically finished. Did you call Sentry.close()?",
81-
e);
82-
}
67+
final @NotNull String id = transaction.getEventId().toString();
68+
if (!compositeDataMap.containsKey(id)) {
69+
compositeDataMap.put(id, new CompositeData(transaction));
8370
}
84-
start(transaction.getEventId().toString());
71+
start(id);
8572
}
8673

8774
@Override
@@ -95,8 +82,10 @@ public void start(final @NotNull String id) {
9582
return;
9683
}
9784

98-
if (!performanceDataMap.containsKey(id)) {
99-
performanceDataMap.put(id, new ArrayList<>());
85+
if (!compositeDataMap.containsKey(id)) {
86+
// Transactions are added in start(ITransaction). If we are here, it means we don't come from
87+
// a transaction
88+
compositeDataMap.put(id, new CompositeData(null));
10089
}
10190
if (!isStarted.getAndSet(true)) {
10291
try (final @NotNull ISentryLifecycleToken ignored = timerLock.acquire()) {
@@ -118,6 +107,7 @@ public void run() {
118107
// and collect() calls.
119108
// This way ICollectors that collect average stats based on time intervals, like
120109
// AndroidCpuCollector, can have an actual time interval to evaluate.
110+
final @NotNull List<ITransaction> timedOutTransactions = new ArrayList<>();
121111
TimerTask timerTask =
122112
new TimerTask() {
123113
@Override
@@ -129,16 +119,31 @@ public void run() {
129119
if (now - lastCollectionTimestamp <= 10) {
130120
return;
131121
}
122+
timedOutTransactions.clear();
123+
132124
lastCollectionTimestamp = now;
133125
final @NotNull PerformanceCollectionData tempData =
134-
new PerformanceCollectionData(new SentryNanotimeDate().nanoTimestamp());
126+
new PerformanceCollectionData(options.getDateProvider().now().nanoTimestamp());
135127

128+
// Enrich tempData using collectors
136129
for (IPerformanceSnapshotCollector collector : snapshotCollectors) {
137130
collector.collect(tempData);
138131
}
139132

140-
for (List<PerformanceCollectionData> data : performanceDataMap.values()) {
141-
data.add(tempData);
133+
// Add the enriched tempData to all transactions/profiles/objects that collect data.
134+
// Then Check if that object timed out.
135+
for (CompositeData data : compositeDataMap.values()) {
136+
if (data.addDataAndCheckTimeout(tempData)) {
137+
// timed out
138+
if (data.transaction != null) {
139+
timedOutTransactions.add(data.transaction);
140+
}
141+
}
142+
}
143+
// Stop timed out transactions outside compositeDataMap loop, as stop() modifies the
144+
// map
145+
for (final @NotNull ITransaction t : timedOutTransactions) {
146+
stop(t);
142147
}
143148
}
144149
};
@@ -183,13 +188,14 @@ public void onSpanFinished(@NotNull ISpan span) {
183188

184189
@Override
185190
public @Nullable List<PerformanceCollectionData> stop(final @NotNull String id) {
186-
final @Nullable List<PerformanceCollectionData> data = performanceDataMap.remove(id);
191+
final @Nullable CompositeData data = compositeDataMap.remove(id);
192+
options.getLogger().log(SentryLevel.DEBUG, "stop collecting performance info for " + id);
187193

188-
// close if they are no more running requests
189-
if (performanceDataMap.isEmpty()) {
194+
// close if there are no more running requests
195+
if (compositeDataMap.isEmpty()) {
190196
close();
191197
}
192-
return data;
198+
return data != null ? data.dataList : null;
193199
}
194200

195201
@Override
@@ -198,7 +204,7 @@ public void close() {
198204
.getLogger()
199205
.log(SentryLevel.DEBUG, "stop collecting all performance info for transactions");
200206

201-
performanceDataMap.clear();
207+
compositeDataMap.clear();
202208
for (final @NotNull IPerformanceContinuousCollector collector : continuousCollectors) {
203209
collector.clear();
204210
}
@@ -211,4 +217,30 @@ public void close() {
211217
}
212218
}
213219
}
220+
221+
private class CompositeData {
222+
private final @NotNull List<PerformanceCollectionData> dataList;
223+
private final @Nullable ITransaction transaction;
224+
private final long startTimestamp;
225+
226+
private CompositeData(final @Nullable ITransaction transaction) {
227+
this.dataList = new ArrayList<>();
228+
this.transaction = transaction;
229+
this.startTimestamp = options.getDateProvider().now().nanoTimestamp();
230+
}
231+
232+
/**
233+
* Adds the data to the internal list of PerformanceCollectionData. Then it checks if data
234+
* collection timed out (for transactions only).
235+
*
236+
* @return true if data collection timed out (for transactions only).
237+
*/
238+
boolean addDataAndCheckTimeout(final @NotNull PerformanceCollectionData data) {
239+
dataList.add(data);
240+
return transaction != null
241+
&& options.getDateProvider().now().nanoTimestamp()
242+
> startTimestamp
243+
+ TimeUnit.MILLISECONDS.toNanos(TRANSACTION_COLLECTION_TIMEOUT_MILLIS);
244+
}
245+
}
214246
}

sentry/src/test/java/io/sentry/DefaultCompositePerformanceCollectorTest.kt

Lines changed: 62 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -1,12 +1,12 @@
11
package io.sentry
22

3-
import io.sentry.test.DeferredExecutorService
43
import io.sentry.test.getCtor
54
import io.sentry.test.getProperty
65
import io.sentry.test.injectForField
76
import io.sentry.util.thread.ThreadChecker
7+
import java.util.Date
88
import java.util.Timer
9-
import java.util.concurrent.RejectedExecutionException
9+
import java.util.concurrent.TimeUnit
1010
import kotlin.test.Test
1111
import kotlin.test.assertEquals
1212
import kotlin.test.assertFailsWith
@@ -36,7 +36,6 @@ class DefaultCompositePerformanceCollectorTest {
3636
val scopes: IScopes = mock()
3737
val options = SentryOptions()
3838
var mockTimer: Timer? = null
39-
val deferredExecutorService = DeferredExecutorService()
4039

4140
val mockCpuCollector: IPerformanceSnapshotCollector =
4241
object : IPerformanceSnapshotCollector {
@@ -54,16 +53,17 @@ class DefaultCompositePerformanceCollectorTest {
5453
fun getSut(
5554
memoryCollector: IPerformanceSnapshotCollector? = JavaMemoryCollector(),
5655
cpuCollector: IPerformanceSnapshotCollector? = mockCpuCollector,
57-
executorService: ISentryExecutorService = deferredExecutorService,
56+
optionsConfiguration: Sentry.OptionsConfiguration<SentryOptions> =
57+
Sentry.OptionsConfiguration {},
5858
): CompositePerformanceCollector {
5959
options.dsn = "https://[email protected]/proj"
60-
options.executorService = executorService
6160
if (cpuCollector != null) {
6261
options.addPerformanceCollector(cpuCollector)
6362
}
6463
if (memoryCollector != null) {
6564
options.addPerformanceCollector(memoryCollector)
6665
}
66+
optionsConfiguration.configure(options)
6767
transaction1 = SentryTracer(TransactionContext("", ""), scopes)
6868
transaction2 = SentryTracer(TransactionContext("", ""), scopes)
6969
val collector = DefaultCompositePerformanceCollector(options)
@@ -184,21 +184,74 @@ class DefaultCompositePerformanceCollectorTest {
184184

185185
@Test
186186
fun `collector times out after 30 seconds`() {
187-
val collector = fixture.getSut()
187+
val mockDateProvider = mock<SentryDateProvider>()
188+
val mockCollector = mock<IPerformanceContinuousCollector>()
189+
val dates =
190+
listOf(
191+
SentryNanotimeDate(
192+
Date().apply { time = TimeUnit.SECONDS.toMillis(100) },
193+
TimeUnit.SECONDS.toNanos(100),
194+
),
195+
SentryNanotimeDate(
196+
Date().apply { time = TimeUnit.SECONDS.toMillis(131) },
197+
TimeUnit.SECONDS.toNanos(131),
198+
),
199+
)
200+
whenever(mockDateProvider.now()).thenReturn(dates[0], dates[0], dates[0], dates[1])
201+
val collector =
202+
fixture.getSut {
203+
it.dateProvider = mockDateProvider
204+
it.addPerformanceCollector(mockCollector)
205+
}
188206
collector.start(fixture.transaction1)
207+
verify(fixture.mockTimer, never())!!.cancel()
208+
189209
// Let's sleep to make the collector get values
190210
Thread.sleep(300)
191-
verify(fixture.mockTimer, never())!!.cancel()
192211

193-
// Let the timeout job stop the collector
194-
fixture.deferredExecutorService.runAll()
212+
// When the collector gets the values, it checks the current date, set 31 seconds after the
213+
// begin. This means it should stop itself
195214
verify(fixture.mockTimer)!!.cancel()
196215

216+
// When the collector times out, the data collection for spans is stopped, too
217+
verify(mockCollector).onSpanFinished(eq(fixture.transaction1))
218+
197219
// Data is deleted after the collector times out
198220
val data1 = collector.stop(fixture.transaction1)
199221
assertNull(data1)
200222
}
201223

224+
@Test
225+
fun `collector collects for 30 seconds`() {
226+
val mockDateProvider = mock<SentryDateProvider>()
227+
val dates =
228+
listOf(
229+
SentryNanotimeDate(
230+
Date().apply { time = TimeUnit.SECONDS.toMillis(100) },
231+
TimeUnit.SECONDS.toNanos(100),
232+
),
233+
SentryNanotimeDate(
234+
Date().apply { time = TimeUnit.SECONDS.toMillis(130) },
235+
TimeUnit.SECONDS.toNanos(130),
236+
),
237+
)
238+
whenever(mockDateProvider.now()).thenReturn(dates[0], dates[0], dates[0], dates[1])
239+
val collector = fixture.getSut { it.dateProvider = mockDateProvider }
240+
collector.start(fixture.transaction1)
241+
verify(fixture.mockTimer, never())!!.cancel()
242+
243+
// Let's sleep to make the collector get values
244+
Thread.sleep(300)
245+
246+
// When the collector gets the values, it checks the current date, set 30 seconds after the
247+
// begin. This means it should continue without being cancelled
248+
verify(fixture.mockTimer, never())!!.cancel()
249+
250+
// Data is deleted after the collector times out
251+
val data1 = collector.stop(fixture.transaction1)
252+
assertNotNull(data1)
253+
}
254+
202255
@Test
203256
fun `collector has no IPerformanceCollector by default`() {
204257
val collector = fixture.getSut(null, null)
@@ -270,25 +323,6 @@ class DefaultCompositePerformanceCollectorTest {
270323
assertNull(collector.stop(fixture.transaction1))
271324
}
272325

273-
@Test
274-
fun `start does not throw on executor shut down`() {
275-
val executorService = mock<ISentryExecutorService>()
276-
whenever(executorService.schedule(any(), any())).thenThrow(RejectedExecutionException())
277-
val logger = mock<ILogger>()
278-
fixture.options.setLogger(logger)
279-
fixture.options.isDebug = true
280-
val sut = fixture.getSut(executorService = executorService)
281-
sut.start(fixture.transaction1)
282-
verify(logger)
283-
.log(
284-
eq(SentryLevel.ERROR),
285-
eq(
286-
"Failed to call the executor. Performance collector will not be automatically finished. Did you call Sentry.close()?"
287-
),
288-
any(),
289-
)
290-
}
291-
292326
@Test
293327
fun `Continuous collectors are notified properly`() {
294328
val collector = mock<IPerformanceContinuousCollector>()

0 commit comments

Comments
 (0)