diff --git a/gtsam/base/timing.cpp b/gtsam/base/timing.cpp index 2f32756d9..eb705ffd5 100644 --- a/gtsam/base/timing.cpp +++ b/gtsam/base/timing.cpp @@ -18,5 +18,9 @@ #include -Timing timing; +boost::shared_ptr timingRoot(new TimingOutline("Total")); +boost::weak_ptr timingCurrent(timingRoot); + +Timing timing; +std::string timingPrefix; diff --git a/gtsam/base/timing.h b/gtsam/base/timing.h index 37fde9765..69a8b6ba5 100644 --- a/gtsam/base/timing.h +++ b/gtsam/base/timing.h @@ -12,22 +12,198 @@ /** * @file timing.h * @brief - * @author Richard Roberts (extracted from Michael Kaess' timing functions) + * @author Richard Roberts, Michael Kaess * @created Oct 5, 2010 */ #pragma once #include #include +#include +#include +#include +#include +#include +#include +#include +#include + + + +//class AutoTimer { +//protected: +// boost::weak_ptr node_; +// struct timeval t0_; +// +// AutoTimer(const boost::weak_ptr& node) : +// node_(node) { +// boost::shared_ptr nodeS(node_.lock()); +// if(nodeS->activeTimer) { +// cerr << "Double createTimer in timing \"" << label_ << "\", exiting" << endl; +// exit(1); +// } +// nodeS->activeTimer = this; +// gettimeofday(&t, NULL); +// } +// +// AutoTimer(const AutoTimer& timer) : +// node_(timer.node_), t0_(timer.t0_) { +// node_.lock()->activeTimer_ = this; +// } +// +// ~AutoTimer() { +// if(node_ && node_.lock()->actimeTimer_ == this) +// release(); +// } +// +// AutoTimer& operator=(const AutoTimer& rhs) { +// throw std::runtime_error("AutoTimer is not assignable, use copy constructor instead."); +// } +// +// void release() { +// struct timeval t; +// gettimeofday(&t, NULL); +// boost::shared_ptr node(node_.lock()); +// if(node && node->activeTimer_ == *this) { +// size_t dt = t.tv_sec*1000000 + t.tv_usec - (t0_.tv_sec*1000000 + t0_.tv_usec); +// node->add(dt); +// node->activeTimer = 0; +// } else { +// cerr << "Double release in timing \"" << node_.lock()->label_ << "\", exiting" << endl; +// exit(1); +// } +// } +//}; + +class TimingOutline; +extern boost::shared_ptr timingRoot; +extern boost::weak_ptr timingCurrent; + +class TimingOutline { +protected: + size_t t_; + size_t tMax_; + size_t tMin_; + size_t n_; + std::string label_; + boost::weak_ptr parent_; + std::vector > children_; + struct timeval t0_; + bool timerActive_; + + void add(size_t usecs) { + if(usecs > tMax_) + tMax_ = usecs; + if(n_ == 0 || usecs < tMin_) + tMin_ = usecs; + t_ += usecs; + ++ n_; + } + +public: + TimingOutline(const std::string& label) : + t_(0), tMax_(0), tMin_(0), n_(0), label_(label), timerActive_(false) {} + + size_t time() const { + size_t time = 0; + bool hasChildren = false; + BOOST_FOREACH(const boost::shared_ptr& child, children_) { + if(child) { + time += child->time(); + hasChildren = true; + } + } + if(hasChildren) + return time; + else + return t_; + } + + void print(const std::string& outline = "") const { + std::cout << outline << " " << label_ << ": " << double(time())/1000000.0 << " (" << + n_ << " times, " << double(t_)/1000000.0 << " summed, min: " << double(tMin_)/1000000.0 << + " max: " << double(tMax_)/1000000.0 << ")\n"; + for(size_t i=0; i 0) + childOutline += "."; + childOutline += (boost::format("%d") % i).str(); + children_[i]->print(childOutline); + } + } + } + + const boost::shared_ptr& child(size_t child, const std::string& label, const boost::weak_ptr& thisPtr) { + assert(thisPtr.lock().get() == this); + // Resize if necessary + if(child >= children_.size()) + children_.resize(child + 1); + // Create child if necessary + if(children_[child]) { +#ifndef NDEBUG + if(children_[child]->label_ != label) { + timingRoot->print(); + std::cerr << "gtsam timing: tic called with id=" << child << ", label=" << label << ", but this id already has the label " << children_[child]->label_ << std::endl; + exit(1); + } +#endif + } else { + children_[child].reset(new TimingOutline(label)); + children_[child]->parent_ = thisPtr; + } + return children_[child]; + } + + void tic() { + assert(!timerActive_); + timerActive_ = true; + gettimeofday(&t0_, NULL); + } + + void toc() { + struct timeval t; + gettimeofday(&t, NULL); + assert(timerActive_); + add(t.tv_sec*1000000 + t.tv_usec - (t0_.tv_sec*1000000 + t0_.tv_usec)); + timerActive_ = false; + } + + friend class AutoTimer; + friend void toc_(size_t id, const std::string& label); +}; + +inline void tic_(size_t id, const std::string& label) { + boost::shared_ptr node = timingCurrent.lock()->child(id, label, timingCurrent); + timingCurrent = node; + node->tic(); +} + +inline void toc_(size_t id, const std::string& label) { + boost::shared_ptr current(timingCurrent.lock()); + current->toc(); + timingCurrent = current->parent_; +} + +#ifdef ENABLE_TIMING +inline void tic(size_t id, const std::string& label) { tic_(id, label); } +inline void toc(size_t id, const std::string& label) { toc_(id, label); } +#else +inline void tic(size_t id, const std::string& label) {} +inline void toc(size_t id, const std::string& label) {} +#endif // simple class for accumulating execution timing information by name class Timing; extern Timing timing; +extern std::string timingPrefix; double tic(); double toc(double t); double tic(const std::string& id); double toc(const std::string& id); +void ticPush(const std::string& id); +void ticPop(const std::string& id); void tictoc_print(); /** These underscore versions work evening when ENABLE_TIMING is not defined */ @@ -35,17 +211,17 @@ double tic_(); double toc_(double t); double tic_(const std::string& id); double toc_(const std::string& id); +void ticPush_(const std::string& id); +void ticPop_(const std::string& id); void tictoc_print_(); -#include -#include -#include // simple class for accumulating execution timing information by name class Timing { class Stats { public: + std::string label; double t0; double t; double t_max; @@ -92,16 +268,34 @@ inline double toc_(double t) { } inline double tic_(const std::string& id) { double t0 = tic_(); - timing.add_t0(id, t0); + timing.add_t0(timingPrefix + " " + id, t0); return t0; } inline double toc_(const std::string& id) { - double dt = toc_(timing.get_t0(id)); - timing.add_dt(id, dt); + std::string comb(timingPrefix + " " + id); + double dt = toc_(timing.get_t0(comb)); + timing.add_dt(comb, dt); return dt; } +inline void ticPush_(const std::string& prefix, const std::string& id) { + if(timingPrefix.size() > 0) + timingPrefix += "."; + timingPrefix += prefix; + tic_(id); +} +inline void ticPop_(const std::string& prefix, const std::string& id) { + toc_(id); + if(timingPrefix.size() < prefix.size()) { + fprintf(stderr, "Seems to be a mismatched push/pop in timing, exiting\n"); + exit(1); + } else if(timingPrefix.size() == prefix.size()) + timingPrefix.resize(0); + else + timingPrefix.resize(timingPrefix.size() - prefix.size() - 1); +} inline void tictoc_print_() { timing.print(); + timingRoot->print(); } #ifdef ENABLE_TIMING @@ -109,11 +303,15 @@ inline double tic() { return tic_(); } inline double toc(double t) { return toc_(t); } inline double tic(const std::string& id) { return tic_(id); } inline double toc(const std::string& id) { return toc_(id); } +inline void ticPush(const std::string& prefix, const std::string& id) { ticPush_(prefix, id); } +inline void ticPop(const std::string& prefix, const std::string& id) { ticPop_(prefix, id); } inline void tictoc_print() { tictoc_print_(); } #else inline double tic() {return 0.;} inline double toc(double t) {return 0.;} inline double tic(const std::string& id) {return 0.;} inline double toc(const std::string& id) {return 0.;} +inline void ticPush(const std::string& prefix, const std::string& id) {} +inline void ticPop(const std::string& prefix, const std::string& id) {} inline void tictoc_print() {} #endif