move dump stats to a separate thread #4382

miasantreble · 2018-09-17T21:17:11Z

Currently statistics are supposed to be dumped to info log at intervals of options.stats_dump_period_sec. However the implementation choice was to bind it with compaction thread, meaning if the database has been serving very light traffic, the stats may not get dumped at all.
We decided to separate stats dumping into a new timed thread using TimerQueue, which is already used in blob_db. This will allow us schedule new timed tasks with more deterministic behavior.

Tested with db_bench using --stats_dump_period_sec=20 in command line:

LOG:2018/09/17-14:07:45.575025 7fe99fbfe700 [WARN] [db/db_impl.cc:605] ------- DUMPING STATS -------
LOG:2018/09/17-14:08:05.643286 7fe99fbfe700 [WARN] [db/db_impl.cc:605] ------- DUMPING STATS -------
LOG:2018/09/17-14:08:25.691325 7fe99fbfe700 [WARN] [db/db_impl.cc:605] ------- DUMPING STATS -------
LOG:2018/09/17-14:08:45.740989 7fe99fbfe700 [WARN] [db/db_impl.cc:605] ------- DUMPING STATS -------

LOG content:

2018/09/17-14:07:45.575025 7fe99fbfe700 [WARN] [db/db_impl.cc:605] ------- DUMPING STATS -------
2018/09/17-14:07:45.575080 7fe99fbfe700 [WARN] [db/db_impl.cc:606]
** DB Stats **
Uptime(secs): 20.0 total, 20.0 interval
Cumulative writes: 4447K writes, 4447K keys, 4447K commit groups, 1.0 writes per commit group, ingest: 5.57 GB, 285.01 MB/s
Cumulative WAL: 4447K writes, 0 syncs, 4447638.00 writes per sync, written: 5.57 GB, 285.01 MB/s
Cumulative stall: 00:00:0.012 H:M:S, 0.1 percent
Interval writes: 4447K writes, 4447K keys, 4447K commit groups, 1.0 writes per commit group, ingest: 5700.71 MB, 285.01 MB/s
Interval WAL: 4447K writes, 0 syncs, 4447638.00 writes per sync, written: 5.57 MB, 285.01 MB/s
Interval stall: 00:00:0.012 H:M:S, 0.1 percent
** Compaction Stats [default] **
Level Files Size Score Read(GB) Rn(GB) Rnp1(GB) Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) Comp(sec) Comp(cnt) Avg(sec) KeyIn KeyDrop

sagar0 · 2018-09-18T17:45:57Z

db/db_impl.cc

-  }
+  PrintStatistics();
+
+  return std::make_pair(true, -1);


Don't you need to re-enqueue into the timer queue after printing? Or does the timer queue take care of automatically calling the function the next time timer expires?

I think by returning make_pair(true, -1) it will automatically re-enqueue, if I understood this comment correctly: https://github.com/facebook/rocksdb/blob/master/utilities/blob_db/blob_db_impl.cc#L1185
I will double check the documentation to confirm this behavior.

I think this is where requeueing happens: https://github.com/facebook/rocksdb/blob/master/util/timer_queue.h#L186
Basically if the boolean is set to true it will be requeued, otherwise no

riversand963

Thanks @miasantreble for adding this. I've left a few comments.

riversand963 · 2018-09-18T21:52:18Z

db/db_impl.cc

