From 6ea88ae1bae70ca85cde58b40a3977e490564ed4 Mon Sep 17 00:00:00 2001 From: sageweil Date: Tue, 28 Aug 2007 05:27:05 +0000 Subject: [PATCH] rewrote logger git-svn-id: https://ceph.svn.sf.net/svnroot/ceph@1711 29311d96-e01e-0410-9327-a35deaab8ce9 --- trunk/ceph/common/Logger.cc | 239 ++++++++++++++++++++++-------------- trunk/ceph/common/Logger.h | 42 +++---- trunk/ceph/mds/CDir.cc | 2 +- trunk/ceph/mds/MDLog.cc | 2 +- trunk/ceph/mds/MDS.cc | 14 +-- trunk/ceph/mds/Server.cc | 4 +- 6 files changed, 171 insertions(+), 132 deletions(-) diff --git a/trunk/ceph/common/Logger.cc b/trunk/ceph/common/Logger.cc index f7fe3fbdc4192..591f4ce9cc94b 100644 --- a/trunk/ceph/common/Logger.cc +++ b/trunk/ceph/common/Logger.cc @@ -27,9 +27,67 @@ #include #include +#include "common/Timer.h" // per-process lock. lame, but this way I protect LogType too! Mutex logger_lock; +SafeTimer logger_timer(logger_lock); +Context *logger_event = 0; +list logger_list; +utime_t start; +int last_flush; // in seconds since start + +static void flush_all_loggers(); + +class C_FlushLoggers : public Context { +public: + void finish(int r) { + if (logger_event == this) { + logger_event = 0; + flush_all_loggers(); + } + } +}; + +static void flush_all_loggers() +{ + generic_dout(20) << "flush_all_loggers" << dendl; + + utime_t now = g_clock.now(); + utime_t fromstart = now; + if (fromstart < start) { + cerr << "logger time jumped backwards from " << start << " to " << fromstart << std::endl; + //assert(0); + start = fromstart; + } + fromstart -= start; + int now_sec = fromstart.sec(); + + // do any catching up we need to + while (now_sec - last_flush >= g_conf.log_interval) { + last_flush += g_conf.log_interval; + generic_dout(20) << "fromstart " << fromstart << " last_flush " << last_flush << " flushign" << dendl; + for (list::iterator p = logger_list.begin(); + p != logger_list.end(); + ++p) + (*p)->_flush(); + } + + // schedule next flush event + utime_t next; + next.sec_ref() = start.sec() + last_flush + g_conf.log_interval; + next.usec_ref() = start.usec(); + generic_dout(20) << "logger now=" << now + << " start=" << start + << " next=" << next + << dendl; + logger_event = new C_FlushLoggers; + logger_timer.add_event_at(next, logger_event); +} + + + +// --------- Logger::Logger(string fn, LogType *type) { @@ -50,37 +108,101 @@ Logger::Logger(string fn, LogType *type) filename += "/"; } filename += fn; - //cout << "log " << filename << endl; - interval = g_conf.log_interval; - - if (!g_conf.clock_tare) - start = g_clock.now(); // time 0! otherwise g_clock does it for us. - last_logged = 0; - wrote_header = -1; - open = false; + out.open(filename.c_str(), ofstream::out); + this->type = type; + wrote_header = -1; + last_logged = 0; wrote_header_last = 0; version = 0; + + if (logger_list.empty()) { + // init logger + if (!g_conf.clock_tare) + start = g_clock.now(); // time 0! otherwise g_clock does it for us. + + last_flush = 0; + + // call manually the first time; then it'll schedule itself. + flush_all_loggers(); + } + logger_list.push_back(this); } logger_lock.Unlock(); - flush(false); } Logger::~Logger() { - flush(true); - out.close(); + logger_lock.Lock(); + { + _flush(); + out.close(); + logger_list.remove(this); // slow, but rare. + if (logger_list.empty()) + logger_event = 0; // stop the timer events. + } + logger_lock.Unlock(); +} + +void Logger::set_start(utime_t s) +{ + start = s; } +void Logger::flush() +{ + logger_lock.Lock(); + _flush(); + logger_lock.Unlock(); +} + +void Logger::_flush() +{ + // header? + wrote_header_last++; + if (wrote_header != type->version || + wrote_header_last > 10) { + out << "#" << type->keymap.size(); + for (unsigned i=0; ikeys.size(); i++) + out << "\t" << type->keys[i]; + out << std::endl; //out << "\t (" << type->keymap.size() << ")" << endl; + wrote_header = type->version; + wrote_header_last = 0; + } + + maybe_resize(type->keys.size()); + + // write line to log + out << last_logged; + for (unsigned i=0; ikeys.size(); i++) { + if (fvals[i] > 0 && vals[i] == 0) + out << "\t" << fvals[i]; + else + out << "\t" << vals[i]; + } + out << std::endl; + + // reset the counters + for (unsigned i=0; ikeys.size(); i++) { + if (type->inc_keys.count(i)) { + this->vals[i] = 0; + this->fvals[i] = 0; + } + } +} + + + long Logger::inc(const char *key, long v) { if (!g_conf.log) return 0; logger_lock.Lock(); int i = type->lookup_key(key); if (i < 0) i = type->add_inc(key); - flush(); + maybe_resize(i+1); + vals[i] += v; long r = vals[i]; logger_lock.Unlock(); @@ -93,7 +215,8 @@ double Logger::finc(const char *key, double v) logger_lock.Lock(); int i = type->lookup_key(key); if (i < 0) i = type->add_inc(key); - flush(); + maybe_resize(i+1); + fvals[i] += v; double r = fvals[i]; logger_lock.Unlock(); @@ -106,7 +229,8 @@ long Logger::set(const char *key, long v) logger_lock.Lock(); int i = type->lookup_key(key); if (i < 0) i = type->add_set(key); - flush(); + maybe_resize(i+1); + long r = vals[i] = v; logger_lock.Unlock(); return r; @@ -119,7 +243,8 @@ double Logger::fset(const char *key, double v) logger_lock.Lock(); int i = type->lookup_key(key); if (i < 0) i = type->add_set(key); - flush(); + maybe_resize(i+1); + double r = fvals[i] = v; logger_lock.Unlock(); return r; @@ -130,88 +255,12 @@ long Logger::get(const char* key) if (!g_conf.log) return 0; logger_lock.Lock(); int i = type->lookup_key(key); + maybe_resize(i+1); + long r = 0; - if (i >= 0 && (int)vals.size() > i) - r = vals[i]; + if (i >= 0 && i < (int)vals.size()) + r = vals[i]; logger_lock.Unlock(); return r; } -void Logger::flush(bool force) -{ - if (!g_conf.log) return; - logger_lock.Lock(); - - if (version != type->version) { - while (type->keys.size() > vals.size()) - vals.push_back(0); - while (type->keys.size() > fvals.size()) - fvals.push_back(0); - version = type->version; - } - - if (!open) { - out.open(filename.c_str(), ofstream::out); - open = true; - //cout << "opening log file " << filename << endl; - } - - utime_t fromstart = g_clock.recent_now(); - if (fromstart < start) { - cerr << "logger time jumped backwards from " << start << " to " << fromstart << std::endl; - assert(0); - start = fromstart; - } - fromstart -= start; - - while (force || - ((fromstart.sec() > last_logged) && - (fromstart.sec() - last_logged >= interval))) { - last_logged += interval; - force = false; - - //cout << "logger " << this << " advancing from " << last_logged << " now " << now << endl; - - if (!open) { - out.open(filename.c_str(), ofstream::out); - open = true; - //cout << "opening log file " << filename << endl; - } - - // header? - wrote_header_last++; - if (wrote_header != type->version || - wrote_header_last > 10) { - out << "#" << type->keymap.size(); - for (unsigned i=0; ikeys.size(); i++) - out << "\t" << type->keys[i]; - out << std::endl; //out << "\t (" << type->keymap.size() << ")" << endl; - wrote_header = type->version; - wrote_header_last = 0; - } - - // write line to log - out << last_logged; - for (unsigned i=0; ikeys.size(); i++) { - if (fvals[i] > 0 && vals[i] == 0) - out << "\t" << fvals[i]; - else - out << "\t" << vals[i]; - } - out << std::endl; - - // reset the counters - for (unsigned i=0; ikeys.size(); i++) { - if (type->inc_keys.count(i)) { - this->vals[i] = 0; - this->fvals[i] = 0; - } - } - } - - logger_lock.Unlock(); -} - - - - diff --git a/trunk/ceph/common/Logger.h b/trunk/ceph/common/Logger.h index 393ad6068c883..9ec8f72d1daaf 100644 --- a/trunk/ceph/common/Logger.h +++ b/trunk/ceph/common/Logger.h @@ -18,51 +18,46 @@ #include "include/types.h" #include "Clock.h" -#include "Mutex.h" #include #include +#include +using std::vector; using std::string; using std::ofstream; -#include -using __gnu_cxx::hash_map; - #include "LogType.h" - - class Logger { protected: - //hash_map, eqstr> vals; - //hash_map, eqstr> fvals; + // values for this instance vector vals; vector fvals; - //Mutex lock; + void maybe_resize(unsigned s) { + if (s >= vals.size()) { + vals.resize(s); + fvals.resize(s); + } + } + + // my type LogType *type; + int version; + + string filename; + ofstream out; - utime_t start; + // what i've written int last_logged; - int interval; int wrote_header; int wrote_header_last; - string filename; - - int version; - - ofstream out; - bool open; - public: Logger(string fn, LogType *type); ~Logger(); - void set_start(const utime_t& a) { start = a; } - utime_t& get_start() { return start; } - long inc(const char *s, long v = 1); long set(const char *s, long v); long get(const char *s); @@ -70,7 +65,10 @@ class Logger { double fset(const char *s, double v); double finc(const char *s, double v); - void flush(bool force = false); + void flush(); + void _flush(); + + void set_start(utime_t s); }; #endif diff --git a/trunk/ceph/mds/CDir.cc b/trunk/ceph/mds/CDir.cc index 895e419bd040e..771b7bb63f8e2 100644 --- a/trunk/ceph/mds/CDir.cc +++ b/trunk/ceph/mds/CDir.cc @@ -874,7 +874,7 @@ void CDir::_fetched(bufferlist &bl) CInode *in = 0; if (cache->have_inode(inode.ino)) { in = cache->get_inode(inode.ino); - dout(12) << "_fetched got (but i already had) " << *in + dout(-12) << "_fetched got (but i already had) " << *in << " mode " << in->inode.mode << " mtime " << in->inode.mtime << dendl; assert(0); // this shouldn't happen!! diff --git a/trunk/ceph/mds/MDLog.cc b/trunk/ceph/mds/MDLog.cc index 04181c368be41..0f262fe838fe9 100644 --- a/trunk/ceph/mds/MDLog.cc +++ b/trunk/ceph/mds/MDLog.cc @@ -77,7 +77,7 @@ void MDLog::init_journaler() void MDLog::flush_logger() { if (logger) - logger->flush(true); + logger->flush(); } diff --git a/trunk/ceph/mds/MDS.cc b/trunk/ceph/mds/MDS.cc index eabe17a556867..68247cabe6244 100644 --- a/trunk/ceph/mds/MDS.cc +++ b/trunk/ceph/mds/MDS.cc @@ -183,14 +183,8 @@ void MDS::reopen_logger() if (whoami < 0) return; // flush+close old log - if (logger) { - logger->flush(true); - delete logger; - } - if (logger2) { - logger2->flush(true); - delete logger2; - } + if (logger) delete logger; + if (logger2) delete logger2; // log string name; @@ -1018,8 +1012,8 @@ void MDS::suicide() dout(1) << "suicide" << dendl; // flush loggers - if (logger) logger->flush(true); - if (logger2) logger2->flush(true); + if (logger) logger->flush(); + if (logger2) logger2->flush(); mdlog->flush_logger(); // stop timers diff --git a/trunk/ceph/mds/Server.cc b/trunk/ceph/mds/Server.cc index 2741cb234afec..6c6458a6ef649 100644 --- a/trunk/ceph/mds/Server.cc +++ b/trunk/ceph/mds/Server.cc @@ -73,10 +73,8 @@ void Server::reopen_logger() mdserver_logtype.add_inc("dsreq"); // slave } - if (logger) { - logger->flush(); + if (logger) delete logger; - } // logger char name[80]; -- 2.39.5