File: event_ack_data.cc

package info (click to toggle)
chromium 138.0.7204.183-1
  • links: PTS, VCS
  • area: main
  • in suites: trixie
  • size: 6,071,908 kB
  • sloc: cpp: 34,937,088; ansic: 7,176,967; javascript: 4,110,704; python: 1,419,953; asm: 946,768; xml: 739,971; pascal: 187,324; sh: 89,623; perl: 88,663; objc: 79,944; sql: 50,304; cs: 41,786; fortran: 24,137; makefile: 21,806; php: 13,980; tcl: 13,166; yacc: 8,925; ruby: 7,485; awk: 3,720; lisp: 3,096; lex: 1,327; ada: 727; jsp: 228; sed: 36
file content (248 lines) | stat: -rw-r--r-- 10,073 bytes parent folder | download | duplicates (6)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
// Copyright 2018 The Chromium Authors
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "extensions/browser/events/event_ack_data.h"

#include <string>
#include <utility>

#include "base/containers/map_util.h"
#include "base/functional/bind.h"
#include "base/functional/callback.h"
#include "base/metrics/histogram_functions.h"
#include "base/uuid.h"
#include "content/public/browser/browser_task_traits.h"
#include "content/public/browser/browser_thread.h"
#include "content/public/browser/service_worker_context.h"
#include "content/public/browser/service_worker_external_request_result.h"
#include "extensions/browser/event_router.h"
#include "extensions/browser/extension_event_histogram_value.h"

