Introduce ServiceWorker.EventDispatchingDelay UMA

content/browser/service_worker/service_worker_version_unittest.cc

 // Copyright 2014 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "content/browser/service_worker/service_worker_version.h"
 
 #include <stdint.h>
 #include <tuple>
 
 #include "base/macros.h"
 #include "base/memory/ptr_util.h"
 #include "base/run_loop.h"
 #include "base/test/histogram_tester.h"
+#include "base/time/time.h"
 #include "content/browser/service_worker/embedded_worker_registry.h"
 #include "content/browser/service_worker/embedded_worker_status.h"
 #include "content/browser/service_worker/embedded_worker_test_helper.h"
 #include "content/browser/service_worker/service_worker_context_core.h"
 #include "content/browser/service_worker/service_worker_registration.h"
 #include "content/browser/service_worker/service_worker_test_utils.h"
 #include "content/common/service_worker/service_worker_utils.h"
 #include "content/public/test/mock_render_process_host.h"
 #include "content/public/test/test_browser_thread_bundle.h"
 #include "content/public/test/test_mojo_service.mojom.h"
 #include "content/public/test/test_utils.h"
 #include "mojo/public/cpp/bindings/strong_binding.h"
 #include "services/shell/public/cpp/interface_registry.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
 // IPC messages for testing ---------------------------------------------------
 
 #define IPC_MESSAGE_IMPL
 #include "ipc/ipc_message_macros.h"
 
 #define IPC_MESSAGE_START TestMsgStart
 
 IPC_MESSAGE_CONTROL0(TestMsg_Message)
 IPC_MESSAGE_ROUTED1(TestMsg_MessageFromWorker, int)
 
 IPC_MESSAGE_CONTROL1(TestMsg_TestEvent, int)
 IPC_MESSAGE_CONTROL2(TestMsg_TestEvent_Multiple, int, int)
 IPC_MESSAGE_ROUTED2(TestMsg_TestEventResult, int, std::string)
-IPC_MESSAGE_ROUTED2(TestMsg_TestSimpleEventResult,
+IPC_MESSAGE_ROUTED3(TestMsg_TestSimpleEventResult,
                     int,
-                    blink::WebServiceWorkerEventResult)
+                    blink::WebServiceWorkerEventResult,
+                    base::Time)
 
 IPC_ENUM_TRAITS_MAX_VALUE(blink::WebServiceWorkerEventResult,
                           blink::WebServiceWorkerEventResultLast)
 
 // ---------------------------------------------------------------------------
 
 namespace content {
 
 namespace {
 
@@ skipping 26 matching lines @@
 
   void SimulateSendEventResult(int embedded_worker_id,
                                int request_id,
                                const std::string& reply) {
     SimulateSend(
         new TestMsg_TestEventResult(embedded_worker_id, request_id, reply));
   }
 
   void SimulateSendSimpleEventResult(int embedded_worker_id,
                                      int request_id,
-                                     blink::WebServiceWorkerEventResult reply) {
-    SimulateSend(new TestMsg_TestSimpleEventResult(embedded_worker_id,
-                                                   request_id, reply));
+                                     blink::WebServiceWorkerEventResult reply,
+                                     base::Time dispatch_event_time) {
+    SimulateSend(new TestMsg_TestSimpleEventResult(
+        embedded_worker_id, request_id, reply, dispatch_event_time));
   }
 
  private:
   void OnMessage() {
     // Do nothing.
   }
 
   int current_embedded_worker_id_;
   DISALLOW_COPY_AND_ASSIGN(MessageReceiver);
 };
@@ skipping 159 matching lines @@
     runner->Run();
     EXPECT_EQ(SERVICE_WORKER_ERROR_MAX_VALUE, status);
     EXPECT_EQ(EmbeddedWorkerStatus::RUNNING, version_->running_status());
 
     // Start request, as if an event is being dispatched.
     int request_id = version_->StartRequest(
         event_type, CreateReceiverOnCurrentThread(&status));
     base::RunLoop().RunUntilIdle();
 
     // And finish request, as if a response to the event was received.
-    EXPECT_TRUE(version_->FinishRequest(request_id, true));
+    EXPECT_TRUE(version_->FinishRequest(request_id, true /* was_handled */,
+                                        base::Time::Now()));
     base::RunLoop().RunUntilIdle();
     EXPECT_EQ(SERVICE_WORKER_ERROR_MAX_VALUE, status);
   }
 
   TestBrowserThreadBundle thread_bundle_;
   std::unique_ptr<MessageReceiver> helper_;
   scoped_refptr<ServiceWorkerRegistration> registration_;
   scoped_refptr<ServiceWorkerVersion> version_;
   GURL pattern_;
 
