2013-10-16 21:59:46 +00:00
|
|
|
// Copyright (c) 2013, Facebook, Inc. All rights reserved.
|
|
|
|
// This source code is licensed under the BSD-style license found in the
|
|
|
|
// LICENSE file in the root directory of this source tree. An additional grant
|
|
|
|
// of patent rights can be found in the PATENTS file in the same directory.
|
|
|
|
//
|
2013-10-05 05:32:05 +00:00
|
|
|
#pragma once
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 06:09:15 +00:00
|
|
|
#include "rocksdb/perf_context.h"
|
|
|
|
#include "util/stop_watch.h"
|
|
|
|
|
2013-10-04 04:49:15 +00:00
|
|
|
namespace rocksdb {
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 06:09:15 +00:00
|
|
|
|
2014-04-08 17:58:07 +00:00
|
|
|
#if defined(NPERF_CONTEXT) || defined(IOS_CROSS_COMPILE)
|
|
|
|
|
|
|
|
#define PERF_TIMER_DECLARE()
|
|
|
|
#define PERF_TIMER_START(metric)
|
|
|
|
#define PERF_TIMER_AUTO(metric)
|
|
|
|
#define PERF_TIMER_MEASURE(metric)
|
|
|
|
#define PERF_TIMER_STOP(metric)
|
|
|
|
#define PERF_COUNTER_ADD(metric, value)
|
|
|
|
|
2014-04-04 20:11:44 +00:00
|
|
|
#else
|
2014-04-08 17:58:07 +00:00
|
|
|
|
2014-04-03 05:59:48 +00:00
|
|
|
extern __thread PerfLevel perf_level;
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 06:09:15 +00:00
|
|
|
|
2014-04-08 17:58:07 +00:00
|
|
|
class PerfStepTimer {
|
|
|
|
public:
|
|
|
|
PerfStepTimer()
|
|
|
|
: enabled_(perf_level >= PerfLevel::kEnableTime),
|
|
|
|
env_(enabled_ ? Env::Default() : nullptr),
|
|
|
|
start_(0) {
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 06:09:15 +00:00
|
|
|
}
|
|
|
|
|
2014-04-08 17:58:07 +00:00
|
|
|
void Start() {
|
|
|
|
if (enabled_) {
|
|
|
|
start_ = env_->NowNanos();
|
|
|
|
}
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 06:09:15 +00:00
|
|
|
}
|
|
|
|
|
2014-04-08 17:58:07 +00:00
|
|
|
void Measure(uint64_t* metric) {
|
|
|
|
if (start_) {
|
|
|
|
uint64_t now = env_->NowNanos();
|
|
|
|
*metric += now - start_;
|
|
|
|
start_ = now;
|
|
|
|
}
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 06:09:15 +00:00
|
|
|
}
|
2014-04-08 17:58:07 +00:00
|
|
|
|
|
|
|
void Stop(uint64_t* metric) {
|
|
|
|
if (start_) {
|
|
|
|
*metric += env_->NowNanos() - start_;
|
|
|
|
start_ = 0;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
private:
|
|
|
|
const bool enabled_;
|
|
|
|
Env* const env_;
|
|
|
|
uint64_t start_;
|
|
|
|
};
|
|
|
|
|
|
|
|
// Declare the local timer object to be used later on
|
|
|
|
#define PERF_TIMER_DECLARE() \
|
|
|
|
PerfStepTimer perf_step_timer;
|
|
|
|
|
|
|
|
// Set start time of the timer
|
|
|
|
#define PERF_TIMER_START(metric) \
|
|
|
|
perf_step_timer.Start();
|
|
|
|
|
|
|
|
// Declare and set start time of the timer
|
|
|
|
#define PERF_TIMER_AUTO(metric) \
|
|
|
|
PerfStepTimer perf_step_timer; \
|
|
|
|
perf_step_timer.Start();
|
|
|
|
|
|
|
|
// Update metric with time elapsed since last START. start time is reset
|
|
|
|
// to current timestamp.
|
|
|
|
#define PERF_TIMER_MEASURE(metric) \
|
|
|
|
perf_step_timer.Measure(&(perf_context.metric));
|
|
|
|
|
|
|
|
// Update metric with time elapsed since last START. But start time is not set.
|
|
|
|
#define PERF_TIMER_STOP(metric) \
|
|
|
|
perf_step_timer.Stop(&(perf_context.metric));
|
|
|
|
|
|
|
|
// Increase metric value
|
|
|
|
#define PERF_COUNTER_ADD(metric, value) \
|
|
|
|
perf_context.metric += value;
|
|
|
|
|
|
|
|
#endif
|
[RocksDB] Added nano second stopwatch and new perf counters to track block read cost
Summary: The pupose of this diff is to expose per user-call level precise timing of block read, so that we can answer questions like: a Get() costs me 100ms, is that somehow related to loading blocks from file system, or sth else? We will answer that with EXACTLY how many blocks have been read, how much time was spent on transfering the bytes from os, how much time was spent on checksum verification and how much time was spent on block decompression, just for that one Get. A nano second stopwatch was introduced to track time with higher precision. The cost/precision of the stopwatch is also measured in unit-test. On my dev box, retrieving one time instance costs about 30ns, on average. The deviation of timing results is good enough to track 100ns-1us level events. And the overhead could be safely ignored for 100us level events (10000 instances/s), for example, a viewstate thrift call.
Test Plan: perf_context_test, also testing with viewstate shadow traffic.
Reviewers: dhruba
Reviewed By: dhruba
CC: leveldb, xjin
Differential Revision: https://reviews.facebook.net/D12351
2013-06-04 06:09:15 +00:00
|
|
|
|
|
|
|
}
|