Expand reporting of timing information.
1. Add an ExecutionSummary object to record execution
information about Ceres objects.
2. Add an EventLogger object to log events in a function call.
3. Add a ScopedExecutionTimer object to log times in ExecutionSummary.
4. Instrument ProgramEvaluator and all the linear solvers
to report their timing statistics.
5. Connect the timing statistics to Summary::FullReport.
6. Add high precision timer on unix systems using
gettimeofday() call.
7. Various minor clean ups all around.
Change-Id: I5e09804b730b09535484124be7dbc1c58eccd1d4
diff --git a/internal/ceres/schur_complement_solver.cc b/internal/ceres/schur_complement_solver.cc
index 9b7d4e5..1753759 100644
--- a/internal/ceres/schur_complement_solver.cc
+++ b/internal/ceres/schur_complement_solver.cc
@@ -44,15 +44,15 @@
#include "ceres/block_sparse_matrix.h"
#include "ceres/block_structure.h"
#include "ceres/detect_structure.h"
+#include "ceres/internal/eigen.h"
+#include "ceres/internal/port.h"
+#include "ceres/internal/scoped_ptr.h"
#include "ceres/linear_solver.h"
#include "ceres/schur_complement_solver.h"
#include "ceres/suitesparse.h"
#include "ceres/triplet_sparse_matrix.h"
-#include "ceres/internal/eigen.h"
-#include "ceres/internal/port.h"
-#include "ceres/internal/scoped_ptr.h"
#include "ceres/types.h"
-
+#include "ceres/wall_time.h"
namespace ceres {
namespace internal {
@@ -62,7 +62,8 @@
const double* b,
const LinearSolver::PerSolveOptions& per_solve_options,
double* x) {
- const time_t start_time = time(NULL);
+ EventLogger event_logger("SchurComplementSolver::Solve");
+
if (eliminator_.get() == NULL) {
InitStorage(A->block_structure());
DetectStructure(*A->block_structure(),
@@ -73,32 +74,27 @@
eliminator_.reset(CHECK_NOTNULL(SchurEliminatorBase::Create(options_)));
eliminator_->Init(options_.elimination_groups[0], A->block_structure());
};
- const time_t init_time = time(NULL);
fill(x, x + A->num_cols(), 0.0);
+ event_logger.AddEvent("Setup");
LinearSolver::Summary summary;
summary.num_iterations = 1;
summary.termination_type = FAILURE;
eliminator_->Eliminate(A, b, per_solve_options.D, lhs_.get(), rhs_.get());
- const time_t eliminate_time = time(NULL);
+ event_logger.AddEvent("Eliminate");
double* reduced_solution = x + A->num_cols() - lhs_->num_cols();
const bool status = SolveReducedLinearSystem(reduced_solution);
- const time_t solve_time = time(NULL);
+ event_logger.AddEvent("ReducedSolve");
if (!status) {
return summary;
}
eliminator_->BackSubstitute(A, b, per_solve_options.D, reduced_solution, x);
- const time_t backsubstitute_time = time(NULL);
summary.termination_type = TOLERANCE;
- VLOG(2) << "time (sec) total: " << (backsubstitute_time - start_time)
- << " init: " << (init_time - start_time)
- << " eliminate: " << (eliminate_time - init_time)
- << " solve: " << (solve_time - eliminate_time)
- << " backsubstitute: " << (backsubstitute_time - solve_time);
+ event_logger.AddEvent("BackSubstitute");
return summary;
}
@@ -267,8 +263,6 @@
// CHOLMOD's sparse cholesky factorization routines.
bool SparseSchurComplementSolver::SolveReducedLinearSystemUsingSuiteSparse(
double* solution) {
- const time_t start_time = time(NULL);
-
TripletSparseMatrix* tsm =
const_cast<TripletSparseMatrix*>(
down_cast<const BlockRandomAccessSparseMatrix*>(lhs())->matrix());
@@ -285,11 +279,9 @@
// The matrix is symmetric, and the upper triangular part of the
// matrix contains the values.
cholmod_lhs->stype = 1;
- const time_t lhs_time = time(NULL);
cholmod_dense* cholmod_rhs =
ss_.CreateDenseVector(const_cast<double*>(rhs()), num_rows, num_rows);
- const time_t rhs_time = time(NULL);
// Symbolic factorization is computed if we don't already have one handy.
if (factor_ == NULL) {
@@ -306,12 +298,9 @@
CHECK_NOTNULL(factor_);
- const time_t symbolic_time = time(NULL);
cholmod_dense* cholmod_solution =
ss_.SolveCholesky(cholmod_lhs, factor_, cholmod_rhs);
- const time_t solve_time = time(NULL);
-
ss_.Free(cholmod_lhs);
cholmod_lhs = NULL;
ss_.Free(cholmod_rhs);
@@ -325,13 +314,6 @@
VectorRef(solution, num_rows)
= VectorRef(static_cast<double*>(cholmod_solution->x), num_rows);
ss_.Free(cholmod_solution);
- const time_t final_time = time(NULL);
- VLOG(2) << "time: " << (final_time - start_time)
- << " lhs : " << (lhs_time - start_time)
- << " rhs: " << (rhs_time - lhs_time)
- << " analyze: " << (symbolic_time - rhs_time)
- << " factor_and_solve: " << (solve_time - symbolic_time)
- << " cleanup: " << (final_time - solve_time);
return true;
}
#else
