From 4e290632c3083233d83c696533ee1e0d284dfd42 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kry=C5=A1tof=20Wold=C5=99ich?= <31292499+krystofwoldrich@users.noreply.github.com> Date: Mon, 13 Nov 2023 09:40:31 +0100 Subject: [PATCH] chore(profiling): Create independent Profiler for Hybrid SDKs (#3016) Co-authored-by: Sentry Github Bot --- CHANGELOG.md | 1 + .../api/sentry-android-core.api | 22 ++ .../sentry/android/core/AndroidProfiler.java | 360 ++++++++++++++++++ .../core/AndroidTransactionProfiler.java | 314 +++------------ .../android/core/AndroidProfilerTest.kt | 309 +++++++++++++++ .../core/AndroidTransactionProfilerTest.kt | 4 +- 6 files changed, 738 insertions(+), 272 deletions(-) create mode 100644 sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java create mode 100644 sentry-android-core/src/test/java/io/sentry/android/core/AndroidProfilerTest.kt diff --git a/CHANGELOG.md b/CHANGELOG.md index 296b80c8ed..54d8e895bb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ ### Fixes +- (Internal) Extract Android Profiler and Measurements for Hybrid SDKs ([#3016](https://github.com/getsentry/sentry-java/pull/3016)) - Ensure DSN uses http/https protocol ([#3044](https://github.com/getsentry/sentry-java/pull/3044)) ### Features diff --git a/sentry-android-core/api/sentry-android-core.api b/sentry-android-core/api/sentry-android-core.api index c94dea1e5f..60f562c02c 100644 --- a/sentry-android-core/api/sentry-android-core.api +++ b/sentry-android-core/api/sentry-android-core.api @@ -49,6 +49,28 @@ public class io/sentry/android/core/AndroidMemoryCollector : io/sentry/ICollecto public fun setup ()V } +public class io/sentry/android/core/AndroidProfiler { + public fun (Ljava/lang/String;ILio/sentry/android/core/internal/util/SentryFrameMetricsCollector;Lio/sentry/android/core/SentryAndroidOptions;Lio/sentry/android/core/BuildInfoProvider;)V + public fun close ()V + public fun endAndCollect (ZLjava/util/List;)Lio/sentry/android/core/AndroidProfiler$ProfileEndData; + public fun start ()Lio/sentry/android/core/AndroidProfiler$ProfileStartData; +} + +public class io/sentry/android/core/AndroidProfiler$ProfileEndData { + public final field didTimeout Z + public final field endCpuMillis J + public final field endNanos J + public final field measurementsMap Ljava/util/Map; + public final field traceFile Ljava/io/File; + public fun (JJZLjava/io/File;Ljava/util/Map;)V +} + +public class io/sentry/android/core/AndroidProfiler$ProfileStartData { + public final field startCpuMillis J + public final field startNanos J + public fun (JJ)V +} + public final class io/sentry/android/core/AnrIntegration : io/sentry/Integration, java/io/Closeable { public fun (Landroid/content/Context;)V public fun close ()V diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java b/sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java new file mode 100644 index 0000000000..ae03673d8b --- /dev/null +++ b/sentry-android-core/src/main/java/io/sentry/android/core/AndroidProfiler.java @@ -0,0 +1,360 @@ +package io.sentry.android.core; + +import android.annotation.SuppressLint; +import android.os.Build; +import android.os.Debug; +import android.os.Process; +import android.os.SystemClock; +import io.sentry.CpuCollectionData; +import io.sentry.MemoryCollectionData; +import io.sentry.PerformanceCollectionData; +import io.sentry.SentryLevel; +import io.sentry.android.core.internal.util.SentryFrameMetricsCollector; +import io.sentry.profilemeasurements.ProfileMeasurement; +import io.sentry.profilemeasurements.ProfileMeasurementValue; +import io.sentry.util.Objects; +import java.io.File; +import java.util.ArrayDeque; +import java.util.HashMap; +import java.util.List; +import java.util.Map; +import java.util.UUID; +import java.util.concurrent.Future; +import java.util.concurrent.RejectedExecutionException; +import java.util.concurrent.TimeUnit; +import org.jetbrains.annotations.ApiStatus; +import org.jetbrains.annotations.NotNull; +import org.jetbrains.annotations.Nullable; + +@ApiStatus.Internal +public class AndroidProfiler { + public static class ProfileStartData { + public final long startNanos; + public final long startCpuMillis; + + public ProfileStartData(final long startNanos, final long startCpuMillis) { + this.startNanos = startNanos; + this.startCpuMillis = startCpuMillis; + } + } + + public static class ProfileEndData { + public final long endNanos; + public final long endCpuMillis; + public final @NotNull File traceFile; + public final @NotNull Map measurementsMap; + public final boolean didTimeout; + + public ProfileEndData( + final long endNanos, + final long endCpuMillis, + final boolean didTimeout, + final @NotNull File traceFile, + final @NotNull Map measurementsMap) { + this.endNanos = endNanos; + this.traceFile = traceFile; + this.endCpuMillis = endCpuMillis; + this.measurementsMap = measurementsMap; + this.didTimeout = didTimeout; + } + } + + /** + * This appears to correspond to the buffer size of the data part of the file, excluding the key + * part. Once the buffer is full, new records are ignored, but the resulting trace file will be + * valid. + * + *

30 second traces can require a buffer of a few MB. 8MB is the default buffer size for + * [Debug.startMethodTracingSampling], but 3 should be enough for most cases. We can adjust this + * in the future if we notice that traces are being truncated in some applications. + */ + private static final int BUFFER_SIZE_BYTES = 3_000_000; + + private static final int PROFILING_TIMEOUT_MILLIS = 30_000; + private long transactionStartNanos = 0; + private final @NotNull File traceFilesDir; + private final int intervalUs; + private @Nullable Future scheduledFinish = null; + private @Nullable File traceFile = null; + private @Nullable String frameMetricsCollectorId; + private volatile @Nullable ProfileEndData timedOutProfilingData = null; + private final @NotNull SentryFrameMetricsCollector frameMetricsCollector; + private final @NotNull ArrayDeque screenFrameRateMeasurements = + new ArrayDeque<>(); + private final @NotNull ArrayDeque slowFrameRenderMeasurements = + new ArrayDeque<>(); + private final @NotNull ArrayDeque frozenFrameRenderMeasurements = + new ArrayDeque<>(); + private final @NotNull Map measurementsMap = new HashMap<>(); + private final @NotNull SentryAndroidOptions options; + private final @NotNull BuildInfoProvider buildInfoProvider; + private boolean isRunning = false; + + public AndroidProfiler( + final @NotNull String tracesFilesDirPath, + final int intervalUs, + final @NotNull SentryFrameMetricsCollector frameMetricsCollector, + final @NotNull SentryAndroidOptions sentryAndroidOptions, + final @NotNull BuildInfoProvider buildInfoProvider) { + this.traceFilesDir = + new File(Objects.requireNonNull(tracesFilesDirPath, "TracesFilesDirPath is required")); + this.intervalUs = intervalUs; + this.options = Objects.requireNonNull(sentryAndroidOptions, "SentryAndroidOptions is required"); + this.frameMetricsCollector = + Objects.requireNonNull(frameMetricsCollector, "SentryFrameMetricsCollector is required"); + this.buildInfoProvider = + Objects.requireNonNull(buildInfoProvider, "The BuildInfoProvider is required."); + } + + @SuppressLint("NewApi") + public synchronized @Nullable ProfileStartData start() { + // intervalUs is 0 only if there was a problem in the init + if (intervalUs == 0) { + options + .getLogger() + .log( + SentryLevel.WARNING, + "Disabling profiling because intervaUs is set to %d", + intervalUs); + return null; + } + + if (isRunning) { + options.getLogger().log(SentryLevel.WARNING, "Profiling has already started..."); + return null; + } + + // and SystemClock.elapsedRealtimeNanos() since Jelly Bean + if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP) return null; + + // We create a file with a uuid name, so no need to check if it already exists + traceFile = new File(traceFilesDir, UUID.randomUUID() + ".trace"); + + measurementsMap.clear(); + screenFrameRateMeasurements.clear(); + slowFrameRenderMeasurements.clear(); + frozenFrameRenderMeasurements.clear(); + + frameMetricsCollectorId = + frameMetricsCollector.startCollection( + new SentryFrameMetricsCollector.FrameMetricsCollectorListener() { + final long nanosInSecond = TimeUnit.SECONDS.toNanos(1); + final long frozenFrameThresholdNanos = TimeUnit.MILLISECONDS.toNanos(700); + float lastRefreshRate = 0; + + @Override + public void onFrameMetricCollected( + final long frameEndNanos, final long durationNanos, float refreshRate) { + // transactionStartNanos is calculated through SystemClock.elapsedRealtimeNanos(), + // but frameEndNanos uses System.nanotime(), so we convert it to get the timestamp + // relative to transactionStartNanos + final long frameTimestampRelativeNanos = + frameEndNanos + - System.nanoTime() + + SystemClock.elapsedRealtimeNanos() + - transactionStartNanos; + + // We don't allow negative relative timestamps. + // So we add a check, even if this should never happen. + if (frameTimestampRelativeNanos < 0) { + return; + } + // Most frames take just a few nanoseconds longer than the optimal calculated + // duration. + // Therefore we subtract one, because otherwise almost all frames would be slow. + boolean isSlow = durationNanos > nanosInSecond / (refreshRate - 1); + float newRefreshRate = (int) (refreshRate * 100) / 100F; + if (durationNanos > frozenFrameThresholdNanos) { + frozenFrameRenderMeasurements.addLast( + new ProfileMeasurementValue(frameTimestampRelativeNanos, durationNanos)); + } else if (isSlow) { + slowFrameRenderMeasurements.addLast( + new ProfileMeasurementValue(frameTimestampRelativeNanos, durationNanos)); + } + if (newRefreshRate != lastRefreshRate) { + lastRefreshRate = newRefreshRate; + screenFrameRateMeasurements.addLast( + new ProfileMeasurementValue(frameTimestampRelativeNanos, newRefreshRate)); + } + } + }); + + // We stop profiling after a timeout to avoid huge profiles to be sent + try { + scheduledFinish = + options + .getExecutorService() + .schedule( + () -> timedOutProfilingData = endAndCollect(true, null), + PROFILING_TIMEOUT_MILLIS); + } catch (RejectedExecutionException e) { + options + .getLogger() + .log( + SentryLevel.ERROR, + "Failed to call the executor. Profiling will not be automatically finished. Did you call Sentry.close()?", + e); + } + + transactionStartNanos = SystemClock.elapsedRealtimeNanos(); + long profileStartCpuMillis = Process.getElapsedCpuTime(); + + // We don't make any check on the file existence or writeable state, because we don't want to + // make file IO in the main thread. + // We cannot offload the work to the executorService, as if that's very busy, profiles could + // start/stop with a lot of delay and even cause ANRs. + try { + // If there is any problem with the file this method will throw (but it will not throw in + // tests) + Debug.startMethodTracingSampling(traceFile.getPath(), BUFFER_SIZE_BYTES, intervalUs); + isRunning = true; + return new ProfileStartData(transactionStartNanos, profileStartCpuMillis); + } catch (Throwable e) { + endAndCollect(false, null); + options.getLogger().log(SentryLevel.ERROR, "Unable to start a profile: ", e); + isRunning = false; + return null; + } + } + + @SuppressLint("NewApi") + public synchronized @Nullable ProfileEndData endAndCollect( + final boolean isTimeout, + final @Nullable List performanceCollectionData) { + // check if profiling timed out + if (timedOutProfilingData != null) { + return timedOutProfilingData; + } + + if (!isRunning) { + options.getLogger().log(SentryLevel.WARNING, "Profiler not running"); + return null; + } + + // and SystemClock.elapsedRealtimeNanos() since Jelly Bean + if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP) return null; + + try { + // If there is any problem with the file this method could throw, but the start is also + // wrapped, so this should never happen (except for tests, where this is the only method that + // throws) + Debug.stopMethodTracing(); + } catch (Throwable e) { + options.getLogger().log(SentryLevel.ERROR, "Error while stopping profiling: ", e); + } finally { + isRunning = false; + } + frameMetricsCollector.stopCollection(frameMetricsCollectorId); + + long transactionEndNanos = SystemClock.elapsedRealtimeNanos(); + long transactionEndCpuMillis = Process.getElapsedCpuTime(); + + if (traceFile == null) { + options.getLogger().log(SentryLevel.ERROR, "Trace file does not exists"); + return null; + } + + if (!slowFrameRenderMeasurements.isEmpty()) { + measurementsMap.put( + ProfileMeasurement.ID_SLOW_FRAME_RENDERS, + new ProfileMeasurement(ProfileMeasurement.UNIT_NANOSECONDS, slowFrameRenderMeasurements)); + } + if (!frozenFrameRenderMeasurements.isEmpty()) { + measurementsMap.put( + ProfileMeasurement.ID_FROZEN_FRAME_RENDERS, + new ProfileMeasurement( + ProfileMeasurement.UNIT_NANOSECONDS, frozenFrameRenderMeasurements)); + } + if (!screenFrameRateMeasurements.isEmpty()) { + measurementsMap.put( + ProfileMeasurement.ID_SCREEN_FRAME_RATES, + new ProfileMeasurement(ProfileMeasurement.UNIT_HZ, screenFrameRateMeasurements)); + } + putPerformanceCollectionDataInMeasurements(performanceCollectionData); + + if (scheduledFinish != null) { + scheduledFinish.cancel(true); + scheduledFinish = null; + } + + return new ProfileEndData( + transactionEndNanos, transactionEndCpuMillis, isTimeout, traceFile, measurementsMap); + } + + public synchronized void close() { + // we cancel any scheduled work + if (scheduledFinish != null) { + scheduledFinish.cancel(true); + scheduledFinish = null; + } + + // stop profiling if running + if (isRunning) { + endAndCollect(true, null); + } + } + + @SuppressLint("NewApi") + private void putPerformanceCollectionDataInMeasurements( + final @Nullable List performanceCollectionData) { + + // onTransactionStart() is only available since Lollipop + // and SystemClock.elapsedRealtimeNanos() since Jelly Bean + if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP) { + return; + } + + // This difference is required, since the PerformanceCollectionData timestamps are expressed in + // terms of System.currentTimeMillis() and measurements timestamps require the nanoseconds since + // the beginning, expressed with SystemClock.elapsedRealtimeNanos() + long timestampDiff = + SystemClock.elapsedRealtimeNanos() + - transactionStartNanos + - TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis()); + if (performanceCollectionData != null) { + final @NotNull ArrayDeque memoryUsageMeasurements = + new ArrayDeque<>(performanceCollectionData.size()); + final @NotNull ArrayDeque nativeMemoryUsageMeasurements = + new ArrayDeque<>(performanceCollectionData.size()); + final @NotNull ArrayDeque cpuUsageMeasurements = + new ArrayDeque<>(performanceCollectionData.size()); + for (PerformanceCollectionData performanceData : performanceCollectionData) { + CpuCollectionData cpuData = performanceData.getCpuData(); + MemoryCollectionData memoryData = performanceData.getMemoryData(); + if (cpuData != null) { + cpuUsageMeasurements.add( + new ProfileMeasurementValue( + TimeUnit.MILLISECONDS.toNanos(cpuData.getTimestampMillis()) + timestampDiff, + cpuData.getCpuUsagePercentage())); + } + if (memoryData != null && memoryData.getUsedHeapMemory() > -1) { + memoryUsageMeasurements.add( + new ProfileMeasurementValue( + TimeUnit.MILLISECONDS.toNanos(memoryData.getTimestampMillis()) + timestampDiff, + memoryData.getUsedHeapMemory())); + } + if (memoryData != null && memoryData.getUsedNativeMemory() > -1) { + nativeMemoryUsageMeasurements.add( + new ProfileMeasurementValue( + TimeUnit.MILLISECONDS.toNanos(memoryData.getTimestampMillis()) + timestampDiff, + memoryData.getUsedNativeMemory())); + } + } + if (!cpuUsageMeasurements.isEmpty()) { + measurementsMap.put( + ProfileMeasurement.ID_CPU_USAGE, + new ProfileMeasurement(ProfileMeasurement.UNIT_PERCENT, cpuUsageMeasurements)); + } + if (!memoryUsageMeasurements.isEmpty()) { + measurementsMap.put( + ProfileMeasurement.ID_MEMORY_FOOTPRINT, + new ProfileMeasurement(ProfileMeasurement.UNIT_BYTES, memoryUsageMeasurements)); + } + if (!nativeMemoryUsageMeasurements.isEmpty()) { + measurementsMap.put( + ProfileMeasurement.ID_MEMORY_NATIVE_FOOTPRINT, + new ProfileMeasurement(ProfileMeasurement.UNIT_BYTES, nativeMemoryUsageMeasurements)); + } + } + } +} diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/AndroidTransactionProfiler.java b/sentry-android-core/src/main/java/io/sentry/android/core/AndroidTransactionProfiler.java index 30e46baeb1..5b465140b9 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/AndroidTransactionProfiler.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/AndroidTransactionProfiler.java @@ -7,78 +7,39 @@ import android.app.ActivityManager; import android.content.Context; import android.os.Build; -import android.os.Debug; import android.os.Process; import android.os.SystemClock; -import io.sentry.CpuCollectionData; import io.sentry.HubAdapter; import io.sentry.IHub; import io.sentry.ITransaction; import io.sentry.ITransactionProfiler; -import io.sentry.MemoryCollectionData; import io.sentry.PerformanceCollectionData; import io.sentry.ProfilingTraceData; import io.sentry.ProfilingTransactionData; import io.sentry.SentryLevel; import io.sentry.android.core.internal.util.CpuInfoUtils; import io.sentry.android.core.internal.util.SentryFrameMetricsCollector; -import io.sentry.profilemeasurements.ProfileMeasurement; -import io.sentry.profilemeasurements.ProfileMeasurementValue; import io.sentry.util.Objects; -import java.io.File; -import java.util.ArrayDeque; import java.util.ArrayList; -import java.util.HashMap; import java.util.List; -import java.util.Map; -import java.util.UUID; -import java.util.concurrent.Future; -import java.util.concurrent.RejectedExecutionException; -import java.util.concurrent.TimeUnit; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; import org.jetbrains.annotations.TestOnly; final class AndroidTransactionProfiler implements ITransactionProfiler { - - /** - * This appears to correspond to the buffer size of the data part of the file, excluding the key - * part. Once the buffer is full, new records are ignored, but the resulting trace file will be - * valid. - * - *

30 second traces can require a buffer of a few MB. 8MB is the default buffer size for - * [Debug.startMethodTracingSampling], but 3 should be enough for most cases. We can adjust this - * in the future if we notice that traces are being truncated in some applications. - */ - private static final int BUFFER_SIZE_BYTES = 3_000_000; - - private static final int PROFILING_TIMEOUT_MILLIS = 30_000; - - private int intervalUs; - private @Nullable File traceFile = null; - private @Nullable File traceFilesDir = null; - private @Nullable Future scheduledFinish = null; - private volatile @Nullable ProfilingTraceData timedOutProfilingData = null; private final @NotNull Context context; private final @NotNull SentryAndroidOptions options; private final @NotNull IHub hub; private final @NotNull BuildInfoProvider buildInfoProvider; - private long transactionStartNanos = 0; - private long profileStartCpuMillis = 0; private boolean isInitialized = false; private int transactionsCounter = 0; - private @Nullable String frameMetricsCollectorId; private final @NotNull SentryFrameMetricsCollector frameMetricsCollector; private @Nullable ProfilingTransactionData currentProfilingTransactionData; - private final @NotNull ArrayDeque screenFrameRateMeasurements = - new ArrayDeque<>(); - private final @NotNull ArrayDeque slowFrameRenderMeasurements = - new ArrayDeque<>(); - private final @NotNull ArrayDeque frozenFrameRenderMeasurements = - new ArrayDeque<>(); - private final @NotNull Map measurementsMap = new HashMap<>(); private @Nullable ITransaction currentTransaction = null; + private @Nullable AndroidProfiler profiler = null; + private long transactionStartNanos; + private long profileStartCpuMillis; public AndroidTransactionProfiler( final @NotNull Context context, @@ -137,8 +98,14 @@ private void init() { intervalHz); return; } - intervalUs = (int) SECONDS.toMicros(1) / intervalHz; - traceFilesDir = new File(tracesFilesDirPath); + + profiler = + new AndroidProfiler( + tracesFilesDirPath, + (int) SECONDS.toMicros(1) / intervalHz, + frameMetricsCollector, + options, + buildInfoProvider); } @Override @@ -149,12 +116,6 @@ public synchronized void onTransactionStart(final @NotNull ITransaction transact // Let's initialize trace folder and profiling interval init(); - // traceFilesDir is null or intervalUs is 0 only if there was a problem in the init, but - // we already logged that - if (traceFilesDir == null || intervalUs == 0) { - return; - } - transactionsCounter++; // When the first transaction is starting, we can start profiling if (transactionsCounter == 1) { @@ -181,97 +142,24 @@ public synchronized void onTransactionStart(final @NotNull ITransaction transact @SuppressLint("NewApi") private boolean onFirstTransactionStarted(final @NotNull ITransaction transaction) { - // We create a file with a uuid name, so no need to check if it already exists - traceFile = new File(traceFilesDir, UUID.randomUUID() + ".trace"); - - measurementsMap.clear(); - screenFrameRateMeasurements.clear(); - slowFrameRenderMeasurements.clear(); - frozenFrameRenderMeasurements.clear(); - - frameMetricsCollectorId = - frameMetricsCollector.startCollection( - new SentryFrameMetricsCollector.FrameMetricsCollectorListener() { - final long nanosInSecond = TimeUnit.SECONDS.toNanos(1); - final long frozenFrameThresholdNanos = TimeUnit.MILLISECONDS.toNanos(700); - float lastRefreshRate = 0; - - @Override - public void onFrameMetricCollected( - final long frameEndNanos, final long durationNanos, float refreshRate) { - // transactionStartNanos is calculated through SystemClock.elapsedRealtimeNanos(), - // but frameEndNanos uses System.nanotime(), so we convert it to get the timestamp - // relative to transactionStartNanos - final long frameTimestampRelativeNanos = - frameEndNanos - - System.nanoTime() - + SystemClock.elapsedRealtimeNanos() - - transactionStartNanos; - - // We don't allow negative relative timestamps. - // So we add a check, even if this should never happen. - if (frameTimestampRelativeNanos < 0) { - return; - } - // Most frames take just a few nanoseconds longer than the optimal calculated - // duration. - // Therefore we subtract one, because otherwise almost all frames would be slow. - boolean isSlow = durationNanos > nanosInSecond / (refreshRate - 1); - float newRefreshRate = (int) (refreshRate * 100) / 100F; - if (durationNanos > frozenFrameThresholdNanos) { - frozenFrameRenderMeasurements.addLast( - new ProfileMeasurementValue(frameTimestampRelativeNanos, durationNanos)); - } else if (isSlow) { - slowFrameRenderMeasurements.addLast( - new ProfileMeasurementValue(frameTimestampRelativeNanos, durationNanos)); - } - if (newRefreshRate != lastRefreshRate) { - lastRefreshRate = newRefreshRate; - screenFrameRateMeasurements.addLast( - new ProfileMeasurementValue(frameTimestampRelativeNanos, newRefreshRate)); - } - } - }); - - currentTransaction = transaction; + // init() didn't create profiler, should never happen + if (profiler == null) { + return false; + } - // We stop profiling after a timeout to avoid huge profiles to be sent - try { - scheduledFinish = - options - .getExecutorService() - .schedule( - () -> timedOutProfilingData = onTransactionFinish(transaction, true, null), - PROFILING_TIMEOUT_MILLIS); - } catch (RejectedExecutionException e) { - options - .getLogger() - .log( - SentryLevel.ERROR, - "Failed to call the executor. Profiling will not be automatically finished. Did you call Sentry.close()?", - e); + final AndroidProfiler.ProfileStartData startData = profiler.start(); + // check if profiling started + if (startData == null) { + return false; } + transactionStartNanos = startData.startNanos; + profileStartCpuMillis = startData.startCpuMillis; - transactionStartNanos = SystemClock.elapsedRealtimeNanos(); - profileStartCpuMillis = Process.getElapsedCpuTime(); + currentTransaction = transaction; currentProfilingTransactionData = new ProfilingTransactionData(transaction, transactionStartNanos, profileStartCpuMillis); - - // We don't make any check on the file existence or writeable state, because we don't want to - // make file IO in the main thread. - // We cannot offload the work to the executorService, as if that's very busy, profiles could - // start/stop with a lot of delay and even cause ANRs. - try { - // If there is any problem with the file this method will throw (but it will not throw in - // tests) - Debug.startMethodTracingSampling(traceFile.getPath(), BUFFER_SIZE_BYTES, intervalUs); - return true; - } catch (Throwable e) { - onTransactionFinish(transaction, null); - options.getLogger().log(SentryLevel.ERROR, "Unable to start a profile: ", e); - return false; - } + return true; } @Override @@ -287,34 +175,18 @@ public void onFrameMetricCollected( final @NotNull ITransaction transaction, final boolean isTimeout, final @Nullable List performanceCollectionData) { + // check if profiler was created + if (profiler == null) { + return null; + } // onTransactionStart() is only available since Lollipop // and SystemClock.elapsedRealtimeNanos() since Jelly Bean if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP) return null; - final ProfilingTraceData profilingData = timedOutProfilingData; - // Transaction finished, but it's not in the current profile if (currentProfilingTransactionData == null || !currentProfilingTransactionData.getId().equals(transaction.getEventId().toString())) { - // We check if we cached a profiling data due to a timeout with this profile in it - // If so, we return it back, otherwise we would simply lose it - if (profilingData != null) { - if (profilingData.getTransactionId().equals(transaction.getEventId().toString())) { - timedOutProfilingData = null; - return profilingData; - } else { - // Another transaction is finishing before the timed out one - options - .getLogger() - .log( - SentryLevel.INFO, - "A timed out profiling data exists, but the finishing transaction %s (%s) is not part of it", - transaction.getName(), - transaction.getSpanContext().getTraceId().toString()); - return null; - } - } // A transaction is finishing, but it's not profiled. We can skip it options .getLogger() @@ -338,7 +210,7 @@ public void onFrameMetricCollected( transaction.getName(), transaction.getSpanContext().getTraceId().toString()); - if (transactionsCounter != 0 && !isTimeout) { + if (transactionsCounter != 0) { // We notify the data referring to this transaction that it finished if (currentProfilingTransactionData != null) { currentProfilingTransactionData.notifyFinish( @@ -350,19 +222,14 @@ public void onFrameMetricCollected( return null; } - try { - // If there is any problem with the file this method could throw, but the start is also - // wrapped, so this should never happen (except for tests, where this is the only method that - // throws) - Debug.stopMethodTracing(); - } catch (Throwable e) { - options.getLogger().log(SentryLevel.ERROR, "Error while stopping profiling: ", e); + final AndroidProfiler.ProfileEndData endData = + profiler.endAndCollect(false, performanceCollectionData); + // check if profiler end successfully + if (endData == null) { + return null; } - frameMetricsCollector.stopCollection(frameMetricsCollectorId); - long transactionEndNanos = SystemClock.elapsedRealtimeNanos(); - long transactionEndCpuMillis = Process.getElapsedCpuTime(); - long transactionDurationNanos = transactionEndNanos - transactionStartNanos; + long transactionDurationNanos = endData.endNanos - transactionStartNanos; List transactionList = new ArrayList<>(1); final ProfilingTransactionData txData = currentProfilingTransactionData; @@ -374,16 +241,6 @@ public void onFrameMetricCollected( transactionsCounter = 0; currentTransaction = null; - if (scheduledFinish != null) { - scheduledFinish.cancel(true); - scheduledFinish = null; - } - - if (traceFile == null) { - options.getLogger().log(SentryLevel.ERROR, "Trace file does not exists"); - return null; - } - String totalMem = "0"; ActivityManager.MemoryInfo memInfo = getMemInfo(); if (memInfo != null) { @@ -395,34 +252,13 @@ public void onFrameMetricCollected( // Some may not have been really finished, in case of a timeout for (ProfilingTransactionData t : transactionList) { t.notifyFinish( - transactionEndNanos, - transactionStartNanos, - transactionEndCpuMillis, - profileStartCpuMillis); + endData.endNanos, transactionStartNanos, endData.endCpuMillis, profileStartCpuMillis); } - if (!slowFrameRenderMeasurements.isEmpty()) { - measurementsMap.put( - ProfileMeasurement.ID_SLOW_FRAME_RENDERS, - new ProfileMeasurement(ProfileMeasurement.UNIT_NANOSECONDS, slowFrameRenderMeasurements)); - } - if (!frozenFrameRenderMeasurements.isEmpty()) { - measurementsMap.put( - ProfileMeasurement.ID_FROZEN_FRAME_RENDERS, - new ProfileMeasurement( - ProfileMeasurement.UNIT_NANOSECONDS, frozenFrameRenderMeasurements)); - } - if (!screenFrameRateMeasurements.isEmpty()) { - measurementsMap.put( - ProfileMeasurement.ID_SCREEN_FRAME_RATES, - new ProfileMeasurement(ProfileMeasurement.UNIT_HZ, screenFrameRateMeasurements)); - } - putPerformanceCollectionDataInMeasurements(performanceCollectionData); - // cpu max frequencies are read with a lambda because reading files is involved, so it will be // done in the background when the trace file is read return new ProfilingTraceData( - traceFile, + endData.traceFile, transactionList, transaction, Long.toString(transactionDurationNanos), @@ -437,87 +273,23 @@ public void onFrameMetricCollected( options.getProguardUuid(), options.getRelease(), options.getEnvironment(), - isTimeout + (endData.didTimeout || isTimeout) ? ProfilingTraceData.TRUNCATION_REASON_TIMEOUT : ProfilingTraceData.TRUNCATION_REASON_NORMAL, - measurementsMap); - } - - @SuppressLint("NewApi") - private void putPerformanceCollectionDataInMeasurements( - final @Nullable List performanceCollectionData) { - - // onTransactionStart() is only available since Lollipop - // and SystemClock.elapsedRealtimeNanos() since Jelly Bean - if (buildInfoProvider.getSdkInfoVersion() < Build.VERSION_CODES.LOLLIPOP) { - return; - } - - // This difference is required, since the PerformanceCollectionData timestamps are expressed in - // terms of System.currentTimeMillis() and measurements timestamps require the nanoseconds since - // the beginning, expressed with SystemClock.elapsedRealtimeNanos() - long timestampDiff = - SystemClock.elapsedRealtimeNanos() - - transactionStartNanos - - TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis()); - if (performanceCollectionData != null) { - final @NotNull ArrayDeque memoryUsageMeasurements = - new ArrayDeque<>(performanceCollectionData.size()); - final @NotNull ArrayDeque nativeMemoryUsageMeasurements = - new ArrayDeque<>(performanceCollectionData.size()); - final @NotNull ArrayDeque cpuUsageMeasurements = - new ArrayDeque<>(performanceCollectionData.size()); - for (PerformanceCollectionData performanceData : performanceCollectionData) { - CpuCollectionData cpuData = performanceData.getCpuData(); - MemoryCollectionData memoryData = performanceData.getMemoryData(); - if (cpuData != null) { - cpuUsageMeasurements.add( - new ProfileMeasurementValue( - TimeUnit.MILLISECONDS.toNanos(cpuData.getTimestampMillis()) + timestampDiff, - cpuData.getCpuUsagePercentage())); - } - if (memoryData != null && memoryData.getUsedHeapMemory() > -1) { - memoryUsageMeasurements.add( - new ProfileMeasurementValue( - TimeUnit.MILLISECONDS.toNanos(memoryData.getTimestampMillis()) + timestampDiff, - memoryData.getUsedHeapMemory())); - } - if (memoryData != null && memoryData.getUsedNativeMemory() > -1) { - nativeMemoryUsageMeasurements.add( - new ProfileMeasurementValue( - TimeUnit.MILLISECONDS.toNanos(memoryData.getTimestampMillis()) + timestampDiff, - memoryData.getUsedNativeMemory())); - } - } - if (!cpuUsageMeasurements.isEmpty()) { - measurementsMap.put( - ProfileMeasurement.ID_CPU_USAGE, - new ProfileMeasurement(ProfileMeasurement.UNIT_PERCENT, cpuUsageMeasurements)); - } - if (!memoryUsageMeasurements.isEmpty()) { - measurementsMap.put( - ProfileMeasurement.ID_MEMORY_FOOTPRINT, - new ProfileMeasurement(ProfileMeasurement.UNIT_BYTES, memoryUsageMeasurements)); - } - if (!nativeMemoryUsageMeasurements.isEmpty()) { - measurementsMap.put( - ProfileMeasurement.ID_MEMORY_NATIVE_FOOTPRINT, - new ProfileMeasurement(ProfileMeasurement.UNIT_BYTES, nativeMemoryUsageMeasurements)); - } - } + endData.measurementsMap); } @Override public void close() { - // we cancel any scheduled work - if (scheduledFinish != null) { - scheduledFinish.cancel(true); - scheduledFinish = null; - } // we stop profiling if (currentTransaction != null) { onTransactionFinish(currentTransaction, true, null); } + + // we have to first stop profiling otherwise we would lost the last profile + if (profiler != null) { + profiler.close(); + } } /** diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/AndroidProfilerTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/AndroidProfilerTest.kt new file mode 100644 index 0000000000..0671a83a9c --- /dev/null +++ b/sentry-android-core/src/test/java/io/sentry/android/core/AndroidProfilerTest.kt @@ -0,0 +1,309 @@ +package io.sentry.android.core + +import android.content.Context +import android.os.Build +import androidx.test.core.app.ApplicationProvider +import androidx.test.ext.junit.runners.AndroidJUnit4 +import io.sentry.CpuCollectionData +import io.sentry.ILogger +import io.sentry.ISentryExecutorService +import io.sentry.MemoryCollectionData +import io.sentry.PerformanceCollectionData +import io.sentry.SentryLevel +import io.sentry.android.core.internal.util.SentryFrameMetricsCollector +import io.sentry.profilemeasurements.ProfileMeasurement +import io.sentry.test.getCtor +import io.sentry.test.getProperty +import org.junit.Test +import org.junit.runner.RunWith +import org.mockito.kotlin.any +import org.mockito.kotlin.eq +import org.mockito.kotlin.mock +import org.mockito.kotlin.spy +import org.mockito.kotlin.times +import org.mockito.kotlin.verify +import org.mockito.kotlin.whenever +import java.io.File +import java.util.concurrent.Callable +import java.util.concurrent.Future +import java.util.concurrent.FutureTask +import kotlin.test.AfterTest +import kotlin.test.BeforeTest +import kotlin.test.assertContentEquals +import kotlin.test.assertFailsWith +import kotlin.test.assertFalse +import kotlin.test.assertNotNull +import kotlin.test.assertNull +import kotlin.test.assertTrue + +@RunWith(AndroidJUnit4::class) +class AndroidProfilerTest { + private lateinit var context: Context + + private val className = "io.sentry.android.core.AndroidProfiler" + private val ctorTypes = arrayOf(String::class.java, Int::class.java, SentryFrameMetricsCollector::class.java, SentryAndroidOptions::class.java, BuildInfoProvider::class.java) + private val fixture = Fixture() + + private class Fixture { + private val mockDsn = "http://key@localhost/proj" + val buildInfo = mock { + whenever(it.sdkInfoVersion).thenReturn(Build.VERSION_CODES.LOLLIPOP) + } + val mockLogger = mock() + var lastScheduledRunnable: Runnable? = null + val mockExecutorService = object : ISentryExecutorService { + override fun submit(runnable: Runnable): Future<*> { + runnable.run() + return FutureTask {} + } + override fun submit(callable: Callable): Future { + val futureTask = mock>() + whenever(futureTask.get()).thenAnswer { + return@thenAnswer try { + callable.call() + } catch (e: Exception) { + null + } + } + return futureTask + } + override fun schedule(runnable: Runnable, delayMillis: Long): Future<*> { + lastScheduledRunnable = runnable + return FutureTask {} + } + override fun close(timeoutMillis: Long) {} + override fun isClosed() = false + } + + val options = spy(SentryAndroidOptions()).apply { + dsn = mockDsn + profilesSampleRate = 1.0 + isDebug = true + setLogger(mockLogger) + executorService = mockExecutorService + } + + val frameMetricsCollector: SentryFrameMetricsCollector = mock() + + fun getSut(interval: Int = 1, buildInfoProvider: BuildInfoProvider = buildInfo): AndroidProfiler { + return AndroidProfiler(options.profilingTracesDirPath!!, interval, frameMetricsCollector, options, buildInfoProvider) + } + } + + @BeforeTest + fun `set up`() { + context = ApplicationProvider.getApplicationContext() + val buildInfoProvider = BuildInfoProvider(fixture.mockLogger) + val loadClass = LoadClass() + val activityFramesTracker = ActivityFramesTracker(loadClass, fixture.options) + AndroidOptionsInitializer.loadDefaultAndMetadataOptions( + fixture.options, + context, + fixture.mockLogger, + buildInfoProvider + ) + + AndroidOptionsInitializer.installDefaultIntegrations( + context, + fixture.options, + buildInfoProvider, + loadClass, + activityFramesTracker, + false, + false + ) + + AndroidOptionsInitializer.initializeIntegrationsAndProcessors( + fixture.options, + context, + buildInfoProvider, + loadClass, + activityFramesTracker + ) + // Profiler doesn't start if the folder doesn't exists. + // Usually it's generated when calling Sentry.init, but for tests we can create it manually. + File(fixture.options.profilingTracesDirPath!!).mkdirs() + } + + @AfterTest + fun clear() { + context.cacheDir.deleteRecursively() + } + + @Test + fun `when null param is provided, invalid argument is thrown`() { + val ctor = className.getCtor(ctorTypes) + + assertFailsWith { + ctor.newInstance(arrayOf(null, 0, mock(), mock(), mock())) + } + assertFailsWith { + ctor.newInstance(arrayOf("mock", 0, null, mock(), mock())) + } + assertFailsWith { + ctor.newInstance(arrayOf("mock", 0, mock(), null, mock())) + } + assertFailsWith { + ctor.newInstance(arrayOf("mock", 0, mock(), mock(), null)) + } + } + + @Test + fun `profiler works only on api 21+`() { + val buildInfo = mock { + whenever(it.sdkInfoVersion).thenReturn(Build.VERSION_CODES.KITKAT) + } + val profiler = fixture.getSut(1, buildInfo) + val startData = profiler.start() + val endData = profiler.endAndCollect(false, null) + assertNull(startData) + assertNull(endData) + } + + @Test + fun `profiler returns start and end timestamps`() { + val profiler = fixture.getSut() + val startData = profiler.start() + val endData = profiler.endAndCollect(false, null) + assertNotNull(startData?.startNanos) + assertNotNull(startData?.startCpuMillis) + assertNotNull(endData?.endNanos) + assertNotNull(endData?.endCpuMillis) + } + + @Test + fun `profiler returns timeout flag`() { + val profiler = fixture.getSut() + profiler.start() + val endData = profiler.endAndCollect(false, null) + assertNotNull(endData?.didTimeout) + } + + @Test + fun `profiler on interval 0`() { + val profiler = fixture.getSut(0) + val startData = profiler.start() + val endData = profiler.endAndCollect(false, null) + assertNull(startData) + assertNull(endData) + } + + @Test + fun `profiler does not throw if traces cannot be written to disk`() { + File(fixture.options.profilingTracesDirPath!!).setWritable(false) + val profiler = fixture.getSut() + profiler.start() + profiler.endAndCollect(false, null) + // We assert that no trace files are written + assertTrue(File(fixture.options.profilingTracesDirPath!!).list()!!.isEmpty()) + verify(fixture.mockLogger).log(eq(SentryLevel.ERROR), eq("Error while stopping profiling: "), any()) + } + + @Test + fun `endAndCollect works only if previously started`() { + val profiler = fixture.getSut() + val endData = profiler.endAndCollect(false, null) + assertNull(endData) + } + + @Test + fun `timedOutData has timeout flag`() { + val profiler = fixture.getSut() + + // Start and finish first transaction profiling + profiler.start() + + // Set timed out data by calling the timeout scheduled job + fixture.lastScheduledRunnable?.run() + + // First transaction finishes: timed out data is returned + val endData = profiler.endAndCollect(false, null) + assert(endData!!.didTimeout) + } + + @Test + fun `subsequent start call doesn't do anything`() { + val profiler = fixture.getSut() + + val startData = profiler.start() + val notStartedData = profiler.start() + + assertNotNull(startData) + assertNull(notStartedData) + verify(fixture.mockLogger).log(eq(SentryLevel.WARNING), eq("Profiling has already started...")) + } + + @Test + fun `profiler starts collecting frame metrics on start`() { + val profiler = fixture.getSut() + profiler.start() + verify(fixture.frameMetricsCollector, times(1)).startCollection(any()) + } + + @Test + fun `profiler stops collecting frame metrics on end`() { + val profiler = fixture.getSut() + val frameMetricsCollectorId = "id" + whenever(fixture.frameMetricsCollector.startCollection(any())).thenReturn(frameMetricsCollectorId) + profiler.start() + profiler.endAndCollect(false, null) + verify(fixture.frameMetricsCollector).stopCollection(frameMetricsCollectorId) + } + + @Test + fun `profiler does not includes performance measurements when null is passed`() { + val profiler = fixture.getSut() + profiler.start() + val data = profiler.endAndCollect(false, null) + assertFalse(data!!.measurementsMap.containsKey(ProfileMeasurement.ID_MEMORY_FOOTPRINT)) + assertFalse(data.measurementsMap.containsKey(ProfileMeasurement.ID_MEMORY_NATIVE_FOOTPRINT)) + assertFalse(data.measurementsMap.containsKey(ProfileMeasurement.ID_CPU_USAGE)) + } + + @Test + fun `profiler includes performance measurements when passed on end`() { + val profiler = fixture.getSut() + val performanceCollectionData = ArrayList() + var singleData = PerformanceCollectionData() + singleData.addMemoryData(MemoryCollectionData(1, 2, 3)) + singleData.addCpuData(CpuCollectionData(1, 1.4)) + performanceCollectionData.add(singleData) + + singleData = PerformanceCollectionData() + singleData.addMemoryData(MemoryCollectionData(2, 3, 4)) + performanceCollectionData.add(singleData) + + profiler.start() + val data = profiler.endAndCollect(false, performanceCollectionData) + assertContentEquals( + listOf(1.4), + data!!.measurementsMap[ProfileMeasurement.ID_CPU_USAGE]!!.values.map { it.value } + ) + assertContentEquals( + listOf(2.0, 3.0), + data.measurementsMap[ProfileMeasurement.ID_MEMORY_FOOTPRINT]!!.values.map { it.value } + ) + assertContentEquals( + listOf(3.0, 4.0), + data.measurementsMap[ProfileMeasurement.ID_MEMORY_NATIVE_FOOTPRINT]!!.values.map { it.value } + ) + } + + @Test + fun `profiler stops profiling, clear running flag and scheduled job on close`() { + val profiler = fixture.getSut() + profiler.start() + assert(profiler.getProperty("isRunning")) + + profiler.close() + assertFalse(profiler.getProperty("isRunning")) + + // The timeout scheduled job should be cleared + val scheduledJob = profiler.getProperty?>("scheduledFinish") + assertNull(scheduledJob) + + // Calling transaction finish returns null, as the profiler was stopped + val profilingTraceData = profiler.endAndCollect(false, null) + assertNull(profilingTraceData) + } +} diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/AndroidTransactionProfilerTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/AndroidTransactionProfilerTest.kt index 6710a418de..1c271fedba 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/AndroidTransactionProfilerTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/AndroidTransactionProfilerTest.kt @@ -374,6 +374,7 @@ class AndroidTransactionProfilerTest { assertEquals(fixture.options.release, profilingTraceData.release) } + @Test fun `profiler starts collecting frame metrics when the first transaction starts`() { val profiler = fixture.getSut(context) profiler.onTransactionStart(fixture.transaction1) @@ -442,7 +443,8 @@ class AndroidTransactionProfilerTest { assertNull(profiler.currentTransaction) // The timeout scheduled job should be cleared - val scheduledJob = profiler.getProperty?>("scheduledFinish") + val androidProfiler = profiler.getProperty("profiler") + val scheduledJob = androidProfiler?.getProperty?>("scheduledFinish") assertNull(scheduledJob) // Calling transaction finish returns null, as the profiler was stopped