1 // Copyright (c) 2011-present, Facebook, Inc. All rights reserved.
2 // This source code is licensed under both the GPLv2 (found in the
3 // COPYING file in the root directory) and Apache 2.0 License
4 // (found in the LICENSE.Apache file in the root directory).
5 //
6 #include <algorithm>
7 #include <iostream>
8 #include <thread>
9 #include <vector>
10
11 #include "monitoring/histogram.h"
12 #include "monitoring/instrumented_mutex.h"
13 #include "monitoring/perf_context_imp.h"
14 #include "monitoring/thread_status_util.h"
15 #include "port/port.h"
16 #include "rocksdb/db.h"
17 #include "rocksdb/memtablerep.h"
18 #include "rocksdb/perf_context.h"
19 #include "rocksdb/slice_transform.h"
20 #include "test_util/testharness.h"
21 #include "util/stop_watch.h"
22 #include "util/string_util.h"
23 #include "utilities/merge_operators.h"
24
25 bool FLAGS_random_key = false;
26 bool FLAGS_use_set_based_memetable = false;
27 int FLAGS_total_keys = 100;
28 int FLAGS_write_buffer_size = 1000000000;
29 int FLAGS_max_write_buffer_number = 8;
30 int FLAGS_min_write_buffer_number_to_merge = 7;
31 bool FLAGS_verbose = false;
32
33 // Path to the database on file system
34 const std::string kDbName =
35 ROCKSDB_NAMESPACE::test::PerThreadDBPath("perf_context_test");
36
37 namespace ROCKSDB_NAMESPACE {
38
OpenDb(bool read_only=false)39 std::shared_ptr<DB> OpenDb(bool read_only = false) {
40 DB* db;
41 Options options;
42 options.create_if_missing = true;
43 options.max_open_files = -1;
44 options.write_buffer_size = FLAGS_write_buffer_size;
45 options.max_write_buffer_number = FLAGS_max_write_buffer_number;
46 options.min_write_buffer_number_to_merge =
47 FLAGS_min_write_buffer_number_to_merge;
48
49 if (FLAGS_use_set_based_memetable) {
50 #ifndef ROCKSDB_LITE
51 options.prefix_extractor.reset(
52 ROCKSDB_NAMESPACE::NewFixedPrefixTransform(0));
53 options.memtable_factory.reset(NewHashSkipListRepFactory());
54 #endif // ROCKSDB_LITE
55 }
56
57 Status s;
58 if (!read_only) {
59 s = DB::Open(options, kDbName, &db);
60 } else {
61 s = DB::OpenForReadOnly(options, kDbName, &db);
62 }
63 EXPECT_OK(s);
64 return std::shared_ptr<DB>(db);
65 }
66
67 class PerfContextTest : public testing::Test {};
68
TEST_F(PerfContextTest,SeekIntoDeletion)69 TEST_F(PerfContextTest, SeekIntoDeletion) {
70 DestroyDB(kDbName, Options());
71 auto db = OpenDb();
72 WriteOptions write_options;
73 ReadOptions read_options;
74
75 for (int i = 0; i < FLAGS_total_keys; ++i) {
76 std::string key = "k" + ToString(i);
77 std::string value = "v" + ToString(i);
78
79 db->Put(write_options, key, value);
80 }
81
82 for (int i = 0; i < FLAGS_total_keys -1 ; ++i) {
83 std::string key = "k" + ToString(i);
84 db->Delete(write_options, key);
85 }
86
87 HistogramImpl hist_get;
88 HistogramImpl hist_get_time;
89 for (int i = 0; i < FLAGS_total_keys - 1; ++i) {
90 std::string key = "k" + ToString(i);
91 std::string value;
92
93 get_perf_context()->Reset();
94 StopWatchNano timer(Env::Default());
95 timer.Start();
96 auto status = db->Get(read_options, key, &value);
97 auto elapsed_nanos = timer.ElapsedNanos();
98 ASSERT_TRUE(status.IsNotFound());
99 hist_get.Add(get_perf_context()->user_key_comparison_count);
100 hist_get_time.Add(elapsed_nanos);
101 }
102
103 if (FLAGS_verbose) {
104 std::cout << "Get user key comparison: \n" << hist_get.ToString()
105 << "Get time: \n" << hist_get_time.ToString();
106 }
107
108 {
109 HistogramImpl hist_seek_to_first;
110 std::unique_ptr<Iterator> iter(db->NewIterator(read_options));
111
112 get_perf_context()->Reset();
113 StopWatchNano timer(Env::Default(), true);
114 iter->SeekToFirst();
115 hist_seek_to_first.Add(get_perf_context()->user_key_comparison_count);
116 auto elapsed_nanos = timer.ElapsedNanos();
117
118 if (FLAGS_verbose) {
119 std::cout << "SeekToFirst uesr key comparison: \n"
120 << hist_seek_to_first.ToString()
121 << "ikey skipped: " << get_perf_context()->internal_key_skipped_count
122 << "\n"
123 << "idelete skipped: "
124 << get_perf_context()->internal_delete_skipped_count << "\n"
125 << "elapsed: " << elapsed_nanos << "\n";
126 }
127 }
128
129 HistogramImpl hist_seek;
130 for (int i = 0; i < FLAGS_total_keys; ++i) {
131 std::unique_ptr<Iterator> iter(db->NewIterator(read_options));
132 std::string key = "k" + ToString(i);
133
134 get_perf_context()->Reset();
135 StopWatchNano timer(Env::Default(), true);
136 iter->Seek(key);
137 auto elapsed_nanos = timer.ElapsedNanos();
138 hist_seek.Add(get_perf_context()->user_key_comparison_count);
139 if (FLAGS_verbose) {
140 std::cout << "seek cmp: " << get_perf_context()->user_key_comparison_count
141 << " ikey skipped " << get_perf_context()->internal_key_skipped_count
142 << " idelete skipped "
143 << get_perf_context()->internal_delete_skipped_count
144 << " elapsed: " << elapsed_nanos << "ns\n";
145 }
146
147 get_perf_context()->Reset();
148 ASSERT_TRUE(iter->Valid());
149 StopWatchNano timer2(Env::Default(), true);
150 iter->Next();
151 auto elapsed_nanos2 = timer2.ElapsedNanos();
152 if (FLAGS_verbose) {
153 std::cout << "next cmp: " << get_perf_context()->user_key_comparison_count
154 << "elapsed: " << elapsed_nanos2 << "ns\n";
155 }
156 }
157
158 if (FLAGS_verbose) {
159 std::cout << "Seek uesr key comparison: \n" << hist_seek.ToString();
160 }
161 }
162
TEST_F(PerfContextTest,StopWatchNanoOverhead)163 TEST_F(PerfContextTest, StopWatchNanoOverhead) {
164 // profile the timer cost by itself!
165 const int kTotalIterations = 1000000;
166 std::vector<uint64_t> timings(kTotalIterations);
167
168 StopWatchNano timer(Env::Default(), true);
169 for (auto& timing : timings) {
170 timing = timer.ElapsedNanos(true /* reset */);
171 }
172
173 HistogramImpl histogram;
174 for (const auto timing : timings) {
175 histogram.Add(timing);
176 }
177
178 if (FLAGS_verbose) {
179 std::cout << histogram.ToString();
180 }
181 }
182
TEST_F(PerfContextTest,StopWatchOverhead)183 TEST_F(PerfContextTest, StopWatchOverhead) {
184 // profile the timer cost by itself!
185 const int kTotalIterations = 1000000;
186 uint64_t elapsed = 0;
187 std::vector<uint64_t> timings(kTotalIterations);
188
189 StopWatch timer(Env::Default(), nullptr, 0, &elapsed);
190 for (auto& timing : timings) {
191 timing = elapsed;
192 }
193
194 HistogramImpl histogram;
195 uint64_t prev_timing = 0;
196 for (const auto timing : timings) {
197 histogram.Add(timing - prev_timing);
198 prev_timing = timing;
199 }
200
201 if (FLAGS_verbose) {
202 std::cout << histogram.ToString();
203 }
204 }
205
ProfileQueries(bool enabled_time=false)206 void ProfileQueries(bool enabled_time = false) {
207 DestroyDB(kDbName, Options()); // Start this test with a fresh DB
208
209 auto db = OpenDb();
210
211 WriteOptions write_options;
212 ReadOptions read_options;
213
214 HistogramImpl hist_put;
215
216 HistogramImpl hist_get;
217 HistogramImpl hist_get_snapshot;
218 HistogramImpl hist_get_memtable;
219 HistogramImpl hist_get_files;
220 HistogramImpl hist_get_post_process;
221 HistogramImpl hist_num_memtable_checked;
222
223 HistogramImpl hist_mget;
224 HistogramImpl hist_mget_snapshot;
225 HistogramImpl hist_mget_memtable;
226 HistogramImpl hist_mget_files;
227 HistogramImpl hist_mget_post_process;
228 HistogramImpl hist_mget_num_memtable_checked;
229
230 HistogramImpl hist_write_pre_post;
231 HistogramImpl hist_write_wal_time;
232 HistogramImpl hist_write_memtable_time;
233 HistogramImpl hist_write_delay_time;
234 HistogramImpl hist_write_thread_wait_nanos;
235 HistogramImpl hist_write_scheduling_time;
236
237 uint64_t total_db_mutex_nanos = 0;
238
239 if (FLAGS_verbose) {
240 std::cout << "Inserting " << FLAGS_total_keys << " key/value pairs\n...\n";
241 }
242
243 std::vector<int> keys;
244 const int kFlushFlag = -1;
245 for (int i = 0; i < FLAGS_total_keys; ++i) {
246 keys.push_back(i);
247 if (i == FLAGS_total_keys / 2) {
248 // Issuing a flush in the middle.
249 keys.push_back(kFlushFlag);
250 }
251 }
252
253 if (FLAGS_random_key) {
254 std::random_shuffle(keys.begin(), keys.end());
255 }
256 #ifndef NDEBUG
257 ThreadStatusUtil::TEST_SetStateDelay(ThreadStatus::STATE_MUTEX_WAIT, 1U);
258 #endif
259 int num_mutex_waited = 0;
260 for (const int i : keys) {
261 if (i == kFlushFlag) {
262 FlushOptions fo;
263 db->Flush(fo);
264 continue;
265 }
266
267 std::string key = "k" + ToString(i);
268 std::string value = "v" + ToString(i);
269
270 std::vector<std::string> values;
271
272 get_perf_context()->Reset();
273 db->Put(write_options, key, value);
274 if (++num_mutex_waited > 3) {
275 #ifndef NDEBUG
276 ThreadStatusUtil::TEST_SetStateDelay(ThreadStatus::STATE_MUTEX_WAIT, 0U);
277 #endif
278 }
279 hist_write_pre_post.Add(
280 get_perf_context()->write_pre_and_post_process_time);
281 hist_write_wal_time.Add(get_perf_context()->write_wal_time);
282 hist_write_memtable_time.Add(get_perf_context()->write_memtable_time);
283 hist_write_delay_time.Add(get_perf_context()->write_delay_time);
284 hist_write_thread_wait_nanos.Add(
285 get_perf_context()->write_thread_wait_nanos);
286 hist_write_scheduling_time.Add(
287 get_perf_context()->write_scheduling_flushes_compactions_time);
288 hist_put.Add(get_perf_context()->user_key_comparison_count);
289 total_db_mutex_nanos += get_perf_context()->db_mutex_lock_nanos;
290 }
291 #ifndef NDEBUG
292 ThreadStatusUtil::TEST_SetStateDelay(ThreadStatus::STATE_MUTEX_WAIT, 0U);
293 #endif
294
295 for (const int i : keys) {
296 if (i == kFlushFlag) {
297 continue;
298 }
299 std::string key = "k" + ToString(i);
300 std::string expected_value = "v" + ToString(i);
301 std::string value;
302
303 std::vector<Slice> multiget_keys = {Slice(key)};
304 std::vector<std::string> values;
305
306 get_perf_context()->Reset();
307 ASSERT_OK(db->Get(read_options, key, &value));
308 ASSERT_EQ(expected_value, value);
309 hist_get_snapshot.Add(get_perf_context()->get_snapshot_time);
310 hist_get_memtable.Add(get_perf_context()->get_from_memtable_time);
311 hist_get_files.Add(get_perf_context()->get_from_output_files_time);
312 hist_num_memtable_checked.Add(get_perf_context()->get_from_memtable_count);
313 hist_get_post_process.Add(get_perf_context()->get_post_process_time);
314 hist_get.Add(get_perf_context()->user_key_comparison_count);
315
316 get_perf_context()->Reset();
317 db->MultiGet(read_options, multiget_keys, &values);
318 hist_mget_snapshot.Add(get_perf_context()->get_snapshot_time);
319 hist_mget_memtable.Add(get_perf_context()->get_from_memtable_time);
320 hist_mget_files.Add(get_perf_context()->get_from_output_files_time);
321 hist_mget_num_memtable_checked.Add(get_perf_context()->get_from_memtable_count);
322 hist_mget_post_process.Add(get_perf_context()->get_post_process_time);
323 hist_mget.Add(get_perf_context()->user_key_comparison_count);
324 }
325
326 if (FLAGS_verbose) {
327 std::cout << "Put uesr key comparison: \n" << hist_put.ToString()
328 << "Get uesr key comparison: \n" << hist_get.ToString()
329 << "MultiGet uesr key comparison: \n" << hist_get.ToString();
330 std::cout << "Put(): Pre and Post Process Time: \n"
331 << hist_write_pre_post.ToString() << " Writing WAL time: \n"
332 << hist_write_wal_time.ToString() << "\n"
333 << " Writing Mem Table time: \n"
334 << hist_write_memtable_time.ToString() << "\n"
335 << " Write Delay: \n" << hist_write_delay_time.ToString() << "\n"
336 << " Waiting for Batch time: \n"
337 << hist_write_thread_wait_nanos.ToString() << "\n"
338 << " Scheduling Flushes and Compactions Time: \n"
339 << hist_write_scheduling_time.ToString() << "\n"
340 << " Total DB mutex nanos: \n" << total_db_mutex_nanos << "\n";
341
342 std::cout << "Get(): Time to get snapshot: \n"
343 << hist_get_snapshot.ToString()
344 << " Time to get value from memtables: \n"
345 << hist_get_memtable.ToString() << "\n"
346 << " Time to get value from output files: \n"
347 << hist_get_files.ToString() << "\n"
348 << " Number of memtables checked: \n"
349 << hist_num_memtable_checked.ToString() << "\n"
350 << " Time to post process: \n" << hist_get_post_process.ToString()
351 << "\n";
352
353 std::cout << "MultiGet(): Time to get snapshot: \n"
354 << hist_mget_snapshot.ToString()
355 << " Time to get value from memtables: \n"
356 << hist_mget_memtable.ToString() << "\n"
357 << " Time to get value from output files: \n"
358 << hist_mget_files.ToString() << "\n"
359 << " Number of memtables checked: \n"
360 << hist_mget_num_memtable_checked.ToString() << "\n"
361 << " Time to post process: \n"
362 << hist_mget_post_process.ToString() << "\n";
363 }
364
365 if (enabled_time) {
366 ASSERT_GT(hist_get.Average(), 0);
367 ASSERT_GT(hist_get_snapshot.Average(), 0);
368 ASSERT_GT(hist_get_memtable.Average(), 0);
369 ASSERT_GT(hist_get_files.Average(), 0);
370 ASSERT_GT(hist_get_post_process.Average(), 0);
371 ASSERT_GT(hist_num_memtable_checked.Average(), 0);
372
373 ASSERT_GT(hist_mget.Average(), 0);
374 ASSERT_GT(hist_mget_snapshot.Average(), 0);
375 ASSERT_GT(hist_mget_memtable.Average(), 0);
376 ASSERT_GT(hist_mget_files.Average(), 0);
377 ASSERT_GT(hist_mget_post_process.Average(), 0);
378 ASSERT_GT(hist_mget_num_memtable_checked.Average(), 0);
379
380 EXPECT_GT(hist_write_pre_post.Average(), 0);
381 EXPECT_GT(hist_write_wal_time.Average(), 0);
382 EXPECT_GT(hist_write_memtable_time.Average(), 0);
383 EXPECT_EQ(hist_write_delay_time.Average(), 0);
384 EXPECT_EQ(hist_write_thread_wait_nanos.Average(), 0);
385 EXPECT_GT(hist_write_scheduling_time.Average(), 0);
386
387 #ifndef NDEBUG
388 ASSERT_GT(total_db_mutex_nanos, 2000U);
389 #endif
390 }
391
392 db.reset();
393 db = OpenDb(true);
394
395 hist_get.Clear();
396 hist_get_snapshot.Clear();
397 hist_get_memtable.Clear();
398 hist_get_files.Clear();
399 hist_get_post_process.Clear();
400 hist_num_memtable_checked.Clear();
401
402 hist_mget.Clear();
403 hist_mget_snapshot.Clear();
404 hist_mget_memtable.Clear();
405 hist_mget_files.Clear();
406 hist_mget_post_process.Clear();
407 hist_mget_num_memtable_checked.Clear();
408
409 for (const int i : keys) {
410 if (i == kFlushFlag) {
411 continue;
412 }
413 std::string key = "k" + ToString(i);
414 std::string expected_value = "v" + ToString(i);
415 std::string value;
416
417 std::vector<Slice> multiget_keys = {Slice(key)};
418 std::vector<std::string> values;
419
420 get_perf_context()->Reset();
421 ASSERT_OK(db->Get(read_options, key, &value));
422 ASSERT_EQ(expected_value, value);
423 hist_get_snapshot.Add(get_perf_context()->get_snapshot_time);
424 hist_get_memtable.Add(get_perf_context()->get_from_memtable_time);
425 hist_get_files.Add(get_perf_context()->get_from_output_files_time);
426 hist_num_memtable_checked.Add(get_perf_context()->get_from_memtable_count);
427 hist_get_post_process.Add(get_perf_context()->get_post_process_time);
428 hist_get.Add(get_perf_context()->user_key_comparison_count);
429
430 get_perf_context()->Reset();
431 db->MultiGet(read_options, multiget_keys, &values);
432 hist_mget_snapshot.Add(get_perf_context()->get_snapshot_time);
433 hist_mget_memtable.Add(get_perf_context()->get_from_memtable_time);
434 hist_mget_files.Add(get_perf_context()->get_from_output_files_time);
435 hist_mget_num_memtable_checked.Add(get_perf_context()->get_from_memtable_count);
436 hist_mget_post_process.Add(get_perf_context()->get_post_process_time);
437 hist_mget.Add(get_perf_context()->user_key_comparison_count);
438 }
439
440 if (FLAGS_verbose) {
441 std::cout << "ReadOnly Get uesr key comparison: \n" << hist_get.ToString()
442 << "ReadOnly MultiGet uesr key comparison: \n"
443 << hist_mget.ToString();
444
445 std::cout << "ReadOnly Get(): Time to get snapshot: \n"
446 << hist_get_snapshot.ToString()
447 << " Time to get value from memtables: \n"
448 << hist_get_memtable.ToString() << "\n"
449 << " Time to get value from output files: \n"
450 << hist_get_files.ToString() << "\n"
451 << " Number of memtables checked: \n"
452 << hist_num_memtable_checked.ToString() << "\n"
453 << " Time to post process: \n" << hist_get_post_process.ToString()
454 << "\n";
455
456 std::cout << "ReadOnly MultiGet(): Time to get snapshot: \n"
457 << hist_mget_snapshot.ToString()
458 << " Time to get value from memtables: \n"
459 << hist_mget_memtable.ToString() << "\n"
460 << " Time to get value from output files: \n"
461 << hist_mget_files.ToString() << "\n"
462 << " Number of memtables checked: \n"
463 << hist_mget_num_memtable_checked.ToString() << "\n"
464 << " Time to post process: \n"
465 << hist_mget_post_process.ToString() << "\n";
466 }
467
468 if (enabled_time) {
469 ASSERT_GT(hist_get.Average(), 0);
470 ASSERT_GT(hist_get_memtable.Average(), 0);
471 ASSERT_GT(hist_get_files.Average(), 0);
472 ASSERT_GT(hist_num_memtable_checked.Average(), 0);
473 // In read-only mode Get(), no super version operation is needed
474 ASSERT_EQ(hist_get_post_process.Average(), 0);
475 ASSERT_GT(hist_get_snapshot.Average(), 0);
476
477 ASSERT_GT(hist_mget.Average(), 0);
478 ASSERT_GT(hist_mget_snapshot.Average(), 0);
479 ASSERT_GT(hist_mget_memtable.Average(), 0);
480 ASSERT_GT(hist_mget_files.Average(), 0);
481 ASSERT_GT(hist_mget_post_process.Average(), 0);
482 ASSERT_GT(hist_mget_num_memtable_checked.Average(), 0);
483 }
484 }
485
486 #ifndef ROCKSDB_LITE
TEST_F(PerfContextTest,KeyComparisonCount)487 TEST_F(PerfContextTest, KeyComparisonCount) {
488 SetPerfLevel(kEnableCount);
489 ProfileQueries();
490
491 SetPerfLevel(kDisable);
492 ProfileQueries();
493
494 SetPerfLevel(kEnableTime);
495 ProfileQueries(true);
496 }
497 #endif // ROCKSDB_LITE
498
499 // make perf_context_test
500 // export ROCKSDB_TESTS=PerfContextTest.SeekKeyComparison
501 // For one memtable:
502 // ./perf_context_test --write_buffer_size=500000 --total_keys=10000
503 // For two memtables:
504 // ./perf_context_test --write_buffer_size=250000 --total_keys=10000
505 // Specify --random_key=1 to shuffle the key before insertion
506 // Results show that, for sequential insertion, worst-case Seek Key comparison
507 // is close to the total number of keys (linear), when there is only one
508 // memtable. When there are two memtables, even the avg Seek Key comparison
509 // starts to become linear to the input size.
510
TEST_F(PerfContextTest,SeekKeyComparison)511 TEST_F(PerfContextTest, SeekKeyComparison) {
512 DestroyDB(kDbName, Options());
513 auto db = OpenDb();
514 WriteOptions write_options;
515 ReadOptions read_options;
516
517 if (FLAGS_verbose) {
518 std::cout << "Inserting " << FLAGS_total_keys << " key/value pairs\n...\n";
519 }
520
521 std::vector<int> keys;
522 for (int i = 0; i < FLAGS_total_keys; ++i) {
523 keys.push_back(i);
524 }
525
526 if (FLAGS_random_key) {
527 std::random_shuffle(keys.begin(), keys.end());
528 }
529
530 HistogramImpl hist_put_time;
531 HistogramImpl hist_wal_time;
532 HistogramImpl hist_time_diff;
533
534 SetPerfLevel(kEnableTime);
535 StopWatchNano timer(Env::Default());
536 for (const int i : keys) {
537 std::string key = "k" + ToString(i);
538 std::string value = "v" + ToString(i);
539
540 get_perf_context()->Reset();
541 timer.Start();
542 db->Put(write_options, key, value);
543 auto put_time = timer.ElapsedNanos();
544 hist_put_time.Add(put_time);
545 hist_wal_time.Add(get_perf_context()->write_wal_time);
546 hist_time_diff.Add(put_time - get_perf_context()->write_wal_time);
547 }
548
549 if (FLAGS_verbose) {
550 std::cout << "Put time:\n" << hist_put_time.ToString() << "WAL time:\n"
551 << hist_wal_time.ToString() << "time diff:\n"
552 << hist_time_diff.ToString();
553 }
554
555 HistogramImpl hist_seek;
556 HistogramImpl hist_next;
557
558 for (int i = 0; i < FLAGS_total_keys; ++i) {
559 std::string key = "k" + ToString(i);
560 std::string value = "v" + ToString(i);
561
562 std::unique_ptr<Iterator> iter(db->NewIterator(read_options));
563 get_perf_context()->Reset();
564 iter->Seek(key);
565 ASSERT_TRUE(iter->Valid());
566 ASSERT_EQ(iter->value().ToString(), value);
567 hist_seek.Add(get_perf_context()->user_key_comparison_count);
568 }
569
570 std::unique_ptr<Iterator> iter(db->NewIterator(read_options));
571 for (iter->SeekToFirst(); iter->Valid();) {
572 get_perf_context()->Reset();
573 iter->Next();
574 hist_next.Add(get_perf_context()->user_key_comparison_count);
575 }
576
577 if (FLAGS_verbose) {
578 std::cout << "Seek:\n" << hist_seek.ToString() << "Next:\n"
579 << hist_next.ToString();
580 }
581 }
582
TEST_F(PerfContextTest,DBMutexLockCounter)583 TEST_F(PerfContextTest, DBMutexLockCounter) {
584 int stats_code[] = {0, static_cast<int>(DB_MUTEX_WAIT_MICROS)};
585 for (PerfLevel perf_level_test :
586 {PerfLevel::kEnableTimeExceptForMutex, PerfLevel::kEnableTime}) {
587 for (int c = 0; c < 2; ++c) {
588 InstrumentedMutex mutex(nullptr, Env::Default(), stats_code[c]);
589 mutex.Lock();
590 ROCKSDB_NAMESPACE::port::Thread child_thread([&] {
591 SetPerfLevel(perf_level_test);
592 get_perf_context()->Reset();
593 ASSERT_EQ(get_perf_context()->db_mutex_lock_nanos, 0);
594 mutex.Lock();
595 mutex.Unlock();
596 if (perf_level_test == PerfLevel::kEnableTimeExceptForMutex ||
597 stats_code[c] != DB_MUTEX_WAIT_MICROS) {
598 ASSERT_EQ(get_perf_context()->db_mutex_lock_nanos, 0);
599 } else {
600 // increment the counter only when it's a DB Mutex
601 ASSERT_GT(get_perf_context()->db_mutex_lock_nanos, 0);
602 }
603 });
604 Env::Default()->SleepForMicroseconds(100);
605 mutex.Unlock();
606 child_thread.join();
607 }
608 }
609 }
610
TEST_F(PerfContextTest,FalseDBMutexWait)611 TEST_F(PerfContextTest, FalseDBMutexWait) {
612 SetPerfLevel(kEnableTime);
613 int stats_code[] = {0, static_cast<int>(DB_MUTEX_WAIT_MICROS)};
614 for (int c = 0; c < 2; ++c) {
615 InstrumentedMutex mutex(nullptr, Env::Default(), stats_code[c]);
616 InstrumentedCondVar lock(&mutex);
617 get_perf_context()->Reset();
618 mutex.Lock();
619 lock.TimedWait(100);
620 mutex.Unlock();
621 if (stats_code[c] == static_cast<int>(DB_MUTEX_WAIT_MICROS)) {
622 // increment the counter only when it's a DB Mutex
623 ASSERT_GT(get_perf_context()->db_condition_wait_nanos, 0);
624 } else {
625 ASSERT_EQ(get_perf_context()->db_condition_wait_nanos, 0);
626 }
627 }
628 }
629
TEST_F(PerfContextTest,ToString)630 TEST_F(PerfContextTest, ToString) {
631 get_perf_context()->Reset();
632 get_perf_context()->block_read_count = 12345;
633
634 std::string zero_included = get_perf_context()->ToString();
635 ASSERT_NE(std::string::npos, zero_included.find("= 0"));
636 ASSERT_NE(std::string::npos, zero_included.find("= 12345"));
637
638 std::string zero_excluded = get_perf_context()->ToString(true);
639 ASSERT_EQ(std::string::npos, zero_excluded.find("= 0"));
640 ASSERT_NE(std::string::npos, zero_excluded.find("= 12345"));
641 }
642
TEST_F(PerfContextTest,MergeOperatorTime)643 TEST_F(PerfContextTest, MergeOperatorTime) {
644 DestroyDB(kDbName, Options());
645 DB* db;
646 Options options;
647 options.create_if_missing = true;
648 options.merge_operator = MergeOperators::CreateStringAppendOperator();
649 Status s = DB::Open(options, kDbName, &db);
650 EXPECT_OK(s);
651
652 std::string val;
653 ASSERT_OK(db->Merge(WriteOptions(), "k1", "val1"));
654 ASSERT_OK(db->Merge(WriteOptions(), "k1", "val2"));
655 ASSERT_OK(db->Merge(WriteOptions(), "k1", "val3"));
656 ASSERT_OK(db->Merge(WriteOptions(), "k1", "val4"));
657
658 SetPerfLevel(kEnableTime);
659 get_perf_context()->Reset();
660 ASSERT_OK(db->Get(ReadOptions(), "k1", &val));
661 #ifdef OS_SOLARIS
662 for (int i = 0; i < 100; i++) {
663 ASSERT_OK(db->Get(ReadOptions(), "k1", &val));
664 }
665 #endif
666 EXPECT_GT(get_perf_context()->merge_operator_time_nanos, 0);
667
668 ASSERT_OK(db->Flush(FlushOptions()));
669
670 get_perf_context()->Reset();
671 ASSERT_OK(db->Get(ReadOptions(), "k1", &val));
672 #ifdef OS_SOLARIS
673 for (int i = 0; i < 100; i++) {
674 ASSERT_OK(db->Get(ReadOptions(), "k1", &val));
675 }
676 #endif
677 EXPECT_GT(get_perf_context()->merge_operator_time_nanos, 0);
678
679 ASSERT_OK(db->CompactRange(CompactRangeOptions(), nullptr, nullptr));
680
681 get_perf_context()->Reset();
682 ASSERT_OK(db->Get(ReadOptions(), "k1", &val));
683 #ifdef OS_SOLARIS
684 for (int i = 0; i < 100; i++) {
685 ASSERT_OK(db->Get(ReadOptions(), "k1", &val));
686 }
687 #endif
688 EXPECT_GT(get_perf_context()->merge_operator_time_nanos, 0);
689
690 delete db;
691 }
692
TEST_F(PerfContextTest,CopyAndMove)693 TEST_F(PerfContextTest, CopyAndMove) {
694 // Assignment operator
695 {
696 get_perf_context()->Reset();
697 get_perf_context()->EnablePerLevelPerfContext();
698 PERF_COUNTER_BY_LEVEL_ADD(bloom_filter_useful, 1, 5);
699 ASSERT_EQ(
700 1,
701 (*(get_perf_context()->level_to_perf_context))[5].bloom_filter_useful);
702 PerfContext perf_context_assign;
703 perf_context_assign = *get_perf_context();
704 ASSERT_EQ(
705 1,
706 (*(perf_context_assign.level_to_perf_context))[5].bloom_filter_useful);
707 get_perf_context()->ClearPerLevelPerfContext();
708 get_perf_context()->Reset();
709 ASSERT_EQ(
710 1,
711 (*(perf_context_assign.level_to_perf_context))[5].bloom_filter_useful);
712 perf_context_assign.ClearPerLevelPerfContext();
713 perf_context_assign.Reset();
714 }
715 // Copy constructor
716 {
717 get_perf_context()->Reset();
718 get_perf_context()->EnablePerLevelPerfContext();
719 PERF_COUNTER_BY_LEVEL_ADD(bloom_filter_useful, 1, 5);
720 ASSERT_EQ(
721 1,
722 (*(get_perf_context()->level_to_perf_context))[5].bloom_filter_useful);
723 PerfContext perf_context_copy(*get_perf_context());
724 ASSERT_EQ(
725 1, (*(perf_context_copy.level_to_perf_context))[5].bloom_filter_useful);
726 get_perf_context()->ClearPerLevelPerfContext();
727 get_perf_context()->Reset();
728 ASSERT_EQ(
729 1, (*(perf_context_copy.level_to_perf_context))[5].bloom_filter_useful);
730 perf_context_copy.ClearPerLevelPerfContext();
731 perf_context_copy.Reset();
732 }
733 // Move constructor
734 {
735 get_perf_context()->Reset();
736 get_perf_context()->EnablePerLevelPerfContext();
737 PERF_COUNTER_BY_LEVEL_ADD(bloom_filter_useful, 1, 5);
738 ASSERT_EQ(
739 1,
740 (*(get_perf_context()->level_to_perf_context))[5].bloom_filter_useful);
741 PerfContext perf_context_move = std::move(*get_perf_context());
742 ASSERT_EQ(
743 1, (*(perf_context_move.level_to_perf_context))[5].bloom_filter_useful);
744 get_perf_context()->ClearPerLevelPerfContext();
745 get_perf_context()->Reset();
746 ASSERT_EQ(
747 1, (*(perf_context_move.level_to_perf_context))[5].bloom_filter_useful);
748 perf_context_move.ClearPerLevelPerfContext();
749 perf_context_move.Reset();
750 }
751 }
752
TEST_F(PerfContextTest,PerfContextDisableEnable)753 TEST_F(PerfContextTest, PerfContextDisableEnable) {
754 get_perf_context()->Reset();
755 get_perf_context()->EnablePerLevelPerfContext();
756 PERF_COUNTER_BY_LEVEL_ADD(bloom_filter_full_positive, 1, 0);
757 get_perf_context()->DisablePerLevelPerfContext();
758 PERF_COUNTER_BY_LEVEL_ADD(bloom_filter_useful, 1, 5);
759 get_perf_context()->EnablePerLevelPerfContext();
760 PERF_COUNTER_BY_LEVEL_ADD(block_cache_hit_count, 1, 0);
761 get_perf_context()->DisablePerLevelPerfContext();
762 PerfContext perf_context_copy(*get_perf_context());
763 ASSERT_EQ(1, (*(perf_context_copy.level_to_perf_context))[0]
764 .bloom_filter_full_positive);
765 // this was set when per level perf context is disabled, should not be copied
766 ASSERT_NE(
767 1, (*(perf_context_copy.level_to_perf_context))[5].bloom_filter_useful);
768 ASSERT_EQ(
769 1, (*(perf_context_copy.level_to_perf_context))[0].block_cache_hit_count);
770 perf_context_copy.ClearPerLevelPerfContext();
771 perf_context_copy.Reset();
772 get_perf_context()->ClearPerLevelPerfContext();
773 get_perf_context()->Reset();
774 }
775
TEST_F(PerfContextTest,PerfContextByLevelGetSet)776 TEST_F(PerfContextTest, PerfContextByLevelGetSet) {
777 get_perf_context()->Reset();
778 get_perf_context()->EnablePerLevelPerfContext();
779 PERF_COUNTER_BY_LEVEL_ADD(bloom_filter_full_positive, 1, 0);
780 PERF_COUNTER_BY_LEVEL_ADD(bloom_filter_useful, 1, 5);
781 PERF_COUNTER_BY_LEVEL_ADD(bloom_filter_useful, 1, 7);
782 PERF_COUNTER_BY_LEVEL_ADD(bloom_filter_useful, 1, 7);
783 PERF_COUNTER_BY_LEVEL_ADD(bloom_filter_full_true_positive, 1, 2);
784 PERF_COUNTER_BY_LEVEL_ADD(block_cache_hit_count, 1, 0);
785 PERF_COUNTER_BY_LEVEL_ADD(block_cache_hit_count, 5, 2);
786 PERF_COUNTER_BY_LEVEL_ADD(block_cache_miss_count, 2, 3);
787 PERF_COUNTER_BY_LEVEL_ADD(block_cache_miss_count, 4, 1);
788 ASSERT_EQ(
789 0, (*(get_perf_context()->level_to_perf_context))[0].bloom_filter_useful);
790 ASSERT_EQ(
791 1, (*(get_perf_context()->level_to_perf_context))[5].bloom_filter_useful);
792 ASSERT_EQ(
793 2, (*(get_perf_context()->level_to_perf_context))[7].bloom_filter_useful);
794 ASSERT_EQ(1, (*(get_perf_context()->level_to_perf_context))[0]
795 .bloom_filter_full_positive);
796 ASSERT_EQ(1, (*(get_perf_context()->level_to_perf_context))[2]
797 .bloom_filter_full_true_positive);
798 ASSERT_EQ(1, (*(get_perf_context()->level_to_perf_context))[0]
799 .block_cache_hit_count);
800 ASSERT_EQ(5, (*(get_perf_context()->level_to_perf_context))[2]
801 .block_cache_hit_count);
802 ASSERT_EQ(2, (*(get_perf_context()->level_to_perf_context))[3]
803 .block_cache_miss_count);
804 ASSERT_EQ(4, (*(get_perf_context()->level_to_perf_context))[1]
805 .block_cache_miss_count);
806 std::string zero_excluded = get_perf_context()->ToString(true);
807 ASSERT_NE(std::string::npos,
808 zero_excluded.find("bloom_filter_useful = 1@level5, 2@level7"));
809 ASSERT_NE(std::string::npos,
810 zero_excluded.find("bloom_filter_full_positive = 1@level0"));
811 ASSERT_NE(std::string::npos,
812 zero_excluded.find("bloom_filter_full_true_positive = 1@level2"));
813 ASSERT_NE(std::string::npos,
814 zero_excluded.find("block_cache_hit_count = 1@level0, 5@level2"));
815 ASSERT_NE(std::string::npos,
816 zero_excluded.find("block_cache_miss_count = 4@level1, 2@level3"));
817 }
818
TEST_F(PerfContextTest,CPUTimer)819 TEST_F(PerfContextTest, CPUTimer) {
820 DestroyDB(kDbName, Options());
821 auto db = OpenDb();
822 WriteOptions write_options;
823 ReadOptions read_options;
824 SetPerfLevel(PerfLevel::kEnableTimeAndCPUTimeExceptForMutex);
825
826 std::string max_str = "0";
827 for (int i = 0; i < FLAGS_total_keys; ++i) {
828 std::string i_str = ToString(i);
829 std::string key = "k" + i_str;
830 std::string value = "v" + i_str;
831 max_str = max_str > i_str ? max_str : i_str;
832
833 db->Put(write_options, key, value);
834 }
835 std::string last_key = "k" + max_str;
836 std::string last_value = "v" + max_str;
837
838 {
839 // Get
840 get_perf_context()->Reset();
841 std::string value;
842 ASSERT_OK(db->Get(read_options, "k0", &value));
843 ASSERT_EQ(value, "v0");
844
845 if (FLAGS_verbose) {
846 std::cout << "Get CPU time nanos: " << get_perf_context()->get_cpu_nanos
847 << "ns\n";
848 }
849
850 // Iter
851 std::unique_ptr<Iterator> iter(db->NewIterator(read_options));
852
853 // Seek
854 get_perf_context()->Reset();
855 iter->Seek(last_key);
856 ASSERT_TRUE(iter->Valid());
857 ASSERT_EQ(last_value, iter->value().ToString());
858
859 if (FLAGS_verbose) {
860 std::cout << "Iter Seek CPU time nanos: "
861 << get_perf_context()->iter_seek_cpu_nanos << "ns\n";
862 }
863
864 // SeekForPrev
865 get_perf_context()->Reset();
866 iter->SeekForPrev(last_key);
867 ASSERT_TRUE(iter->Valid());
868
869 if (FLAGS_verbose) {
870 std::cout << "Iter SeekForPrev CPU time nanos: "
871 << get_perf_context()->iter_seek_cpu_nanos << "ns\n";
872 }
873
874 // SeekToLast
875 get_perf_context()->Reset();
876 iter->SeekToLast();
877 ASSERT_TRUE(iter->Valid());
878 ASSERT_EQ(last_value, iter->value().ToString());
879
880 if (FLAGS_verbose) {
881 std::cout << "Iter SeekToLast CPU time nanos: "
882 << get_perf_context()->iter_seek_cpu_nanos << "ns\n";
883 }
884
885 // SeekToFirst
886 get_perf_context()->Reset();
887 iter->SeekToFirst();
888 ASSERT_TRUE(iter->Valid());
889 ASSERT_EQ("v0", iter->value().ToString());
890
891 if (FLAGS_verbose) {
892 std::cout << "Iter SeekToFirst CPU time nanos: "
893 << get_perf_context()->iter_seek_cpu_nanos << "ns\n";
894 }
895
896 // Next
897 get_perf_context()->Reset();
898 iter->Next();
899 ASSERT_TRUE(iter->Valid());
900 ASSERT_EQ("v1", iter->value().ToString());
901
902 if (FLAGS_verbose) {
903 std::cout << "Iter Next CPU time nanos: "
904 << get_perf_context()->iter_next_cpu_nanos << "ns\n";
905 }
906
907 // Prev
908 get_perf_context()->Reset();
909 iter->Prev();
910 ASSERT_TRUE(iter->Valid());
911 ASSERT_EQ("v0", iter->value().ToString());
912
913 if (FLAGS_verbose) {
914 std::cout << "Iter Prev CPU time nanos: "
915 << get_perf_context()->iter_prev_cpu_nanos << "ns\n";
916 }
917
918 // monotonically increasing
919 get_perf_context()->Reset();
920 auto count = get_perf_context()->iter_seek_cpu_nanos;
921 for (int i = 0; i < FLAGS_total_keys; ++i) {
922 iter->Seek("k" + ToString(i));
923 ASSERT_TRUE(iter->Valid());
924 ASSERT_EQ("v" + ToString(i), iter->value().ToString());
925 auto next_count = get_perf_context()->iter_seek_cpu_nanos;
926 ASSERT_GT(next_count, count);
927 count = next_count;
928 }
929
930 // iterator creation/destruction; multiple iterators
931 {
932 std::unique_ptr<Iterator> iter2(db->NewIterator(read_options));
933 ASSERT_EQ(count, get_perf_context()->iter_seek_cpu_nanos);
934 iter2->Seek(last_key);
935 ASSERT_TRUE(iter2->Valid());
936 ASSERT_EQ(last_value, iter2->value().ToString());
937 ASSERT_GT(get_perf_context()->iter_seek_cpu_nanos, count);
938 count = get_perf_context()->iter_seek_cpu_nanos;
939 }
940 ASSERT_EQ(count, get_perf_context()->iter_seek_cpu_nanos);
941 }
942 }
943 } // namespace ROCKSDB_NAMESPACE
944
main(int argc,char ** argv)945 int main(int argc, char** argv) {
946 ::testing::InitGoogleTest(&argc, argv);
947
948 for (int i = 1; i < argc; i++) {
949 int n;
950 char junk;
951
952 if (sscanf(argv[i], "--write_buffer_size=%d%c", &n, &junk) == 1) {
953 FLAGS_write_buffer_size = n;
954 }
955
956 if (sscanf(argv[i], "--total_keys=%d%c", &n, &junk) == 1) {
957 FLAGS_total_keys = n;
958 }
959
960 if (sscanf(argv[i], "--random_key=%d%c", &n, &junk) == 1 &&
961 (n == 0 || n == 1)) {
962 FLAGS_random_key = n;
963 }
964
965 if (sscanf(argv[i], "--use_set_based_memetable=%d%c", &n, &junk) == 1 &&
966 (n == 0 || n == 1)) {
967 FLAGS_use_set_based_memetable = n;
968 }
969
970 if (sscanf(argv[i], "--verbose=%d%c", &n, &junk) == 1 &&
971 (n == 0 || n == 1)) {
972 FLAGS_verbose = n;
973 }
974 }
975
976 if (FLAGS_verbose) {
977 std::cout << kDbName << "\n";
978 }
979
980 return RUN_ALL_TESTS();
981 }
982