Log the overhead latency of app function requests

Flag: android.app.appfunctions.flags.enable_app_function_manager
Bug: 376688078
Test: manual test (will write tests in separate CL)
Change-Id: I6c9638c2e022b65e1b491c0cc4695bf8e5e80eb9

4 files changed, 49 insertions, 19 deletions

diff --git a/core/java/android/app/appfunctions/SafeOneTimeExecuteAppFunctionCallback.java b/core/java/android/app/appfunctions/SafeOneTimeExecuteAppFunctionCallback.java
index e290169bdea8..e527de209a75 100644
--- a/core/java/android/app/appfunctions/SafeOneTimeExecuteAppFunctionCallback.java
+++ b/core/java/android/app/appfunctions/SafeOneTimeExecuteAppFunctionCallback.java
@@ -19,10 +19,12 @@ package android.app.appfunctions;
 import android.annotation.NonNull;
 import android.annotation.Nullable;
 import android.os.RemoteException;
+import android.os.SystemClock;
 import android.util.Log;
 
 import java.util.Objects;
 import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.concurrent.atomic.AtomicLong;
 
 /**
  * A wrapper of IExecuteAppFunctionCallback which swallows the {@link RemoteException}. This
@@ -38,7 +40,10 @@ public class SafeOneTimeExecuteAppFunctionCallback {
 
     @NonNull private final IExecuteAppFunctionCallback mCallback;
 
-    @Nullable CompletionCallback mCompletionCallback;
+    @Nullable
+    private final CompletionCallback mCompletionCallback;
+
+    private final AtomicLong mExecutionStartTimeAfterBindMillis = new AtomicLong();
 
     public SafeOneTimeExecuteAppFunctionCallback(@NonNull IExecuteAppFunctionCallback callback) {
         this(callback, /* completionCallback= */ null);