@@ skipping 361 matching lines @@
   idle_time = version_->idle_time_;
   SimulateDispatchEvent(ServiceWorkerMetrics::EventType::FETCH_MAIN_FRAME);
   EXPECT_LT(idle_time, version_->idle_time_);
 
   // Starting and finishing a request resets the idle time.
   version_->idle_time_ -= kOneSecond;
   idle_time = version_->idle_time_;
   int request_id =
       version_->StartRequest(ServiceWorkerMetrics::EventType::SYNC,
                              CreateReceiverOnCurrentThread(&status));
-  EXPECT_TRUE(version_->FinishRequest(request_id, true));
+  EXPECT_TRUE(version_->FinishRequest(request_id, true /* was_handled */,
+                                      base::Time::Now()));
 
   EXPECT_EQ(SERVICE_WORKER_OK, status);
   EXPECT_LT(idle_time, version_->idle_time_);
 }
 
 TEST_F(ServiceWorkerVersionTest, SetDevToolsAttached) {
   ServiceWorkerStatusCode status = SERVICE_WORKER_ERROR_FAILED;
   version_->StartWorker(ServiceWorkerMetrics::EventType::UNKNOWN,
                         CreateReceiverOnCurrentThread(&status));
 
@@ skipping 161 matching lines @@
   EXPECT_EQ(SERVICE_WORKER_ERROR_NETWORK, status);
   EXPECT_EQ(EmbeddedWorkerStatus::RUNNING, version_->running_status());
 
   // Simulate timeout.
   EXPECT_TRUE(version_->timeout_timer_.IsRunning());
   version_->SetAllRequestExpirations(base::TimeTicks::Now());
   version_->timeout_timer_.user_task().Run();
   base::RunLoop().RunUntilIdle();
   EXPECT_EQ(SERVICE_WORKER_ERROR_TIMEOUT, status);
   EXPECT_EQ(EmbeddedWorkerStatus::STOPPED, version_->running_status());
-  EXPECT_FALSE(version_->FinishRequest(request_id, true));
+  EXPECT_FALSE(version_->FinishRequest(request_id, true /* was_handled */,
+                                       base::Time::Now()));
 }
 
 TEST_F(ServiceWorkerVersionTest, RequestCustomizedTimeout) {
   ServiceWorkerStatusCode status = SERVICE_WORKER_ERROR_NETWORK;  // dummy value
   version_->SetStatus(ServiceWorkerVersion::ACTIVATED);
 
   version_->StartWorker(ServiceWorkerMetrics::EventType::SYNC,
                         base::Bind(&ServiceWorkerUtils::NoOpStatusCallback));
   base::RunLoop().RunUntilIdle();
 
   // Create a request that should expire Now().
   int request_id = version_->StartRequestWithCustomTimeout(
       ServiceWorkerMetrics::EventType::SYNC,
       CreateReceiverOnCurrentThread(&status), base::TimeDelta(),
       ServiceWorkerVersion::CONTINUE_ON_TIMEOUT);
 
   base::RunLoop().RunUntilIdle();
   EXPECT_TRUE(version_->timeout_timer_.IsRunning());
   version_->timeout_timer_.user_task().Run();
   base::RunLoop().RunUntilIdle();
   EXPECT_EQ(SERVICE_WORKER_ERROR_TIMEOUT, status);
 
-  EXPECT_FALSE(version_->FinishRequest(request_id, true));
+  EXPECT_FALSE(version_->FinishRequest(request_id, true /* was_handled */,
+                                       base::Time::Now()));
 
   // CONTINUE_ON_TIMEOUT timeouts don't stop the service worker.
   EXPECT_EQ(EmbeddedWorkerStatus::RUNNING, version_->running_status());
 }
 
 TEST_F(ServiceWorkerVersionTest, RequestCustomizedTimeoutKill) {
   ServiceWorkerStatusCode status = SERVICE_WORKER_ERROR_NETWORK;  // dummy value
   version_->SetStatus(ServiceWorkerVersion::ACTIVATED);
 
   version_->StartWorker(ServiceWorkerMetrics::EventType::SYNC,
                         base::Bind(&ServiceWorkerUtils::NoOpStatusCallback));
   base::RunLoop().RunUntilIdle();
 
   // Create a request that should expire Now().
   int request_id = version_->StartRequestWithCustomTimeout(
       ServiceWorkerMetrics::EventType::SYNC,
       CreateReceiverOnCurrentThread(&status), base::TimeDelta(),
       ServiceWorkerVersion::KILL_ON_TIMEOUT);
 
   base::RunLoop().RunUntilIdle();
   EXPECT_TRUE(version_->timeout_timer_.IsRunning());
   version_->timeout_timer_.user_task().Run();
   base::RunLoop().RunUntilIdle();
   EXPECT_EQ(SERVICE_WORKER_ERROR_TIMEOUT, status);
 
-  EXPECT_FALSE(version_->FinishRequest(request_id, true));
+  EXPECT_FALSE(version_->FinishRequest(request_id, true /* was_handled */,
+                                       base::Time::Now()));
 
   // KILL_ON_TIMEOUT timeouts should stop the service worker.
   EXPECT_EQ(EmbeddedWorkerStatus::STOPPED, version_->running_status());
 }
 
 TEST_F(ServiceWorkerVersionTest, MixedRequestTimeouts) {
   ServiceWorkerStatusCode sync_status =
       SERVICE_WORKER_ERROR_NETWORK;  // dummy value
   ServiceWorkerStatusCode fetch_status =
       SERVICE_WORKER_ERROR_NETWORK;  // dummy value
@@ skipping 19 matching lines @@
   EXPECT_TRUE(version_->timeout_timer_.IsRunning());
   version_->timeout_timer_.user_task().Run();
   base::RunLoop().RunUntilIdle();
   EXPECT_EQ(SERVICE_WORKER_ERROR_TIMEOUT, sync_status);
   EXPECT_EQ(SERVICE_WORKER_ERROR_NETWORK, fetch_status);
 
   // Background sync timeouts don't stop the service worker.
   EXPECT_EQ(EmbeddedWorkerStatus::RUNNING, version_->running_status());
 
   // Gracefully handle the sync event finishing after the timeout.
-  EXPECT_FALSE(version_->FinishRequest(sync_request_id, true));
+  EXPECT_FALSE(version_->FinishRequest(sync_request_id, true /* was_handled */,
+                                       base::Time::Now()));
 
   // Verify that the fetch times out later.
   version_->SetAllRequestExpirations(base::TimeTicks::Now());
   version_->timeout_timer_.user_task().Run();
   base::RunLoop().RunUntilIdle();
   EXPECT_EQ(SERVICE_WORKER_ERROR_TIMEOUT, fetch_status);
 
   // Fetch request should no longer exist.
-  EXPECT_FALSE(version_->FinishRequest(fetch_request_id, true));
+  EXPECT_FALSE(version_->FinishRequest(fetch_request_id, true /* was_handled */,
+                                       base::Time::Now()));
 
   // Other timeouts do stop the service worker.
   EXPECT_EQ(EmbeddedWorkerStatus::STOPPED, version_->running_status());
 }
 
 TEST_F(ServiceWorkerFailToStartTest, RendererCrash) {
   ServiceWorkerStatusCode status = SERVICE_WORKER_ERROR_NETWORK;  // dummy value
   version_->StartWorker(ServiceWorkerMetrics::EventType::UNKNOWN,
                         CreateReceiverOnCurrentThread(&status));
   base::RunLoop().RunUntilIdle();
@@ skipping 221 matching lines @@
   helper_->context()->RemoveAllProviderHostsForProcess(process_id);
   helper_->context()->embedded_worker_registry()->RemoveChildProcessSender(
       process_id);
   base::RunLoop().RunUntilIdle();
 
   // Callback completed.
   EXPECT_EQ(SERVICE_WORKER_ERROR_FAILED, status);
   EXPECT_EQ(EmbeddedWorkerStatus::STOPPED, version_->running_status());
 
   // Request already failed, calling finsh should return false.
-  EXPECT_FALSE(version_->FinishRequest(request_id, true));
+  EXPECT_FALSE(version_->FinishRequest(request_id, true /* was_handled */,
+                                       base::Time::Now()));
 }
 
 TEST_F(ServiceWorkerVersionWithMojoTest, MojoService) {
   ServiceWorkerStatusCode status = SERVICE_WORKER_ERROR_NETWORK;  // dummy value
 
   version_->SetStatus(ServiceWorkerVersion::ACTIVATED);
   version_->StartWorker(ServiceWorkerMetrics::EventType::SYNC,
                         CreateReceiverOnCurrentThread(&status));
   base::RunLoop().RunUntilIdle();
   EXPECT_EQ(SERVICE_WORKER_OK, status);
   EXPECT_EQ(EmbeddedWorkerStatus::RUNNING, version_->running_status());
 
   scoped_refptr<MessageLoopRunner> runner(new MessageLoopRunner);
   int request_id = version_->StartRequest(
       ServiceWorkerMetrics::EventType::SYNC,
       CreateReceiverOnCurrentThread(&status, runner->QuitClosure()));
   base::WeakPtr<mojom::TestMojoService> service =
       version_->GetMojoServiceForRequest<mojom::TestMojoService>(request_id);
   service->DoSomething(runner->QuitClosure());
   runner->Run();
 
   // Mojo service does exist in worker, so error callback should not have been
   // called and FinishRequest should return true.
   EXPECT_EQ(SERVICE_WORKER_OK, status);
-  EXPECT_TRUE(version_->FinishRequest(request_id, true));
+  EXPECT_TRUE(version_->FinishRequest(request_id, true /* was_handled */,
+                                      base::Time::Now()));
 }
 
 TEST_F(ServiceWorkerVersionTest, NonExistentMojoService) {
   ServiceWorkerStatusCode status = SERVICE_WORKER_ERROR_NETWORK;  // dummy value
 
   version_->SetStatus(ServiceWorkerVersion::ACTIVATED);
   version_->StartWorker(ServiceWorkerMetrics::EventType::SYNC,
                         CreateReceiverOnCurrentThread(&status));
   base::RunLoop().RunUntilIdle();
   EXPECT_EQ(SERVICE_WORKER_OK, status);
   EXPECT_EQ(EmbeddedWorkerStatus::RUNNING, version_->running_status());
 
   scoped_refptr<MessageLoopRunner> runner(new MessageLoopRunner);
   int request_id = version_->StartRequest(
       ServiceWorkerMetrics::EventType::SYNC,
       CreateReceiverOnCurrentThread(&status, runner->QuitClosure()));
   base::WeakPtr<mojom::TestMojoService> service =
       version_->GetMojoServiceForRequest<mojom::TestMojoService>(request_id);
   service->DoSomething(runner->QuitClosure());
   runner->Run();
 
   // Mojo service doesn't exist in worker, so error callback should have been
   // called and FinishRequest should return false.
   EXPECT_EQ(SERVICE_WORKER_ERROR_FAILED, status);
-  EXPECT_FALSE(version_->FinishRequest(request_id, true));
+  EXPECT_FALSE(version_->FinishRequest(request_id, true /* was_handled */,
+                                       base::Time::Now()));
 }
 
 TEST_F(ServiceWorkerVersionTest, DispatchEvent) {
   ServiceWorkerStatusCode status = SERVICE_WORKER_ERROR_NETWORK;  // dummy value
 
   // Activate and start worker.
   version_->SetStatus(ServiceWorkerVersion::ACTIVATED);
   version_->StartWorker(ServiceWorkerMetrics::EventType::SYNC,
                         CreateReceiverOnCurrentThread(&status));
   base::RunLoop().RunUntilIdle();
@@ skipping 24 matching lines @@
       version_->embedded_worker()->embedded_worker_id(), request_id, reply);
   runner->Run();
 
   // Verify message callback got called with correct reply.
   EXPECT_EQ(request_id, received_request_id);
   EXPECT_EQ(reply, received_data);
 
   // Should not have timed out, so error callback should not have been
   // called and FinishRequest should return true.
   EXPECT_EQ(SERVICE_WORKER_OK, status);
