From 75acfb92355e866503b5d7b1c92379be58e9db39 Mon Sep 17 00:00:00 2001 From: Enginex0 Date: Thu, 26 Mar 2026 02:11:17 +0100 Subject: [PATCH] perf(logging): add rate limiter and lazy formatting to SystemLogger Under binder stress, debug builds hammered logd with 6-7 syscalls per keygen, causing thread contention that spiked ping latency past G10b's threshold. Rate-limit debug/info/verbose to 15 msgs per 1s window with atomic CAS on window boundaries. Warnings and errors always pass. Expensive verbose calls in AttestationBuilder, AttestationPatcher, and DeviceAttestationService now use lazy lambdas so ASN.1 formatting only runs when the message will actually be emitted. --- .../attestation/AttestationBuilder.kt | 7 +- .../attestation/AttestationPatcher.kt | 14 ++-- .../attestation/DeviceAttestationService.kt | 7 +- .../TEESimulator/logging/SystemLogger.kt | 82 +++++++++++++++---- 4 files changed, 81 insertions(+), 29 deletions(-) diff --git a/app/src/main/java/org/matrix/TEESimulator/attestation/AttestationBuilder.kt b/app/src/main/java/org/matrix/TEESimulator/attestation/AttestationBuilder.kt index 0b5f1e3..17acc1c 100644 --- a/app/src/main/java/org/matrix/TEESimulator/attestation/AttestationBuilder.kt +++ b/app/src/main/java/org/matrix/TEESimulator/attestation/AttestationBuilder.kt @@ -43,11 +43,12 @@ object AttestationBuilder { securityLevel: Int, ): Extension { val keyDescription = buildKeyDescription(params, uid, securityLevel) - var formattedString = - keyDescription.joinToString(separator = ", ") { + SystemLogger.verbose { + val formattedString = keyDescription.joinToString(separator = ", ") { AttestationPatcher.formatAsn1Primitive(it) } - SystemLogger.verbose("Forged attestation data: ${formattedString}") + "Forged attestation data: $formattedString" + } return Extension(ATTESTATION_OID, false, DEROctetString(keyDescription.encoded)) } diff --git a/app/src/main/java/org/matrix/TEESimulator/attestation/AttestationPatcher.kt b/app/src/main/java/org/matrix/TEESimulator/attestation/AttestationPatcher.kt index 44a7e85..097462b 100644 --- a/app/src/main/java/org/matrix/TEESimulator/attestation/AttestationPatcher.kt +++ b/app/src/main/java/org/matrix/TEESimulator/attestation/AttestationPatcher.kt @@ -164,7 +164,7 @@ object AttestationPatcher { // Log the signature of the newly created certificate to observe its non-deterministic // nature. val signatureBytes = (newCertificate as X509Certificate).signature - SystemLogger.verbose("Signature of patched leaf cert: ${signatureBytes.toHex()}") + SystemLogger.verbose { "Signature of patched leaf cert: ${signatureBytes.toHex()}" } return newCertificate } @@ -286,8 +286,10 @@ object AttestationPatcher { private fun createPatchedAttestationExtension(parsed: ParsedAttestation, uid: Int): Extension { val (allFields, teeEnforcedMap, originalRootOfTrust) = parsed - var formattedString = allFields.joinToString(separator = ", ") { formatAsn1Primitive(it) } - SystemLogger.verbose("Original attestation data: ${formattedString}") + SystemLogger.verbose { + val formattedString = allFields.joinToString(separator = ", ") { formatAsn1Primitive(it) } + "Original attestation data: $formattedString" + } // Build the new Root of Trust and add/replace it in the map. val newRootOfTrust = AttestationBuilder.buildRootOfTrust(originalRootOfTrust) @@ -314,8 +316,10 @@ object AttestationPatcher { allFields[AttestationConstants.KEY_DESCRIPTION_TEE_ENFORCED_INDEX] = sortedTeeEnforced val patchedSequence = DERSequence(allFields) - formattedString = patchedSequence.joinToString(separator = ", ") { formatAsn1Primitive(it) } - SystemLogger.verbose("Patched attestation data: ${formattedString}") + SystemLogger.verbose { + val formattedString = patchedSequence.joinToString(separator = ", ") { formatAsn1Primitive(it) } + "Patched attestation data: $formattedString" + } val patchedOctets = DEROctetString(patchedSequence) return Extension(ATTESTATION_OID, false, patchedOctets) diff --git a/app/src/main/java/org/matrix/TEESimulator/attestation/DeviceAttestationService.kt b/app/src/main/java/org/matrix/TEESimulator/attestation/DeviceAttestationService.kt index 114ad3d..aef1fcb 100644 --- a/app/src/main/java/org/matrix/TEESimulator/attestation/DeviceAttestationService.kt +++ b/app/src/main/java/org/matrix/TEESimulator/attestation/DeviceAttestationService.kt @@ -148,11 +148,12 @@ object DeviceAttestationService { // The extension's value is an ASN.1 sequence. val keyDescriptionSeq = ASN1Sequence.getInstance(extension.extnValue.octets) - var formattedString = - keyDescriptionSeq.joinToString(separator = ", ") { + SystemLogger.verbose { + val formattedString = keyDescriptionSeq.joinToString(separator = ", ") { AttestationPatcher.formatAsn1Primitive(it) } - SystemLogger.verbose("Cached attestation data: ${formattedString}") + "Cached attestation data: $formattedString" + } val fields = keyDescriptionSeq.toArray() val attestVersion = diff --git a/app/src/main/java/org/matrix/TEESimulator/logging/SystemLogger.kt b/app/src/main/java/org/matrix/TEESimulator/logging/SystemLogger.kt index 05aa0cb..9a8c35e 100644 --- a/app/src/main/java/org/matrix/TEESimulator/logging/SystemLogger.kt +++ b/app/src/main/java/org/matrix/TEESimulator/logging/SystemLogger.kt @@ -1,42 +1,86 @@ package org.matrix.TEESimulator.logging import android.util.Log +import java.util.concurrent.atomic.AtomicInteger +import java.util.concurrent.atomic.AtomicLong import org.matrix.TEESimulator.BuildConfig /** * A centralized logging utility for the TEESimulator application. This object provides a consistent * logging tag and format for all application logs, making it easier to filter and debug in Logcat. + * + * Includes a rate limiter that caps logd syscalls during binder stress to prevent thread pool + * contention. The first [RATE_LIMIT_BURST] messages per [RATE_LIMIT_WINDOW_MS] window are logged + * normally; subsequent messages are suppressed and a summary is emitted when the window resets. */ object SystemLogger { - // The tag used for all log messages from this application. - private const val TAG = "TEESimulator" + @PublishedApi internal const val TAG = "TEESimulator" - private val isDebugBuild = BuildConfig.DEBUG + @PublishedApi internal val isDebugBuild = BuildConfig.DEBUG + + // Rate limiter: allow BURST messages per WINDOW, then suppress until window resets. + private const val RATE_LIMIT_BURST = 15 + private const val RATE_LIMIT_WINDOW_MS = 1000L + private val windowStart = AtomicLong(System.currentTimeMillis()) + private val windowCount = AtomicInteger(0) + private val suppressedCount = AtomicInteger(0) + + /** + * Returns true if this message should be emitted. Resets the window if expired + * and emits a suppression summary for the previous window. + */ + @PublishedApi internal fun acquireLogPermit(): Boolean { + val now = System.currentTimeMillis() + val start = windowStart.get() + if (now - start > RATE_LIMIT_WINDOW_MS) { + // Window expired: reset and emit suppression summary if needed. + if (windowStart.compareAndSet(start, now)) { + val suppressed = suppressedCount.getAndSet(0) + windowCount.set(1) // this call counts as #1 in the new window + if (suppressed > 0) { + Log.i(TAG, "[rate-limit] suppressed $suppressed log messages in previous window") + } + return true + } + } + val count = windowCount.incrementAndGet() + if (count <= RATE_LIMIT_BURST) return true + suppressedCount.incrementAndGet() + return false + } /** * Logs a debug message. Use this for fine-grained information that is useful for debugging. - * - * @param message The message to log. */ fun debug(message: String) { if (!isDebugBuild) return + if (!acquireLogPermit()) return Log.d(TAG, message) } + /** Lazy debug: lambda only evaluates if message will be logged. */ + inline fun debug(message: () -> String) { + if (!isDebugBuild) return + if (!acquireLogPermit()) return + Log.d(TAG, message()) + } + /** * Logs an informational message. Use this to report major application lifecycle events. - * - * @param message The message to log. */ fun info(message: String) { + if (!acquireLogPermit()) return Log.i(TAG, message) } + /** Lazy info: lambda only evaluates if message will be logged. */ + inline fun info(message: () -> String) { + if (!acquireLogPermit()) return + Log.i(TAG, message()) + } + /** - * Logs a warning message. Use this to report unexpected but non-fatal issues. - * - * @param message The message to log. - * @param throwable An optional exception to log with the message. + * Logs a warning message. Warnings are never rate-limited. */ fun warning(message: String, throwable: Throwable? = null) { if (throwable != null) { @@ -47,11 +91,7 @@ object SystemLogger { } /** - * Logs an error message. Use this to report fatal errors or exceptions that disrupt - * functionality. - * - * @param message The message to log. - * @param throwable An optional exception to log with the message. + * Logs an error message. Errors are never rate-limited. */ fun error(message: String, throwable: Throwable? = null) { if (throwable != null) { @@ -64,11 +104,17 @@ object SystemLogger { /** * Logs a verbose message. This level is for highly detailed logs that are generally not needed * unless tracking a very specific issue. - * - * @param message The message to log. */ fun verbose(message: String) { if (!isDebugBuild) return + if (!acquireLogPermit()) return Log.v(TAG, message) } + + /** Lazy verbose: lambda only evaluates if message will be logged. */ + inline fun verbose(message: () -> String) { + if (!isDebugBuild) return + if (!acquireLogPermit()) return + Log.v(TAG, message()) + } }