Add hooks for IsolatedCompilation metrics
Enhance the CompOS service to report more details on failure.
Create a new IsolatedCompilationMetrics class to handle reporting when
compilation is scheduled and when it succeeds/fails.
No metrics are logged yet - we first need to define the proto format
in atoms.proto.
Additionally, improve the handling of multiple calls to onCompletion so
only the first one does anything. (We can get binderDied() called
after success, since composd exits.)
Bug: 218525257
Test: stage an APEX, run the job, observe logs
Test: run composd_cmd, cause it to fail in various ways
Change-Id: I4f97a82ddb5c1d53d67921e1e7ecc6c61229fb76
diff --git a/compos/composd/aidl/android/system/composd/ICompilationTaskCallback.aidl b/compos/composd/aidl/android/system/composd/ICompilationTaskCallback.aidl
index b334d8b..569bba5 100644
--- a/compos/composd/aidl/android/system/composd/ICompilationTaskCallback.aidl
+++ b/compos/composd/aidl/android/system/composd/ICompilationTaskCallback.aidl
@@ -20,6 +20,13 @@
* requested compilation task completes.
*/
oneway interface ICompilationTaskCallback {
+ enum FailureReason {
+ /** We failed to successfully start the VM and run compilation in it. */
+ CompilationFailed,
+ /** We ran compilation in the VM, but it reported a problem. */
+ UnexpectedCompilationResult,
+ }
+
/**
* Called if a compilation task has ended successfully, generating all the required artifacts.
*/
@@ -28,5 +35,5 @@
/**
* Called if a compilation task has ended unsuccessfully.
*/
- void onFailure();
+ void onFailure(FailureReason reason, String message);
}
diff --git a/compos/composd/src/odrefresh_task.rs b/compos/composd/src/odrefresh_task.rs
index 9dec1c1..e06e5fe 100644
--- a/compos/composd/src/odrefresh_task.rs
+++ b/compos/composd/src/odrefresh_task.rs
@@ -19,7 +19,8 @@
use crate::fd_server_helper::FdServerConfig;
use crate::instance_starter::CompOsInstance;
use android_system_composd::aidl::android::system::composd::{
- ICompilationTask::ICompilationTask, ICompilationTaskCallback::ICompilationTaskCallback,
+ ICompilationTask::ICompilationTask,
+ ICompilationTaskCallback::{FailureReason::FailureReason, ICompilationTaskCallback},
};
use android_system_composd::binder::{Interface, Result as BinderResult, Strong};
use anyhow::{Context, Result};
@@ -99,12 +100,15 @@
task.callback.onSuccess()
}
Ok(exit_code) => {
- error!("Unexpected odrefresh result: {:?}", exit_code);
- task.callback.onFailure()
+ let message = format!("Unexpected odrefresh result: {:?}", exit_code);
+ error!("{}", message);
+ task.callback
+ .onFailure(FailureReason::UnexpectedCompilationResult, &message)
}
Err(e) => {
- error!("Running odrefresh failed: {:?}", e);
- task.callback.onFailure()
+ let message = format!("Running odrefresh failed: {:?}", e);
+ error!("{}", message);
+ task.callback.onFailure(FailureReason::CompilationFailed, &message)
}
};
if let Err(e) = result {
diff --git a/compos/composd_cmd/composd_cmd.rs b/compos/composd_cmd/composd_cmd.rs
index 9f535d5..6afd711 100644
--- a/compos/composd_cmd/composd_cmd.rs
+++ b/compos/composd_cmd/composd_cmd.rs
@@ -19,7 +19,9 @@
use android_system_composd::{
aidl::android::system::composd::{
ICompilationTask::ICompilationTask,
- ICompilationTaskCallback::{BnCompilationTaskCallback, ICompilationTaskCallback},
+ ICompilationTaskCallback::{
+ BnCompilationTaskCallback, FailureReason::FailureReason, ICompilationTaskCallback,
+ },
IIsolatedCompilationService::ApexSource::ApexSource,
IIsolatedCompilationService::IIsolatedCompilationService,
},
@@ -68,10 +70,10 @@
completed: Condvar,
}
-#[derive(Copy, Clone)]
enum Outcome {
Succeeded,
- Failed,
+ Failed(FailureReason, String),
+ TaskDied,
}
impl Interface for Callback {}
@@ -82,8 +84,8 @@
Ok(())
}
- fn onFailure(&self) -> BinderResult<()> {
- self.0.set_outcome(Outcome::Failed);
+ fn onFailure(&self, reason: FailureReason, message: &str) -> BinderResult<()> {
+ self.0.set_outcome(Outcome::Failed(reason, message.to_owned()));
Ok(())
}
}
@@ -97,14 +99,14 @@
}
fn wait(&self, duration: Duration) -> Result<Outcome> {
- let (outcome, result) = self
+ let (mut outcome, result) = self
.completed
.wait_timeout_while(self.mutex.lock().unwrap(), duration, |outcome| outcome.is_none())
.unwrap();
if result.timed_out() {
bail!("Timed out waiting for compilation")
}
- Ok(outcome.unwrap())
+ Ok(outcome.take().unwrap())
}
}
@@ -138,7 +140,7 @@
let state_clone = state.clone();
let mut death_recipient = DeathRecipient::new(move || {
eprintln!("CompilationTask died");
- state_clone.set_outcome(Outcome::Failed);
+ state_clone.set_outcome(Outcome::TaskDied);
});
// Note that dropping death_recipient cancels this, so we can't use a temporary here.
task.as_binder().link_to_death(&mut death_recipient)?;
@@ -147,7 +149,10 @@
match state.wait(timeouts()?.odrefresh_max_execution_time) {
Ok(Outcome::Succeeded) => Ok(()),
- Ok(Outcome::Failed) => bail!("Compilation failed"),
+ Ok(Outcome::TaskDied) => bail!("Compilation task died"),
+ Ok(Outcome::Failed(reason, message)) => {
+ bail!("Compilation failed: {:?}: {}", reason, message)
+ }
Err(e) => {
if let Err(e) = task.cancel() {
eprintln!("Failed to cancel compilation: {:?}", e);
diff --git a/compos/service/java/com/android/server/compos/IsolatedCompilationJobService.java b/compos/service/java/com/android/server/compos/IsolatedCompilationJobService.java
index 75f5334..f77406d 100644
--- a/compos/service/java/com/android/server/compos/IsolatedCompilationJobService.java
+++ b/compos/service/java/com/android/server/compos/IsolatedCompilationJobService.java
@@ -31,6 +31,9 @@
import android.system.composd.IIsolatedCompilationService;
import android.util.Log;
+import com.android.server.compos.IsolatedCompilationMetrics.CompilationResult;
+
+import java.util.NoSuchElementException;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicReference;
@@ -73,9 +76,15 @@
.setRequiresCharging(true)
.setRequiresStorageNotLow(true)
.build());
- if (result != JobScheduler.RESULT_SUCCESS) {
+ if (result == JobScheduler.RESULT_SUCCESS) {
+ IsolatedCompilationMetrics.onCompilationScheduled(
+ IsolatedCompilationMetrics.SCHEDULING_SUCCESS);
+ } else {
+ IsolatedCompilationMetrics.onCompilationScheduled(
+ IsolatedCompilationMetrics.SCHEDULING_FAILURE);
Log.e(TAG, "Failed to schedule staged APEX job");
}
+
}
static boolean isStagedApexJobScheduled(JobScheduler scheduler) {
@@ -99,8 +108,13 @@
return false; // Already finished
}
+ IsolatedCompilationMetrics metrics = new IsolatedCompilationMetrics();
+ if (jobId != STAGED_APEX_JOB_ID) {
+ metrics.disable();
+ }
+
CompilationJob newJob = new CompilationJob(IsolatedCompilationJobService.this::onCompletion,
- params);
+ params, metrics);
mCurrentJob.set(newJob);
// This can take some time - we need to start up a VM - so we do it on a separate
@@ -113,6 +127,7 @@
newJob.start(jobId);
} catch (RuntimeException e) {
Log.e(TAG, "Starting CompilationJob failed", e);
+ metrics.onCompilationEnded(IsolatedCompilationMetrics.RESULT_FAILED_TO_START);
mCurrentJob.set(null);
newJob.stop(); // Just in case it managed to start before failure
jobFinished(params, /*wantReschedule=*/ false);
@@ -153,15 +168,17 @@
static class CompilationJob extends ICompilationTaskCallback.Stub
implements IBinder.DeathRecipient {
+ private final IsolatedCompilationMetrics mMetrics;
private final AtomicReference<ICompilationTask> mTask = new AtomicReference<>();
private final CompilationCallback mCallback;
private final JobParameters mParams;
private volatile boolean mStopRequested = false;
- private volatile boolean mCanceled = false;
- CompilationJob(CompilationCallback callback, JobParameters params) {
+ CompilationJob(CompilationCallback callback, JobParameters params,
+ IsolatedCompilationMetrics metrics) {
mCallback = requireNonNull(callback);
mParams = params;
+ mMetrics = requireNonNull(metrics);
}
void start(int jobId) {
@@ -181,6 +198,7 @@
} else {
composTask = composd.startStagedApexCompile(this);
}
+ mMetrics.onCompilationStarted();
mTask.set(composTask);
composTask.asBinder().linkToDeath(this, 0);
} catch (RemoteException e) {
@@ -202,10 +220,10 @@
private void cancelTask() {
ICompilationTask task = mTask.getAndSet(null);
if (task != null) {
- mCanceled = true;
Log.i(TAG, "Cancelling task");
try {
task.cancel();
+ mMetrics.onCompilationEnded(IsolatedCompilationMetrics.RESULT_JOB_CANCELED);
} catch (RuntimeException | RemoteException e) {
// If canceling failed we'll assume it means that the task has already failed;
// there's nothing else we can do anyway.
@@ -216,23 +234,44 @@
@Override
public void binderDied() {
- onFailure();
+ onCompletion(false, IsolatedCompilationMetrics.RESULT_COMPOSD_DIED);
}
@Override
public void onSuccess() {
- onCompletion(true);
+ onCompletion(true, IsolatedCompilationMetrics.RESULT_SUCCESS);
}
@Override
- public void onFailure() {
- onCompletion(false);
+ public void onFailure(byte reason, String message) {
+ int result;
+ switch (reason) {
+ case ICompilationTaskCallback.FailureReason.CompilationFailed:
+ result = IsolatedCompilationMetrics.RESULT_COMPILATION_FAILED;
+ break;
+
+ case ICompilationTaskCallback.FailureReason.UnexpectedCompilationResult:
+ result = IsolatedCompilationMetrics.RESULT_UNEXPECTED_COMPILATION_RESULT;
+ break;
+
+ default:
+ result = IsolatedCompilationMetrics.RESULT_UNKNOWN_FAILURE;
+ break;
+ }
+ Log.w(TAG, "Compilation failed: " + message);
+ onCompletion(false, result);
}
- private void onCompletion(boolean succeeded) {
- mTask.set(null);
- if (!mCanceled) {
+ private void onCompletion(boolean succeeded, @CompilationResult int result) {
+ ICompilationTask task = mTask.getAndSet(null);
+ if (task != null) {
+ mMetrics.onCompilationEnded(result);
mCallback.onCompletion(mParams, succeeded);
+ try {
+ task.asBinder().unlinkToDeath(this, 0);
+ } catch (NoSuchElementException e) {
+ // Harmless
+ }
}
}
}
diff --git a/compos/service/java/com/android/server/compos/IsolatedCompilationMetrics.java b/compos/service/java/com/android/server/compos/IsolatedCompilationMetrics.java
new file mode 100644
index 0000000..a8fc39d
--- /dev/null
+++ b/compos/service/java/com/android/server/compos/IsolatedCompilationMetrics.java
@@ -0,0 +1,87 @@
+/*
+ * Copyright 2022 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.server.compos;
+
+import android.annotation.IntDef;
+import android.os.SystemClock;
+import android.util.Log;
+
+import java.lang.annotation.Retention;
+import java.lang.annotation.RetentionPolicy;
+
+/**
+ * A class that handles reporting metrics relating to Isolated Compilation to statsd.
+ *
+ * @hide
+ */
+class IsolatedCompilationMetrics {
+ private static final String TAG = IsolatedCompilationMetrics.class.getName();
+
+ // TODO(b/218525257): Move the definition of these enums to atoms.proto
+ @Retention(RetentionPolicy.SOURCE)
+ @IntDef({RESULT_SUCCESS, RESULT_UNKNOWN_FAILURE, RESULT_FAILED_TO_START, RESULT_JOB_CANCELED,
+ RESULT_COMPILATION_FAILED, RESULT_UNEXPECTED_COMPILATION_RESULT, RESULT_COMPOSD_DIED})
+ public @interface CompilationResult {}
+
+ public static final int RESULT_SUCCESS = 0;
+ public static final int RESULT_UNKNOWN_FAILURE = 1;
+ public static final int RESULT_FAILED_TO_START = 2;
+ public static final int RESULT_JOB_CANCELED = 3;
+ public static final int RESULT_COMPILATION_FAILED = 4;
+ public static final int RESULT_UNEXPECTED_COMPILATION_RESULT = 5;
+ public static final int RESULT_COMPOSD_DIED = 6;
+
+ @Retention(RetentionPolicy.SOURCE)
+ @IntDef({SCHEDULING_SUCCESS, SCHEDULING_FAILURE})
+ public @interface ScheduleJobResult {}
+
+ public static final int SCHEDULING_SUCCESS = 0;
+ public static final int SCHEDULING_FAILURE = 1;
+
+ private long mCompilationStartTimeMs = 0;
+ private boolean mEnabled = true; // TODO(b/205296305) Remove this
+
+ public static void onCompilationScheduled(@ScheduleJobResult int result) {
+ // TODO(b/218525257): write to ArtStatsLog instead of logcat
+ // ArtStatsLog.write(ArtStatsLog.ISOLATED_COMPILATION_SCHEDULED, result);
+ Log.i(TAG, "ISOLATED_COMPILATION_SCHEDULED: " + result);
+ }
+
+ public void disable() {
+ mEnabled = false;
+ }
+
+ public void onCompilationStarted() {
+ if (mEnabled) {
+ mCompilationStartTimeMs = SystemClock.elapsedRealtime();
+ }
+ }
+
+ public void onCompilationEnded(@CompilationResult int result) {
+ if (!mEnabled) {
+ return;
+ }
+
+ long compilationTime = mCompilationStartTimeMs == 0 ? -1
+ : SystemClock.elapsedRealtime() - mCompilationStartTimeMs;
+ mCompilationStartTimeMs = 0;
+
+ // TODO(b/218525257): write to ArtStatsLog instead of logcat
+ // ArtStatsLog.write(ArtStatsLog.ISOLATED_COMPILATION_ENDED, result, compilationTime);
+ Log.i(TAG, "ISOLATED_COMPILATION_ENDED: " + result + ", " + compilationTime);
+ }
+}