-  EXPECT_TRUE(version_->FinishRequest(request_id, true));
+  EXPECT_TRUE(version_->FinishRequest(request_id, true /* was_handled */,
+                                      base::Time::Now()));
 }
 
 TEST_F(ServiceWorkerFailToStartTest, FailingWorkerUsesNewRendererProcess) {
   ServiceWorkerStatusCode status = SERVICE_WORKER_ERROR_MAX_VALUE;
 
   helper_->SimulateAddProcessToPattern(pattern_,
                                        helper_->new_render_process_id());
   ServiceWorkerContextCore* context = helper_->context();
   int64_t id = version_->version_id();
   version_->SetStatus(ServiceWorkerVersion::ACTIVATED);
@@ skipping 125 matching lines @@
   std::string reply2("foobar");
   helper_->SimulateSendEventResult(
       version_->embedded_worker()->embedded_worker_id(), request_id2, reply2);
   runner2->Run();
 
   // Verify correct message callback got called with correct reply.
   EXPECT_EQ(0, received_request_id1);
   EXPECT_EQ(request_id2, received_request_id2);
   EXPECT_EQ(reply2, received_data2);
   EXPECT_EQ(SERVICE_WORKER_OK, status2);
-  EXPECT_TRUE(version_->FinishRequest(request_id2, true));
+  EXPECT_TRUE(version_->FinishRequest(request_id2, true /* was_handled */,
+                                      base::Time::Now()));
 
   // Reply to first event.
   std::string reply1("hello world");
   helper_->SimulateSendEventResult(
       version_->embedded_worker()->embedded_worker_id(), request_id1, reply1);
   runner1->Run();
 
   // Verify correct response was received.
   EXPECT_EQ(request_id1, received_request_id1);
   EXPECT_EQ(request_id2, received_request_id2);
   EXPECT_EQ(reply1, received_data1);
   EXPECT_EQ(SERVICE_WORKER_OK, status1);
-  EXPECT_TRUE(version_->FinishRequest(request_id1, true));
+  EXPECT_TRUE(version_->FinishRequest(request_id1, true /* was_handled */,
+                                      base::Time::Now()));
 }
 
 TEST_F(ServiceWorkerVersionTest, DispatchSimpleEvent_Completed) {
   ServiceWorkerStatusCode status =
       SERVICE_WORKER_ERROR_MAX_VALUE;  // dummy value
 
   // Activate and start worker.
   version_->SetStatus(ServiceWorkerVersion::ACTIVATED);
   version_->StartWorker(ServiceWorkerMetrics::EventType::SYNC,
                         CreateReceiverOnCurrentThread(&status));
@@ skipping 12 matching lines @@
 
   // Verify event got dispatched to worker.
   base::RunLoop().RunUntilIdle();
   ASSERT_EQ(1u, helper_->inner_ipc_sink()->message_count());
   const IPC::Message* msg = helper_->inner_ipc_sink()->GetMessageAt(0);
   EXPECT_EQ(TestMsg_TestEvent::ID, msg->type());
 
   // Simulate sending reply to event.
   helper_->SimulateSendSimpleEventResult(
       version_->embedded_worker()->embedded_worker_id(), request_id,
-      blink::WebServiceWorkerEventResultCompleted);
+      blink::WebServiceWorkerEventResultCompleted, base::Time::Now());
   runner->Run();
 
   // Verify callback was called with correct status.
   EXPECT_EQ(SERVICE_WORKER_OK, status);
 }
 
 TEST_F(ServiceWorkerVersionTest, DispatchSimpleEvent_Rejected) {
   ServiceWorkerStatusCode status =
       SERVICE_WORKER_ERROR_MAX_VALUE;  // dummy value
 
@@ skipping 16 matching lines @@
 
   // Verify event got dispatched to worker.
   base::RunLoop().RunUntilIdle();
   ASSERT_EQ(1u, helper_->inner_ipc_sink()->message_count());
   const IPC::Message* msg = helper_->inner_ipc_sink()->GetMessageAt(0);
   EXPECT_EQ(TestMsg_TestEvent::ID, msg->type());
 
   // Simulate sending reply to event.
   helper_->SimulateSendSimpleEventResult(
       version_->embedded_worker()->embedded_worker_id(), request_id,
-      blink::WebServiceWorkerEventResultRejected);
+      blink::WebServiceWorkerEventResultRejected, base::Time::Now());
   runner->Run();
 
   // Verify callback was called with correct status.
   EXPECT_EQ(SERVICE_WORKER_ERROR_EVENT_WAITUNTIL_REJECTED, status);
 }
 
 TEST_F(ServiceWorkerVersionTest, DispatchEvent_MultipleResponse) {
   ServiceWorkerStatusCode status = SERVICE_WORKER_ERROR_MAX_VALUE;
 
   // Activate and start worker.
@@ skipping 49 matching lines @@
       version_->embedded_worker()->embedded_worker_id(), request_id2, reply2);
   runner->Run();
 
   // Verify message callback got called with correct reply.
   EXPECT_EQ(request_id2, received_request_id2);
   EXPECT_EQ(reply2, received_data2);
 
   // Should not have timed out, so error callback should not have been
   // called and FinishRequest should return true.
   EXPECT_EQ(SERVICE_WORKER_OK, status);
