commit a9477038804f6f2ff93eac364ac1bd0faa7d60db
author terryguan <terryguan@google.com> Thu Aug 10 16:05:24 2023 -0700
committer terryguan <terryguan@google.com> Thu Aug 10 16:05:24 2023 -0700
tree 4b82c7ec16bdbbe9bad606deb3b835694c95783f
parent 9e0fcba01a7421eb6e244451d76f8390f9f3f698

Fix logging for latency

GetPropertySyncLatency was casting before subtraction causing floating
point rounding errors, this is exacerbated by large floaing point
numbers since their rounding is larger.

Bug: 295378910
Test: manual, logcat
Change-Id: Ie7bad9cce717acdf8eed3ee4a263e537513a80aa

service/src/com/android/car/CarPropertyService.java

diff --git a/service/src/com/android/car/CarPropertyService.java b/service/src/com/android/car/CarPropertyService.java
index cea1282..de04484 100644
--- a/service/src/com/android/car/CarPropertyService.java
+++ b/service/src/com/android/car/CarPropertyService.java
@@ -565,14 +565,18 @@
             throws IllegalArgumentException, ServiceSpecificException {
         validateGetParameters(propertyId, areaId);
         Trace.traceBegin(TRACE_TAG, "CarPropertyValue#getProperty");
-        float currentTimeMs = System.currentTimeMillis();
+        long currentTimeMs = System.currentTimeMillis();
         try {
             return runSyncOperationCheckLimit(() -> {
                 return mPropertyHalService.getProperty(propertyId, areaId);
             });
         } finally {
-            sGetPropertySyncLatencyHistogram.logSample((float) System.currentTimeMillis()
-                    - currentTimeMs);
+            if (DBG) {
+                Slogf.d(TAG, "Latency of getPropertySync is: %f", (float) (System
+                        .currentTimeMillis() - currentTimeMs));
+            }
+            sGetPropertySyncLatencyHistogram.logSample((float) (System.currentTimeMillis()
+                    - currentTimeMs));
             Trace.traceEnd(TRACE_TAG);
         }
     }
@@ -648,8 +652,12 @@
             mClientMap.put(listenerBinder, client);
             updateSetOperationRecorderLocked(carPropertyValue.getPropertyId(),
                     carPropertyValue.getAreaId(), client);
-            sSetPropertySyncLatencyHistogram.logSample((float) System.currentTimeMillis()
-                    - currentTimeMs);
+            if (DBG) {
+                Slogf.d(TAG, "Latency of setPropertySync is: %f", (float) (System
+                        .currentTimeMillis() - currentTimeMs));
+            }
+            sSetPropertySyncLatencyHistogram.logSample((float) (System.currentTimeMillis()
+                    - currentTimeMs));
         }
     }
 
@@ -791,7 +799,11 @@
         }
         mPropertyHalService.getCarPropertyValuesAsync(getPropertyServiceRequests,
                 asyncPropertyResultCallback, timeoutInMs, currentTime);
-        sGetAsyncLatencyHistogram.logSample((float) System.currentTimeMillis() - currentTime);
+        if (DBG) {
+            Slogf.d(TAG, "Latency of getPropertyAsync is: %f", (float) (System
+                    .currentTimeMillis() - currentTime));
+        }
+        sGetAsyncLatencyHistogram.logSample((float) (System.currentTimeMillis() - currentTime));
     }
 
     /**
@@ -836,7 +848,11 @@
         }
         mPropertyHalService.setCarPropertyValuesAsync(setPropertyServiceRequestList,
                 asyncPropertyResultCallback, timeoutInMs, currentTime);
-        sSetAsyncLatencyHistogram.logSample((float) System.currentTimeMillis() - currentTime);
+        if (DBG) {
+            Slogf.d(TAG, "Latency of setPropertyAsync is: %f", (float) (System
+                    .currentTimeMillis() - currentTime));
+        }
+        sSetAsyncLatencyHistogram.logSample((float) (System.currentTimeMillis() - currentTime));
     }
 
     /**