@@ -59,7 +64,8 @@ public class SafeOneTimeExecuteAppFunctionCallback {
         try {
             mCallback.onSuccess(result);
             if (mCompletionCallback != null) {
-                mCompletionCallback.finalizeOnSuccess(result);
+                mCompletionCallback.finalizeOnSuccess(result,
+                        mExecutionStartTimeAfterBindMillis.get());
             }
         } catch (RemoteException ex) {
             // Failed to notify the other end. Ignore.
@@ -76,7 +82,8 @@ public class SafeOneTimeExecuteAppFunctionCallback {
         try {
             mCallback.onError(error);
             if (mCompletionCallback != null) {
-                mCompletionCallback.finalizeOnError(error);
+                mCompletionCallback.finalizeOnError(error,
+                        mExecutionStartTimeAfterBindMillis.get());
             }
         } catch (RemoteException ex) {
             // Failed to notify the other end. Ignore.
@@ -93,14 +100,25 @@ public class SafeOneTimeExecuteAppFunctionCallback {
     }
 
     /**
+     * Sets the execution start time of the request. Used to calculate the overhead latency of
+     * requests.
+     */
+    public void setExecutionStartTimeMillis() {
+        if (!mExecutionStartTimeAfterBindMillis.compareAndSet(0, SystemClock.elapsedRealtime())) {
+            Log.w(TAG, "Ignore subsequent calls to setExecutionStartTimeMillis()");
+        }
+    }
+
+    /**
      * Provides a hook to execute additional actions after the {@link IExecuteAppFunctionCallback}
      * has been invoked.
      */
     public interface CompletionCallback {
         /** Called after {@link IExecuteAppFunctionCallback#onSuccess}. */
-        void finalizeOnSuccess(@NonNull ExecuteAppFunctionResponse result);
+        void finalizeOnSuccess(@NonNull ExecuteAppFunctionResponse result,
+                long executionStartTimeMillis);
 
         /** Called after {@link IExecuteAppFunctionCallback#onError}. */
-        void finalizeOnError(@NonNull AppFunctionException error);
+        void finalizeOnError(@NonNull AppFunctionException error, long executionStartTimeMillis);
     }
 }
diff --git a/services/appfunctions/java/com/android/server/appfunctions/AppFunctionManagerServiceImpl.java b/services/appfunctions/java/com/android/server/appfunctions/AppFunctionManagerServiceImpl.java
index 9cc5a8c97258..669025f071c0 100644
--- a/services/appfunctions/java/com/android/server/appfunctions/AppFunctionManagerServiceImpl.java
+++ b/services/appfunctions/java/com/android/server/appfunctions/AppFunctionManagerServiceImpl.java
@@ -159,15 +159,17 @@ public class AppFunctionManagerServiceImpl extends IAppFunctionManager.Stub {
                         new SafeOneTimeExecuteAppFunctionCallback.CompletionCallback() {
                             @Override
                             public void finalizeOnSuccess(
-                                    @NonNull ExecuteAppFunctionResponse result) {
+                                    @NonNull ExecuteAppFunctionResponse result,
+                                    long executionStartTimeMillis) {
                                 mLoggerWrapper.logAppFunctionSuccess(requestInternal, result,
-                                        callingUid);
+                                        callingUid, executionStartTimeMillis);
                             }
 
                             @Override
-                            public void finalizeOnError(@NonNull AppFunctionException error) {
+                            public void finalizeOnError(@NonNull AppFunctionException error,
+                                    long executionStartTimeMillis) {
                                 mLoggerWrapper.logAppFunctionError(requestInternal,
-                                        error.getErrorCode(), callingUid);
+                                        error.getErrorCode(), callingUid, executionStartTimeMillis);
                             }
                         });
 
diff --git a/services/appfunctions/java/com/android/server/appfunctions/AppFunctionsLoggerWrapper.java b/services/appfunctions/java/com/android/server/appfunctions/AppFunctionsLoggerWrapper.java
index b59915aa6343..7ba1bbc536f6 100644
--- a/services/appfunctions/java/com/android/server/appfunctions/AppFunctionsLoggerWrapper.java
+++ b/services/appfunctions/java/com/android/server/appfunctions/AppFunctionsLoggerWrapper.java
@@ -41,25 +41,34 @@ public class AppFunctionsLoggerWrapper {
     }
 
     void logAppFunctionSuccess(ExecuteAppFunctionAidlRequest request,
-            ExecuteAppFunctionResponse response, int callingUid) {
+            ExecuteAppFunctionResponse response, int callingUid, long executionStartTimeMillis) {
         logAppFunctionsRequestReported(request, SUCCESS_RESPONSE_CODE,
-                response.getResponseDataSize(), callingUid);
+                response.getResponseDataSize(), callingUid, executionStartTimeMillis);
     }
 
-    void logAppFunctionError(ExecuteAppFunctionAidlRequest request, int errorCode, int callingUid) {
-        logAppFunctionsRequestReported(request, errorCode, /* responseSizeBytes = */ 0, callingUid);
+    void logAppFunctionError(ExecuteAppFunctionAidlRequest request, int errorCode, int callingUid,
+            long executionStartTimeMillis) {
+        logAppFunctionsRequestReported(request, errorCode, /* responseSizeBytes = */ 0, callingUid,
+                executionStartTimeMillis);
     }
 
     private void logAppFunctionsRequestReported(ExecuteAppFunctionAidlRequest request,
-            int errorCode, int responseSizeBytes, int callingUid) {
-        final long latency = SystemClock.elapsedRealtime() - request.getRequestTime();
+            int errorCode, int responseSizeBytes, int callingUid, long executionStartTimeMillis) {
+        final long e2eRequestLatencyMillis =
+                SystemClock.elapsedRealtime() - request.getRequestTime();
+        final long requestOverheadMillis =
+                executionStartTimeMillis > 0 ? (executionStartTimeMillis - request.getRequestTime())
+                        : e2eRequestLatencyMillis;
         LOGGING_THREAD_EXECUTOR.execute(() -> AppFunctionsStatsLog.write(
                 AppFunctionsStatsLog.APP_FUNCTIONS_REQUEST_REPORTED,
-                callingUid,
+                /* callerPackageUid= */ callingUid,
+                /* targetPackageUid= */
                 getPackageUid(request.getClientRequest().getTargetPackageName()),
-                errorCode,
-                request.getClientRequest().getRequestDataSize(), responseSizeBytes,
-                latency)
+                /* errorCode= */ errorCode,
+                /* requestSizeBytes= */ request.getClientRequest().getRequestDataSize(),
+                /* responseSizeBytes= */  responseSizeBytes,
+                /* requestDurationMs= */ e2eRequestLatencyMillis,
+                /* requestOverheadMs= */ requestOverheadMillis)
         );
     }
 
diff --git a/services/appfunctions/java/com/android/server/appfunctions/RunAppFunctionServiceCallback.java b/services/appfunctions/java/com/android/server/appfunctions/RunAppFunctionServiceCallback.java
index 896c0fc51683..a5ae7e310022 100644
--- a/services/appfunctions/java/com/android/server/appfunctions/RunAppFunctionServiceCallback.java
+++ b/services/appfunctions/java/com/android/server/appfunctions/RunAppFunctionServiceCallback.java
@@ -52,6 +52,7 @@ public class RunAppFunctionServiceCallback implements RunServiceCallCallback<IAp
             @NonNull IAppFunctionService service,
             @NonNull ServiceUsageCompleteListener serviceUsageCompleteListener) {
         try {
+            mSafeExecuteAppFunctionCallback.setExecutionStartTimeMillis();
             service.executeAppFunction(
                     mRequestInternal.getClientRequest(),
                     mRequestInternal.getCallingPackage(),