From 71007d4550ab4a757360a6c165f90a91f3dff059 Mon Sep 17 00:00:00 2001 From: Richard Roberts Date: Mon, 14 Feb 2011 17:02:50 +0000 Subject: [PATCH] Debugging switches in timing statements, and additional timing statements --- gtsam/base/timing.cpp | 2 +- gtsam/base/timing.h | 97 ++++++++------------- gtsam/linear/GaussianMultifrontalSolver.cpp | 5 +- gtsam/linear/GaussianSequentialSolver.cpp | 5 ++ 4 files changed, 46 insertions(+), 63 deletions(-) diff --git a/gtsam/base/timing.cpp b/gtsam/base/timing.cpp index eb705ffd5..06d2fed3e 100644 --- a/gtsam/base/timing.cpp +++ b/gtsam/base/timing.cpp @@ -12,7 +12,7 @@ /** * @file timing.cpp * @brief - * @author Richard Roberts (extracted from Michael Kaess' timing functions) + * @author Richard Roberts, Michael Kaess * @created Oct 5, 2010 */ diff --git a/gtsam/base/timing.h b/gtsam/base/timing.h index 25acb39b3..529320b50 100644 --- a/gtsam/base/timing.h +++ b/gtsam/base/timing.h @@ -17,6 +17,7 @@ */ #pragma once +#include #include #include #include @@ -29,52 +30,6 @@ #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; @@ -92,17 +47,17 @@ protected: struct timeval t0_; bool timerActive_; - void add(size_t usecs) { + inline void add(size_t usecs) { t_ += usecs; tIt_ += usecs; ++ n_; } public: - TimingOutline(const std::string& label) : + inline TimingOutline(const std::string& label) : t_(0), tIt_(0), tMax_(0), tMin_(0), n_(0), label_(label), timerActive_(false) {} - size_t time() const { + inline size_t time() const { size_t time = 0; bool hasChildren = false; BOOST_FOREACH(const boost::shared_ptr& child, children_) { @@ -117,7 +72,7 @@ public: return t_; } - void print(const std::string& outline = "") const { + inline void print(const std::string& outline = "") const { std::cout << outline << " " << label_ << ": " << double(t_)/1000000.0 << " (" << n_ << " times, " << double(time())/1000000.0 << " children, min: " << double(tMin_)/1000000.0 << " max: " << double(tMax_)/1000000.0 << ")\n"; @@ -136,7 +91,7 @@ public: } } - const boost::shared_ptr& child(size_t child, const std::string& label, const boost::weak_ptr& thisPtr) { + inline 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()) @@ -157,13 +112,13 @@ public: return children_[child]; } - void tic() { + inline void tic() { assert(!timerActive_); timerActive_ = true; gettimeofday(&t0_, NULL); } - void toc() { + inline void toc() { struct timeval t; gettimeofday(&t, NULL); assert(timerActive_); @@ -171,7 +126,7 @@ public: timerActive_ = false; } - void finishedIteration() { + inline void finishedIteration() { if(tIt_ > tMax_) tMax_ = tIt_; if(tMin_ == 0 || tIt_ < tMin_) @@ -188,26 +143,46 @@ public: }; inline void tic_(size_t id, const std::string& label) { + if(ISDEBUG("timing-verbose")) + std::cout << "tic(" << id << ", " << label << ")" << std::endl; boost::shared_ptr node = timingCurrent.lock()->child(id, label, timingCurrent); timingCurrent = node; node->tic(); } inline void toc_(size_t id) { + if(ISDEBUG("timing-verbose")) + std::cout << "toc(" << id << ")" << std::endl; boost::shared_ptr current(timingCurrent.lock()); - assert(id < current->parent_.lock()->children_.size() && current->parent_.lock()->children_[id] == current); + if(!(id < current->parent_.lock()->children_.size() && current->parent_.lock()->children_[id] == current)) { + std::cout << "gtsam timing: Incorrect ID passed to toc" << std::endl; + timingRoot->print(); + throw std::invalid_argument("gtsam timing: Incorrect ID passed to toc"); + } current->toc(); + if(!current->parent_.lock()) { + std::cout << "gtsam timing: extra toc, already at the root" << std::endl; + timingRoot->print(); + throw std::invalid_argument("gtsam timing: extra toc, already at the root"); + } timingCurrent = current->parent_; } inline void toc_(size_t id, const std::string& label) { -#ifndef NDEBUG - if(label != timingCurrent.lock()->label_) { - std::cerr << "gtsam timing: toc called with id=" << id << ", label=\"" << label << "\", but expecting \"" << timingCurrent.lock()->label_ << "\"" << std::endl; - timingRoot->print(); - exit(1); - } + if(ISDEBUG("timing-verbose")) + std::cout << "toc(" << id << ", " << label << ")" << std::endl; +#ifdef NDEBUG + // If NDEBUG is defined, still do this debug check if the granular debugging + // flag is enabled. If NDEBUG is not defined, always do this check. + if(ISDEBUG("timing-debug")) #endif + { + if(label != timingCurrent.lock()->label_) { + std::cerr << "gtsam timing: toc called with id=" << id << ", label=\"" << label << "\", but expecting \"" << timingCurrent.lock()->label_ << "\"" << std::endl; + timingRoot->print(); + exit(1); + } + } toc_(id); } diff --git a/gtsam/linear/GaussianMultifrontalSolver.cpp b/gtsam/linear/GaussianMultifrontalSolver.cpp index 8b61c575c..c1e16b826 100644 --- a/gtsam/linear/GaussianMultifrontalSolver.cpp +++ b/gtsam/linear/GaussianMultifrontalSolver.cpp @@ -53,7 +53,10 @@ BayesTree::shared_ptr GaussianMultifrontalSolver::eliminate /* ************************************************************************* */ VectorValues::shared_ptr GaussianMultifrontalSolver::optimize() const { - return VectorValues::shared_ptr(new VectorValues(junctionTree_->optimize())); + tic(2,"optimize"); + VectorValues::shared_ptr values(new VectorValues(junctionTree_->optimize())); + toc(2,"optimize"); + return values; } /* ************************************************************************* */ diff --git a/gtsam/linear/GaussianSequentialSolver.cpp b/gtsam/linear/GaussianSequentialSolver.cpp index ed0c9bf90..c2d91ed1b 100644 --- a/gtsam/linear/GaussianSequentialSolver.cpp +++ b/gtsam/linear/GaussianSequentialSolver.cpp @@ -16,6 +16,7 @@ * @created Oct 19, 2010 */ +#include #include #include @@ -59,16 +60,20 @@ VectorValues::shared_ptr GaussianSequentialSolver::optimize() const { if(debug) this->factors_->print("GaussianSequentialSolver, eliminating "); if(debug) this->eliminationTree_->print("GaussianSequentialSolver, elimination tree "); + tic(1,"eliminate"); // Eliminate using the elimination tree GaussianBayesNet::shared_ptr bayesNet(this->eliminate()); + toc(1,"eliminate"); if(debug) bayesNet->print("GaussianSequentialSolver, Bayes net "); // Allocate the solution vector if it is not already allocated // VectorValues::shared_ptr solution = allocateVectorValues(*bayesNet); + tic(2,"optimize"); // Back-substitute VectorValues::shared_ptr solution(gtsam::optimize_(*bayesNet)); + toc(2,"optimize"); if(debug) solution->print("GaussianSequentialSolver, solution ");