]>
Commit | Line | Data |
---|---|---|
7c673cae | 1 | // Copyright (c) 2011-present, Facebook, Inc. All rights reserved. |
11fdf7f2 TL |
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). | |
7c673cae FG |
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/thread_status_util.h" | |
14 | #include "port/port.h" | |
15 | #include "rocksdb/db.h" | |
16 | #include "rocksdb/memtablerep.h" | |
17 | #include "rocksdb/perf_context.h" | |
18 | #include "rocksdb/slice_transform.h" | |
19 | #include "util/stop_watch.h" | |
20 | #include "util/string_util.h" | |
21 | #include "util/testharness.h" | |
22 | #include "utilities/merge_operators.h" | |
23 | ||
24 | bool FLAGS_random_key = false; | |
25 | bool FLAGS_use_set_based_memetable = false; | |
26 | int FLAGS_total_keys = 100; | |
27 | int FLAGS_write_buffer_size = 1000000000; | |
28 | int FLAGS_max_write_buffer_number = 8; | |
29 | int FLAGS_min_write_buffer_number_to_merge = 7; | |
30 | bool FLAGS_verbose = false; | |
31 | ||
32 | // Path to the database on file system | |
11fdf7f2 | 33 | const std::string kDbName = rocksdb::test::PerThreadDBPath("perf_context_test"); |
7c673cae FG |
34 | |
35 | namespace rocksdb { | |
36 | ||
37 | std::shared_ptr<DB> OpenDb(bool read_only = false) { | |
38 | DB* db; | |
39 | Options options; | |
40 | options.create_if_missing = true; | |
41 | options.max_open_files = -1; | |
42 | options.write_buffer_size = FLAGS_write_buffer_size; | |
43 | options.max_write_buffer_number = FLAGS_max_write_buffer_number; | |
44 | options.min_write_buffer_number_to_merge = | |
45 | FLAGS_min_write_buffer_number_to_merge; | |
46 | ||
47 | if (FLAGS_use_set_based_memetable) { | |
48 | #ifndef ROCKSDB_LITE | |
49 | options.prefix_extractor.reset(rocksdb::NewFixedPrefixTransform(0)); | |
50 | options.memtable_factory.reset(NewHashSkipListRepFactory()); | |
51 | #endif // ROCKSDB_LITE | |
52 | } | |
53 | ||
54 | Status s; | |
55 | if (!read_only) { | |
56 | s = DB::Open(options, kDbName, &db); | |
57 | } else { | |
58 | s = DB::OpenForReadOnly(options, kDbName, &db); | |
59 | } | |
60 | EXPECT_OK(s); | |
61 | return std::shared_ptr<DB>(db); | |
62 | } | |
63 | ||
64 | class PerfContextTest : public testing::Test {}; | |
65 | ||
66 | TEST_F(PerfContextTest, SeekIntoDeletion) { | |
67 | DestroyDB(kDbName, Options()); | |
68 | auto db = OpenDb(); | |
69 | WriteOptions write_options; | |
70 | ReadOptions read_options; | |
71 | ||
72 | for (int i = 0; i < FLAGS_total_keys; ++i) { | |
73 | std::string key = "k" + ToString(i); | |
74 | std::string value = "v" + ToString(i); | |
75 | ||
76 | db->Put(write_options, key, value); | |
77 | } | |
78 | ||
79 | for (int i = 0; i < FLAGS_total_keys -1 ; ++i) { | |
80 | std::string key = "k" + ToString(i); | |
81 | db->Delete(write_options, key); | |
82 | } | |
83 | ||
84 | HistogramImpl hist_get; | |
85 | HistogramImpl hist_get_time; | |
86 | for (int i = 0; i < FLAGS_total_keys - 1; ++i) { | |
87 | std::string key = "k" + ToString(i); | |
88 | std::string value; | |
89 | ||
11fdf7f2 | 90 | get_perf_context()->Reset(); |
7c673cae FG |
91 | StopWatchNano timer(Env::Default()); |
92 | timer.Start(); | |
93 | auto status = db->Get(read_options, key, &value); | |
94 | auto elapsed_nanos = timer.ElapsedNanos(); | |
95 | ASSERT_TRUE(status.IsNotFound()); | |
11fdf7f2 | 96 | hist_get.Add(get_perf_context()->user_key_comparison_count); |
7c673cae FG |
97 | hist_get_time.Add(elapsed_nanos); |
98 | } | |
99 | ||
100 | if (FLAGS_verbose) { | |
101 | std::cout << "Get user key comparison: \n" << hist_get.ToString() | |
102 | << "Get time: \n" << hist_get_time.ToString(); | |
103 | } | |
104 | ||
105 | { | |
106 | HistogramImpl hist_seek_to_first; | |
107 | std::unique_ptr<Iterator> iter(db->NewIterator(read_options)); | |
108 | ||
11fdf7f2 | 109 | get_perf_context()->Reset(); |
7c673cae FG |
110 | StopWatchNano timer(Env::Default(), true); |
111 | iter->SeekToFirst(); | |
11fdf7f2 | 112 | hist_seek_to_first.Add(get_perf_context()->user_key_comparison_count); |
7c673cae FG |
113 | auto elapsed_nanos = timer.ElapsedNanos(); |
114 | ||
115 | if (FLAGS_verbose) { | |
116 | std::cout << "SeekToFirst uesr key comparison: \n" | |
117 | << hist_seek_to_first.ToString() | |
11fdf7f2 | 118 | << "ikey skipped: " << get_perf_context()->internal_key_skipped_count |
7c673cae FG |
119 | << "\n" |
120 | << "idelete skipped: " | |
11fdf7f2 | 121 | << get_perf_context()->internal_delete_skipped_count << "\n" |
7c673cae FG |
122 | << "elapsed: " << elapsed_nanos << "\n"; |
123 | } | |
124 | } | |
125 | ||
126 | HistogramImpl hist_seek; | |
127 | for (int i = 0; i < FLAGS_total_keys; ++i) { | |
128 | std::unique_ptr<Iterator> iter(db->NewIterator(read_options)); | |
129 | std::string key = "k" + ToString(i); | |
130 | ||
11fdf7f2 | 131 | get_perf_context()->Reset(); |
7c673cae FG |
132 | StopWatchNano timer(Env::Default(), true); |
133 | iter->Seek(key); | |
134 | auto elapsed_nanos = timer.ElapsedNanos(); | |
11fdf7f2 | 135 | hist_seek.Add(get_perf_context()->user_key_comparison_count); |
7c673cae | 136 | if (FLAGS_verbose) { |
11fdf7f2 TL |
137 | std::cout << "seek cmp: " << get_perf_context()->user_key_comparison_count |
138 | << " ikey skipped " << get_perf_context()->internal_key_skipped_count | |
7c673cae | 139 | << " idelete skipped " |
11fdf7f2 | 140 | << get_perf_context()->internal_delete_skipped_count |
7c673cae FG |
141 | << " elapsed: " << elapsed_nanos << "ns\n"; |
142 | } | |
143 | ||
11fdf7f2 | 144 | get_perf_context()->Reset(); |
7c673cae FG |
145 | ASSERT_TRUE(iter->Valid()); |
146 | StopWatchNano timer2(Env::Default(), true); | |
147 | iter->Next(); | |
148 | auto elapsed_nanos2 = timer2.ElapsedNanos(); | |
149 | if (FLAGS_verbose) { | |
11fdf7f2 | 150 | std::cout << "next cmp: " << get_perf_context()->user_key_comparison_count |
7c673cae FG |
151 | << "elapsed: " << elapsed_nanos2 << "ns\n"; |
152 | } | |
153 | } | |
154 | ||
155 | if (FLAGS_verbose) { | |
156 | std::cout << "Seek uesr key comparison: \n" << hist_seek.ToString(); | |
157 | } | |
158 | } | |
159 | ||
160 | TEST_F(PerfContextTest, StopWatchNanoOverhead) { | |
161 | // profile the timer cost by itself! | |
162 | const int kTotalIterations = 1000000; | |
163 | std::vector<uint64_t> timings(kTotalIterations); | |
164 | ||
165 | StopWatchNano timer(Env::Default(), true); | |
166 | for (auto& timing : timings) { | |
167 | timing = timer.ElapsedNanos(true /* reset */); | |
168 | } | |
169 | ||
170 | HistogramImpl histogram; | |
171 | for (const auto timing : timings) { | |
172 | histogram.Add(timing); | |
173 | } | |
174 | ||
175 | if (FLAGS_verbose) { | |
176 | std::cout << histogram.ToString(); | |
177 | } | |
178 | } | |
179 | ||
180 | TEST_F(PerfContextTest, StopWatchOverhead) { | |
181 | // profile the timer cost by itself! | |
182 | const int kTotalIterations = 1000000; | |
183 | uint64_t elapsed = 0; | |
184 | std::vector<uint64_t> timings(kTotalIterations); | |
185 | ||
186 | StopWatch timer(Env::Default(), nullptr, 0, &elapsed); | |
187 | for (auto& timing : timings) { | |
188 | timing = elapsed; | |
189 | } | |
190 | ||
191 | HistogramImpl histogram; | |
192 | uint64_t prev_timing = 0; | |
193 | for (const auto timing : timings) { | |
194 | histogram.Add(timing - prev_timing); | |
195 | prev_timing = timing; | |
196 | } | |
197 | ||
198 | if (FLAGS_verbose) { | |
199 | std::cout << histogram.ToString(); | |
200 | } | |
201 | } | |
202 | ||
203 | void ProfileQueries(bool enabled_time = false) { | |
204 | DestroyDB(kDbName, Options()); // Start this test with a fresh DB | |
205 | ||
206 | auto db = OpenDb(); | |
207 | ||
208 | WriteOptions write_options; | |
209 | ReadOptions read_options; | |
210 | ||
211 | HistogramImpl hist_put; | |
212 | ||
213 | HistogramImpl hist_get; | |
214 | HistogramImpl hist_get_snapshot; | |
215 | HistogramImpl hist_get_memtable; | |
216 | HistogramImpl hist_get_files; | |
217 | HistogramImpl hist_get_post_process; | |
218 | HistogramImpl hist_num_memtable_checked; | |
219 | ||
220 | HistogramImpl hist_mget; | |
221 | HistogramImpl hist_mget_snapshot; | |
222 | HistogramImpl hist_mget_memtable; | |
223 | HistogramImpl hist_mget_files; | |
224 | HistogramImpl hist_mget_post_process; | |
225 | HistogramImpl hist_mget_num_memtable_checked; | |
226 | ||
227 | HistogramImpl hist_write_pre_post; | |
228 | HistogramImpl hist_write_wal_time; | |
229 | HistogramImpl hist_write_memtable_time; | |
11fdf7f2 TL |
230 | HistogramImpl hist_write_delay_time; |
231 | HistogramImpl hist_write_thread_wait_nanos; | |
232 | HistogramImpl hist_write_scheduling_time; | |
7c673cae FG |
233 | |
234 | uint64_t total_db_mutex_nanos = 0; | |
235 | ||
236 | if (FLAGS_verbose) { | |
237 | std::cout << "Inserting " << FLAGS_total_keys << " key/value pairs\n...\n"; | |
238 | } | |
239 | ||
240 | std::vector<int> keys; | |
241 | const int kFlushFlag = -1; | |
242 | for (int i = 0; i < FLAGS_total_keys; ++i) { | |
243 | keys.push_back(i); | |
244 | if (i == FLAGS_total_keys / 2) { | |
245 | // Issuing a flush in the middle. | |
246 | keys.push_back(kFlushFlag); | |
247 | } | |
248 | } | |
249 | ||
250 | if (FLAGS_random_key) { | |
251 | std::random_shuffle(keys.begin(), keys.end()); | |
252 | } | |
253 | #ifndef NDEBUG | |
254 | ThreadStatusUtil::TEST_SetStateDelay(ThreadStatus::STATE_MUTEX_WAIT, 1U); | |
255 | #endif | |
256 | int num_mutex_waited = 0; | |
257 | for (const int i : keys) { | |
258 | if (i == kFlushFlag) { | |
259 | FlushOptions fo; | |
260 | db->Flush(fo); | |
261 | continue; | |
262 | } | |
263 | ||
264 | std::string key = "k" + ToString(i); | |
265 | std::string value = "v" + ToString(i); | |
266 | ||
267 | std::vector<std::string> values; | |
268 | ||
11fdf7f2 | 269 | get_perf_context()->Reset(); |
7c673cae FG |
270 | db->Put(write_options, key, value); |
271 | if (++num_mutex_waited > 3) { | |
272 | #ifndef NDEBUG | |
273 | ThreadStatusUtil::TEST_SetStateDelay(ThreadStatus::STATE_MUTEX_WAIT, 0U); | |
274 | #endif | |
275 | } | |
11fdf7f2 TL |
276 | hist_write_pre_post.Add( |
277 | get_perf_context()->write_pre_and_post_process_time); | |
278 | hist_write_wal_time.Add(get_perf_context()->write_wal_time); | |
279 | hist_write_memtable_time.Add(get_perf_context()->write_memtable_time); | |
280 | hist_write_delay_time.Add(get_perf_context()->write_delay_time); | |
281 | hist_write_thread_wait_nanos.Add( | |
282 | get_perf_context()->write_thread_wait_nanos); | |
283 | hist_write_scheduling_time.Add( | |
284 | get_perf_context()->write_scheduling_flushes_compactions_time); | |
285 | hist_put.Add(get_perf_context()->user_key_comparison_count); | |
286 | total_db_mutex_nanos += get_perf_context()->db_mutex_lock_nanos; | |
7c673cae FG |
287 | } |
288 | #ifndef NDEBUG | |
289 | ThreadStatusUtil::TEST_SetStateDelay(ThreadStatus::STATE_MUTEX_WAIT, 0U); | |
290 | #endif | |
291 | ||
292 | for (const int i : keys) { | |
293 | if (i == kFlushFlag) { | |
294 | continue; | |
295 | } | |
296 | std::string key = "k" + ToString(i); | |
297 | std::string expected_value = "v" + ToString(i); | |
298 | std::string value; | |
299 | ||
300 | std::vector<Slice> multiget_keys = {Slice(key)}; | |
301 | std::vector<std::string> values; | |
302 | ||
11fdf7f2 | 303 | get_perf_context()->Reset(); |
7c673cae FG |
304 | ASSERT_OK(db->Get(read_options, key, &value)); |
305 | ASSERT_EQ(expected_value, value); | |
11fdf7f2 TL |
306 | hist_get_snapshot.Add(get_perf_context()->get_snapshot_time); |
307 | hist_get_memtable.Add(get_perf_context()->get_from_memtable_time); | |
308 | hist_get_files.Add(get_perf_context()->get_from_output_files_time); | |
309 | hist_num_memtable_checked.Add(get_perf_context()->get_from_memtable_count); | |
310 | hist_get_post_process.Add(get_perf_context()->get_post_process_time); | |
311 | hist_get.Add(get_perf_context()->user_key_comparison_count); | |
312 | ||
313 | get_perf_context()->Reset(); | |
7c673cae | 314 | db->MultiGet(read_options, multiget_keys, &values); |
11fdf7f2 TL |
315 | hist_mget_snapshot.Add(get_perf_context()->get_snapshot_time); |
316 | hist_mget_memtable.Add(get_perf_context()->get_from_memtable_time); | |
317 | hist_mget_files.Add(get_perf_context()->get_from_output_files_time); | |
318 | hist_mget_num_memtable_checked.Add(get_perf_context()->get_from_memtable_count); | |
319 | hist_mget_post_process.Add(get_perf_context()->get_post_process_time); | |
320 | hist_mget.Add(get_perf_context()->user_key_comparison_count); | |
7c673cae FG |
321 | } |
322 | ||
323 | if (FLAGS_verbose) { | |
324 | std::cout << "Put uesr key comparison: \n" << hist_put.ToString() | |
325 | << "Get uesr key comparison: \n" << hist_get.ToString() | |
326 | << "MultiGet uesr key comparison: \n" << hist_get.ToString(); | |
327 | std::cout << "Put(): Pre and Post Process Time: \n" | |
328 | << hist_write_pre_post.ToString() << " Writing WAL time: \n" | |
329 | << hist_write_wal_time.ToString() << "\n" | |
330 | << " Writing Mem Table time: \n" | |
331 | << hist_write_memtable_time.ToString() << "\n" | |
11fdf7f2 TL |
332 | << " Write Delay: \n" << hist_write_delay_time.ToString() << "\n" |
333 | << " Waiting for Batch time: \n" | |
334 | << hist_write_thread_wait_nanos.ToString() << "\n" | |
335 | << " Scheduling Flushes and Compactions Time: \n" | |
336 | << hist_write_scheduling_time.ToString() << "\n" | |
7c673cae FG |
337 | << " Total DB mutex nanos: \n" << total_db_mutex_nanos << "\n"; |
338 | ||
339 | std::cout << "Get(): Time to get snapshot: \n" | |
340 | << hist_get_snapshot.ToString() | |
341 | << " Time to get value from memtables: \n" | |
342 | << hist_get_memtable.ToString() << "\n" | |
343 | << " Time to get value from output files: \n" | |
344 | << hist_get_files.ToString() << "\n" | |
345 | << " Number of memtables checked: \n" | |
346 | << hist_num_memtable_checked.ToString() << "\n" | |
347 | << " Time to post process: \n" << hist_get_post_process.ToString() | |
348 | << "\n"; | |
349 | ||
350 | std::cout << "MultiGet(): Time to get snapshot: \n" | |
351 | << hist_mget_snapshot.ToString() | |
352 | << " Time to get value from memtables: \n" | |
353 | << hist_mget_memtable.ToString() << "\n" | |
354 | << " Time to get value from output files: \n" | |
355 | << hist_mget_files.ToString() << "\n" | |
356 | << " Number of memtables checked: \n" | |
357 | << hist_mget_num_memtable_checked.ToString() << "\n" | |
358 | << " Time to post process: \n" | |
359 | << hist_mget_post_process.ToString() << "\n"; | |
360 | } | |
361 | ||
362 | if (enabled_time) { | |
363 | ASSERT_GT(hist_get.Average(), 0); | |
364 | ASSERT_GT(hist_get_snapshot.Average(), 0); | |
365 | ASSERT_GT(hist_get_memtable.Average(), 0); | |
366 | ASSERT_GT(hist_get_files.Average(), 0); | |
367 | ASSERT_GT(hist_get_post_process.Average(), 0); | |
368 | ASSERT_GT(hist_num_memtable_checked.Average(), 0); | |
369 | ||
370 | ASSERT_GT(hist_mget.Average(), 0); | |
371 | ASSERT_GT(hist_mget_snapshot.Average(), 0); | |
372 | ASSERT_GT(hist_mget_memtable.Average(), 0); | |
373 | ASSERT_GT(hist_mget_files.Average(), 0); | |
374 | ASSERT_GT(hist_mget_post_process.Average(), 0); | |
375 | ASSERT_GT(hist_mget_num_memtable_checked.Average(), 0); | |
11fdf7f2 TL |
376 | |
377 | EXPECT_GT(hist_write_pre_post.Average(), 0); | |
378 | EXPECT_GT(hist_write_wal_time.Average(), 0); | |
379 | EXPECT_GT(hist_write_memtable_time.Average(), 0); | |
380 | EXPECT_EQ(hist_write_delay_time.Average(), 0); | |
381 | EXPECT_EQ(hist_write_thread_wait_nanos.Average(), 0); | |
382 | EXPECT_GT(hist_write_scheduling_time.Average(), 0); | |
383 | ||
7c673cae FG |
384 | #ifndef NDEBUG |
385 | ASSERT_GT(total_db_mutex_nanos, 2000U); | |
386 | #endif | |
387 | } | |
388 | ||
389 | db.reset(); | |
390 | db = OpenDb(true); | |
391 | ||
392 | hist_get.Clear(); | |
393 | hist_get_snapshot.Clear(); | |
394 | hist_get_memtable.Clear(); | |
395 | hist_get_files.Clear(); | |
396 | hist_get_post_process.Clear(); | |
397 | hist_num_memtable_checked.Clear(); | |
398 | ||
399 | hist_mget.Clear(); | |
400 | hist_mget_snapshot.Clear(); | |
401 | hist_mget_memtable.Clear(); | |
402 | hist_mget_files.Clear(); | |
403 | hist_mget_post_process.Clear(); | |
404 | hist_mget_num_memtable_checked.Clear(); | |
405 | ||
406 | for (const int i : keys) { | |
407 | if (i == kFlushFlag) { | |
408 | continue; | |
409 | } | |
410 | std::string key = "k" + ToString(i); | |
411 | std::string expected_value = "v" + ToString(i); | |
412 | std::string value; | |
413 | ||
414 | std::vector<Slice> multiget_keys = {Slice(key)}; | |
415 | std::vector<std::string> values; | |
416 | ||
11fdf7f2 | 417 | get_perf_context()->Reset(); |
7c673cae FG |
418 | ASSERT_OK(db->Get(read_options, key, &value)); |
419 | ASSERT_EQ(expected_value, value); | |
11fdf7f2 TL |
420 | hist_get_snapshot.Add(get_perf_context()->get_snapshot_time); |
421 | hist_get_memtable.Add(get_perf_context()->get_from_memtable_time); | |
422 | hist_get_files.Add(get_perf_context()->get_from_output_files_time); | |
423 | hist_num_memtable_checked.Add(get_perf_context()->get_from_memtable_count); | |
424 | hist_get_post_process.Add(get_perf_context()->get_post_process_time); | |
425 | hist_get.Add(get_perf_context()->user_key_comparison_count); | |
426 | ||
427 | get_perf_context()->Reset(); | |
7c673cae | 428 | db->MultiGet(read_options, multiget_keys, &values); |
11fdf7f2 TL |
429 | hist_mget_snapshot.Add(get_perf_context()->get_snapshot_time); |
430 | hist_mget_memtable.Add(get_perf_context()->get_from_memtable_time); | |
431 | hist_mget_files.Add(get_perf_context()->get_from_output_files_time); | |
432 | hist_mget_num_memtable_checked.Add(get_perf_context()->get_from_memtable_count); | |
433 | hist_mget_post_process.Add(get_perf_context()->get_post_process_time); | |
434 | hist_mget.Add(get_perf_context()->user_key_comparison_count); | |
7c673cae FG |
435 | } |
436 | ||
437 | if (FLAGS_verbose) { | |
438 | std::cout << "ReadOnly Get uesr key comparison: \n" << hist_get.ToString() | |
439 | << "ReadOnly MultiGet uesr key comparison: \n" | |
440 | << hist_mget.ToString(); | |
441 | ||
442 | std::cout << "ReadOnly Get(): Time to get snapshot: \n" | |
443 | << hist_get_snapshot.ToString() | |
444 | << " Time to get value from memtables: \n" | |
445 | << hist_get_memtable.ToString() << "\n" | |
446 | << " Time to get value from output files: \n" | |
447 | << hist_get_files.ToString() << "\n" | |
448 | << " Number of memtables checked: \n" | |
449 | << hist_num_memtable_checked.ToString() << "\n" | |
450 | << " Time to post process: \n" << hist_get_post_process.ToString() | |
451 | << "\n"; | |
452 | ||
453 | std::cout << "ReadOnly MultiGet(): Time to get snapshot: \n" | |
454 | << hist_mget_snapshot.ToString() | |
455 | << " Time to get value from memtables: \n" | |
456 | << hist_mget_memtable.ToString() << "\n" | |
457 | << " Time to get value from output files: \n" | |
458 | << hist_mget_files.ToString() << "\n" | |
459 | << " Number of memtables checked: \n" | |
460 | << hist_mget_num_memtable_checked.ToString() << "\n" | |
461 | << " Time to post process: \n" | |
462 | << hist_mget_post_process.ToString() << "\n"; | |
463 | } | |
464 | ||
465 | if (enabled_time) { | |
466 | ASSERT_GT(hist_get.Average(), 0); | |
467 | ASSERT_GT(hist_get_memtable.Average(), 0); | |
468 | ASSERT_GT(hist_get_files.Average(), 0); | |
469 | ASSERT_GT(hist_num_memtable_checked.Average(), 0); | |
470 | // In read-only mode Get(), no super version operation is needed | |
471 | ASSERT_EQ(hist_get_post_process.Average(), 0); | |
11fdf7f2 | 472 | ASSERT_GT(hist_get_snapshot.Average(), 0); |
7c673cae FG |
473 | |
474 | ASSERT_GT(hist_mget.Average(), 0); | |
475 | ASSERT_GT(hist_mget_snapshot.Average(), 0); | |
476 | ASSERT_GT(hist_mget_memtable.Average(), 0); | |
477 | ASSERT_GT(hist_mget_files.Average(), 0); | |
478 | ASSERT_GT(hist_mget_post_process.Average(), 0); | |
479 | ASSERT_GT(hist_mget_num_memtable_checked.Average(), 0); | |
480 | } | |
481 | } | |
482 | ||
483 | #ifndef ROCKSDB_LITE | |
484 | TEST_F(PerfContextTest, KeyComparisonCount) { | |
485 | SetPerfLevel(kEnableCount); | |
486 | ProfileQueries(); | |
487 | ||
488 | SetPerfLevel(kDisable); | |
489 | ProfileQueries(); | |
490 | ||
491 | SetPerfLevel(kEnableTime); | |
492 | ProfileQueries(true); | |
493 | } | |
494 | #endif // ROCKSDB_LITE | |
495 | ||
496 | // make perf_context_test | |
497 | // export ROCKSDB_TESTS=PerfContextTest.SeekKeyComparison | |
498 | // For one memtable: | |
499 | // ./perf_context_test --write_buffer_size=500000 --total_keys=10000 | |
500 | // For two memtables: | |
501 | // ./perf_context_test --write_buffer_size=250000 --total_keys=10000 | |
502 | // Specify --random_key=1 to shuffle the key before insertion | |
503 | // Results show that, for sequential insertion, worst-case Seek Key comparison | |
504 | // is close to the total number of keys (linear), when there is only one | |
505 | // memtable. When there are two memtables, even the avg Seek Key comparison | |
506 | // starts to become linear to the input size. | |
507 | ||
508 | TEST_F(PerfContextTest, SeekKeyComparison) { | |
509 | DestroyDB(kDbName, Options()); | |
510 | auto db = OpenDb(); | |
511 | WriteOptions write_options; | |
512 | ReadOptions read_options; | |
513 | ||
514 | if (FLAGS_verbose) { | |
515 | std::cout << "Inserting " << FLAGS_total_keys << " key/value pairs\n...\n"; | |
516 | } | |
517 | ||
518 | std::vector<int> keys; | |
519 | for (int i = 0; i < FLAGS_total_keys; ++i) { | |
520 | keys.push_back(i); | |
521 | } | |
522 | ||
523 | if (FLAGS_random_key) { | |
524 | std::random_shuffle(keys.begin(), keys.end()); | |
525 | } | |
526 | ||
527 | HistogramImpl hist_put_time; | |
528 | HistogramImpl hist_wal_time; | |
529 | HistogramImpl hist_time_diff; | |
530 | ||
531 | SetPerfLevel(kEnableTime); | |
532 | StopWatchNano timer(Env::Default()); | |
533 | for (const int i : keys) { | |
534 | std::string key = "k" + ToString(i); | |
535 | std::string value = "v" + ToString(i); | |
536 | ||
11fdf7f2 | 537 | get_perf_context()->Reset(); |
7c673cae FG |
538 | timer.Start(); |
539 | db->Put(write_options, key, value); | |
540 | auto put_time = timer.ElapsedNanos(); | |
541 | hist_put_time.Add(put_time); | |
11fdf7f2 TL |
542 | hist_wal_time.Add(get_perf_context()->write_wal_time); |
543 | hist_time_diff.Add(put_time - get_perf_context()->write_wal_time); | |
7c673cae FG |
544 | } |
545 | ||
546 | if (FLAGS_verbose) { | |
547 | std::cout << "Put time:\n" << hist_put_time.ToString() << "WAL time:\n" | |
548 | << hist_wal_time.ToString() << "time diff:\n" | |
549 | << hist_time_diff.ToString(); | |
550 | } | |
551 | ||
552 | HistogramImpl hist_seek; | |
553 | HistogramImpl hist_next; | |
554 | ||
555 | for (int i = 0; i < FLAGS_total_keys; ++i) { | |
556 | std::string key = "k" + ToString(i); | |
557 | std::string value = "v" + ToString(i); | |
558 | ||
559 | std::unique_ptr<Iterator> iter(db->NewIterator(read_options)); | |
11fdf7f2 | 560 | get_perf_context()->Reset(); |
7c673cae FG |
561 | iter->Seek(key); |
562 | ASSERT_TRUE(iter->Valid()); | |
563 | ASSERT_EQ(iter->value().ToString(), value); | |
11fdf7f2 | 564 | hist_seek.Add(get_perf_context()->user_key_comparison_count); |
7c673cae FG |
565 | } |
566 | ||
567 | std::unique_ptr<Iterator> iter(db->NewIterator(read_options)); | |
568 | for (iter->SeekToFirst(); iter->Valid();) { | |
11fdf7f2 | 569 | get_perf_context()->Reset(); |
7c673cae | 570 | iter->Next(); |
11fdf7f2 | 571 | hist_next.Add(get_perf_context()->user_key_comparison_count); |
7c673cae FG |
572 | } |
573 | ||
574 | if (FLAGS_verbose) { | |
575 | std::cout << "Seek:\n" << hist_seek.ToString() << "Next:\n" | |
576 | << hist_next.ToString(); | |
577 | } | |
578 | } | |
579 | ||
580 | TEST_F(PerfContextTest, DBMutexLockCounter) { | |
581 | int stats_code[] = {0, static_cast<int>(DB_MUTEX_WAIT_MICROS)}; | |
582 | for (PerfLevel perf_level : | |
583 | {PerfLevel::kEnableTimeExceptForMutex, PerfLevel::kEnableTime}) { | |
584 | for (int c = 0; c < 2; ++c) { | |
585 | InstrumentedMutex mutex(nullptr, Env::Default(), stats_code[c]); | |
586 | mutex.Lock(); | |
587 | rocksdb::port::Thread child_thread([&] { | |
588 | SetPerfLevel(perf_level); | |
11fdf7f2 TL |
589 | get_perf_context()->Reset(); |
590 | ASSERT_EQ(get_perf_context()->db_mutex_lock_nanos, 0); | |
7c673cae FG |
591 | mutex.Lock(); |
592 | mutex.Unlock(); | |
593 | if (perf_level == PerfLevel::kEnableTimeExceptForMutex || | |
594 | stats_code[c] != DB_MUTEX_WAIT_MICROS) { | |
11fdf7f2 | 595 | ASSERT_EQ(get_perf_context()->db_mutex_lock_nanos, 0); |
7c673cae FG |
596 | } else { |
597 | // increment the counter only when it's a DB Mutex | |
11fdf7f2 | 598 | ASSERT_GT(get_perf_context()->db_mutex_lock_nanos, 0); |
7c673cae FG |
599 | } |
600 | }); | |
601 | Env::Default()->SleepForMicroseconds(100); | |
602 | mutex.Unlock(); | |
603 | child_thread.join(); | |
604 | } | |
605 | } | |
606 | } | |
607 | ||
608 | TEST_F(PerfContextTest, FalseDBMutexWait) { | |
609 | SetPerfLevel(kEnableTime); | |
610 | int stats_code[] = {0, static_cast<int>(DB_MUTEX_WAIT_MICROS)}; | |
611 | for (int c = 0; c < 2; ++c) { | |
612 | InstrumentedMutex mutex(nullptr, Env::Default(), stats_code[c]); | |
613 | InstrumentedCondVar lock(&mutex); | |
11fdf7f2 | 614 | get_perf_context()->Reset(); |
7c673cae FG |
615 | mutex.Lock(); |
616 | lock.TimedWait(100); | |
617 | mutex.Unlock(); | |
618 | if (stats_code[c] == static_cast<int>(DB_MUTEX_WAIT_MICROS)) { | |
619 | // increment the counter only when it's a DB Mutex | |
11fdf7f2 | 620 | ASSERT_GT(get_perf_context()->db_condition_wait_nanos, 0); |
7c673cae | 621 | } else { |
11fdf7f2 | 622 | ASSERT_EQ(get_perf_context()->db_condition_wait_nanos, 0); |
7c673cae FG |
623 | } |
624 | } | |
625 | } | |
626 | ||
627 | TEST_F(PerfContextTest, ToString) { | |
11fdf7f2 TL |
628 | get_perf_context()->Reset(); |
629 | get_perf_context()->block_read_count = 12345; | |
7c673cae | 630 | |
11fdf7f2 | 631 | std::string zero_included = get_perf_context()->ToString(); |
7c673cae FG |
632 | ASSERT_NE(std::string::npos, zero_included.find("= 0")); |
633 | ASSERT_NE(std::string::npos, zero_included.find("= 12345")); | |
634 | ||
11fdf7f2 | 635 | std::string zero_excluded = get_perf_context()->ToString(true); |
7c673cae FG |
636 | ASSERT_EQ(std::string::npos, zero_excluded.find("= 0")); |
637 | ASSERT_NE(std::string::npos, zero_excluded.find("= 12345")); | |
638 | } | |
639 | ||
640 | TEST_F(PerfContextTest, MergeOperatorTime) { | |
641 | DestroyDB(kDbName, Options()); | |
642 | DB* db; | |
643 | Options options; | |
644 | options.create_if_missing = true; | |
645 | options.merge_operator = MergeOperators::CreateStringAppendOperator(); | |
646 | Status s = DB::Open(options, kDbName, &db); | |
647 | EXPECT_OK(s); | |
648 | ||
649 | std::string val; | |
650 | ASSERT_OK(db->Merge(WriteOptions(), "k1", "val1")); | |
651 | ASSERT_OK(db->Merge(WriteOptions(), "k1", "val2")); | |
652 | ASSERT_OK(db->Merge(WriteOptions(), "k1", "val3")); | |
653 | ASSERT_OK(db->Merge(WriteOptions(), "k1", "val4")); | |
654 | ||
655 | SetPerfLevel(kEnableTime); | |
11fdf7f2 | 656 | get_perf_context()->Reset(); |
7c673cae FG |
657 | ASSERT_OK(db->Get(ReadOptions(), "k1", &val)); |
658 | #ifdef OS_SOLARIS | |
659 | for (int i = 0; i < 100; i++) { | |
660 | ASSERT_OK(db->Get(ReadOptions(), "k1", &val)); | |
661 | } | |
662 | #endif | |
11fdf7f2 | 663 | EXPECT_GT(get_perf_context()->merge_operator_time_nanos, 0); |
7c673cae FG |
664 | |
665 | ASSERT_OK(db->Flush(FlushOptions())); | |
666 | ||
11fdf7f2 | 667 | get_perf_context()->Reset(); |
7c673cae FG |
668 | ASSERT_OK(db->Get(ReadOptions(), "k1", &val)); |
669 | #ifdef OS_SOLARIS | |
670 | for (int i = 0; i < 100; i++) { | |
671 | ASSERT_OK(db->Get(ReadOptions(), "k1", &val)); | |
672 | } | |
673 | #endif | |
11fdf7f2 | 674 | EXPECT_GT(get_perf_context()->merge_operator_time_nanos, 0); |
7c673cae FG |
675 | |
676 | ASSERT_OK(db->CompactRange(CompactRangeOptions(), nullptr, nullptr)); | |
677 | ||
11fdf7f2 | 678 | get_perf_context()->Reset(); |
7c673cae FG |
679 | ASSERT_OK(db->Get(ReadOptions(), "k1", &val)); |
680 | #ifdef OS_SOLARIS | |
681 | for (int i = 0; i < 100; i++) { | |
682 | ASSERT_OK(db->Get(ReadOptions(), "k1", &val)); | |
683 | } | |
684 | #endif | |
11fdf7f2 | 685 | EXPECT_GT(get_perf_context()->merge_operator_time_nanos, 0); |
7c673cae FG |
686 | |
687 | delete db; | |
688 | } | |
689 | } | |
690 | ||
691 | int main(int argc, char** argv) { | |
692 | ::testing::InitGoogleTest(&argc, argv); | |
693 | ||
694 | for (int i = 1; i < argc; i++) { | |
695 | int n; | |
696 | char junk; | |
697 | ||
698 | if (sscanf(argv[i], "--write_buffer_size=%d%c", &n, &junk) == 1) { | |
699 | FLAGS_write_buffer_size = n; | |
700 | } | |
701 | ||
702 | if (sscanf(argv[i], "--total_keys=%d%c", &n, &junk) == 1) { | |
703 | FLAGS_total_keys = n; | |
704 | } | |
705 | ||
706 | if (sscanf(argv[i], "--random_key=%d%c", &n, &junk) == 1 && | |
707 | (n == 0 || n == 1)) { | |
708 | FLAGS_random_key = n; | |
709 | } | |
710 | ||
711 | if (sscanf(argv[i], "--use_set_based_memetable=%d%c", &n, &junk) == 1 && | |
712 | (n == 0 || n == 1)) { | |
713 | FLAGS_use_set_based_memetable = n; | |
714 | } | |
715 | ||
716 | if (sscanf(argv[i], "--verbose=%d%c", &n, &junk) == 1 && | |
717 | (n == 0 || n == 1)) { | |
718 | FLAGS_verbose = n; | |
719 | } | |
720 | } | |
721 | ||
722 | if (FLAGS_verbose) { | |
723 | std::cout << kDbName << "\n"; | |
724 | } | |
725 | ||
726 | return RUN_ALL_TESTS(); | |
727 | } |