diff --git a/CHANGELOG.md b/CHANGELOG.md index 23335431abc..e19d5a3188c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,8 @@ ### Fixes - [ANR] Removed AndroidTransactionProfiler lock ([#4817](https://github.com/getsentry/sentry-java/pull/4817)) +- Avoid ExecutorService for DefaultCompositePerformanceCollector timeout ([#4841](https://github.com/getsentry/sentry-java/pull/4841)) + - This avoids infinite data collection for never stopped transactions, leading to OOMs - Fix wrong .super() call in SentryTimberTree ([#4844](https://github.com/getsentry/sentry-java/pull/4844)) ### Improvements diff --git a/sentry/src/main/java/io/sentry/DefaultCompositePerformanceCollector.java b/sentry/src/main/java/io/sentry/DefaultCompositePerformanceCollector.java index 4189ec7b6a2..1861381a853 100644 --- a/sentry/src/main/java/io/sentry/DefaultCompositePerformanceCollector.java +++ b/sentry/src/main/java/io/sentry/DefaultCompositePerformanceCollector.java @@ -8,7 +8,7 @@ import java.util.Timer; import java.util.TimerTask; import java.util.concurrent.ConcurrentHashMap; -import java.util.concurrent.RejectedExecutionException; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; import org.jetbrains.annotations.ApiStatus; import org.jetbrains.annotations.NotNull; @@ -20,8 +20,7 @@ public final class DefaultCompositePerformanceCollector implements CompositePerf private static final long TRANSACTION_COLLECTION_TIMEOUT_MILLIS = 30000; private final @NotNull AutoClosableReentrantLock timerLock = new AutoClosableReentrantLock(); private volatile @Nullable Timer timer = null; - private final @NotNull Map> performanceDataMap = - new ConcurrentHashMap<>(); + private final @NotNull Map compositeDataMap = new ConcurrentHashMap<>(); private final @NotNull List snapshotCollectors; private final @NotNull List continuousCollectors; private final boolean hasNoCollectors; @@ -65,23 +64,11 @@ public void start(final @NotNull ITransaction transaction) { collector.onSpanStarted(transaction); } - if (!performanceDataMap.containsKey(transaction.getEventId().toString())) { - performanceDataMap.put(transaction.getEventId().toString(), new ArrayList<>()); - // We schedule deletion of collected performance data after a timeout - try { - options - .getExecutorService() - .schedule(() -> stop(transaction), TRANSACTION_COLLECTION_TIMEOUT_MILLIS); - } catch (RejectedExecutionException e) { - options - .getLogger() - .log( - SentryLevel.ERROR, - "Failed to call the executor. Performance collector will not be automatically finished. Did you call Sentry.close()?", - e); - } + final @NotNull String id = transaction.getEventId().toString(); + if (!compositeDataMap.containsKey(id)) { + compositeDataMap.put(id, new CompositeData(transaction)); } - start(transaction.getEventId().toString()); + start(id); } @Override @@ -95,8 +82,10 @@ public void start(final @NotNull String id) { return; } - if (!performanceDataMap.containsKey(id)) { - performanceDataMap.put(id, new ArrayList<>()); + if (!compositeDataMap.containsKey(id)) { + // Transactions are added in start(ITransaction). If we are here, it means we don't come from + // a transaction + compositeDataMap.put(id, new CompositeData(null)); } if (!isStarted.getAndSet(true)) { try (final @NotNull ISentryLifecycleToken ignored = timerLock.acquire()) { @@ -118,6 +107,7 @@ public void run() { // and collect() calls. // This way ICollectors that collect average stats based on time intervals, like // AndroidCpuCollector, can have an actual time interval to evaluate. + final @NotNull List timedOutTransactions = new ArrayList<>(); TimerTask timerTask = new TimerTask() { @Override @@ -129,16 +119,31 @@ public void run() { if (now - lastCollectionTimestamp <= 10) { return; } + timedOutTransactions.clear(); + lastCollectionTimestamp = now; final @NotNull PerformanceCollectionData tempData = - new PerformanceCollectionData(new SentryNanotimeDate().nanoTimestamp()); + new PerformanceCollectionData(options.getDateProvider().now().nanoTimestamp()); + // Enrich tempData using collectors for (IPerformanceSnapshotCollector collector : snapshotCollectors) { collector.collect(tempData); } - for (List data : performanceDataMap.values()) { - data.add(tempData); + // Add the enriched tempData to all transactions/profiles/objects that collect data. + // Then Check if that object timed out. + for (CompositeData data : compositeDataMap.values()) { + if (data.addDataAndCheckTimeout(tempData)) { + // timed out + if (data.transaction != null) { + timedOutTransactions.add(data.transaction); + } + } + } + // Stop timed out transactions outside compositeDataMap loop, as stop() modifies the + // map + for (final @NotNull ITransaction t : timedOutTransactions) { + stop(t); } } }; @@ -183,13 +188,14 @@ public void onSpanFinished(@NotNull ISpan span) { @Override public @Nullable List stop(final @NotNull String id) { - final @Nullable List data = performanceDataMap.remove(id); + final @Nullable CompositeData data = compositeDataMap.remove(id); + options.getLogger().log(SentryLevel.DEBUG, "stop collecting performance info for " + id); - // close if they are no more running requests - if (performanceDataMap.isEmpty()) { + // close if there are no more running requests + if (compositeDataMap.isEmpty()) { close(); } - return data; + return data != null ? data.dataList : null; } @Override @@ -198,7 +204,7 @@ public void close() { .getLogger() .log(SentryLevel.DEBUG, "stop collecting all performance info for transactions"); - performanceDataMap.clear(); + compositeDataMap.clear(); for (final @NotNull IPerformanceContinuousCollector collector : continuousCollectors) { collector.clear(); } @@ -211,4 +217,30 @@ public void close() { } } } + + private class CompositeData { + private final @NotNull List dataList; + private final @Nullable ITransaction transaction; + private final long startTimestamp; + + private CompositeData(final @Nullable ITransaction transaction) { + this.dataList = new ArrayList<>(); + this.transaction = transaction; + this.startTimestamp = options.getDateProvider().now().nanoTimestamp(); + } + + /** + * Adds the data to the internal list of PerformanceCollectionData. Then it checks if data + * collection timed out (for transactions only). + * + * @return true if data collection timed out (for transactions only). + */ + boolean addDataAndCheckTimeout(final @NotNull PerformanceCollectionData data) { + dataList.add(data); + return transaction != null + && options.getDateProvider().now().nanoTimestamp() + > startTimestamp + + TimeUnit.MILLISECONDS.toNanos(TRANSACTION_COLLECTION_TIMEOUT_MILLIS); + } + } } diff --git a/sentry/src/test/java/io/sentry/DefaultCompositePerformanceCollectorTest.kt b/sentry/src/test/java/io/sentry/DefaultCompositePerformanceCollectorTest.kt index 99b2822aedd..46c304358df 100644 --- a/sentry/src/test/java/io/sentry/DefaultCompositePerformanceCollectorTest.kt +++ b/sentry/src/test/java/io/sentry/DefaultCompositePerformanceCollectorTest.kt @@ -1,12 +1,12 @@ package io.sentry -import io.sentry.test.DeferredExecutorService import io.sentry.test.getCtor import io.sentry.test.getProperty import io.sentry.test.injectForField import io.sentry.util.thread.ThreadChecker +import java.util.Date import java.util.Timer -import java.util.concurrent.RejectedExecutionException +import java.util.concurrent.TimeUnit import kotlin.test.Test import kotlin.test.assertEquals import kotlin.test.assertFailsWith @@ -36,7 +36,6 @@ class DefaultCompositePerformanceCollectorTest { val scopes: IScopes = mock() val options = SentryOptions() var mockTimer: Timer? = null - val deferredExecutorService = DeferredExecutorService() val mockCpuCollector: IPerformanceSnapshotCollector = object : IPerformanceSnapshotCollector { @@ -54,16 +53,17 @@ class DefaultCompositePerformanceCollectorTest { fun getSut( memoryCollector: IPerformanceSnapshotCollector? = JavaMemoryCollector(), cpuCollector: IPerformanceSnapshotCollector? = mockCpuCollector, - executorService: ISentryExecutorService = deferredExecutorService, + optionsConfiguration: Sentry.OptionsConfiguration = + Sentry.OptionsConfiguration {}, ): CompositePerformanceCollector { options.dsn = "https://key@sentry.io/proj" - options.executorService = executorService if (cpuCollector != null) { options.addPerformanceCollector(cpuCollector) } if (memoryCollector != null) { options.addPerformanceCollector(memoryCollector) } + optionsConfiguration.configure(options) transaction1 = SentryTracer(TransactionContext("", ""), scopes) transaction2 = SentryTracer(TransactionContext("", ""), scopes) val collector = DefaultCompositePerformanceCollector(options) @@ -184,21 +184,74 @@ class DefaultCompositePerformanceCollectorTest { @Test fun `collector times out after 30 seconds`() { - val collector = fixture.getSut() + val mockDateProvider = mock() + val mockCollector = mock() + val dates = + listOf( + SentryNanotimeDate( + Date().apply { time = TimeUnit.SECONDS.toMillis(100) }, + TimeUnit.SECONDS.toNanos(100), + ), + SentryNanotimeDate( + Date().apply { time = TimeUnit.SECONDS.toMillis(131) }, + TimeUnit.SECONDS.toNanos(131), + ), + ) + whenever(mockDateProvider.now()).thenReturn(dates[0], dates[0], dates[0], dates[1]) + val collector = + fixture.getSut { + it.dateProvider = mockDateProvider + it.addPerformanceCollector(mockCollector) + } collector.start(fixture.transaction1) + verify(fixture.mockTimer, never())!!.cancel() + // Let's sleep to make the collector get values Thread.sleep(300) - verify(fixture.mockTimer, never())!!.cancel() - // Let the timeout job stop the collector - fixture.deferredExecutorService.runAll() + // When the collector gets the values, it checks the current date, set 31 seconds after the + // begin. This means it should stop itself verify(fixture.mockTimer)!!.cancel() + // When the collector times out, the data collection for spans is stopped, too + verify(mockCollector).onSpanFinished(eq(fixture.transaction1)) + // Data is deleted after the collector times out val data1 = collector.stop(fixture.transaction1) assertNull(data1) } + @Test + fun `collector collects for 30 seconds`() { + val mockDateProvider = mock() + val dates = + listOf( + SentryNanotimeDate( + Date().apply { time = TimeUnit.SECONDS.toMillis(100) }, + TimeUnit.SECONDS.toNanos(100), + ), + SentryNanotimeDate( + Date().apply { time = TimeUnit.SECONDS.toMillis(130) }, + TimeUnit.SECONDS.toNanos(130), + ), + ) + whenever(mockDateProvider.now()).thenReturn(dates[0], dates[0], dates[0], dates[1]) + val collector = fixture.getSut { it.dateProvider = mockDateProvider } + collector.start(fixture.transaction1) + verify(fixture.mockTimer, never())!!.cancel() + + // Let's sleep to make the collector get values + Thread.sleep(300) + + // When the collector gets the values, it checks the current date, set 30 seconds after the + // begin. This means it should continue without being cancelled + verify(fixture.mockTimer, never())!!.cancel() + + // Data is deleted after the collector times out + val data1 = collector.stop(fixture.transaction1) + assertNotNull(data1) + } + @Test fun `collector has no IPerformanceCollector by default`() { val collector = fixture.getSut(null, null) @@ -270,25 +323,6 @@ class DefaultCompositePerformanceCollectorTest { assertNull(collector.stop(fixture.transaction1)) } - @Test - fun `start does not throw on executor shut down`() { - val executorService = mock() - whenever(executorService.schedule(any(), any())).thenThrow(RejectedExecutionException()) - val logger = mock() - fixture.options.setLogger(logger) - fixture.options.isDebug = true - val sut = fixture.getSut(executorService = executorService) - sut.start(fixture.transaction1) - verify(logger) - .log( - eq(SentryLevel.ERROR), - eq( - "Failed to call the executor. Performance collector will not be automatically finished. Did you call Sentry.close()?" - ), - any(), - ) - } - @Test fun `Continuous collectors are notified properly`() { val collector = mock()