-  EXPECT_TRUE(version_->FinishRequest(request_id1, true));
-  EXPECT_TRUE(version_->FinishRequest(request_id2, true));
+  EXPECT_TRUE(version_->FinishRequest(request_id1, true /* was_handled */,
+                                      base::Time::Now()));
+  EXPECT_TRUE(version_->FinishRequest(request_id2, true /* was_handled */,
+                                      base::Time::Now()));
 }
 
 class ServiceWorkerNavigationHintUMATest : public ServiceWorkerVersionTest {
  protected:
   ServiceWorkerNavigationHintUMATest() : ServiceWorkerVersionTest() {}
 
   void StartWorker(ServiceWorkerMetrics::EventType purpose) {
     ServiceWorkerStatusCode status = SERVICE_WORKER_ERROR_MAX_VALUE;
     version_->StartWorker(purpose, CreateReceiverOnCurrentThread(&status));
     base::RunLoop().RunUntilIdle();
@@ skipping 136 matching lines @@
   histogram_tester_.ExpectTotalCount(kLinkMouseDown, 1);
   histogram_tester_.ExpectTotalCount(kLinkTapDown, 0);
   EXPECT_EQ(SERVICE_WORKER_OK, status);
   StopWorker();
   // The UMA for kLinkMouseDown must be recorded when the worker stopped.
   histogram_tester_.ExpectTotalCount(kLinkMouseDown, 1);
   histogram_tester_.ExpectTotalCount(kLinkTapDown, 1);
 }
 
 }  // namespace content