contrib/fb303/cpp/ServiceTracker.cpp - packaging/sources/thrift - Gitiles

 /*
  * Licensed to the Apache Software Foundation (ASF) under one
  * or more contributor license agreements. See the NOTICE file
  * distributed with this work for additional information
  * regarding copyright ownership. The ASF licenses this file
  * to you under the Apache License, Version 2.0 (the
  * "License"); you may not use this file except in compliance
  * with the License. You may obtain a copy of the License at
  *
  *   http://www.apache.org/licenses/LICENSE-2.0
  *
  * Unless required by applicable law or agreed to in writing,
  * software distributed under the License is distributed on an
  * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
  * KIND, either express or implied. See the License for the
  * specific language governing permissions and limitations
  * under the License.
  */

 #include <sys/time.h>

 #include "FacebookBase.h"
 #include "ServiceTracker.h"
 #include <thrift/concurrency/ThreadManager.h>

 using namespace std;
 using namespace facebook::fb303;
 using namespace apache::thrift::concurrency;


 uint64_t ServiceTracker::CHECKPOINT_MINIMUM_INTERVAL_SECONDS = 60;
 int ServiceTracker::LOG_LEVEL = 5;


 ServiceTracker::ServiceTracker(facebook::fb303::FacebookBase *handler,
                                void (*logMethod)(int, const string &),
                                bool featureCheckpoint,
                                bool featureStatusCheck,
                                bool featureThreadCheck,
                                Stopwatch::Unit stopwatchUnit)
   : handler_(handler), logMethod_(logMethod),
     featureCheckpoint_(featureCheckpoint),
     featureStatusCheck_(featureStatusCheck),
     featureThreadCheck_(featureThreadCheck),
     stopwatchUnit_(stopwatchUnit),
     checkpointServices_(0)
 {
   if (featureCheckpoint_) {
     time_t now = time(NULL);
     checkpointTime_ = now;
   } else {
     checkpointTime_ = 0;
   }
 }

 /**
  * Registers the beginning of a "service method": basically, any of
  * the implementations of Thrift remote procedure calls that a
  * FacebookBase handler is handling.  Controls concurrent
  * services and reports statistics (via log and via fb303 counters).
  * Throws an exception if the server is not ready to handle service
  * methods yet.
  *
  * note: The relationship between startService() and finishService()
  * is currently defined so that a call to finishService() should only
  * be matched to this call to startService() if this method returns
  * without exception.  It wouldn't be a problem to implement things
  * the other way, so that *every* start needed a finish, but this
  * convention was chosen to match the way an object's constructor and
  * destructor work together, i.e. to work well with ServiceMethod
  * objects.
  *
  * @param const ServiceMethod &serviceMethod A reference to the ServiceMethod
  *                                           object instantiated at the start
  *                                           of the service method.
  */
 void
 ServiceTracker::startService(const ServiceMethod &serviceMethod)
 {
   // note: serviceMethod.timer_ automatically starts at construction.

   // log service start
   logMethod_(5, serviceMethod.signature_);

   // check handler ready
   if (featureStatusCheck_ && !serviceMethod.featureLogOnly_) {
     // note: Throwing exceptions before counting statistics.  See note
     // in method header.
     // note: A STOPPING server is not accepting new connections, but it
     // is still handling any already-connected threads -- so from the
     // service method's point of view, a status of STOPPING is a green
     // light.
     facebook::fb303::fb_status status = handler_->getStatus();
     if (status != facebook::fb303::ALIVE
         && status != facebook::fb303::STOPPING) {
       if (status == facebook::fb303::STARTING) {
         throw ServiceException("Server starting up; please try again later");
       } else {
         throw ServiceException("Server not alive; please try again later");
       }
     }
   }

   // check server threads
   if (featureThreadCheck_ && !serviceMethod.featureLogOnly_) {
     // note: Might want to put these messages in reportCheckpoint() if
     // log is getting spammed.
     if (threadManager_ != NULL) {
       size_t idle_count = threadManager_->idleWorkerCount();
       if (idle_count == 0) {
         stringstream message;
         message << "service " << serviceMethod.signature_
                 << ": all threads (" << threadManager_->workerCount()
                 << ") in use";
         logMethod_(3, message.str());
       }
     }
   }
 }

 /**
  * Logs a significant step in the middle of a "service method"; see
  * startService.
  *
  * @param const ServiceMethod &serviceMethod A reference to the ServiceMethod
  *                                           object instantiated at the start
  *                                           of the service method.
  * @return int64_t Elapsed units (see stopwatchUnit_) since ServiceMethod
  *                 instantiation.
  */
 int64_t
 ServiceTracker::stepService(const ServiceMethod &serviceMethod,
                             const string &stepName)
 {
   stringstream message;
   string elapsed_label;
   int64_t elapsed = serviceMethod.timer_.elapsedUnits(stopwatchUnit_,
                                                       &elapsed_label);
   message << serviceMethod.signature_
           << ' ' << stepName
           << " [" << elapsed_label << ']';
   logMethod_(5, message.str());
   return elapsed;
 }

 /**
  * Registers the end of a "service method"; see startService().
  *
  * @param const ServiceMethod &serviceMethod A reference to the ServiceMethod
  *                                           object instantiated at the start
  *                                           of the service method.
  */
 void
 ServiceTracker::finishService(const ServiceMethod &serviceMethod)
 {
   // log end of service
   stringstream message;
   string duration_label;
   int64_t duration = serviceMethod.timer_.elapsedUnits(stopwatchUnit_,
                                                        &duration_label);
   message << serviceMethod.signature_
           << " finish [" << duration_label << ']';
   logMethod_(5, message.str());

   // count, record, and maybe report service statistics
   if (!serviceMethod.featureLogOnly_) {

     if (!featureCheckpoint_) {

       // lifetime counters
       // (note: No need to lock statisticsMutex_ if not doing checkpoint;
       // FacebookService::incrementCounter() is already thread-safe.)
       handler_->incrementCounter("lifetime_services");

     } else {

       statisticsMutex_.lock();
       // note: No exceptions expected from this code block.  Wrap in a try
       // just to be safe.
       try {

         // lifetime counters
         // note: Good to synchronize this with the increment of
         // checkpoint services, even though incrementCounter() is
         // already thread-safe, for the sake of checkpoint reporting
         // consistency (i.e.  since the last checkpoint,
         // lifetime_services has incremented by checkpointServices_).
         handler_->incrementCounter("lifetime_services");

         // checkpoint counters
         checkpointServices_++;
         checkpointDuration_ += duration;

         // per-service timing
         // note kjv: According to my tests it is very slightly faster to
         // call insert() once (and detect not-found) than calling find()
         // and then maybe insert (if not-found).  However, the difference
         // is tiny for small maps like this one, and the code for the
         // faster solution is slightly less readable.  Also, I wonder if
         // the instantiation of the (often unused) pair to insert makes
         // the first algorithm slower after all.
         map<string, pair<uint64_t, uint64_t> >::iterator iter;
         iter = checkpointServiceDuration_.find(serviceMethod.name_);
         if (iter != checkpointServiceDuration_.end()) {
           iter->second.first++;
           iter->second.second += duration;
         } else {
           checkpointServiceDuration_.insert(make_pair(serviceMethod.name_,
                                                       make_pair(1, duration)));
         }

         // maybe report checkpoint
         // note: ...if it's been long enough since the last report.
         time_t now = time(NULL);
         uint64_t check_interval = now - checkpointTime_;
         if (check_interval >= CHECKPOINT_MINIMUM_INTERVAL_SECONDS) {
           reportCheckpoint();
         }

       } catch (...) {
         statisticsMutex_.unlock();
         throw;
       }
       statisticsMutex_.unlock();

     }
   }
 }

 /**
  * Logs some statistics gathered since the last call to this method.
  *
  * note: Thread race conditions on this method could cause
  * misreporting and/or undefined behavior; the caller must protect
  * uses of the object variables (and calls to this method) with a
  * mutex.
  *
  */
 void
 ServiceTracker::reportCheckpoint()
 {
   time_t now = time(NULL);

   uint64_t check_count = checkpointServices_;
   uint64_t check_interval = now - checkpointTime_;
   uint64_t check_duration = checkpointDuration_;

   // export counters for timing of service methods (by service name)
   handler_->setCounter("checkpoint_time", check_interval);
   map<string, pair<uint64_t, uint64_t> >::iterator iter;
   uint64_t count;
   for (iter = checkpointServiceDuration_.begin();
        iter != checkpointServiceDuration_.end();
        iter++) {
     count = iter->second.first;
     handler_->setCounter(string("checkpoint_count_") + iter->first, count);
     if (count == 0) {
       handler_->setCounter(string("checkpoint_speed_") + iter->first,
                            0);
     } else {
       handler_->setCounter(string("checkpoint_speed_") + iter->first,
                            iter->second.second / count);
     }
   }

   // reset checkpoint variables
   // note: Clearing the map while other threads are using it might
   // cause undefined behavior.
   checkpointServiceDuration_.clear();
   checkpointTime_ = now;
   checkpointServices_ = 0;
   checkpointDuration_ = 0;

   // get lifetime variables
   uint64_t life_count = handler_->getCounter("lifetime_services");
   uint64_t life_interval = now - handler_->aliveSince();

   // log checkpoint
   stringstream message;
   message << "checkpoint_time:" << check_interval
           << " checkpoint_services:" << check_count
           << " checkpoint_speed_sum:" << check_duration
           << " lifetime_time:" << life_interval
           << " lifetime_services:" << life_count;
   if (featureThreadCheck_ && threadManager_ != NULL) {
     size_t worker_count = threadManager_->workerCount();
     size_t idle_count = threadManager_->idleWorkerCount();
     message << " total_workers:" << worker_count
             << " active_workers:" << (worker_count - idle_count);
   }
   logMethod_(4, message.str());
 }

 /**
  * Remembers the thread manager used in the server, for monitoring thread
  * activity.
  *
  * @param shared_ptr<ThreadManager> threadManager The server's thread manager.
  */
 void
 ServiceTracker::setThreadManager(boost::shared_ptr<ThreadManager>
                                  threadManager)
 {
   threadManager_ = threadManager;
 }

 /**
  * Logs messages to stdout; the passed message will be logged if the
  * passed level is less than or equal to LOG_LEVEL.
  *
  * This is the default logging method used by the ServiceTracker.  An
  * alternate logging method (that accepts the same parameters) may be
  * specified to the constructor.
  *
  * @param int level A level associated with the message: higher levels
  *                  are used to indicate higher levels of detail.
  * @param string message The message to log.
  */
 void
 ServiceTracker::defaultLogMethod(int level, const string &message)
 {
   if (level <= LOG_LEVEL) {
     string level_string;
     time_t now = time(NULL);
     char now_pretty[26];
     ctime_r(&now, now_pretty);
     now_pretty[24] = '\0';
     switch (level) {
     case 1:
       level_string = "CRITICAL";
       break;
     case 2:
       level_string = "ERROR";
       break;
     case 3:
       level_string = "WARNING";
       break;
     case 5:
       level_string = "DEBUG";
       break;
     case 4:
     default:
       level_string = "INFO";
       break;
     }
     cout << '[' << level_string << "] [" << now_pretty << "] "
          << message << endl;
   }
 }


 /**
  * Creates a Stopwatch, which can report the time elapsed since its
  * creation.
  *
  */
 Stopwatch::Stopwatch()
 {
   gettimeofday(&startTime_, NULL);
 }

 void
 Stopwatch::reset()
 {
   gettimeofday(&startTime_, NULL);
 }

 uint64_t
 Stopwatch::elapsedUnits(Stopwatch::Unit unit, string *label) const
 {
   timeval now_time;
   gettimeofday(&now_time, NULL);
   time_t duration_secs = now_time.tv_sec - startTime_.tv_sec;

   uint64_t duration_units;
   switch (unit) {
   case UNIT_SECONDS:
     duration_units = duration_secs
       + (now_time.tv_usec - startTime_.tv_usec + 500000) / 1000000;
     if (NULL != label) {
       stringstream ss_label;
       ss_label << duration_units << " secs";
       label->assign(ss_label.str());
     }
     break;
   case UNIT_MICROSECONDS:
     duration_units = duration_secs * 1000000
       + now_time.tv_usec - startTime_.tv_usec;
     if (NULL != label) {
       stringstream ss_label;
       ss_label << duration_units << " us";
       label->assign(ss_label.str());
     }
     break;
   case UNIT_MILLISECONDS:
   default:
     duration_units = duration_secs * 1000
       + (now_time.tv_usec - startTime_.tv_usec + 500) / 1000;
     if (NULL != label) {
       stringstream ss_label;
       ss_label << duration_units << " ms";
       label->assign(ss_label.str());
     }
     break;
   }
   return duration_units;
 }

 /**
  * Creates a ServiceMethod, used for tracking a single service method
  * invocation (via the ServiceTracker).  The passed name of the
  * ServiceMethod is used to group statistics (e.g. counts and durations)
  * for similar invocations; the passed signature is used to uniquely
  * identify the particular invocation in the log.
  *
  * note: A version of this constructor is provided that automatically
  * forms a signature the name and a passed numeric id.  Silly, sure,
  * but commonly used, since it often saves the caller a line or two of
  * code.
  *
  * @param ServiceTracker *tracker The service tracker that will track this
  *                                ServiceMethod.
  * @param const string &name The service method name (usually independent
  *                           of service method parameters).
  * @param const string &signature A signature uniquely identifying the method
  *                                invocation (usually name plus parameters).
  */
 ServiceMethod::ServiceMethod(ServiceTracker *tracker,
                              const string &name,
                              const string &signature,
                              bool featureLogOnly)
   : tracker_(tracker), name_(name), signature_(signature),
     featureLogOnly_(featureLogOnly)
 {
   // note: timer_ automatically starts at construction.

   // invoke tracker to start service
   // note: Might throw.  If it throws, then this object's destructor
   // won't be called, which is according to plan: finishService() is
   // only supposed to be matched to startService() if startService()
   // returns without error.
   tracker_->startService(*this);
 }

 ServiceMethod::ServiceMethod(ServiceTracker *tracker,
                              const string &name,
                              uint64_t id,
                              bool featureLogOnly)
   : tracker_(tracker), name_(name), featureLogOnly_(featureLogOnly)
 {
   // note: timer_ automatically starts at construction.
   stringstream ss_signature;
   ss_signature << name << " (" << id << ')';
   signature_ = ss_signature.str();

   // invoke tracker to start service
   // note: Might throw.  If it throws, then this object's destructor
   // won't be called, which is according to plan: finishService() is
   // only supposed to be matched to startService() if startService()
   // returns without error.
   tracker_->startService(*this);
 }

 ServiceMethod::~ServiceMethod()
 {
   // invoke tracker to finish service
   // note: Not expecting an exception from this code, but
   // finishService() might conceivably throw an out-of-memory
   // exception.
   try {
     tracker_->finishService(*this);
   } catch (...) {
     // don't throw
   }
 }

 uint64_t
 ServiceMethod::step(const std::string &stepName)
 {
   return tracker_->stepService(*this, stepName);
 }
	/*
	* Licensed to the Apache Software Foundation (ASF) under one
	* or more contributor license agreements. See the NOTICE file
	* distributed with this work for additional information
	* regarding copyright ownership. The ASF licenses this file
	* to you under the Apache License, Version 2.0 (the
	* "License"); you may not use this file except in compliance
	* with the License. You may obtain a copy of the License at
	*
	* http://www.apache.org/licenses/LICENSE-2.0
	*
	* Unless required by applicable law or agreed to in writing,
	* software distributed under the License is distributed on an
	* "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
	* KIND, either express or implied. See the License for the
	* specific language governing permissions and limitations
	* under the License.
	*/

	#include <sys/time.h>

	#include "FacebookBase.h"
	#include "ServiceTracker.h"
	#include <thrift/concurrency/ThreadManager.h>

	using namespace std;
	using namespace facebook::fb303;
	using namespace apache::thrift::concurrency;


	uint64_t ServiceTracker::CHECKPOINT_MINIMUM_INTERVAL_SECONDS = 60;
	int ServiceTracker::LOG_LEVEL = 5;


	ServiceTracker::ServiceTracker(facebook::fb303::FacebookBase *handler,
	void (*logMethod)(int, const string &),
	bool featureCheckpoint,
	bool featureStatusCheck,
	bool featureThreadCheck,
	Stopwatch::Unit stopwatchUnit)
	: handler_(handler), logMethod_(logMethod),
	featureCheckpoint_(featureCheckpoint),
	featureStatusCheck_(featureStatusCheck),
	featureThreadCheck_(featureThreadCheck),
	stopwatchUnit_(stopwatchUnit),
	checkpointServices_(0)
	{
	if (featureCheckpoint_) {
	time_t now = time(NULL);
	checkpointTime_ = now;
	} else {
	checkpointTime_ = 0;
	}
	}

	/**
	* Registers the beginning of a "service method": basically, any of
	* the implementations of Thrift remote procedure calls that a
	* FacebookBase handler is handling. Controls concurrent
	* services and reports statistics (via log and via fb303 counters).
	* Throws an exception if the server is not ready to handle service
	* methods yet.
	*
	* note: The relationship between startService() and finishService()
	* is currently defined so that a call to finishService() should only
	* be matched to this call to startService() if this method returns
	* without exception. It wouldn't be a problem to implement things
	* the other way, so that every start needed a finish, but this
	* convention was chosen to match the way an object's constructor and
	* destructor work together, i.e. to work well with ServiceMethod
	* objects.
	*
	* @param const ServiceMethod &serviceMethod A reference to the ServiceMethod
	* object instantiated at the start
	* of the service method.
	*/
	void
	ServiceTracker::startService(const ServiceMethod &serviceMethod)
	{
	// note: serviceMethod.timer_ automatically starts at construction.

	// log service start
	logMethod_(5, serviceMethod.signature_);

	// check handler ready
	if (featureStatusCheck_ && !serviceMethod.featureLogOnly_) {
	// note: Throwing exceptions before counting statistics. See note
	// in method header.
	// note: A STOPPING server is not accepting new connections, but it
	// is still handling any already-connected threads -- so from the
	// service method's point of view, a status of STOPPING is a green
	// light.
	facebook::fb303::fb_status status = handler_->getStatus();
	if (status != facebook::fb303::ALIVE
	&& status != facebook::fb303::STOPPING) {
	if (status == facebook::fb303::STARTING) {
	throw ServiceException("Server starting up; please try again later");
	} else {
	throw ServiceException("Server not alive; please try again later");
	}
	}
	}

	// check server threads
	if (featureThreadCheck_ && !serviceMethod.featureLogOnly_) {
	// note: Might want to put these messages in reportCheckpoint() if
	// log is getting spammed.
	if (threadManager_ != NULL) {
	size_t idle_count = threadManager_->idleWorkerCount();
	if (idle_count == 0) {
	stringstream message;
	message << "service " << serviceMethod.signature_
	<< ": all threads (" << threadManager_->workerCount()
	<< ") in use";
	logMethod_(3, message.str());
	}
	}
	}
	}

	/**
	* Logs a significant step in the middle of a "service method"; see
	* startService.
	*
	* @param const ServiceMethod &serviceMethod A reference to the ServiceMethod
	* object instantiated at the start
	* of the service method.
	* @return int64_t Elapsed units (see stopwatchUnit_) since ServiceMethod
	* instantiation.
	*/
	int64_t
	ServiceTracker::stepService(const ServiceMethod &serviceMethod,
	const string &stepName)
	{
	stringstream message;
	string elapsed_label;
	int64_t elapsed = serviceMethod.timer_.elapsedUnits(stopwatchUnit_,
	&elapsed_label);
	message << serviceMethod.signature_
	<< ' ' << stepName
	<< " [" << elapsed_label << ']';
	logMethod_(5, message.str());
	return elapsed;
	}

	/**
	* Registers the end of a "service method"; see startService().
	*
	* @param const ServiceMethod &serviceMethod A reference to the ServiceMethod
	* object instantiated at the start
	* of the service method.
	*/
	void
	ServiceTracker::finishService(const ServiceMethod &serviceMethod)
	{
	// log end of service
	stringstream message;
	string duration_label;
	int64_t duration = serviceMethod.timer_.elapsedUnits(stopwatchUnit_,
	&duration_label);
	message << serviceMethod.signature_
	<< " finish [" << duration_label << ']';
	logMethod_(5, message.str());

	// count, record, and maybe report service statistics
	if (!serviceMethod.featureLogOnly_) {

	if (!featureCheckpoint_) {

	// lifetime counters
	// (note: No need to lock statisticsMutex_ if not doing checkpoint;
	// FacebookService::incrementCounter() is already thread-safe.)
	handler_->incrementCounter("lifetime_services");

	} else {

	statisticsMutex_.lock();
	// note: No exceptions expected from this code block. Wrap in a try
	// just to be safe.
	try {

	// lifetime counters
	// note: Good to synchronize this with the increment of
	// checkpoint services, even though incrementCounter() is
	// already thread-safe, for the sake of checkpoint reporting
	// consistency (i.e. since the last checkpoint,
	// lifetime_services has incremented by checkpointServices_).
	handler_->incrementCounter("lifetime_services");

	// checkpoint counters
	checkpointServices_++;
	checkpointDuration_ += duration;

	// per-service timing
	// note kjv: According to my tests it is very slightly faster to
	// call insert() once (and detect not-found) than calling find()
	// and then maybe insert (if not-found). However, the difference
	// is tiny for small maps like this one, and the code for the
	// faster solution is slightly less readable. Also, I wonder if
	// the instantiation of the (often unused) pair to insert makes
	// the first algorithm slower after all.
	map<string, pair<uint64_t, uint64_t> >::iterator iter;
	iter = checkpointServiceDuration_.find(serviceMethod.name_);
	if (iter != checkpointServiceDuration_.end()) {
	iter->second.first++;
	iter->second.second += duration;
	} else {
	checkpointServiceDuration_.insert(make_pair(serviceMethod.name_,
	make_pair(1, duration)));
	}

	// maybe report checkpoint
	// note: ...if it's been long enough since the last report.
	time_t now = time(NULL);
	uint64_t check_interval = now - checkpointTime_;
	if (check_interval >= CHECKPOINT_MINIMUM_INTERVAL_SECONDS) {
	reportCheckpoint();
	}

	} catch (...) {
	statisticsMutex_.unlock();
	throw;
	}
	statisticsMutex_.unlock();

	}
	}
	}

	/**
	* Logs some statistics gathered since the last call to this method.
	*
	* note: Thread race conditions on this method could cause
	* misreporting and/or undefined behavior; the caller must protect
	* uses of the object variables (and calls to this method) with a
	* mutex.
	*
	*/
	void
	ServiceTracker::reportCheckpoint()
	{
	time_t now = time(NULL);

	uint64_t check_count = checkpointServices_;
	uint64_t check_interval = now - checkpointTime_;
	uint64_t check_duration = checkpointDuration_;

	// export counters for timing of service methods (by service name)
	handler_->setCounter("checkpoint_time", check_interval);
	map<string, pair<uint64_t, uint64_t> >::iterator iter;
	uint64_t count;
	for (iter = checkpointServiceDuration_.begin();
	iter != checkpointServiceDuration_.end();
	iter++) {
	count = iter->second.first;
	handler_->setCounter(string("checkpoint_count_") + iter->first, count);
	if (count == 0) {
	handler_->setCounter(string("checkpoint_speed_") + iter->first,
	0);
	} else {
	handler_->setCounter(string("checkpoint_speed_") + iter->first,
	iter->second.second / count);
	}
	}

	// reset checkpoint variables
	// note: Clearing the map while other threads are using it might
	// cause undefined behavior.
	checkpointServiceDuration_.clear();
	checkpointTime_ = now;
	checkpointServices_ = 0;
	checkpointDuration_ = 0;

	// get lifetime variables
	uint64_t life_count = handler_->getCounter("lifetime_services");
	uint64_t life_interval = now - handler_->aliveSince();

	// log checkpoint
	stringstream message;
	message << "checkpoint_time:" << check_interval
	<< " checkpoint_services:" << check_count
	<< " checkpoint_speed_sum:" << check_duration
	<< " lifetime_time:" << life_interval
	<< " lifetime_services:" << life_count;
	if (featureThreadCheck_ && threadManager_ != NULL) {
	size_t worker_count = threadManager_->workerCount();
	size_t idle_count = threadManager_->idleWorkerCount();
	message << " total_workers:" << worker_count
	<< " active_workers:" << (worker_count - idle_count);
	}
	logMethod_(4, message.str());
	}

	/**
	* Remembers the thread manager used in the server, for monitoring thread
	* activity.
	*
	* @param shared_ptr<ThreadManager> threadManager The server's thread manager.
	*/
	void
	ServiceTracker::setThreadManager(boost::shared_ptr<ThreadManager>
	threadManager)
	{
	threadManager_ = threadManager;
	}

	/**
	* Logs messages to stdout; the passed message will be logged if the
	* passed level is less than or equal to LOG_LEVEL.
	*
	* This is the default logging method used by the ServiceTracker. An
	* alternate logging method (that accepts the same parameters) may be
	* specified to the constructor.
	*
	* @param int level A level associated with the message: higher levels
	* are used to indicate higher levels of detail.
	* @param string message The message to log.
	*/
	void
	ServiceTracker::defaultLogMethod(int level, const string &message)
	{
	if (level <= LOG_LEVEL) {
	string level_string;
	time_t now = time(NULL);
	char now_pretty[26];
	ctime_r(&now, now_pretty);
	now_pretty[24] = '\0';
	switch (level) {
	case 1:
	level_string = "CRITICAL";
	break;
	case 2:
	level_string = "ERROR";
	break;
	case 3:
	level_string = "WARNING";
	break;
	case 5:
	level_string = "DEBUG";
	break;
	case 4:
	default:
	level_string = "INFO";
	break;
	}
	cout << '[' << level_string << "] [" << now_pretty << "] "
	<< message << endl;
	}
	}


	/**
	* Creates a Stopwatch, which can report the time elapsed since its
	* creation.
	*
	*/
	Stopwatch::Stopwatch()
	{
	gettimeofday(&startTime_, NULL);
	}

	void
	Stopwatch::reset()
	{
	gettimeofday(&startTime_, NULL);
	}

	uint64_t
	Stopwatch::elapsedUnits(Stopwatch::Unit unit, string *label) const
	{
	timeval now_time;
	gettimeofday(&now_time, NULL);
	time_t duration_secs = now_time.tv_sec - startTime_.tv_sec;

	uint64_t duration_units;
	switch (unit) {
	case UNIT_SECONDS:
	duration_units = duration_secs
	+ (now_time.tv_usec - startTime_.tv_usec + 500000) / 1000000;
	if (NULL != label) {
	stringstream ss_label;
	ss_label << duration_units << " secs";
	label->assign(ss_label.str());
	}
	break;
	case UNIT_MICROSECONDS:
	duration_units = duration_secs * 1000000
	+ now_time.tv_usec - startTime_.tv_usec;
	if (NULL != label) {
	stringstream ss_label;
	ss_label << duration_units << " us";
	label->assign(ss_label.str());
	}
	break;
	case UNIT_MILLISECONDS:
	default:
	duration_units = duration_secs * 1000
	+ (now_time.tv_usec - startTime_.tv_usec + 500) / 1000;
	if (NULL != label) {
	stringstream ss_label;
	ss_label << duration_units << " ms";
	label->assign(ss_label.str());
	}
	break;
	}
	return duration_units;
	}

	/**
	* Creates a ServiceMethod, used for tracking a single service method
	* invocation (via the ServiceTracker). The passed name of the
	* ServiceMethod is used to group statistics (e.g. counts and durations)
	* for similar invocations; the passed signature is used to uniquely
	* identify the particular invocation in the log.
	*
	* note: A version of this constructor is provided that automatically
	* forms a signature the name and a passed numeric id. Silly, sure,
	* but commonly used, since it often saves the caller a line or two of
	* code.
	*
	* @param ServiceTracker *tracker The service tracker that will track this
	* ServiceMethod.
	* @param const string &name The service method name (usually independent
	* of service method parameters).
	* @param const string &signature A signature uniquely identifying the method
	* invocation (usually name plus parameters).
	*/
	ServiceMethod::ServiceMethod(ServiceTracker *tracker,
	const string &name,
	const string &signature,
	bool featureLogOnly)
	: tracker_(tracker), name_(name), signature_(signature),
	featureLogOnly_(featureLogOnly)
	{
	// note: timer_ automatically starts at construction.

	// invoke tracker to start service
	// note: Might throw. If it throws, then this object's destructor
	// won't be called, which is according to plan: finishService() is
	// only supposed to be matched to startService() if startService()
	// returns without error.
	tracker_->startService(*this);
	}

	ServiceMethod::ServiceMethod(ServiceTracker *tracker,
	const string &name,
	uint64_t id,
	bool featureLogOnly)
	: tracker_(tracker), name_(name), featureLogOnly_(featureLogOnly)
	{
	// note: timer_ automatically starts at construction.
	stringstream ss_signature;
	ss_signature << name << " (" << id << ')';
	signature_ = ss_signature.str();

	// invoke tracker to start service
	// note: Might throw. If it throws, then this object's destructor
	// won't be called, which is according to plan: finishService() is
	// only supposed to be matched to startService() if startService()
	// returns without error.
	tracker_->startService(*this);
	}

	ServiceMethod::~ServiceMethod()
	{
	// invoke tracker to finish service
	// note: Not expecting an exception from this code, but
	// finishService() might conceivably throw an out-of-memory
	// exception.
	try {
	tracker_->finishService(*this);
	} catch (...) {
	// don't throw
	}
	}

	uint64_t
	ServiceMethod::step(const std::string &stepName)
	{
	return tracker_->stepService(*this, stepName);
	}