-  const uint64_t now_micros = env_->NowMicros();
+void DBImpl::StartTimedTasks() {
+  tqueue_.add(static_cast<int64_t>(
+              mutable_db_options_.stats_dump_period_sec * 1000),


The type of mutable_db_options_.stats_dump_period_sec is unsigned int. Multiplying an unsigned int with 1000 (32-bit int) may cause overflow before static_cast<int64_t> comes into play. Therefore, I suggest that we use static_cast<int64_t>(stats_dump_period_sec) * 1000 or something similar.

What if stats_dump_period_sec is 0?

good catch, thanks

riversand963 · 2018-09-18T21:57:30Z

db/db_impl.h

@@ -1509,6 +1513,9 @@ class DBImpl : public DB {
    return Env::WLTH_SHORT;
  }

+  // timer based queue to execute tasks
+  TimerQueue tqueue_;


Nit: can we use a more meaningful name?

facebook-github-bot

miasantreble has imported this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

yiwu-arbug · 2018-09-21T21:30:02Z

In fact, I don't suggest we use TimerQueue. The code didn't go through good code review and has weird interface. Unless we are going to run one more round of code review on TimerQueeu, I'm wondering if it is an option if we submit the stat dump job to compaction thread pool. Sorry for making a late request like this.

sagar0 · 2018-09-21T22:58:39Z

We can definitely move the dumping to a separate low-priority thread (similar to the ones in compaction thread pool); but still, that doesn't have offer the functionality of running that thread every x seconds. I believe it might be good to re-visit Timers implementation and improve them if we know of any major issues in there (improve the in interface, maybe?).

yiwu-arbug · 2018-09-24T00:41:53Z

@sagar0 I plan to send a PR to reimplement RepeatableThread from fbcode, which uses CondVar::Wait() to run callback periodically. This one will be simpler to understand because it doesn't have queueing.

Regarding TimerQueue, I doubt if we had even go through legal to check if it is okay to use the code (though from the license statement it looks okay). I didn't go through the code thoroughly to inspect if there's any issue. One thing I want to improve on it is to have it use time methods from Env instead of std::chrono so we can mock the time in tests.

miasantreble · 2018-09-24T17:00:17Z

@yiwu-arbug I will hold this PR and wait for your RepeatableThread PR. Thanks

yiwu-arbug · 2018-09-25T00:03:22Z

db/db_impl.cc

-
-  const uint64_t now_micros = env_->NowMicros();
+void DBImpl::StartTimedTasks() {
+  if (mutable_db_options_.stats_dump_period_sec > 0) {


Should hold db mutex when access mutable_db_options_.

yiwu-arbug · 2018-09-25T00:04:36Z

db/db_impl.cc

-
-  const uint64_t now_micros = env_->NowMicros();
+void DBImpl::StartTimedTasks() {
+  if (mutable_db_options_.stats_dump_period_sec > 0) {


stats_dump_period_sec is dynamic changeable. How do you handle that?

added logic in SetOptions to cancel and relaunch thread

Summary: Introduce `RepeatableThread` utility to run task periodically in a separate thread. It is basically the same as the the same class in fbcode, and in addition provide a helper method to let tests mock time and trigger execution one at a time. We can use this class to replace `TimerQueue` in #4382 and `BlobDB`. Pull Request resolved: #4423 Differential Revision: D10020932 Pulled By: yiwu-arbug fbshipit-source-id: 3616bef108c39a33c92eedb1256de424b7c04087

facebook-github-bot · 2018-10-02T19:01:51Z

@miasantreble has updated the pull request. Re-import the pull request

facebook-github-bot · 2018-10-03T23:52:33Z

@miasantreble has updated the pull request. Re-import the pull request

facebook-github-bot · 2018-10-04T17:29:07Z

@miasantreble has updated the pull request. Re-import the pull request

facebook-github-bot

miasantreble has imported this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

yiwu-arbug · 2018-10-05T17:45:15Z

db/db_impl.cc

+        }
+        thread_dump_stats_ = new rocksdb::RepeatableThread(
+            [this]() { DBImpl::MaybeDumpStats(); }, "dump_st", env_,
+            new_options.stats_dump_period_sec * 1000000);


check new_options.stats_dump_period_sec > 0.

yiwu-arbug · 2018-10-05T18:12:35Z

db/db_impl.cc

-    // atomically. We could see more than one dump during one dump
-    // period in rare cases.
-    last_stats_dump_time_microsec_ = now_micros;
+void DBImpl::MaybeDumpStats() {


nit: s/MaybeDumpStats/DumpStats ?

yiwu-arbug · 2018-10-05T18:14:58Z

db/db_impl.cc

+  assert(db_property_info != nullptr);
+
+  std::string stats;
+  if (shutdown_initiated_) {


shutdown_initiated_ is not an atomic, and I believe accessing it also require holding db mutex. Maybe you want to turn it into an atomic?

yiwu-arbug · 2018-10-05T18:19:43Z

db/db_impl.h

@@ -1468,6 +1472,8 @@ class DBImpl : public DB {
  // Only to be set during initialization
  std::unique_ptr<PreReleaseCallback> recoverable_state_pre_release_callback_;

+  rocksdb::RepeatableThread* thread_dump_stats_ = nullptr;


Make it a unique_ptr, and always hold db mutex when setting/unsetting it.

yiwu-arbug · 2018-10-05T19:43:24Z

Do you want to include a test with the change? :)

miasantreble · 2018-10-07T21:31:47Z

@yiwu-arbug I'm wondering if DB::Open() covers all cases where stats dumping is needed, in other words, is there other code path that doesn't go through DB::Open() but RocksDB may still be collecting stats?
About tests, I didn't find any existing test coverage for stats dumping so it's reasonable to ask for new test coverage. However I'm not sure if we have test infrastructure to verify what's being written to info logs. I did run db_bench to manually verify though

facebook-github-bot · 2018-10-08T02:24:38Z

@miasantreble has updated the pull request. Re-import the pull request

facebook-github-bot

miasantreble has imported this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

yiwu-arbug · 2018-10-08T17:37:24Z

@miasantreble I believe it is safe to assume DB has to go through Open() before collecting stats.

For test, how about just a sync point inside DumpStats and check it is triggered? If you have extra bandwidth, mocking Logger should not be difficult either.

yiwu-arbug

LGTM overall. Thanks!

yiwu-arbug · 2018-10-08T17:42:12Z

db/db_impl.cc

@@ -762,6 +771,18 @@ Status DBImpl::SetDBOptions(
            new_options.max_background_compactions, Env::Priority::LOW);
        MaybeScheduleFlushOrCompaction();
      }
+      if (new_options.stats_dump_period_sec > 0 &&


cancel thread_dump_stats_ if new_options.stats_dump_period == 0?

facebook-github-bot · 2018-10-08T20:11:18Z

@miasantreble has updated the pull request. Re-import the pull request

facebook-github-bot

miasantreble has imported this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

yiwu-arbug · 2018-10-08T21:06:59Z

db/db_impl.cc

@@ -771,7 +773,15 @@ Status DBImpl::SetDBOptions(
            new_options.max_background_compactions, Env::Priority::LOW);
        MaybeScheduleFlushOrCompaction();
      }
-      if (new_options.stats_dump_period_sec > 0 &&
+      if (new_options.stats_dump_period_sec == 0) {


nit: The logic can be simplified as

if (new_options.xxx != existing_options.xxx) { if (thread_dump_stats_ != nullptr) { cancel_thread(); } if (new_options.xxx > 0) { start_thread(); } }

yiwu-arbug · 2018-10-08T21:12:27Z

db/db_options_test.cc

+  rocksdb::SyncPoint::GetInstance()->EnableProcessing();
+  Reopen(options);
+  ASSERT_EQ(5, dbfull()->GetDBOptions().stats_dump_period_sec);
+  env_->SleepForMicroseconds(6000000);


It might be flaky to rely on sleep. Do you consider either use a cond var like the RepeatableThreadTest::TimedTest, or use MockTimeEnv like RepeatableThreadTest::MockEnvTest to make the test more deterministic? :)
https://github.com/facebook/rocksdb/blob/master/util/repeatable_thread_test.cc#L22

facebook-github-bot · 2018-10-08T22:28:39Z

@miasantreble has updated the pull request. Re-import the pull request

facebook-github-bot

miasantreble has imported this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

facebook-github-bot

miasantreble has imported this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

facebook-github-bot · 2018-10-09T04:19:55Z

@miasantreble has updated the pull request. Re-import the pull request

facebook-github-bot

miasantreble has imported this pull request. If you are a Facebook employee, you can view this diff on Phabricator.

miasantreble requested review from sagar0 and siying September 17, 2018 21:17

facebook-github-bot added the CLA Signed label Sep 17, 2018

miasantreble changed the title ~~move dump stats in a separate thread~~ move dump stats to a separate thread Sep 17, 2018

sagar0 reviewed Sep 18, 2018

View reviewed changes

riversand963 reviewed Sep 18, 2018

View reviewed changes

facebook-github-bot reviewed Sep 19, 2018

View reviewed changes

yiwu-arbug mentioned this pull request Sep 24, 2018

Utility to run task periodically in a thread #4423

Closed

yiwu-arbug reviewed Sep 25, 2018

View reviewed changes

miasantreble added 3 commits October 2, 2018 12:00

move dump stats in a separate thread

3105c30

add cast to avoid overflow

fe887bc

use RepeatableThread to schedule timed task

6e90ec4

miasantreble force-pushed the dump-stats-separate-thread branch from 8b92d67 to 6e90ec4 Compare October 2, 2018 19:01

fix hang & address review comments

08d7efc

fix deadlock

c071d5b

facebook-github-bot reviewed Oct 4, 2018

View reviewed changes

yiwu-arbug reviewed Oct 5, 2018

View reviewed changes

address Yi's comments

6f4436f

facebook-github-bot reviewed Oct 8, 2018

View reviewed changes

yiwu-arbug reviewed Oct 8, 2018

View reviewed changes

add test coverage

7236bf5

facebook-github-bot reviewed Oct 8, 2018

View reviewed changes

yiwu-arbug approved these changes Oct 8, 2018

View reviewed changes

address review comments

7ad5d45

facebook-github-bot reviewed Oct 8, 2018

View reviewed changes

yiwu-arbug approved these changes Oct 8, 2018

View reviewed changes

facebook-github-bot reviewed Oct 8, 2018

View reviewed changes

fix travis crash

7fa6a49

facebook-github-bot reviewed Oct 9, 2018

View reviewed changes

facebook-github-bot closed this in cac87fc Oct 9, 2018

miasantreble deleted the dump-stats-separate-thread branch October 9, 2018 21:23

move dump stats to a separate thread #4382

move dump stats to a separate thread #4382

Conversation

miasantreble commented Sep 17, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

riversand963 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

facebook-github-bot left a comment

Choose a reason for hiding this comment

yiwu-arbug commented Sep 21, 2018

sagar0 commented Sep 21, 2018 • edited Loading

yiwu-arbug commented Sep 24, 2018

miasantreble commented Sep 24, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

miasantreble Oct 4, 2018 • edited Loading

Choose a reason for hiding this comment

facebook-github-bot commented Oct 2, 2018

facebook-github-bot commented Oct 3, 2018

facebook-github-bot commented Oct 4, 2018

facebook-github-bot left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yiwu-arbug commented Oct 5, 2018

miasantreble commented Oct 7, 2018 • edited Loading

facebook-github-bot commented Oct 8, 2018

facebook-github-bot left a comment

Choose a reason for hiding this comment

yiwu-arbug commented Oct 8, 2018

yiwu-arbug left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

facebook-github-bot commented Oct 8, 2018

facebook-github-bot left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

facebook-github-bot commented Oct 8, 2018

facebook-github-bot left a comment

Choose a reason for hiding this comment

facebook-github-bot left a comment

Choose a reason for hiding this comment

facebook-github-bot commented Oct 9, 2018

facebook-github-bot left a comment

Choose a reason for hiding this comment

miasantreble commented Sep 17, 2018 •

edited

Loading

sagar0 commented Sep 21, 2018 •

edited

Loading

miasantreble Oct 4, 2018 •

edited

Loading

miasantreble commented Oct 7, 2018 •

edited

Loading