Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 95699b3b authored by Aaron Massey's avatar Aaron Massey
Browse files

stats: Add initial telemetry with first AdvancedPrintUiLaunched event

We want to start logging printing metrics.

Add initial telemetry logic and tests starting with
AdvancedPrintUiLaunched event.

Bug: 390478410
Test: atest PrintSpoolerRobolectricTests
Test: m PrintSpooler
Test: validate logged events via adb and webui
Flag: com.android.printspooler.flags.printing_telemetry
Change-Id: I4c4e91058439d09a6225a269180553a9853458fc
parent b34b6e8e
Loading
Loading
Loading
Loading
+10 −0
Original line number Diff line number Diff line
@@ -46,7 +46,9 @@ android_library {
    name: "PrintSpoolerLib",
    resource_dirs: ["res"],
    srcs: [
        ":statslog-printspooler-java-gen",
        "src/**/*.java",
        "src/**/*.kt",
        "src/com/android/printspooler/renderer/IPdfEditor.aidl",
        "src/com/android/printspooler/renderer/IPdfRenderer.aidl",
    ],
@@ -59,6 +61,7 @@ android_library {
        "android-support-fragment",
        "android-support-media-compat",
        "android-support-v7-recyclerview",
        "androidx.annotation_annotation",
        "printspooler_aconfig_flags_java_lib",
    ],
    flags_packages: [
@@ -80,3 +83,10 @@ java_aconfig_library {
    name: "printspooler_aconfig_flags_java_lib",
    aconfig_declarations: "printspooler_aconfig_declarations",
}

genrule {
    name: "statslog-printspooler-java-gen",
    tools: ["stats-log-api-gen"],
    cmd: "$(location stats-log-api-gen) --java $(out) --module printspooler --javaPackage com.android.printspooler.stats --javaClass PrintSpoolerStatsLog",
    out: ["com/android/PrintSooler/PrintSpoolerStatsLog.java"],
}
+3 −0
Original line number Diff line number Diff line
@@ -7,6 +7,9 @@
  "postsubmit": [
    {
      "name": "PrintSpoolerOutOfProcessTests"
    },
    {
      "name": "PrintSpoolerRobolectricTests"
    }
  ]
}
+7 −0
Original line number Diff line number Diff line
@@ -7,3 +7,10 @@ flag {
  description: "Log print job creation and state transitions."
  bug: "385340868"
}

flag {
  name: "printing_telemetry"
  namespace: "printing"
  description: "Metrics tracking final print job status, printer discovery, printer capabilities, and major UI actions."
  bug: "390478410"
}
+8 −0
Original line number Diff line number Diff line
@@ -69,6 +69,7 @@ import com.android.internal.util.dump.DualDumpOutputStream;
import com.android.internal.util.function.pooled.PooledLambda;
import com.android.printspooler.R;
import com.android.printspooler.flags.Flags;
import com.android.printspooler.stats.StatsAsyncLogger;
import com.android.printspooler.util.ApprovedPrintServices;

import libcore.io.IoUtils;
@@ -155,10 +156,17 @@ public final class PrintSpoolerService extends Service {
        synchronized (sLock) {
            sInstance = this;
        }

        if (Flags.printingTelemetry()) {
            StatsAsyncLogger.INSTANCE.startLogging();
        }
    }

    @Override
    public void onDestroy() {
        if (Flags.printingTelemetry()) {
            StatsAsyncLogger.INSTANCE.stopLogging();
        }
        super.onDestroy();
    }

+150 −0
Original line number Diff line number Diff line
/*
 * Copyright (C) 2025 The Android Open Source Project
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 * http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */

package com.android.printspooler.stats

import android.annotation.UserIdInt
import android.os.Handler
import android.os.HandlerThread
import android.os.SystemClock
import android.util.Log
import androidx.annotation.VisibleForTesting
import java.util.concurrent.Semaphore
import java.util.concurrent.TimeUnit
import kotlin.math.max
import kotlin.time.Duration
import kotlin.time.Duration.Companion.milliseconds

/**
 * @hide
 */
object StatsAsyncLogger {
    private val TAG = StatsAsyncLogger::class.java.simpleName
    private val DEBUG = false

    @VisibleForTesting val EVENT_REPORTED_MIN_INTERVAL: Duration = 10.milliseconds
    @VisibleForTesting val MAX_EVENT_QUEUE = 150

    private var semaphore = Semaphore(MAX_EVENT_QUEUE)
    private lateinit var handlerThread: HandlerThread
    private lateinit var eventHandler: Handler
    private var nextAvailableTimeMillis = SystemClock.uptimeMillis()
    private var statsLogWrapper = StatsLogWrapper()
    private var logging = false

    @VisibleForTesting
    fun testSetStatsLogWrapper(wrapper: StatsLogWrapper) {
        statsLogWrapper = wrapper
    }

    @VisibleForTesting
    fun testSetSemaphore(s: Semaphore) {
        semaphore = s
    }

    @VisibleForTesting
    fun testSetHandler(handler: Handler) {
        eventHandler = handler
    }

    private fun getNextAvailableTimeMillis(): Long {
        return max(
            // Handles back to back records
            nextAvailableTimeMillis + EVENT_REPORTED_MIN_INTERVAL.inWholeMilliseconds,
            // Updates next time to more recent value if it wasn't recently
            SystemClock.uptimeMillis() + EVENT_REPORTED_MIN_INTERVAL.inWholeMilliseconds,
        )
    }

    // Initializes Async Logger for logging events. Returns true if
    // started logging and False if logging was already started.
    fun startLogging(): Boolean {
        if (logging) {
            return false
        }
        logging = true
        if (DEBUG) {
            Log.d(TAG, "Logging started")
        }
        semaphore = Semaphore(MAX_EVENT_QUEUE)
        handlerThread = HandlerThread("StatsEventLoggerWrapper").also { it.start() }
        eventHandler = Handler(handlerThread.getLooper())
        nextAvailableTimeMillis = SystemClock.uptimeMillis()
        return true
    }

    // Returns true if logging was started and the logger successfully
    // logged all pending events while ending. Returns false
    // otherwise.
    fun stopLogging(): Boolean {
        if (!logging) {
            return false
        }
        logging = false
        if (DEBUG) {
            Log.d(TAG, "Begin flushing events")
        }
        val acquired =
            semaphore.tryAcquire(
                MAX_EVENT_QUEUE,
                MAX_EVENT_QUEUE * EVENT_REPORTED_MIN_INTERVAL.inWholeMilliseconds,
                TimeUnit.MILLISECONDS,
            )
        if (!acquired) {
            Log.w(TAG, "Time exceeded awaiting stats events")
        }
        if (DEBUG) {
            Log.d(TAG, "End flushing events")
        }
        handlerThread.quit()
        return acquired
    }

    fun AdvancedOptionsUiLaunched(@UserIdInt printServiceId: Int): Boolean {
        if (!logging) {
            return false
        }
        if (DEBUG) {
            Log.d(TAG, "Logging AdvancedOptionsUiLaunched event")
        }
        synchronized(semaphore) {
            if (!semaphore.tryAcquire()) {
                Log.w(TAG, "Logging too many events, dropping AdvancedOptionsUiLaunched event")
                return false
            }
            val result =
                eventHandler.postAtTime(
                    Runnable {
                        synchronized(semaphore) {
                            if (DEBUG) {
                                Log.d(TAG, "Async logging AdvancedOptionsUiLaunched event")
                            }
                            statsLogWrapper.internalAdvancedOptionsUiLaunched(printServiceId)
                            semaphore.release()
                        }
                    },
                    nextAvailableTimeMillis,
                )
            if (!result) {
                Log.e(TAG, "Could not log AdvancedOptionsUiLaunched event")
                semaphore.release()
                return false
            }
            nextAvailableTimeMillis = getNextAvailableTimeMillis()
        }
        return true
    }
}
Loading