1 // Copyright 2023 The Chromium Authors
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 #include "base/metrics/statistics_recorder.h"
6
7 #include <atomic>
8
9 #include "base/containers/span.h"
10 #include "base/logging.h"
11 #include "base/metrics/histogram_functions.h"
12 #include "base/metrics/persistent_histogram_allocator.h"
13 #include "base/strings/strcat.h"
14 #include "base/strings/string_number_conversions.h"
15 #include "base/strings/string_util.h"
16 #include "base/threading/platform_thread.h"
17 #include "base/threading/simple_thread.h"
18 #include "base/time/time.h"
19 #include "build/build_config.h"
20 #include "testing/gtest/include/gtest/gtest.h"
21
22 namespace base {
23
24 namespace {
25
26 constexpr TimeDelta kTestRunningTime = Seconds(5);
27 constexpr char kHistogramNamePrefix[] = "SRStarvationTest.";
28
29 class BaseThread : public SimpleThread {
30 public:
BaseThread(const std::string & thread_name)31 explicit BaseThread(const std::string& thread_name)
32 : SimpleThread(thread_name, Options()), thread_name_(thread_name) {}
33
34 BaseThread(const BaseThread&) = delete;
35 BaseThread& operator=(const BaseThread&) = delete;
36
37 ~BaseThread() override = default;
38
thread_name()39 const std::string& thread_name() { return thread_name_; }
SetStartTime()40 void SetStartTime() { start_time_ = Time::Now(); }
ShouldStop()41 bool ShouldStop() { return stop_.load(std::memory_order_relaxed); }
Stop()42 void Stop() {
43 stop_.store(true, std::memory_order_relaxed);
44 end_time_ = Time::Now();
45 }
IncrementIterCount()46 void IncrementIterCount() { ++iter_count_; }
iter_count()47 size_t iter_count() { return iter_count_; }
running_time()48 TimeDelta running_time() { return end_time_ - start_time_; }
average_time_per_iter()49 TimeDelta average_time_per_iter() { return running_time() / iter_count_; }
50
51 private:
52 std::string thread_name_;
53 std::atomic<bool> stop_ = false;
54 size_t iter_count_ = 0;
55 Time start_time_;
56 Time end_time_;
57 };
58
59 class ReadThread : public BaseThread {
60 public:
ReadThread(size_t id)61 explicit ReadThread(size_t id)
62 : BaseThread(/*thread_name=*/StrCat({"ReadThread", NumberToString(id)})) {
63 }
64
Run()65 void Run() override {
66 SetStartTime();
67
68 const std::string histogram_name =
69 StrCat({kHistogramNamePrefix, "ReadThreadHistogram"});
70 while (!ShouldStop()) {
71 // Continuously emit to the same histogram. Because this histogram should
72 // already exist within the StatisticsRecorder's internal map (except the
73 // first time this is called), it should not cause any modifications to
74 // it, only a lookup. In other words, it will call
75 // StatisticsRecorder::FindHistogram().
76 UmaHistogramBoolean(histogram_name, false);
77 IncrementIterCount();
78 }
79 }
80 };
81
82 class WriteThread : public BaseThread {
83 public:
WriteThread(size_t id)84 explicit WriteThread(size_t id)
85 : BaseThread(
86 /*thread_name=*/StrCat({"WriteThread", NumberToString(id)})) {}
87
Run()88 void Run() override {
89 SetStartTime();
90
91 const std::string base_name =
92 StrCat({kHistogramNamePrefix, thread_name(), ".Iteration"});
93 while (!ShouldStop()) {
94 // Continuously emit to a new histogram. Because this histogram should not
95 // exist within the StatisticsRecorder's internal map, it will cause an
96 // insertion to it every time. In other words, it will call
97 // StatisticsRecorder::RegisterOrDeleteDuplicate().
98 UmaHistogramBoolean(StrCat({base_name, NumberToString(iter_count())}),
99 false);
100 IncrementIterCount();
101 }
102 }
103 };
104
105 } // namespace
106
107 // Determines the number of reader and writer threads to run in the test.
108 struct StarvationTestParams {
109 size_t num_read_threads;
110 size_t num_write_threads;
111 };
112
113 // Determines which threads should start running first.
114 enum class FirstThreadsToStart {
115 kReaders,
116 kWriters,
117 };
118
119 class StatisticsRecorderStarvationTest
120 : public testing::TestWithParam<
121 std::tuple<StarvationTestParams, FirstThreadsToStart>> {
122 public:
123 StatisticsRecorderStarvationTest() = default;
124
125 StatisticsRecorderStarvationTest(const StatisticsRecorderStarvationTest&) =
126 delete;
127 StatisticsRecorderStarvationTest& operator=(
128 const StatisticsRecorderStarvationTest&) = delete;
129
130 ~StatisticsRecorderStarvationTest() override = default;
131
SetUp()132 void SetUp() override {
133 // Create a new StatisticsRecorder so that this test run will not affect
134 // future ones. In particular, this test relies on creating new histograms
135 // and adding them to the SR.
136 sr_ = StatisticsRecorder::CreateTemporaryForTesting();
137
138 // Emit a bunch of histograms, which will add them to the SR's internal
139 // histogram map. This is so that lookups and insertions (FindHistogram()
140 // and RegisterOrDeleteDuplicate()) during the test don't complete (pretty
141 // much) instantly.
142 for (size_t i = 0; i < 10000; ++i) {
143 UmaHistogramBoolean(
144 StrCat({kHistogramNamePrefix, "Dummy", NumberToString(i)}), false);
145 }
146 }
147
TearDown()148 void TearDown() override {
149 // Clean up histograms that were allocated during this test. Note that the
150 // histogram objects are deleted after releasing the temporary `sr_`.
151 // Otherwise, for a brief moment, the temporary `sr_` would be holding
152 // dangling pointers.
153 auto histograms = sr_->GetHistograms();
154 sr_.reset();
155 for (auto* histogram : histograms) {
156 if (StartsWith(histogram->histogram_name(), kHistogramNamePrefix)) {
157 delete histogram;
158 }
159 }
160 }
161
162 // Starts reader and writer threads.
StartThreads()163 void StartThreads() {
164 for (size_t i = 0; i < num_read_threads(); ++i) {
165 read_threads_.emplace_back(std::make_unique<ReadThread>(/*id=*/i));
166 }
167 for (size_t i = 0; i < num_write_threads(); ++i) {
168 write_threads_.emplace_back(std::make_unique<WriteThread>(/*id=*/i));
169 }
170
171 // Depending on the value of GetFirstThreadsToStart(), either start the
172 // readers or the writers first. Because some implementations will give
173 // priority to whatever managed to get the lock first, do this to have
174 // coverage.
175 span<std::unique_ptr<BaseThread>> start_first_threads;
176 span<std::unique_ptr<BaseThread>> start_second_threads;
177 switch (GetFirstThreadsToStart()) {
178 case FirstThreadsToStart::kReaders:
179 start_first_threads = read_threads_;
180 start_second_threads = write_threads_;
181 break;
182 case FirstThreadsToStart::kWriters:
183 start_first_threads = write_threads_;
184 start_second_threads = read_threads_;
185 break;
186 }
187 for (auto& thread : start_first_threads) {
188 thread->Start();
189 }
190 PlatformThread::Sleep(Milliseconds(100));
191 for (auto& thread : start_second_threads) {
192 thread->Start();
193 }
194 }
195
196 // Stops reader and writer threads.
StopThreads()197 void StopThreads() {
198 for (auto* thread : GetAllThreads()) {
199 thread->Stop();
200 thread->Join();
201 }
202 }
203
GetAllThreads()204 std::vector<BaseThread*> GetAllThreads() {
205 std::vector<BaseThread*> threads;
206 threads.reserve(num_read_threads() + num_write_threads());
207 for (auto& read_thread : read_threads_) {
208 threads.push_back(read_thread.get());
209 }
210 for (auto& write_thread : write_threads_) {
211 threads.push_back(write_thread.get());
212 }
213 return threads;
214 }
215
num_read_threads()216 size_t num_read_threads() { return std::get<0>(GetParam()).num_read_threads; }
217
num_write_threads()218 size_t num_write_threads() {
219 return std::get<0>(GetParam()).num_write_threads;
220 }
221
GetFirstThreadsToStart()222 FirstThreadsToStart GetFirstThreadsToStart() {
223 return std::get<1>(GetParam());
224 }
225
226 protected:
227 std::vector<std::unique_ptr<BaseThread>> read_threads_;
228 std::vector<std::unique_ptr<BaseThread>> write_threads_;
229
230 private:
231 std::unique_ptr<StatisticsRecorder> sr_;
232 };
233
234 // Verifies that there are no starvation issues when emitting histograms (since
235 // it may be done from any thread). In particular, emitting a histogram requires
236 // a lock to look up (and sometimes write to) an internal map in the
237 // StatisticsRecorder. When switching to a Read/Write lock (see crbug/1123627),
238 // we encountered such a starvation issue, where a thread trying to write to the
239 // internal map was starved out for 10+ seconds by readers on iOS.
240 // TODO(crbug.com/1516818): StatisticsRecorderNoStarvation continuously emits a
241 // new histogram which can cause the app memory footprint to grow unbounded and
242 // watchdog kill the unit test on iOS devices.
TEST_P(StatisticsRecorderStarvationTest,StatisticsRecorderNoStarvation)243 TEST_P(StatisticsRecorderStarvationTest, StatisticsRecorderNoStarvation) {
244 // Make sure there is no GlobalHistogramAllocator so that histograms emitted
245 // during this test are all allocated on the heap, which makes it a lot easier
246 // to clean them up at the end.
247 ASSERT_FALSE(GlobalHistogramAllocator::Get());
248
249 // Start reader and writer threads.
250 StartThreads();
251
252 // Let the test run for |kTestRunningTime|.
253 PlatformThread::Sleep(kTestRunningTime);
254
255 // Stop reader and writer threads. This waits for them to complete by joining
256 // the threads.
257 StopThreads();
258
259 // Verify that on average, on each thread, performing a read or write took
260 // less than 1ms. There is no meaning to 50ms -- this is just to ensure that
261 // there is no egregious starvation effect (for example, we've seen crash
262 // reports where readers were starving out writers for >10 seconds). Note that
263 // the average time it took to perform one iteration is:
264 // average_time_per_iteration = running_time / iteration_count.
265 static constexpr TimeDelta kStarvationThreshold = Milliseconds(50);
266 std::vector<BaseThread*> threads = GetAllThreads();
267 for (auto* thread : threads) {
268 EXPECT_LT(thread->average_time_per_iter(), kStarvationThreshold);
269 }
270
271 // Print some useful information that could come in handy if this test fails
272 // (or for diagnostic purposes).
273 LOG(INFO) << "Params: num_read_threads=" << num_read_threads()
274 << ", num_write_threads=" << num_write_threads()
275 << ", FirstThreadsToStart="
276 << static_cast<int>(GetFirstThreadsToStart());
277 for (auto* thread : threads) {
278 LOG(INFO) << thread->thread_name() << " iter_count=" << thread->iter_count()
279 << ", running_time=" << thread->running_time()
280 << ", average_time_per_iter=" << thread->average_time_per_iter();
281 }
282 }
283
284 INSTANTIATE_TEST_SUITE_P(
285 All,
286 StatisticsRecorderStarvationTest,
287 testing::Combine(
288 testing::Values(StarvationTestParams{.num_read_threads = 10,
289 .num_write_threads = 1},
290 StarvationTestParams{.num_read_threads = 1,
291 .num_write_threads = 10},
292 StarvationTestParams{.num_read_threads = 1,
293 .num_write_threads = 1},
294 StarvationTestParams{.num_read_threads = 5,
295 .num_write_threads = 5}),
296 testing::Values(FirstThreadsToStart::kReaders,
297 FirstThreadsToStart::kWriters)));
298
299 } // namespace base
300