diff --git a/CHANGELOG.md b/CHANGELOG.md index 6d37da44d4b..65f23c6fd30 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,8 @@ ### Fixes +- Batch and coalesce scope-persistence disk writes to reduce startup cost ([#5791](https://github.com/getsentry/sentry-java/pull/5791)) + - Scope mutations are now coalesced (latest value per field) and breadcrumbs are appended in batches behind a single fsync, instead of one synchronous disk write per mutation. Persisted scope data (used to enrich crash/ANR events on the next launch) may now lag real-time changes by up to ~100 ms. - Backfill release, environment, distribution, tags, and app version/build—and use the matching replay-on-error sample rate—for `ApplicationExitInfo` ANR and native crash events captured before SDK initialization, without reusing options cached by a later app update ([#5762](https://github.com/getsentry/sentry-java/pull/5762)) - `SentryTagModifierNode.isImportantForBounds` now matches the default behavior and returns `true` ([#5789](https://github.com/getsentry/sentry-java/pull/5789)) - Prevent a `StackOverflowError` when a `beforeSend`, `beforeBreadcrumb`, `beforeSendLog`, or `beforeEnvelope` callback triggers another capture (directly or through a logging integration such as Timber) ([#5737](https://github.com/getsentry/sentry-java/pull/5737)) diff --git a/sentry/api/sentry.api b/sentry/api/sentry.api index c623e71d08f..61d531ea53e 100644 --- a/sentry/api/sentry.api +++ b/sentry/api/sentry.api @@ -4922,6 +4922,7 @@ public abstract class io/sentry/cache/tape/ObjectQueue : java/io/Closeable, java public fun remove ()V public abstract fun remove (I)V public abstract fun size ()I + public fun sync ()V } public abstract interface class io/sentry/cache/tape/ObjectQueue$Converter { @@ -4942,6 +4943,7 @@ public final class io/sentry/cache/tape/QueueFile : java/io/Closeable, java/lang public fun remove ()V public fun remove (I)V public fun size ()I + public fun sync ()V public fun toString ()Ljava/lang/String; } @@ -4949,6 +4951,7 @@ public final class io/sentry/cache/tape/QueueFile$Builder { public fun (Ljava/io/File;)V public fun build ()Lio/sentry/cache/tape/QueueFile; public fun size (I)Lio/sentry/cache/tape/QueueFile$Builder; + public fun synchronousWrites (Z)Lio/sentry/cache/tape/QueueFile$Builder; public fun zero (Z)Lio/sentry/cache/tape/QueueFile$Builder; } diff --git a/sentry/src/main/java/io/sentry/cache/PersistingScopeObserver.java b/sentry/src/main/java/io/sentry/cache/PersistingScopeObserver.java index 420d0d31e22..d3fd867878e 100644 --- a/sentry/src/main/java/io/sentry/cache/PersistingScopeObserver.java +++ b/sentry/src/main/java/io/sentry/cache/PersistingScopeObserver.java @@ -7,7 +7,6 @@ import io.sentry.Breadcrumb; import io.sentry.IScope; import io.sentry.ScopeObserverAdapter; -import io.sentry.SentryExecutorService; import io.sentry.SentryLevel; import io.sentry.SentryOptions; import io.sentry.SpanContext; @@ -29,15 +28,33 @@ import java.io.Reader; import java.io.Writer; import java.nio.charset.Charset; +import java.util.ArrayList; import java.util.Collection; import java.util.Map; +import java.util.Queue; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.ConcurrentLinkedQueue; +import java.util.concurrent.atomic.AtomicBoolean; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; +import org.jetbrains.annotations.TestOnly; public final class PersistingScopeObserver extends ScopeObserverAdapter { private static final Charset UTF_8 = Charset.forName("UTF-8"); + /** + * How long scope mutations are coalesced before being flushed to disk. Rather than writing on + * every mutation, we keep only the latest value per file (and buffer breadcrumbs) and flush them + * together after this delay. This trades a small data-loss window (mutations from the last + * ~{@value #FLUSH_AFTER_MS} ms before the process dies) for far fewer disk writes and fsyncs, + * which is significant during startup. + */ + static final long FLUSH_AFTER_MS = 100; + + /** Sentinel value marking a file that should be deleted rather than written on the next flush. */ + private static final Object DELETE_MARKER = new Object(); + public static final String SCOPE_CACHE = ".scope-cache"; public static final String USER_FILENAME = "user.json"; public static final String BREADCRUMBS_FILENAME = "breadcrumbs.json"; @@ -65,7 +82,11 @@ public final class PersistingScopeObserver extends ScopeObserverAdapter { final File file = new File(cacheDir, BREADCRUMBS_FILENAME); try { try { - queueFile = new QueueFile.Builder(file).size(options.getMaxBreadcrumbs()).build(); + queueFile = + new QueueFile.Builder(file) + .size(options.getMaxBreadcrumbs()) + .synchronousWrites(false) + .build(); } catch (IOException e) { // if file is corrupted we simply delete it and try to create it again. We accept // the trade @@ -74,7 +95,11 @@ public final class PersistingScopeObserver extends ScopeObserverAdapter { // update where the new format was introduced file.delete(); - queueFile = new QueueFile.Builder(file).size(options.getMaxBreadcrumbs()).build(); + queueFile = + new QueueFile.Builder(file) + .size(options.getMaxBreadcrumbs()) + .synchronousWrites(false) + .build(); } } catch (IOException e) { options.getLogger().log(ERROR, "Failed to create breadcrumbs queue", e); @@ -106,32 +131,29 @@ public void toStream(Breadcrumb value, OutputStream sink) throws IOException { }); }); + // Latest pending value per file (or DELETE_MARKER), coalesced until the next flush. + private final @NotNull Map pendingWrites = new ConcurrentHashMap<>(); + // Breadcrumbs buffered since the last flush, appended together behind a single fsync. + private final @NotNull Queue pendingBreadcrumbs = new ConcurrentLinkedQueue<>(); + private final @NotNull AtomicBoolean pendingBreadcrumbsClear = new AtomicBoolean(false); + private final @NotNull AtomicBoolean hasScheduledFlush = new AtomicBoolean(false); + public PersistingScopeObserver(final @NotNull SentryOptions options) { this.options = options; } @Override public void setUser(final @Nullable User user) { - serializeToDisk( - () -> { - if (user == null) { - delete(USER_FILENAME); - } else { - store(user, USER_FILENAME); - } - }); + enqueue(USER_FILENAME, user); } @Override public void addBreadcrumb(@NotNull Breadcrumb crumb) { - serializeToDisk( - () -> { - try { - breadcrumbsQueue.getValue().add(crumb); - } catch (IOException e) { - options.getLogger().log(ERROR, "Failed to add breadcrumb to file queue", e); - } - }); + if (!options.isEnableScopePersistence()) { + return; + } + pendingBreadcrumbs.offer(crumb); + scheduleFlush(); } @Override @@ -139,110 +161,155 @@ public void setBreadcrumbs(@NotNull Collection breadcrumbs) { if (breadcrumbs.isEmpty()) { // we only clear the queue if the new collection is empty (someone called clearBreadcrumbs) // If it's not empty, we'd add breadcrumbs one-by-one in the method above - serializeToDisk( - () -> { - try { - breadcrumbsQueue.getValue().clear(); - } catch (IOException e) { - options.getLogger().log(ERROR, "Failed to clear breadcrumbs from file queue", e); - } - }); + if (!options.isEnableScopePersistence()) { + return; + } + // drop breadcrumbs buffered before the clear; anything added after it is enqueued again + pendingBreadcrumbs.clear(); + pendingBreadcrumbsClear.set(true); + scheduleFlush(); } } @Override public void setTags(@NotNull Map tags) { - serializeToDisk(() -> store(tags, TAGS_FILENAME)); + enqueue(TAGS_FILENAME, tags); } @Override public void setExtras(@NotNull Map extras) { - serializeToDisk(() -> store(extras, EXTRAS_FILENAME)); + enqueue(EXTRAS_FILENAME, extras); } @Override public void setRequest(@Nullable Request request) { - serializeToDisk( - () -> { - if (request == null) { - delete(REQUEST_FILENAME); - } else { - store(request, REQUEST_FILENAME); - } - }); + enqueue(REQUEST_FILENAME, request); } @Override public void setFingerprint(@NotNull Collection fingerprint) { - serializeToDisk(() -> store(fingerprint, FINGERPRINT_FILENAME)); + enqueue(FINGERPRINT_FILENAME, fingerprint); } @Override public void setLevel(@Nullable SentryLevel level) { - serializeToDisk( - () -> { - if (level == null) { - delete(LEVEL_FILENAME); - } else { - store(level, LEVEL_FILENAME); - } - }); + enqueue(LEVEL_FILENAME, level); } @Override public void setTransaction(@Nullable String transaction) { - serializeToDisk( - () -> { - if (transaction == null) { - delete(TRANSACTION_FILENAME); - } else { - store(transaction, TRANSACTION_FILENAME); - } - }); + enqueue(TRANSACTION_FILENAME, transaction); } @Override public void setTrace(@Nullable SpanContext spanContext, @NotNull IScope scope) { - serializeToDisk( - () -> { - if (spanContext == null) { - // we always need a trace_id to properly link with traces/replays, so we fallback to - // propagation context values and create a fake SpanContext - store(scope.getPropagationContext().toSpanContext(), TRACE_FILENAME); - } else { - store(spanContext, TRACE_FILENAME); - } - }); + // we always need a trace_id to properly link with traces/replays, so we fallback to + // propagation context values and create a fake SpanContext + enqueue( + TRACE_FILENAME, + spanContext == null ? scope.getPropagationContext().toSpanContext() : spanContext); } @Override public void setContexts(@NotNull Contexts contexts) { - serializeToDisk(() -> store(contexts, CONTEXTS_FILENAME)); + enqueue(CONTEXTS_FILENAME, contexts); } @Override public void setReplayId(@NotNull SentryId replayId) { - serializeToDisk(() -> store(replayId, REPLAY_FILENAME)); + enqueue(REPLAY_FILENAME, replayId); } - @SuppressWarnings("FutureReturnValueIgnored") - private void serializeToDisk(final @NotNull Runnable task) { + private void enqueue(final @NotNull String fileName, final @Nullable Object entity) { if (!options.isEnableScopePersistence()) { return; } - if (SentryExecutorService.isSentryExecutorThread()) { - // we're already on the sentry executor thread, so we can just execute it directly - runSafely(task); + // latest value wins; a null entity means the file should be deleted on the next flush + pendingWrites.put(fileName, entity == null ? DELETE_MARKER : entity); + scheduleFlush(); + } + + @SuppressWarnings("FutureReturnValueIgnored") + private void scheduleFlush() { + if (!hasScheduledFlush.compareAndSet(false, true)) { + // a flush is already scheduled; it will pick up the latest pending state return; } - try { - options.getExecutorService().submit(() -> runSafely(task)); + options.getExecutorService().schedule(this::flushOnExecutor, FLUSH_AFTER_MS); } catch (Throwable e) { - options.getLogger().log(ERROR, "Serialization task could not be scheduled", e); + hasScheduledFlush.set(false); + options.getLogger().log(ERROR, "Scope persistence flush could not be scheduled", e); + } + } + + private void flushOnExecutor() { + runSafely(this::flushPending); + hasScheduledFlush.set(false); + // reschedule if mutations arrived while we were flushing + if (!pendingWrites.isEmpty() + || !pendingBreadcrumbs.isEmpty() + || pendingBreadcrumbsClear.get()) { + scheduleFlush(); } } + /** Writes all coalesced scope state to disk. Does I/O; must run off the caller/main thread. */ + private void flushPending() { + for (final @NotNull String fileName : new ArrayList<>(pendingWrites.keySet())) { + final @Nullable Object entity = pendingWrites.remove(fileName); + if (entity == null) { + // removed by a concurrent flush + continue; + } + if (entity == DELETE_MARKER) { + delete(fileName); + } else { + store(entity, fileName); + } + } + + boolean breadcrumbsChanged = false; + final @NotNull ObjectQueue queue = breadcrumbsQueue.getValue(); + + if (pendingBreadcrumbsClear.compareAndSet(true, false)) { + try { + queue.clear(); + breadcrumbsChanged = true; + } catch (IOException e) { + options.getLogger().log(ERROR, "Failed to clear breadcrumbs from file queue", e); + } + } + + Breadcrumb crumb; + while ((crumb = pendingBreadcrumbs.poll()) != null) { + try { + queue.add(crumb); + breadcrumbsChanged = true; + } catch (IOException e) { + options.getLogger().log(ERROR, "Failed to add breadcrumb to file queue", e); + } + } + + if (breadcrumbsChanged) { + try { + // single fsync for the whole batch instead of one per breadcrumb + queue.sync(); + } catch (IOException e) { + options.getLogger().log(ERROR, "Failed to sync breadcrumbs file queue", e); + } + } + } + + /** + * Synchronously writes any pending scope state to disk. Does I/O on the calling thread, so it's + * only meant for tests and shutdown, not the hot path. + */ + @TestOnly + void flush() { + runSafely(this::flushPending); + } + private void runSafely(final @NotNull Runnable task) { try { task.run(); @@ -288,7 +355,10 @@ public static void store( public void resetCache() { // since it keeps a reference to the file and we cannot delete it, breadcrumbs we just clear try { - breadcrumbsQueue.getValue().clear(); + final @NotNull ObjectQueue queue = breadcrumbsQueue.getValue(); + queue.clear(); + // breadcrumbs use buffered writes, so make the clear durable explicitly + queue.sync(); } catch (IOException e) { options.getLogger().log(ERROR, "Failed to clear breadcrumbs from file queue", e); } diff --git a/sentry/src/main/java/io/sentry/cache/tape/FileObjectQueue.java b/sentry/src/main/java/io/sentry/cache/tape/FileObjectQueue.java index 31b111e03ad..d7cf5cd1f98 100644 --- a/sentry/src/main/java/io/sentry/cache/tape/FileObjectQueue.java +++ b/sentry/src/main/java/io/sentry/cache/tape/FileObjectQueue.java @@ -59,6 +59,11 @@ public void add(T entry) throws IOException { queueFile.add(bytes.getArray(), 0, bytes.size()); } + @Override + public void sync() throws IOException { + queueFile.sync(); + } + @Override public @Nullable T peek() throws IOException { byte[] bytes = queueFile.peek(); diff --git a/sentry/src/main/java/io/sentry/cache/tape/ObjectQueue.java b/sentry/src/main/java/io/sentry/cache/tape/ObjectQueue.java index c92cad36218..49a4ae272bb 100644 --- a/sentry/src/main/java/io/sentry/cache/tape/ObjectQueue.java +++ b/sentry/src/main/java/io/sentry/cache/tape/ObjectQueue.java @@ -54,6 +54,12 @@ public boolean isEmpty() { /** Enqueues an entry that can be processed at any time. */ public abstract void add(T entry) throws IOException; + /** + * Flushes any buffered writes to storage. No-op for queues that already write synchronously or + * are purely in-memory. + */ + public void sync() throws IOException {} + /** * Returns the head of the queue, or {@code null} if the queue is empty. Does not modify the * queue. diff --git a/sentry/src/main/java/io/sentry/cache/tape/QueueFile.java b/sentry/src/main/java/io/sentry/cache/tape/QueueFile.java index bc2ed568267..92fbcf8e4b1 100644 --- a/sentry/src/main/java/io/sentry/cache/tape/QueueFile.java +++ b/sentry/src/main/java/io/sentry/cache/tape/QueueFile.java @@ -130,13 +130,22 @@ public final class QueueFile implements Closeable, Iterable { /** A number of elements at which this queue will wrap around (ring buffer). */ private final int maxElements; + /** + * When {@code false}, writes are buffered by the OS and callers must call {@link #sync()} to make + * them durable. This lets callers batch many adds behind a single fsync instead of paying one + * fsync per write. + */ + private final boolean synchronousWrites; + boolean closed; - static RandomAccessFile initializeFromFile(File file) throws IOException { + static RandomAccessFile initializeFromFile(File file, boolean synchronousWrites) + throws IOException { if (!file.exists()) { // Use a temp file so we don't leave a partially-initialized file. File tempFile = new File(file.getPath() + ".tmp"); - RandomAccessFile raf = open(tempFile); + // The one-time initialization is always synchronous so the header is durable before rename. + RandomAccessFile raf = open(tempFile, true); try { raf.setLength(INITIAL_LENGTH); raf.seek(0); @@ -152,23 +161,36 @@ static RandomAccessFile initializeFromFile(File file) throws IOException { } } - return open(file); + return open(file, synchronousWrites); } - /** Opens a random access file that writes synchronously. */ - private static RandomAccessFile open(File file) throws FileNotFoundException { - return new RandomAccessFile(file, "rwd"); + private static RandomAccessFile open(File file, boolean synchronousWrites) + throws FileNotFoundException { + return new RandomAccessFile(file, synchronousWrites ? "rwd" : "rw"); } - QueueFile(File file, RandomAccessFile raf, boolean zero, int maxElements) throws IOException { + QueueFile( + File file, RandomAccessFile raf, boolean zero, int maxElements, boolean synchronousWrites) + throws IOException { this.file = file; this.raf = raf; this.zero = zero; this.maxElements = maxElements; + this.synchronousWrites = synchronousWrites; readInitialData(); } + /** + * Flushes buffered writes to storage. No-op when the queue was opened with synchronous writes, + * since those are already durable. + */ + public void sync() throws IOException { + if (!synchronousWrites) { + raf.getChannel().force(false); + } + } + private void readInitialData() throws IOException { raf.seek(0); raf.readFully(buffer); @@ -196,7 +218,7 @@ private void readInitialData() throws IOException { private void resetFile() throws IOException { raf.close(); file.delete(); - raf = initializeFromFile(file); + raf = initializeFromFile(file, synchronousWrites); readInitialData(); } @@ -767,6 +789,7 @@ public static final class Builder { final File file; boolean zero = true; int size = -1; + boolean synchronousWrites = true; /** Start constructing a new queue backed by the given file. */ public Builder(File file) { @@ -788,15 +811,24 @@ public Builder size(int size) { return this; } + /** + * When {@code false}, writes are buffered and the caller must call {@link QueueFile#sync()} to + * make them durable. Defaults to {@code true} (every write is fsync'd). + */ + public Builder synchronousWrites(boolean synchronousWrites) { + this.synchronousWrites = synchronousWrites; + return this; + } + /** * Constructs a new queue backed by the given builder. Only one instance should access a given * file at a time. */ public QueueFile build() throws IOException { - RandomAccessFile raf = initializeFromFile(file); + RandomAccessFile raf = initializeFromFile(file, synchronousWrites); QueueFile qf = null; try { - qf = new QueueFile(file, raf, zero, size); + qf = new QueueFile(file, raf, zero, size, synchronousWrites); return qf; } finally { if (qf == null) { diff --git a/sentry/src/test/java/io/sentry/cache/PersistingScopeObserverBatchingTest.kt b/sentry/src/test/java/io/sentry/cache/PersistingScopeObserverBatchingTest.kt new file mode 100644 index 00000000000..715e9f8a28b --- /dev/null +++ b/sentry/src/test/java/io/sentry/cache/PersistingScopeObserverBatchingTest.kt @@ -0,0 +1,93 @@ +package io.sentry.cache + +import com.google.common.truth.Truth.assertThat +import io.sentry.Breadcrumb +import io.sentry.ISentryExecutorService +import io.sentry.SentryOptions +import io.sentry.cache.PersistingScopeObserver.BREADCRUMBS_FILENAME +import io.sentry.cache.PersistingScopeObserver.TRANSACTION_FILENAME +import io.sentry.test.DeferredExecutorService +import kotlin.test.Test +import org.junit.Rule +import org.junit.rules.TemporaryFolder + +class PersistingScopeObserverBatchingTest { + @get:Rule val tmpDir = TemporaryFolder() + + private val options = SentryOptions() + + private fun getSut(executor: ISentryExecutorService): PersistingScopeObserver { + options.executorService = executor + options.cacheDirPath = tmpDir.newFolder().absolutePath + return PersistingScopeObserver(options) + } + + private fun PersistingScopeObserver.readTransaction(): String? = + read(options, TRANSACTION_FILENAME, String::class.java) + + @Suppress("UNCHECKED_CAST") + private fun PersistingScopeObserver.readBreadcrumbs(): List = + read(options, BREADCRUMBS_FILENAME, List::class.java) as List + + @Test + fun `defers writes until the scheduled flush runs`() { + val executor = DeferredExecutorService() + val sut = getSut(executor) + + sut.setTransaction("MainActivity") + assertThat(sut.readTransaction()).isNull() + + executor.runAll() + assertThat(sut.readTransaction()).isEqualTo("MainActivity") + } + + @Test + fun `coalesces repeated writes keeping only the latest value`() { + val executor = DeferredExecutorService() + val sut = getSut(executor) + + sut.setTransaction("A") + sut.setTransaction("B") + sut.setTransaction("C") + executor.runAll() + + assertThat(sut.readTransaction()).isEqualTo("C") + } + + @Test + fun `batches breadcrumbs and persists all of them`() { + val executor = DeferredExecutorService() + val sut = getSut(executor) + + sut.addBreadcrumb(Breadcrumb().apply { message = "one" }) + sut.addBreadcrumb(Breadcrumb().apply { message = "two" }) + assertThat(sut.readBreadcrumbs()).isEmpty() + + executor.runAll() + assertThat(sut.readBreadcrumbs().map { it.message }).containsExactly("one", "two").inOrder() + } + + @Test + fun `clearing breadcrumbs drops earlier pending adds but keeps later ones`() { + val executor = DeferredExecutorService() + val sut = getSut(executor) + + sut.addBreadcrumb(Breadcrumb().apply { message = "dropped" }) + sut.setBreadcrumbs(emptyList()) + sut.addBreadcrumb(Breadcrumb().apply { message = "kept" }) + executor.runAll() + + assertThat(sut.readBreadcrumbs().map { it.message }).containsExactly("kept") + } + + @Test + fun `flush writes pending state synchronously`() { + val executor = DeferredExecutorService() + val sut = getSut(executor) + + sut.setTransaction("Sync") + sut.flush() + + assertThat(sut.readTransaction()).isEqualTo("Sync") + } +} diff --git a/sentry/src/test/java/io/sentry/cache/tape/QueueFileTest.kt b/sentry/src/test/java/io/sentry/cache/tape/QueueFileTest.kt index c909b48a9b3..db5f3ebfae7 100644 --- a/sentry/src/test/java/io/sentry/cache/tape/QueueFileTest.kt +++ b/sentry/src/test/java/io/sentry/cache/tape/QueueFileTest.kt @@ -49,7 +49,8 @@ class QueueFileTest { @get:Rule val folder = TemporaryFolder() private lateinit var file: File - private fun newQueueFile(raf: RandomAccessFile): QueueFile = QueueFile(this.file, raf, true, -1) + private fun newQueueFile(raf: RandomAccessFile): QueueFile = + QueueFile(this.file, raf, true, -1, true) private fun newQueueFile(zero: Boolean = true, size: Int = -1): QueueFile = Builder(file).zero(zero).size(size).build() @@ -72,6 +73,21 @@ class QueueFileTest { assertArrayEquals(queue.peek(), expected) } + @Test + fun bufferedWritesSurviveReopenAfterSync() { + var queue = Builder(file).synchronousWrites(false).build() + val first = values[253] + val second = values[25] + queue.add(first) + queue.add(second) + queue.sync() + queue.close() + + queue = newQueueFile() + assertEquals(2, queue.size()) + assertArrayEquals(queue.peek(), first) + } + @Test fun testClearErases() { val queue = newQueueFile()