RC: Add a start_time to global memory dumps.

This will allow a narrower guestimate at the validity of performance
measurements relating to load events.

Bug: 755840
Change-Id: I7087c5840106102844ef7518c0ad42648f4abe3e
Reviewed-on: https://chromium-review.googlesource.com/1101304
Commit-Queue: Sigurður Ásgeirsson <siggi@chromium.org>
Commit-Queue: Will Harris <wfh@chromium.org>
Reviewed-by: Will Harris <wfh@chromium.org>
Reviewed-by: Primiano Tucci <primiano@chromium.org>
Cr-Commit-Position: refs/heads/master@{#568096}

services/resource_coordinator/memory_instrumentation/coordinator_impl_unittest.cc

@@ -8,6 +8,8 @@
 #include "base/message_loop/message_loop.h"
 #include "base/run_loop.h"
 #include "base/test/trace_event_analyzer.h"
+#include "base/threading/platform_thread.h"
+#include "base/time/time.h"
 #include "base/trace_event/memory_dump_request_args.h"
 #include "build/build_config.h"
 #include "mojo/public/cpp/bindings/binding.h"
@@ -299,6 +301,52 @@ TEST_F(CoordinatorImplTest, SeveralClients) {
   run_loop.Run();
 }
 
+// Issuing two requests will cause the second one to be queued.
+TEST_F(CoordinatorImplTest, QueuedRequest) {
+  base::RunLoop run_loop;
+
+  NiceMock<MockClientProcess> client_process_1(this, 1,
+                                               mojom::ProcessType::BROWSER);
+  NiceMock<MockClientProcess> client_process_2(this);
+
+  // Each request will invoke on both processes.
+  EXPECT_CALL(client_process_1, RequestChromeMemoryDumpMock(_, _)).Times(2);
+  EXPECT_CALL(client_process_2, RequestChromeMemoryDumpMock(_, _))
+      .Times(2)
+      .WillRepeatedly(Invoke(
+          [](const MemoryDumpRequestArgs& args,
+             MockClientProcess::RequestChromeMemoryDumpCallback& callback) {
+            // Delay the response here to make sure the start times are strictly
+            // increasing.
+            base::PlatformThread::Sleep(base::TimeDelta::FromMilliseconds(10));
+            MemoryDumpArgs dump_args{MemoryDumpLevelOfDetail::DETAILED};
+            auto pmd = std::make_unique<ProcessMemoryDump>(dump_args);
+            std::move(callback).Run(true, args.dump_guid, std::move(pmd));
+          }));
+
+  MockGlobalMemoryDumpCallback callback1;
+  MockGlobalMemoryDumpCallback callback2;
+
+  // Verify that the start time of subsequent dumps is monotonically
+  // increasing.
+  base::TimeTicks before = base::TimeTicks::Now();
+  base::TimeTicks first_dump_time;
+  EXPECT_CALL(callback1, OnCall(true, NotNull()))
+      .WillOnce(Invoke([&](bool success, GlobalMemoryDump* global_dump) {
+        EXPECT_LT(before, global_dump->start_time);
+        first_dump_time = global_dump->start_time;
+      }));
+  EXPECT_CALL(callback2, OnCall(true, NotNull()))
+      .WillOnce(Invoke([&](bool success, GlobalMemoryDump* global_dump) {
+        EXPECT_LT(before, global_dump->start_time);
+        EXPECT_LT(first_dump_time, global_dump->start_time);
+        run_loop.Quit();
+      }));
+  RequestGlobalMemoryDump(callback1.Get());
+  RequestGlobalMemoryDump(callback2.Get());
+  run_loop.Run();
+}
+
 TEST_F(CoordinatorImplTest, MissingChromeDump) {
   base::RunLoop run_loop;
 

services/resource_coordinator/memory_instrumentation/queued_request.h

@@ -109,7 +109,7 @@ struct QueuedRequest {
 
   // The time we started handling the request (does not including queuing
   // time).
-  base::Time start_time;
+  base::TimeTicks start_time;
 };
 
 // Holds data for pending requests enqueued via GetVmRegionsForHeapProfiler().

services/resource_coordinator/memory_instrumentation/queued_request_dispatcher.cc

@@ -187,7 +187,7 @@ void QueuedRequestDispatcher::SetUpAndDispatch(
   DCHECK(!request->dump_in_progress);
   request->dump_in_progress = true;
 
-  request->start_time = base::Time::Now();
+  request->start_time = base::TimeTicks::Now();
 
   TRACE_EVENT_NESTABLE_ASYNC_BEGIN2(
       base::trace_event::MemoryDumpManager::kTraceCategory, "GlobalMemoryDump",
@@ -439,6 +439,7 @@ void QueuedRequestDispatcher::Finalize(QueuedRequest* request,
 
   // Build up the global dump by iterating on the |valid| process dumps.
   mojom::GlobalMemoryDumpPtr global_dump(mojom::GlobalMemoryDump::New());
+  global_dump->start_time = request->start_time;
   global_dump->process_dumps.reserve(request->responses.size());
   for (const auto& response : request->responses) {
     base::ProcessId pid = response.second.process_id;
@@ -552,7 +553,7 @@ void QueuedRequestDispatcher::Finalize(QueuedRequest* request,
   std::move(callback).Run(global_success, request->dump_guid,
                           std::move(global_dump));
   UMA_HISTOGRAM_MEDIUM_TIMES("Memory.Experimental.Debug.GlobalDumpDuration",
-                             base::Time::Now() - request->start_time);
+                             base::TimeTicks::Now() - request->start_time);
   UMA_HISTOGRAM_COUNTS_1000(
       "Memory.Experimental.Debug.FailedProcessDumpsPerGlobalDump",
       request->failed_memory_dump_count);

services/resource_coordinator/public/mojom/memory_instrumentation/memory_instrumentation.mojom

@@ -5,6 +5,7 @@
 module memory_instrumentation.mojom;
 
 import "mojo/public/mojom/base/process_id.mojom";
+import "mojo/public/mojom/base/time.mojom";
 
 // Common structs:
 
@@ -189,6 +190,10 @@ struct ProcessMemoryDump {
 // This struct is returned by the public-facing API
 // Coordinator::RequestGlobalMemoryDump().
 struct GlobalMemoryDump {
+  // This time stamp precedes any of the data captured in |process_dumps|. Since
+  // dumps are queued, and since at most one dump is captured at a time, the
+  // start time of a global dump may lag the request time substantially.
+  mojo_base.mojom.TimeTicks start_time;
   array<ProcessMemoryDump> process_dumps;
 };