Commit af5c4044 authored by Zhang Jingwang's avatar Zhang Jingwang Committed by Dries Kimpe
Browse files

Add performance counter to monitor write performance.

Five counters are added by this commit, here is the details:
- write_sm: Counter on how many write state machine tasks are created.
  It will be increased by one when a new write request arrives.
- write_sm_livetime: The duration from a specific write request is
  created to the time it is deleted.
- write_sm_recvtime: The time duration spent to receive the data buffer
  from the client in a write request.
- write_sm_waittime: The time duration spent in waiting for CPU in the
  task queue for every write request.
- write_sm_fsiotime: The time duration spent in performing IO requests
  to the backend file system.

This commit added a dumper thread to dump all the counters to std::cout
periodically. You can start this thread by giving a positive number to
"counters { dumpinterval = %% }" in the configure file.

These counters could be enabled separately in the configure file, this
commit also demonstrated how to do that.

Change-Id: Ieaf4d1f6c2ed71e8c17df3ab1f588be133c88a5a
parent b616dabf
......@@ -213,3 +213,9 @@ requesthandler {
//}
}
counters
{
sm = "write_sm_livetime.time.single.counter,write_sm.inc.single.counter,write_sm_recvtime.time.single.counter";
dumpinterval = "1";
}
......@@ -83,7 +83,8 @@ void IOFWDMain::boot ()
ZLOG_DEBUG (mainlog_, "Starting IOFWD Frontend");
//frontend_.reset (new frontend::IOFWDFrontend (*resources_));
iofwdutil::stats::CounterConfig::instance().parseConfig(config_.openSectionDefault ("counters"));
frontend_->setConfig (config_.openSectionDefault ("frontend"));
frontend_->init ();
......@@ -115,13 +116,39 @@ void IOFWDMain::shutdown ()
iofwdutil::stats::CounterTable::instance().dumpCounters();
}
class CounterMonitor {
int sleeptime;
public:
CounterMonitor(int i = 1) : sleeptime(i) {};
void operator()() {
while (true) {
sleep(sleeptime);
iofwdutil::stats::CounterTable::instance().dumpCounters();
}
}
};
void IOFWDMain::run ()
{
// Start counters dumper
ConfigFile config(config_.openSectionDefault("counters"));
try
{
int dumpinterval = config.getKeyAs<int>("dumpinterval");
if (dumpinterval > 0) {
CounterMonitor cm(dumpinterval);
boost::thread counterDumper(cm);
}
}
catch (const iofwdutil::CFKeyMissingException &e)
{
// It's OK, if dumpinterval is missing, we don't dump counters.
}
// Wait for ctrl-c
sigset_t set;
sigemptyset (&set);
if (!notrap_)
sigaddset (&set, SIGINT);
......
#include "iofwd/tasksm/WriteTaskSM.hh"
#include "zoidfs/zoidfs-proto.h"
#include "iofwdutil/stats/TimeCounter.hh"
#include "iofwdutil/stats/IncCounter.hh"
namespace sm {
template<>
void sm::SimpleSlots<1, iofwd::tasksm::WriteTaskSM>::callback(int pos, const iofwdevent::CBException e) {
boost::mutex::scoped_lock l(locks_[pos]);
Slot & s = slots_[pos];
ASSERT((s.status_ == WAITING) && "Need to use it as callback"
" first!");
if (s.next_)
{
// if next was set, we had already executed a 'wait' on this
// slot. We can transition right away and the slot becomes free.
// We need to any slot exception as the current pending exception.
next_method_t next = s.next_;
s.next_ = 0;
s.status_ = FREE;
// We unlock the mutex so, that if we end up destroying
// ourselves,
// we don't destroy a locked mutex.
l.unlock ();
iofwdutil::stats::TimeCounter *tc;
tc = iofwdutil::stats::TimeCounter::get("write_sm_waittime");
if (tc)
client_.wait_time = tc->start();
client_.resumeSM (next, e);
}
else
{
// Didn't do a wait on this slot yet. Store any exception in the
// slot and update the status to COMPLETED
s.status_ = COMPLETED;
s.exception_ = e;
}
}
}
namespace iofwd
{
......@@ -26,10 +69,28 @@ namespace iofwd
ret_(zoidfs::ZFS_OK),
pipeline_size_(0)
{
wait_time = 0;
total_wait = 0;
iofwdutil::stats::TimeCounter *tc;
tc = iofwdutil::stats::TimeCounter::get("write_sm_livetime");
if (tc)
create_time = tc->start();
iofwdutil::stats::IncCounter *ic;
ic = iofwdutil::stats::IncCounter::get("write_sm");
if (ic) ic->update();
}
WriteTaskSM::~WriteTaskSM()
{
iofwdutil::stats::TimeCounter *tc;
tc = iofwdutil::stats::TimeCounter::get("write_sm_livetime");
if (tc) {
double duration = tc->stop() - create_time;
tc->update(duration);
}
tc = iofwdutil::stats::TimeCounter::get("write_sm_waittime");
if (tc) tc->update(total_wait);
/* cleanup rbuffer_ wrappers */
for(int i = 0 ; i < total_buffers_ ; i++)
{
......@@ -45,9 +106,22 @@ namespace iofwd
delete &request_;
}
void WriteTaskSM::update_waittime() {
iofwdutil::stats::TimeCounter *tc;
tc = iofwdutil::stats::TimeCounter::get("write_sm_waittime");
if (tc && wait_time) {
total_wait += tc->stop() - wait_time;
wait_time = 0;
}
}
/* recv the input data to write to the disk */
void WriteTaskSM::recvBuffers()
{
iofwdutil::stats::TimeCounter *tc;
tc = iofwdutil::stats::TimeCounter::get("write_sm_recvtime");
if (tc)
recv_time = tc->start();
/* issue the recv buffer */
request_.recvBuffers(slots_[WRITE_SLOT], rbuffer_[0]);
......@@ -58,6 +132,11 @@ namespace iofwd
/* execute the write I/O path */
void WriteTaskSM::writeNormal()
{
iofwdutil::stats::TimeCounter *tc;
tc = iofwdutil::stats::TimeCounter::get("write_sm_fsiotime");
if (tc)
fsio_time = tc->start();
#if SIZEOF_SIZE_T == SIZEOF_INT64_T
api_->write(slots_[WRITE_SLOT], &ret_, p.handle, p.mem_count,
const_cast<const void**>(reinterpret_cast<void**>(p.mem_starts.get())), p.mem_sizes.get(),
......
......@@ -9,6 +9,7 @@
#include "iofwdutil/InjectPool.hh"
#include "iofwd/WriteRequest.hh"
#include "iofwdutil/InjectPool.hh"
#include "iofwdutil/stats/TimeCounter.hh"
#include "zoidfs/zoidfs.h"
......@@ -95,6 +96,7 @@ class WriteTaskSM : public sm::SimpleSM< WriteTaskSM >, public
void waitAllocateSingleBuffer(iofwdevent::CBException e)
{
e.check ();
update_waittime();
// init the task params
request_.initRequestParams(p, rbuffer_[0]->buffer_->getMemory());
......@@ -110,8 +112,15 @@ class WriteTaskSM : public sm::SimpleSM< WriteTaskSM >, public
void waitRecvInputBuffers(iofwdevent::CBException e)
{
update_waittime();
e.check ();
setNextMethod(&WriteTaskSM::postEnqueueWrite);
iofwdutil::stats::TimeCounter *tc;
tc = iofwdutil::stats::TimeCounter::get("write_sm_recvtime");
if (tc) {
double duration = tc->stop() - recv_time;
tc->update(duration);
}
}
void postEnqueueWrite(iofwdevent::CBException e)
......@@ -122,11 +131,20 @@ class WriteTaskSM : public sm::SimpleSM< WriteTaskSM >, public
void waitEnqueueWrite(iofwdevent::CBException e)
{
update_waittime();
e.check ();
/* free the buffer */
request_.releaseBuffer(rbuffer_[0]);
setNextMethod(&WriteTaskSM::postReply);
iofwdutil::stats::TimeCounter *tc;
tc = iofwdutil::stats::TimeCounter::get("write_sm_fsiotime");
if (tc) {
double duration = tc->stop() - fsio_time;
tc->update(duration);
}
}
void postReply(iofwdevent::CBException e)
......@@ -137,6 +155,7 @@ class WriteTaskSM : public sm::SimpleSM< WriteTaskSM >, public
void waitReply(iofwdevent::CBException e)
{
update_waittime();
e.check ();
// done...
}
......@@ -228,6 +247,10 @@ class WriteTaskSM : public sm::SimpleSM< WriteTaskSM >, public
}
}
double wait_time;
double total_wait;
void update_waittime();
protected:
/* normal mode operations */
......@@ -276,6 +299,10 @@ class WriteTaskSM : public sm::SimpleSM< WriteTaskSM >, public
iofwdevent::CBType s_;
size_t pipeline_size_;
double create_time;
double recv_time;
double fsio_time;
};
}
}
......
......@@ -87,7 +87,7 @@ class CounterConfig : public iofwdutil::Singleton< CounterConfig >
public:
/* constructors, destructors, and assign ops */
CounterConfig();
CounterConfig(): log_ (iofwdutil::IOFWDLog::getSource ("counters")) {};
CounterConfig(const CounterConfig & rhs);
CounterConfig & operator= (const CounterConfig & rhs);
~CounterConfig();
......
......@@ -60,6 +60,9 @@ class SingleCounter : public BaseCounter
std::cout << name_
<< " "
<< boost::lexical_cast<std::string>(val_)
<< " " << counter_min()
<< " " << counter_mean()
<< " " << counter_max()
<< std::endl;
}
}
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment