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

3 files changed, 26 insertions, 14 deletions

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(),