diff --git a/src/common/ProfLogger.cc b/src/common/ProfLogger.cc index 918f45d7a89..5db56e97c53 100644 --- a/src/common/ProfLogger.cc +++ b/src/common/ProfLogger.cc @@ -1,4 +1,4 @@ -// -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*- +// -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*- // vim: ts=8 sw=2 smarttab /* * Ceph - scalable distributed file system @@ -7,9 +7,9 @@ * * This is free software; you can redistribute it and/or * modify it under the terms of the GNU Lesser General Public - * License version 2.1, as published by the Free Software + * License version 2.1, as published by the Free Software * Foundation. See file COPYING. - * + * */ @@ -30,79 +30,71 @@ #include "common/Timer.h" -// per-process lock. lame, but this way I protect ProfLogType too! -Mutex prof_logger_lock("prof_logger_lock"); -SafeTimer logger_timer(prof_logger_lock); -Context *logger_event = 0; -list logger_list; -utime_t start; -int last_flush = 0; // in seconds since start - -bool logger_need_reopen = true; -bool logger_need_reset = false; - -static void flush_all_loggers(); -static void stop(); - -struct FlusherStopper { - ~FlusherStopper() { - stop(); - } -} stopper; - -class C_FlushProfLoggers : public Context { +//////////////// C_FlushProfLoggers //////////////// +class C_FlushProfLoggers : public Context +{ public: - void finish(int r) { - if (logger_event == this) { - logger_event = 0; - flush_all_loggers(); - } + C_FlushProfLoggers(ProfLoggerCollection *coll_) + : coll(coll_) + { } + + void finish(int r) { + coll->flush_all_loggers(); + } + +private: + ProfLoggerCollection *coll; }; -ProfLoggerConfObs::~ProfLoggerConfObs() +//////////////// ProfLoggerCollection //////////////// +ProfLoggerCollection:: +ProfLoggerCollection(CephContext *ctx_) + : lock("ProfLoggerCollection::lock"), + logger_timer(lock), logger_event(NULL), + last_flush(0), need_reopen(true), need_reset(false), ctx(ctx_) { } -const char **ProfLoggerConfObs::get_tracked_conf_keys() const +ProfLoggerCollection:: +~ProfLoggerCollection() { - static const char *KEYS[] = { - "profiling_logger", "profiling_logger_interval", "profiling_logger_calc_variance", - "profiling_logger_subdir", "profiling_logger_dir", NULL - }; - return KEYS; + try { + lock.Lock(); + logger_timer.shutdown(); + lock.Unlock(); + } + catch (...) { + } } -void ProfLoggerConfObs::handle_conf_change(const md_config_t *conf, - const std::set &changed) +void ProfLoggerCollection:: +logger_reopen_all() { - // This could be done a *lot* smarter, if anyone cares to spend time - // fixing this up. - // We could probably just take the mutex and call _open_log from here. - logger_reopen_all(); + Mutex::Locker l(lock); + need_reopen = true; } -void logger_reopen_all() +void ProfLoggerCollection:: +logger_reset_all() { - logger_need_reopen = true; + Mutex::Locker l(lock); + need_reopen = true; + need_reset = true; } -void logger_reset_all() +void ProfLoggerCollection:: +logger_start() { - logger_need_reopen = true; - logger_need_reset = true; -} - -void logger_start() -{ - Mutex::Locker l(prof_logger_lock); + Mutex::Locker l(lock); logger_timer.init(); flush_all_loggers(); } -void logger_tare(utime_t s) +void ProfLoggerCollection:: +logger_tare(utime_t s) { - Mutex::Locker l(prof_logger_lock); + Mutex::Locker l(lock); generic_dout(10) << "logger_tare " << s << dendl; @@ -118,9 +110,10 @@ void logger_tare(utime_t s) last_flush = fromstart.sec(); } -void logger_add(ProfLogger *logger) +void ProfLoggerCollection:: +logger_add(ProfLogger *logger) { - Mutex::Locker l(prof_logger_lock); + Mutex::Locker l(lock); if (logger_list.empty()) { if (start == utime_t()) @@ -128,24 +121,34 @@ void logger_add(ProfLogger *logger) last_flush = 0; } logger_list.push_back(logger); + logger->lock = &lock; } -void logger_remove(ProfLogger *logger) +void ProfLoggerCollection:: +logger_remove(ProfLogger *logger) { - Mutex::Locker l(prof_logger_lock); + Mutex::Locker l(lock); for (list::iterator p = logger_list.begin(); p != logger_list.end(); p++) { if (*p == logger) { logger_list.erase(p); - break; + delete logger; + if (logger_list.empty() && logger_event) { + // If there are no timers, stop the timer events. + logger_timer.cancel_event(logger_event); + logger_event = 0; + } + return; } } } -static void flush_all_loggers() +void ProfLoggerCollection:: +flush_all_loggers() { + // ProfLoggerCollection lock must be held here. generic_dout(20) << "flush_all_loggers" << dendl; if (!g_conf->profiling_logger) @@ -166,20 +169,23 @@ static void flush_all_loggers() bool twice = now_sec - last_flush >= 2 * g_conf->profiling_logger_interval; again: generic_dout(20) << "fromstart " << fromstart << " last_flush " << last_flush << " flushing" << dendl; - - bool reopen = logger_need_reopen; - bool reset = logger_need_reset; + + // This logic seems unecessary. We're holding the mutex the whole time here, + // so need_reopen and need_reset can't change unless we change them. + // TODO: clean this up slightly + bool reopen = need_reopen; + bool reset = need_reset; for (list::iterator p = logger_list.begin(); p != logger_list.end(); - ++p) - (*p)->_flush(); - + ++p) + (*p)->_flush(need_reopen, need_reset, last_flush); + // did full pass while true? - if (reopen && logger_need_reopen) - logger_need_reopen = false; - if (reset && logger_need_reset) - logger_need_reset = false; + if (reopen && need_reopen) + need_reopen = false; + if (reset && need_reset) + need_reset = false; last_flush = now_sec - (now_sec % g_conf->profiling_logger_interval); if (twice) { @@ -192,24 +198,42 @@ static void flush_all_loggers() next.sec_ref() = start.sec() + last_flush + g_conf->profiling_logger_interval; next.nsec_ref() = start.nsec(); generic_dout(20) << "logger now=" << now - << " start=" << start - << " next=" << next + << " start=" << start + << " next=" << next << dendl; - logger_event = new C_FlushProfLoggers; + logger_event = new C_FlushProfLoggers(this); logger_timer.add_event_at(next, logger_event); } -static void stop() +//////////////// ProfLoggerConfObs //////////////// +ProfLoggerConfObs::ProfLoggerConfObs(ProfLoggerCollection *coll_) + : coll(coll_) { - prof_logger_lock.Lock(); - logger_timer.shutdown(); - prof_logger_lock.Unlock(); } +ProfLoggerConfObs::~ProfLoggerConfObs() +{ +} +const char **ProfLoggerConfObs::get_tracked_conf_keys() const +{ + static const char *KEYS[] = { + "profiling_logger", "profiling_logger_interval", "profiling_logger_calc_variance", + "profiling_logger_subdir", "profiling_logger_dir", NULL + }; + return KEYS; +} -// --------- +void ProfLoggerConfObs::handle_conf_change(const md_config_t *conf, + const std::set &changed) +{ + // This could be done a *lot* smarter, if anyone cares to spend time + // fixing this up. + // We could probably just take the mutex and call _open_log from here. + coll->logger_reopen_all(); +} +//////////////// ProfLogger //////////////// void ProfLogger::_open_log() { struct stat st; @@ -223,7 +247,7 @@ void ProfLogger::_open_log() filename = c; filename += "/"; } - + filename = g_conf->profiling_logger_dir; // make (feeble) attempt to create logger_dir @@ -242,7 +266,7 @@ void ProfLogger::_open_log() if (out.is_open()) out.close(); out.open(filename.c_str(), - (need_reset || logger_need_reset) ? ofstream::out : ofstream::out|ofstream::app); + (need_reset || need_reset) ? ofstream::out : ofstream::out|ofstream::app); if (!out.is_open()) { generic_dout(10) << "failed to open '" << filename << "'" << dendl; return; // we fail @@ -252,37 +276,30 @@ void ProfLogger::_open_log() need_open = false; } - ProfLogger::~ProfLogger() { - Mutex::Locker l(prof_logger_lock); - - _flush(); out.close(); - logger_list.remove(this); // slow, but rare. - if (logger_list.empty()) - logger_event = 0; // stop the timer events. } void ProfLogger::reopen() { - Mutex::Locker l(prof_logger_lock); + Mutex::Locker l(*lock); need_open = true; } void ProfLogger::reset() { - Mutex::Locker l(prof_logger_lock); + Mutex::Locker l(*lock); need_open = true; need_reset = true; } -void ProfLogger::_flush() +void ProfLogger::_flush(bool need_reopen, bool need_reset, int last_flush) { - if (need_open || logger_need_reopen) + if (need_reopen) _open_log(); - if (need_reset || logger_need_reset) { + if (need_reset) { // reset the counters for (int i=0; inum_keys; i++) { this->vals[i] = 0; @@ -299,7 +316,7 @@ void ProfLogger::_flush() out << "#" << type->num_keys; for (int i=0; inum_keys; i++) { out << "\t" << (type->key_name[i] ? type->key_name[i] : "???"); - if (type->avg_keys[i]) + if (type->avg_keys[i]) out << "\t(n)\t(var)"; } out << std::endl; //out << "\t (" << type->keymap.size() << ")" << endl; @@ -315,7 +332,7 @@ void ProfLogger::_flush() double var = 0.0; if (g_conf->profiling_logger_calc_variance && (unsigned)vals[i] == vals_to_avg[i].size()) { - for (vector::iterator p = vals_to_avg[i].begin(); p != vals_to_avg[i].end(); ++p) + for (vector::iterator p = vals_to_avg[i].begin(); p != vals_to_avg[i].end(); ++p) var += (avg - *p) * (avg - *p); } char s[256]; @@ -350,11 +367,11 @@ int64_t ProfLogger::inc(int key, int64_t v) { if (!g_conf->profiling_logger) return 0; - prof_logger_lock.Lock(); + lock->Lock(); int i = type->lookup_key(key); vals[i] += v; int64_t r = vals[i]; - prof_logger_lock.Unlock(); + lock->Unlock(); return r; } @@ -362,11 +379,11 @@ double ProfLogger::finc(int key, double v) { if (!g_conf->profiling_logger) return 0; - prof_logger_lock.Lock(); + lock->Lock(); int i = type->lookup_key(key); fvals[i] += v; double r = fvals[i]; - prof_logger_lock.Unlock(); + lock->Unlock(); return r; } @@ -374,11 +391,11 @@ int64_t ProfLogger::set(int key, int64_t v) { if (!g_conf->profiling_logger) return 0; - prof_logger_lock.Lock(); + lock->Lock(); int i = type->lookup_key(key); //cout << this << " set " << i << " to " << v << std::endl; int64_t r = vals[i] = v; - prof_logger_lock.Unlock(); + lock->Unlock(); return r; } @@ -387,11 +404,11 @@ double ProfLogger::fset(int key, double v) { if (!g_conf->profiling_logger) return 0; - prof_logger_lock.Lock(); + lock->Lock(); int i = type->lookup_key(key); //cout << this << " fset " << i << " to " << v << std::endl; double r = fvals[i] = v; - prof_logger_lock.Unlock(); + lock->Unlock(); return r; } @@ -399,13 +416,13 @@ double ProfLogger::favg(int key, double v) { if (!g_conf->profiling_logger) return 0; - prof_logger_lock.Lock(); + lock->Lock(); int i = type->lookup_key(key); vals[i]++; double r = fvals[i] += v; if (g_conf->profiling_logger_calc_variance) vals_to_avg[i].push_back(v); - prof_logger_lock.Unlock(); + lock->Unlock(); return r; } @@ -413,12 +430,12 @@ int64_t ProfLogger::get(int key) { if (!g_conf->profiling_logger) return 0; - prof_logger_lock.Lock(); + lock->Lock(); int i = type->lookup_key(key); int64_t r = 0; if (i >= 0 && i < (int)vals.size()) r = vals[i]; - prof_logger_lock.Unlock(); + lock->Unlock(); return r; } diff --git a/src/common/ProfLogger.h b/src/common/ProfLogger.h index bcbbc5986ff..aee85eca8a7 100644 --- a/src/common/ProfLogger.h +++ b/src/common/ProfLogger.h @@ -19,25 +19,48 @@ #include "common/config.h" #include "common/Clock.h" #include "common/ProfLogType.h" +#include "common/Timer.h" #include "include/types.h" #include #include #include -extern void logger_reopen_all(); -extern void logger_reset_all(); -extern void logger_add(class ProfLogger *l); -extern void logger_remove(class ProfLogger *l); -extern void logger_tare(utime_t when); -extern void logger_start(); +class ProfLogger; + +class ProfLoggerCollection +{ +public: + ProfLoggerCollection(CephContext *ctx_); + ~ProfLoggerCollection(); + void logger_reopen_all(); + void logger_reset_all(); + void logger_add(class ProfLogger *l); + void logger_remove(class ProfLogger *l); + void flush_all_loggers(); + void logger_tare(utime_t when); + void logger_start(); +private: + Mutex lock; // big lock. lame, but this way I protect ProfLogType too! + SafeTimer logger_timer; + Context *logger_event; + list logger_list; + utime_t start; + int last_flush; // in seconds since start + bool need_reopen; + bool need_reset; + CephContext *ctx; +}; class ProfLoggerConfObs : public md_config_obs_t { public: + ProfLoggerConfObs(ProfLoggerCollection *coll_); ~ProfLoggerConfObs(); virtual const char** get_tracked_conf_keys() const; virtual void handle_conf_change(const md_config_t *conf, const std::set &changed); +private: + ProfLoggerCollection *coll; }; class ProfLogger { @@ -63,12 +86,15 @@ class ProfLogger { void _open_log(); + private: + Mutex *lock; + public: ProfLogger(const std::string &n, ProfLogType *t) : name(n), type(t), need_open(true), need_reset(false), need_close(false), vals(t->num_keys), fvals(t->num_keys), vals_to_avg(t->num_keys), - wrote_header_last(10000) { } + wrote_header_last(10000), lock(NULL) { } ~ProfLogger(); int64_t inc(int f, int64_t v = 1); @@ -79,11 +105,13 @@ class ProfLogger { double finc(int f, double v); double favg(int f, double v); - void _flush(); + void _flush(bool need_reopen, bool need_reset, int last_flush); void reopen(); void reset(); void close(); + + friend class ProfLoggerCollection; }; #endif diff --git a/src/common/ceph_context.cc b/src/common/ceph_context.cc index 7ab89b4e8de..8fbcdf7f290 100644 --- a/src/common/ceph_context.cc +++ b/src/common/ceph_context.cc @@ -52,6 +52,7 @@ public: } if (_reopen_logs) { _cct->_doss->reopen_logs(_cct->_conf); + _cct->_prof_logger_collection->logger_reopen_all(); _reopen_logs = false; } } @@ -79,16 +80,19 @@ private: CephContext:: CephContext(uint32_t module_type_) - : _doss(new DoutStreambuf ::traits_type>()), + : _conf(new md_config_t()), + _doss(new DoutStreambuf ::traits_type>()), _dout(_doss), - module_type(module_type_), - _prof_logger_conf_obs(new ProfLoggerConfObs()), - _service_thread(NULL) + _module_type(module_type_), + _service_thread(NULL), + _prof_logger_collection(NULL), + _prof_logger_conf_obs(NULL) { - _conf = new md_config_t(); + pthread_spin_init(&_service_thread_lock, PTHREAD_PROCESS_SHARED); + _prof_logger_collection = new ProfLoggerCollection(this); + _prof_logger_conf_obs = new ProfLoggerConfObs(_prof_logger_collection); _conf->add_observer(_doss); _conf->add_observer(_prof_logger_conf_obs); - pthread_spin_init(&_service_thread_lock, PTHREAD_PROCESS_SHARED); } CephContext:: @@ -99,13 +103,18 @@ CephContext:: _conf->remove_observer(_prof_logger_conf_obs); _conf->remove_observer(_doss); - delete _doss; - _doss = NULL; + delete _prof_logger_collection; + _prof_logger_collection = NULL; + delete _prof_logger_conf_obs; _prof_logger_conf_obs = NULL; + delete _doss; + _doss = NULL; + delete _conf; pthread_spin_destroy(&_service_thread_lock); + } void CephContext:: @@ -166,11 +175,17 @@ join_service_thread() uint32_t CephContext:: get_module_type() const { - return module_type; + return _module_type; } void CephContext:: set_module_type(uint32_t module_type_) { - module_type = module_type_; + _module_type = module_type_; +} + +ProfLoggerCollection *CephContext:: +GetProfLoggerCollection() +{ + return _prof_logger_collection; } diff --git a/src/common/ceph_context.h b/src/common/ceph_context.h index 840b8c506e2..56d145fc17d 100644 --- a/src/common/ceph_context.h +++ b/src/common/ceph_context.h @@ -26,6 +26,7 @@ class md_config_t; class md_config_obs_t; class CephContextServiceThread; class DoutLocker; +class ProfLoggerCollection; /* A CephContext represents the context held by a single library user. * There can be multiple CephContexts in the same process. @@ -60,13 +61,14 @@ public: /* Set module type (TODO: remove) */ void set_module_type(uint32_t module_type_); + /* Get the ProfLoggerCollection of this CephContext */ + ProfLoggerCollection *GetProfLoggerCollection(); + private: /* Stop and join the Ceph Context's service thread */ void join_service_thread(); - uint32_t module_type; - - md_config_obs_t *_prof_logger_conf_obs; + uint32_t _module_type; /* libcommon service thread. * SIGHUP wakes this thread, which then reopens logfiles */ @@ -75,6 +77,11 @@ private: /* lock which protects service thread creation, destruction, etc. */ pthread_spinlock_t _service_thread_lock; + + /* The collection of profiling loggers associated with this context */ + ProfLoggerCollection *_prof_logger_collection; + + md_config_obs_t *_prof_logger_conf_obs; }; /* Globals (FIXME: remove) */ diff --git a/src/mds/MDLog.cc b/src/mds/MDLog.cc index 350005fdc88..8fa50961961 100644 --- a/src/mds/MDLog.cc +++ b/src/mds/MDLog.cc @@ -42,7 +42,7 @@ MDLog::~MDLog() { if (journaler) { delete journaler; journaler = 0; } if (logger) { - logger_remove(logger); + g_ceph_context.GetProfLoggerCollection()->logger_remove(logger); delete logger; logger = 0; } @@ -79,7 +79,7 @@ void MDLog::open_logger() char name[80]; snprintf(name, sizeof(name), "mds.%s.log", g_conf->name.get_id().c_str()); logger = new ProfLogger(name, &mdlog_logtype); - logger_add(logger); + g_ceph_context.GetProfLoggerCollection()->logger_add(logger); } void MDLog::init_journaler() diff --git a/src/mds/MDS.cc b/src/mds/MDS.cc index a591fc72276..5f087526d8e 100644 --- a/src/mds/MDS.cc +++ b/src/mds/MDS.cc @@ -173,13 +173,14 @@ MDS::~MDS() { if (objecter) { delete objecter; objecter = 0; } if (logger) { - logger_remove(logger); + g_ceph_context.GetProfLoggerCollection()->logger_remove(logger); delete logger; logger = 0; } if (mlogger) { - logger_remove(mlogger); + g_ceph_context.GetProfLoggerCollection()->logger_remove(logger); delete mlogger; + mlogger = 0; } if (messenger) @@ -286,19 +287,22 @@ void MDS::open_logger() g_conf->name.get_id().c_str(), (unsigned long long) monc->get_global_id()); logger = new ProfLogger(name, (ProfLogType*)&mds_logtype); - logger_add(logger); + g_ceph_context.GetProfLoggerCollection()->logger_add(logger); snprintf(name, sizeof(name), "mds.%s.%llu.mem.log", g_conf->name.get_id().c_str(), (unsigned long long) monc->get_global_id()); mlogger = new ProfLogger(name, (ProfLogType*)&mdm_logtype); - logger_add(mlogger); + g_ceph_context.GetProfLoggerCollection()->logger_add(mlogger); mdlog->open_logger(); server->open_logger(); - logger_tare(mdsmap->get_created()); - logger_start(); + { + ProfLoggerCollection *coll = g_ceph_context.GetProfLoggerCollection(); + coll->logger_tare(mdsmap->get_created()); + coll->logger_start(); + } } diff --git a/src/mds/Server.cc b/src/mds/Server.cc index 74d7e2da10a..1d506db2bf3 100644 --- a/src/mds/Server.cc +++ b/src/mds/Server.cc @@ -82,7 +82,7 @@ void Server::open_logger() char name[80]; snprintf(name, sizeof(name), "mds.%s.server.log", g_conf->name.get_id().c_str()); logger = new ProfLogger(name, &mdserver_logtype); - logger_add(logger); + g_ceph_context.GetProfLoggerCollection()->logger_add(logger); } diff --git a/src/mds/Server.h b/src/mds/Server.h index a711aa6d562..cee38eac2db 100644 --- a/src/mds/Server.h +++ b/src/mds/Server.h @@ -57,7 +57,7 @@ public: terminating_sessions(false) { } ~Server() { - logger_remove(logger); + g_ceph_context.GetProfLoggerCollection()->logger_remove(logger); delete logger; } diff --git a/src/os/FileStore.cc b/src/os/FileStore.cc index 27c546fe551..5ef29b63679 100644 --- a/src/os/FileStore.cc +++ b/src/os/FileStore.cc @@ -1905,9 +1905,12 @@ void FileStore::start_logger(int whoami, utime_t tare) logger = new ProfLogger(name, (ProfLogType*)&fs_logtype); if (journal) journal->logger = logger; - logger_add(logger); - logger_tare(tare); - logger_start(); + { + ProfLoggerCollection *coll = g_ceph_context.GetProfLoggerCollection(); + coll->logger_add(logger); + coll->logger_tare(tare); + coll->logger_start(); + } } void FileStore::stop_logger() @@ -1916,7 +1919,7 @@ void FileStore::stop_logger() if (logger) { if (journal) journal->logger = NULL; - logger_remove(logger); + g_ceph_context.GetProfLoggerCollection()->logger_remove(logger); delete logger; logger = NULL; } diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc index 1b94b7687e4..ebbaf7491a4 100644 --- a/src/osd/OSD.cc +++ b/src/osd/OSD.cc @@ -480,7 +480,7 @@ OSD::~OSD() { delete map_in_progress_cond; delete class_handler; - logger_remove(logger); + g_ceph_context.GetProfLoggerCollection()->logger_remove(logger); delete logger; delete store; } @@ -696,7 +696,7 @@ void OSD::open_logger() char name[80]; snprintf(name, sizeof(name), "osd.%d.log", whoami); logger = new ProfLogger(name, (ProfLogType*)&osd_logtype); - logger_add(logger); + g_ceph_context.GetProfLoggerCollection()->logger_add(logger); if (osdmap->get_epoch() > 0) start_logger(); @@ -704,8 +704,9 @@ void OSD::open_logger() void OSD::start_logger() { - logger_tare(osdmap->get_created()); - logger_start(); + ProfLoggerCollection *coll = g_ceph_context.GetProfLoggerCollection(); + coll->logger_tare(osdmap->get_created()); + coll->logger_start(); logger_started = true; // start the objectstore logger too @@ -2326,9 +2327,9 @@ void OSD::handle_command(MMonCommand *m) } } else if (m->cmd.size() == 2 && m->cmd[0] == "logger" && m->cmd[1] == "reset") { - logger_reset_all(); + g_ceph_context.GetProfLoggerCollection()->logger_reset_all(); } else if (m->cmd.size() == 2 && m->cmd[0] == "logger" && m->cmd[1] == "reopen") { - logger_reopen_all(); + g_ceph_context.reopen_logs(); } else if (m->cmd[0] == "heap") { if (ceph_using_tcmalloc()) ceph_heap_profiler_handle_command(m->cmd, clog); @@ -3180,7 +3181,7 @@ void OSD::handle_osd_map(MOSDMap *m) note_down_osd(*p); if (!logger_started) - start_logger(); + g_ceph_context.GetProfLoggerCollection()->logger_start(); osdmap = newmap;