diff --git a/detekt_custom_safe_calls.yml b/detekt_custom_safe_calls.yml index 60724bed46..b2a61ec690 100644 --- a/detekt_custom_safe_calls.yml +++ b/detekt_custom_safe_calls.yml @@ -960,6 +960,7 @@ datadog: - "kotlin.collections.MutableMap?.forEach(kotlin.Function1)" - "kotlin.collections.MutableSet.add(com.datadog.android.api.feature.FeatureContextUpdateReceiver)" - "kotlin.collections.MutableSet.add(com.datadog.android.core.internal.persistence.ConsentAwareStorage.Batch)" + - "kotlin.collections.MutableSet.add(com.datadog.android.profiling.internal.perfetto.PerfettoProfiler.TelemetryData)" - "kotlin.collections.MutableSet.add(com.datadog.android.sessionreplay.ExtensionSupport)" - "kotlin.collections.MutableSet.add(com.datadog.android.telemetry.internal.TelemetryEventId)" - "kotlin.collections.MutableSet.add(java.io.File)" diff --git a/features/dd-sdk-android-profiling/src/main/java/com/datadog/android/profiling/internal/perfetto/PerfettoProfiler.kt b/features/dd-sdk-android-profiling/src/main/java/com/datadog/android/profiling/internal/perfetto/PerfettoProfiler.kt index 293a638ff3..6c60d03ecb 100644 --- a/features/dd-sdk-android-profiling/src/main/java/com/datadog/android/profiling/internal/perfetto/PerfettoProfiler.kt +++ b/features/dd-sdk-android-profiling/src/main/java/com/datadog/android/profiling/internal/perfetto/PerfettoProfiler.kt @@ -16,6 +16,7 @@ import androidx.core.os.StackSamplingRequestBuilder import androidx.core.os.requestProfiling import com.datadog.android.api.InternalLogger import com.datadog.android.core.internal.persistence.file.lengthSafe +import com.datadog.android.core.metrics.MethodCallSamplingRate import com.datadog.android.internal.time.TimeProvider import com.datadog.android.profiling.internal.Profiler import com.datadog.android.profiling.internal.ProfilerCallback @@ -48,7 +49,16 @@ internal class PerfettoProfiler( @Volatile private var profilingStartTime = 0L + private val pendingTelemetry: MutableSet = mutableSetOf() + + @Volatile override var internalLogger: InternalLogger? = null + set(value) { + field = value + if (value != null) { + consumePendingTelemetry(value) + } + } // Map of private val callbackMap: MutableMap = ConcurrentHashMap() @@ -97,7 +107,6 @@ internal class PerfettoProfiler( override fun start(appContext: Context, sdkInstanceNames: Set) { // profiling will be launched when no instance is currently running profiling. if (runningInstances.compareAndSet(emptySet(), sdkInstanceNames)) { - sendProfilingStartTelemetry() profilingStartTime = timeProvider.getDeviceTimestampMillis() requestProfiling( appContext, @@ -114,7 +123,6 @@ internal class PerfettoProfiler( // overwritten by that time. Probably need to allow a single profiler instance and stop profiler before // starting another request. stopSignal?.cancel() - stopSignal = null } } @@ -133,37 +141,60 @@ internal class PerfettoProfiler( callbackMap.remove(sdkInstanceName) } - private fun sendProfilingStartTelemetry() { - internalLogger?.log( - level = InternalLogger.Level.INFO, - target = InternalLogger.Target.TELEMETRY, - messageBuilder = { TELEMETRY_MSG_PROFILING_STARTED }, - throwable = null, - onlyOnce = true, - additionalProperties = mapOf( - TELEMETRY_KEY_PROFILING to mapOf( - TELEMETRY_KEY_TAG to PROFILING_TAG_APPLICATION_LAUNCH - ) - ) + private fun sendProfilingEndTelemetry(result: ProfilingResult, duration: Long) { + val telemetryData = TelemetryData( + errorCode = result.errorCode, + errorMessage = result.errorMessage, + filePath = result.resultFilePath, + duration = duration, + stopReason = resolveStopReason(result.errorCode) ) + internalLogger?.let { + performLogMetric(it, telemetryData) + } ?: run { + synchronized(pendingTelemetry) { + pendingTelemetry.add(telemetryData) + } + } } - private fun sendProfilingEndTelemetry(result: ProfilingResult, duration: Long) { - internalLogger?.log( - level = InternalLogger.Level.INFO, - target = InternalLogger.Target.TELEMETRY, - messageBuilder = { TELEMETRY_MSG_PROFILING_FINISHED }, - throwable = null, - onlyOnce = true, + private fun resolveStopReason(errorCode: Int): String { + return if (stopSignal?.isCanceled == true) { + TELEMETRY_VALUE_STOPPED_REASON_MANUAL + } else { + when (errorCode) { + ProfilingResult.ERROR_NONE -> TELEMETRY_VALUE_STOPPED_REASON_TIMEOUT + else -> TELEMETRY_VALUE_STOPPED_REASON_ERROR + } + } + } + + private fun consumePendingTelemetry(logger: InternalLogger) { + synchronized(pendingTelemetry) { + pendingTelemetry.forEach { data -> + performLogMetric(logger, data) + } + pendingTelemetry.clear() + } + } + + private fun performLogMetric(logger: InternalLogger, telemetryData: TelemetryData) { + logger.logMetric( + messageBuilder = { TELEMETRY_MSG_PROFILING_APP_LAUNCH }, additionalProperties = mapOf( - TELEMETRY_KEY_PROFILING to mapOf( - TELEMETRY_KEY_ERROR_CODE to result.errorCode, - TELEMETRY_KEY_TAG to PROFILING_TAG_APPLICATION_LAUNCH, - TELEMETRY_KEY_ERROR_MESSAGE to result.errorMessage, - TELEMETRY_KEY_DURATION to duration, - TELEMETRY_KEY_FILE_SIZE to getFileSize(result.resultFilePath) + TELEMETRY_KEY_PROFILING_APP_LAUNCH to mapOf( + TELEMETRY_KEY_ERROR_CODE to telemetryData.errorCode, + TELEMETRY_KEY_ERROR_MESSAGE to telemetryData.errorMessage, + TELEMETRY_KEY_DURATION to telemetryData.duration, + TELEMETRY_KEY_FILE_SIZE to getFileSize(telemetryData.filePath), + TELEMETRY_KEY_STOPPED_REASON to telemetryData.stopReason + ), + TELEMETRY_KEY_PROFILING_CONFIG to mapOf( + TELEMETRY_KEY_BUFFER_SIZE to BUFFER_SIZE_KB, + TELEMETRY_KEY_SAMPLING_FREQUENCY to PROFILING_SAMPLING_RATE ) - ) + ), + samplingRate = MethodCallSamplingRate.ALL.rate ) } @@ -176,6 +207,14 @@ internal class PerfettoProfiler( } ?: 0 } + private data class TelemetryData( + val errorCode: Int, + val errorMessage: String?, + val filePath: String?, + val duration: Long, + val stopReason: String + ) + companion object { // Duration is based on the current P99 TTID metric. @@ -186,16 +225,22 @@ internal class PerfettoProfiler( // increased or configurable if needed. private const val BUFFER_SIZE_KB = 5120 // 5MB - // Currently we give 100HZ frequency to balance the sampling accuracy and performance - // overhead, it can be updated or configurable if needed. - private const val PROFILING_SAMPLING_RATE = 100 // 100Hz - private const val TELEMETRY_MSG_PROFILING_STARTED = "Profiling started." - private const val TELEMETRY_MSG_PROFILING_FINISHED = "Profiling finished." - private const val TELEMETRY_KEY_PROFILING = "profiling" + // Currently we give 101HZ frequency to balance the sampling accuracy and performance + // overhead also to avoid lockstep sampling, it can be updated or configurable if needed. + private const val PROFILING_SAMPLING_RATE = 101 // 101Hz + private const val TELEMETRY_MSG_PROFILING_APP_LAUNCH = + "[Mobile Metric] Profiling App Launch" + private const val TELEMETRY_KEY_PROFILING_APP_LAUNCH = "profiling_app_launch" + private const val TELEMETRY_KEY_PROFILING_CONFIG = "profiling_config" private const val TELEMETRY_KEY_ERROR_CODE = "error_code" - private const val TELEMETRY_KEY_TAG = "tag" private const val TELEMETRY_KEY_ERROR_MESSAGE = "error_message" private const val TELEMETRY_KEY_DURATION = "duration" - private const val TELEMETRY_KEY_FILE_SIZE = "size_bytes" + private const val TELEMETRY_KEY_FILE_SIZE = "file_size" + private const val TELEMETRY_KEY_BUFFER_SIZE = "buffer_size" + private const val TELEMETRY_KEY_SAMPLING_FREQUENCY = "sampling_frequency" + private const val TELEMETRY_KEY_STOPPED_REASON = "stopped_reason" + private const val TELEMETRY_VALUE_STOPPED_REASON_MANUAL = "manual" + private const val TELEMETRY_VALUE_STOPPED_REASON_TIMEOUT = "timeout" + private const val TELEMETRY_VALUE_STOPPED_REASON_ERROR = "error" } } diff --git a/features/dd-sdk-android-profiling/src/test/kotlin/com/datadog/android/profiling/internal/PerfettoProfilerTest.kt b/features/dd-sdk-android-profiling/src/test/kotlin/com/datadog/android/profiling/internal/PerfettoProfilerTest.kt index cbcdd5ffeb..b2028e30ef 100644 --- a/features/dd-sdk-android-profiling/src/test/kotlin/com/datadog/android/profiling/internal/PerfettoProfilerTest.kt +++ b/features/dd-sdk-android-profiling/src/test/kotlin/com/datadog/android/profiling/internal/PerfettoProfilerTest.kt @@ -12,9 +12,11 @@ import android.os.CancellationSignal import android.os.ProfilingManager import android.os.ProfilingResult import com.datadog.android.api.InternalLogger +import com.datadog.android.core.metrics.MethodCallSamplingRate import com.datadog.android.internal.time.TimeProvider import com.datadog.android.profiling.internal.perfetto.PerfettoProfiler import com.datadog.android.profiling.internal.perfetto.PerfettoResult +import fr.xgouchet.elmyr.annotation.IntForgery import fr.xgouchet.elmyr.annotation.LongForgery import fr.xgouchet.elmyr.annotation.StringForgery import fr.xgouchet.elmyr.junit5.ForgeExtension @@ -123,35 +125,28 @@ class PerfettoProfilerTest { } @Test - fun `M log info message W start()`() { + fun `M request profiling stack sampling only once W several call start(){ same instance }`() { // When testedProfiler.start(mockContext, setOf(fakeInstanceName)) + testedProfiler.start(mockContext, setOf(fakeInstanceName)) // Then - val messageCaptor = argumentCaptor<() -> String>() - val expectedProps = mapOf( - "profiling" to mapOf( - "tag" to "ApplicationLaunch" - ) - ) - verify(mockInternalLogger) - .log( - eq(InternalLogger.Level.INFO), - eq(InternalLogger.Target.TELEMETRY), - messageCaptor.capture(), - isNull(), - eq(true), - eq(expectedProps) + verify(mockService) + .requestProfiling( + eq(ProfilingManager.PROFILING_TYPE_STACK_SAMPLING), + any(), + any(), + any(), + any(), + any() ) - - assertThat(messageCaptor.firstValue.invoke()).isEqualTo("Profiling started.") } @Test - fun `M request profiling stack sampling only once W several call start(){ same instance }`() { + fun `M request profiling stack sampling only once W several call start(){ different instance }`() { // When testedProfiler.start(mockContext, setOf(fakeInstanceName)) - testedProfiler.start(mockContext, setOf(fakeInstanceName)) + testedProfiler.start(mockContext, setOf(otherInstanceName)) // Then verify(mockService) @@ -166,10 +161,75 @@ class PerfettoProfilerTest { } @Test - fun `M request profiling stack sampling only once W several call start(){ different instance }`() { + fun `M send telemetry W profiling finishes {with timeout}`( + @StringForgery fakeErrorMessage: String, + @LongForgery(min = 0L) fakeStartTime: Long, + @LongForgery(min = 0L) fakeDuration: Long + ) { + // Given + stubTimeProvider.startTime = fakeStartTime + stubTimeProvider.endTime = fakeStartTime + fakeDuration + + // When + testedProfiler.start(mockContext, setOf(fakeInstanceName)) + + // Then + val stopSignalCaptor = argumentCaptor() + verify(mockService) + .requestProfiling( + eq(ProfilingManager.PROFILING_TYPE_STACK_SAMPLING), + any(), + any(), + stopSignalCaptor.capture(), + any(), + callbackCaptor.capture() + ) + + val mockResult = mock { + on { errorCode } doReturn ProfilingResult.ERROR_NONE + on { errorMessage } doReturn fakeErrorMessage + } + + callbackCaptor.firstValue.accept(mockResult) + + val messageCaptor = argumentCaptor<() -> String>() + val expectedProps = mapOf( + "profiling_app_launch" to mapOf( + "error_code" to ProfilingResult.ERROR_NONE, + "error_message" to fakeErrorMessage, + "duration" to fakeDuration, + "file_size" to 0L, + "stopped_reason" to "timeout" + ), + "profiling_config" to mapOf( + "buffer_size" to 5120, + "sampling_frequency" to 101 + ) + ) + verify(mockInternalLogger) + .logMetric( + messageCaptor.capture(), + eq(expectedProps), + eq(MethodCallSamplingRate.ALL.rate), + isNull() + ) + + assertThat(messageCaptor.firstValue.invoke()).isEqualTo("[Mobile Metric] Profiling App Launch") + } + + @Test + fun `M send telemetry W profiling finishes {with error}`( + @StringForgery fakeErrorMessage: String, + @LongForgery(min = 0L) fakeStartTime: Long, + @LongForgery(min = 0L) fakeDuration: Long, + @IntForgery(min = 1, max = 8) fakeErrorCode: Int + ) { + // Given + stubTimeProvider.startTime = fakeStartTime + stubTimeProvider.endTime = fakeStartTime + fakeDuration + // When testedProfiler.start(mockContext, setOf(fakeInstanceName)) - testedProfiler.start(mockContext, setOf(otherInstanceName)) // Then verify(mockService) @@ -179,12 +239,43 @@ class PerfettoProfilerTest { any(), any(), any(), - any() + callbackCaptor.capture() ) + + val mockResult = mock { + on { errorCode } doReturn fakeErrorCode + on { errorMessage } doReturn fakeErrorMessage + } + + callbackCaptor.firstValue.accept(mockResult) + + val messageCaptor = argumentCaptor<() -> String>() + val expectedProps = mapOf( + "profiling_app_launch" to mapOf( + "error_code" to fakeErrorCode, + "error_message" to fakeErrorMessage, + "duration" to fakeDuration, + "file_size" to 0L, + "stopped_reason" to "error" + ), + "profiling_config" to mapOf( + "buffer_size" to 5120, + "sampling_frequency" to 101 + ) + ) + verify(mockInternalLogger) + .logMetric( + messageCaptor.capture(), + eq(expectedProps), + eq(MethodCallSamplingRate.ALL.rate), + isNull() + ) + + assertThat(messageCaptor.firstValue.invoke()).isEqualTo("[Mobile Metric] Profiling App Launch") } @Test - fun `M send telemetry W profiling finishes`( + fun `M send metric telemetry W internalLogger is assigned later`( @StringForgery fakeErrorMessage: String, @LongForgery(min = 0L) fakeStartTime: Long, @LongForgery(min = 0L) fakeDuration: Long @@ -192,11 +283,12 @@ class PerfettoProfilerTest { // Given stubTimeProvider.startTime = fakeStartTime stubTimeProvider.endTime = fakeStartTime + fakeDuration + testedProfiler.internalLogger = null // When testedProfiler.start(mockContext, setOf(fakeInstanceName)) + testedProfiler.internalLogger = mockInternalLogger - // Then verify(mockService) .requestProfiling( eq(ProfilingManager.PROFILING_TYPE_STACK_SAMPLING), @@ -214,27 +306,30 @@ class PerfettoProfilerTest { callbackCaptor.firstValue.accept(mockResult) + // Then val messageCaptor = argumentCaptor<() -> String>() val expectedProps = mapOf( - "profiling" to mapOf( + "profiling_app_launch" to mapOf( "error_code" to ProfilingResult.ERROR_FAILED_PROFILING_IN_PROGRESS, - "tag" to "ApplicationLaunch", "error_message" to fakeErrorMessage, "duration" to fakeDuration, - "size_bytes" to 0L + "file_size" to 0L, + "stopped_reason" to "error" + ), + "profiling_config" to mapOf( + "buffer_size" to 5120, + "sampling_frequency" to 101 ) ) verify(mockInternalLogger) - .log( - eq(InternalLogger.Level.INFO), - eq(InternalLogger.Target.TELEMETRY), + .logMetric( messageCaptor.capture(), - isNull(), - eq(true), - eq(expectedProps) + eq(expectedProps), + eq(MethodCallSamplingRate.ALL.rate), + isNull() ) - assertThat(messageCaptor.firstValue.invoke()).isEqualTo("Profiling finished.") + assertThat(messageCaptor.firstValue.invoke()).isEqualTo("[Mobile Metric] Profiling App Launch") } @Test