namespace extensions {

EventAckData::EventInfo::EventInfo(
    const base::Uuid& request_uuid,
    int render_process_id,
    bool start_ok,
    content::ServiceWorkerExternalRequestResult external_request_result,
    base::TimeTicks dispatch_start_time,
    EventDispatchSource dispatch_source,
    bool lazy_background_active_on_dispatch,
    const events::HistogramValue histogram_value)
    : request_uuid(request_uuid),
      render_process_id(render_process_id),
      start_ok(start_ok),
      external_request_result(external_request_result),
      dispatch_start_time(dispatch_start_time),
      dispatch_source(dispatch_source),
      lazy_background_active_on_dispatch(lazy_background_active_on_dispatch),
      histogram_value(histogram_value) {}

EventAckData::EventInfo::EventInfo(EventInfo&& other) = default;

EventAckData::EventAckData() = default;

EventAckData::~EventAckData() = default;

void EventAckData::IncrementInflightEvent(
    content::ServiceWorkerContext* context,
    int render_process_id,
    int64_t version_id,
    int event_id,
    base::TimeTicks dispatch_start_time,
    EventDispatchSource dispatch_source,
    bool lazy_background_active_on_dispatch,
    events::HistogramValue histogram_value) {
  DCHECK_CURRENTLY_ON(content::BrowserThread::UI);

  base::Uuid request_uuid = base::Uuid::GenerateRandomV4();
  bool start_ok = true;

  content::ServiceWorkerExternalRequestResult external_request_result =
      context->StartingExternalRequest(
          version_id,
          content::ServiceWorkerExternalRequestTimeoutType::kDefault,
          request_uuid);
  base::UmaHistogramEnumeration(
      "Extensions.ServiceWorkerBackground.StartingExternalRequest_Result",
      external_request_result);
  if (external_request_result !=
      content::ServiceWorkerExternalRequestResult::kOk) {
    LOG(ERROR) << "StartExternalRequest failed: "
               << static_cast<int>(external_request_result);
    start_ok = false;
  }

  auto insert_result = unacked_events_.try_emplace(
      event_id,
      EventInfo{request_uuid, render_process_id, start_ok,
                external_request_result, dispatch_start_time, dispatch_source,
                lazy_background_active_on_dispatch, histogram_value});
  DCHECK(insert_result.second) << "EventAckData: Duplicate event_id.";

  if (dispatch_source == EventDispatchSource::kDispatchEventToProcess) {
    base::SingleThreadTaskRunner::GetCurrentDefault()->PostDelayedTask(
        FROM_HERE,
        base::BindOnce(&EventAckData::EmitLateAckedEventTask,
                       weak_factory_.GetWeakPtr(), event_id),
        kEventAckMetricTimeLimit);
  }
}

void EventAckData::EmitLateAckedEventTask(int event_id) {
  // If the event is still present then we haven't received the ack yet in
  // `EventAckData::DecrementInflightEvent()`.
  if (auto* value = base::FindOrNull(unacked_events_, event_id)) {
    base::UmaHistogramBoolean(
        "Extensions.Events.DidDispatchToAckSucceed.ExtensionServiceWorker3",
        false);
    EmitLateAckedEventTaskMetrics(*value);
  }
}

// Emit metrics helpful in determining causes of `unacked_events_` that are not
// acked within the timeout.
void EventAckData::EmitLateAckedEventTaskMetrics(const EventInfo& event_info) {
  base::UmaHistogramEnumeration(
      "Extensions.Events.ServiceWorkerDispatchFailed.Event",
      event_info.histogram_value, events::ENUM_BOUNDARY);

  base::UmaHistogramBoolean(
      "Extensions.Events.ServiceWorkerDispatchFailed.StartExternalRequestOk",
      event_info.start_ok);
  if (!event_info.start_ok) {
    base::UmaHistogramEnumeration(
        "Extensions.Events.ServiceWorkerDispatchFailed."
        "StartExternalRequestResult",
        event_info.external_request_result);
  }

  // TODO(crbug.com/40909770): Implement service worker running status as a late
  // acked event metric when it can be more accurately determined. For example,
  // it could be useful to determine if the late acked events are for already
  // shut down workers and therefore wouldn't be "late".
}

// static
void EventAckData::EmitDispatchTimeMetrics(EventInfo& event_info) {
  // Only emit events that use the EventRouter::DispatchEventToProcess() event
  // routing flow since EventRouter::DispatchEventToSender() uses a different
  // flow that doesn't include dispatch start and service worker start time.
  if (event_info.dispatch_source ==
      EventDispatchSource::kDispatchEventToProcess) {
    base::UmaHistogramCustomMicrosecondsTimes(
        "Extensions.Events.DispatchToAckTime.ExtensionServiceWorker2",
        /*sample=*/base::TimeTicks::Now() - event_info.dispatch_start_time,
        /*min=*/base::Microseconds(1), /*max=*/base::Minutes(5),
        /*buckets=*/100);
    const char* active_metric_name =
        event_info.lazy_background_active_on_dispatch
            ? "Extensions.Events.DispatchToAckTime.ExtensionServiceWorker2."
              "Active3"
            : "Extensions.Events.DispatchToAckTime.ExtensionServiceWorker2."
              "Inactive3";
    base::UmaHistogramCustomMicrosecondsTimes(
        active_metric_name,
        /*sample=*/base::TimeTicks::Now() - event_info.dispatch_start_time,
        /*min=*/base::Microseconds(1), /*max=*/base::Minutes(5),
        /*buckets=*/100);

    base::UmaHistogramCustomTimes(
        "Extensions.Events.DispatchToAckLongTime.ExtensionServiceWorker2",
        /*sample=*/base::TimeTicks::Now() - event_info.dispatch_start_time,
        /*min=*/base::Seconds(1), /*max=*/base::Days(1),
        /*buckets=*/100);

    // Emit only if we're within the expected event ack time limit. We'll take
    // care of the emit for a late ack via a delayed task.
    bool late_ack = (base::TimeTicks::Now() - event_info.dispatch_start_time) >
                    kEventAckMetricTimeLimit;
    if (!late_ack) {
      base::UmaHistogramBoolean(
          "Extensions.Events.DidDispatchToAckSucceed.ExtensionServiceWorker3",
          true);
    }
  }
}

void EventAckData::DecrementInflightEvent(
    content::ServiceWorkerContext* context,
    int render_process_id,
    int64_t version_id,
    int event_id,
    bool worker_stopped,
    base::OnceClosure failure_callback) {
  DCHECK_CURRENTLY_ON(content::BrowserThread::UI);

  auto request_info_iter = unacked_events_.find(event_id);
  if (request_info_iter == unacked_events_.end() ||
      request_info_iter->second.render_process_id != render_process_id) {
    std::move(failure_callback).Run();
    return;
  }

  EventInfo& event_info = request_info_iter->second;

  EmitDispatchTimeMetrics(event_info);

  base::Uuid request_uuid = std::move(event_info.request_uuid);
  bool start_ok = event_info.start_ok;
  unacked_events_.erase(request_info_iter);

  content::ServiceWorkerExternalRequestResult result =
      context->FinishedExternalRequest(version_id, request_uuid);
  base::UmaHistogramEnumeration(
      "Extensions.ServiceWorkerBackground.FinishedExternalRequest_Result",
      result);
  // If the worker was already stopped or StartExternalRequest didn't succeed,
  // the FinishedExternalRequest will legitimately fail.
  if (worker_stopped || !start_ok) {
    return;
  }

  base::UmaHistogramEnumeration(
      "Extensions.ServiceWorkerBackground.FinishedExternalRequest_Result_"
      "PostReturn",
      result);

  switch (result) {
    case content::ServiceWorkerExternalRequestResult::kOk:
    // Metrics have shown us that it is possible that a worker may not be found
    // or not running at this point.
    case content::ServiceWorkerExternalRequestResult::kWorkerNotFound:
    case content::ServiceWorkerExternalRequestResult::kWorkerNotRunning:
    // Null context can happen in the rare case if ServiceWorkerContextCore is
    // torn down when EventRouter + BrowserContext are still alive and an
    // event happens to be acked here.
    case content::ServiceWorkerExternalRequestResult::kNullContext:
      // TODO(crbug.com/41494056): Perform more graceful shutdown when
      // ServiceWorkerContextCore is torn down.

    // kBadRequestId can expectedly happen if a new instance of a worker starts
    // while an ack for the previous worker is in-flight to the browser. We then
    // receive the ack and ServiceWorkerContext can't find the
    // external/in-flight request because the previous worker's
    // `ServiceWorkerVersion` has been replaced by the new worker's
    // `ServiceWorkerVersion`. The new version then does not have a record of
    // the external/in-flight request and returns kBadRequestId.
    case content::ServiceWorkerExternalRequestResult::kBadRequestId:
      // TODO(crbug.com/40072982): Reliably detect when the above occurs and
      // continue to not kill the renderer. But if the event is not for an old
      // instance of the worker then consider CHECK()-ing since this could
      // indicate a bug in the tracking of external requests in the browser.
      break;
  }
}

void EventAckData::ClearUnackedEventsForRenderProcess(int render_process_id) {
  std::erase_if(unacked_events_, [render_process_id](const auto& entry) {
    return entry.second.render_process_id == render_process_id;
  });
}

bool EventAckData::HasUnackedEventForTesting(int event_id) {
  return base::FindOrNull(unacked_events_, event_id);
}

}  // namespace extensions