[DO NOT MERGE] Log Winscope tracing with the frame composition time

Currently the tracing log takes the current timestamp for the log entry.
However, the tracing start after the frame is composed. On winscope
this result in the trace entry being linked to the incorrect video
frame (screenrecord). Now we obtain the frame composition time (before
the frame is send to the video recorder) and use this time for the log
entry.

Test: Log a SF trace and screen recording. Open both on winscope.
Change-Id: I81a88ef7a81a084f2ecf75bf5574a1118301a48e

3 files changed, 8 insertions, 4 deletions

diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp
index 3057ed13e7..cb6dd8b9eb 100644
--- a/services/surfaceflinger/SurfaceFlinger.cpp
+++ b/services/surfaceflinger/SurfaceFlinger.cpp
@@ -1808,6 +1808,7 @@ void SurfaceFlinger::handleMessageRefresh() {
     preComposition();
     rebuildLayerStacks();
     calculateWorkingSet();
+    long compositionTime = elapsedRealtimeNano();
     for (const auto& [token, display] : mDisplays) {
         beginFrame(display);
         prepareFrame(display);
@@ -1837,7 +1838,7 @@ void SurfaceFlinger::handleMessageRefresh() {
     if (mVisibleRegionsDirty) {
         mVisibleRegionsDirty = false;
         if (mTracingEnabled) {
-            mTracing.notify("visibleRegionsDirty");
+            mTracing.notify(compositionTime, "visibleRegionsDirty");
         }
     }
 }
diff --git a/services/surfaceflinger/SurfaceTracing.cpp b/services/surfaceflinger/SurfaceTracing.cpp
index 9053f2c7de..5d9be0b8a9 100644
--- a/services/surfaceflinger/SurfaceTracing.cpp
+++ b/services/surfaceflinger/SurfaceTracing.cpp
@@ -68,8 +68,9 @@ bool SurfaceTracing::addTraceToBuffer(LayersTraceProto& entry) {
     return mEnabled;
 }
 
-void SurfaceTracing::notify(const char* where) {
+void SurfaceTracing::notify(long compositionTime, const char* where) {
     std::scoped_lock lock(mSfLock);
+    mCompositionTime = compositionTime;
     mWhere = where;
     mCanStartTrace.notify_one();
 }
@@ -160,7 +161,7 @@ LayersTraceProto SurfaceTracing::traceLayersLocked(const char* where) {
     ATRACE_CALL();
 
     LayersTraceProto entry;
-    entry.set_elapsed_realtime_nanos(elapsedRealtimeNano());
+    entry.set_elapsed_realtime_nanos(mCompositionTime);
     entry.set_where(where);
     LayersProto layers(mFlinger.dumpDrawingStateProto(mTraceFlags));
     entry.mutable_layers()->Swap(&layers);
diff --git a/services/surfaceflinger/SurfaceTracing.h b/services/surfaceflinger/SurfaceTracing.h
index 4773307a65..395d5622c7 100644
--- a/services/surfaceflinger/SurfaceTracing.h
+++ b/services/surfaceflinger/SurfaceTracing.h
@@ -46,7 +46,7 @@ public:
     bool disable();
     status_t writeToFile();
     bool isEnabled() const;
-    void notify(const char* where);
+    void notify(long compositionTime, const char* where);
 
     void setBufferSize(size_t bufferSizeInByte);
     void writeToFileAsync();
@@ -81,6 +81,8 @@ private:
         std::queue<LayersTraceProto> mStorage;
     };
 
+    long mCompositionTime;
+
     void mainLoop();
     void addFirstEntry();
     LayersTraceProto traceWhenNotified();