More refined event logging in solver_impl.cc

Change-Id: Ie3061c921c006d2600d16185c690f52ccf816f68

internal/ceres/solver.cc

diff --git a/internal/ceres/solver.cc b/internal/ceres/solver.cc
index 2ae255a..3004717 100644
--- a/internal/ceres/solver.cc
+++ b/internal/ceres/solver.cc
@@ -266,23 +266,23 @@
                 num_unsuccessful_steps);
   StringAppendF(&report, "Total                    % 20d\n",
                 num_successful_steps + num_unsuccessful_steps);
-  StringAppendF(&report, "\nTime (in seconds):\n");
-  StringAppendF(&report, "Preprocessor        % 25.3e\n",
-                preprocessor_time_in_seconds);
 
-  StringAppendF(&report, "\n  Residual Evaluations % 22.3e\n",
+  StringAppendF(&report, "\nTime (in seconds):\n");
+  StringAppendF(&report, "Preprocessor        %25.3f\n",
+                preprocessor_time_in_seconds);
+  StringAppendF(&report, "\n  Residual Evaluations %22.3f\n",
                 residual_evaluation_time_in_seconds);
-  StringAppendF(&report, "  Jacobian Evaluations % 22.3e\n",
+  StringAppendF(&report, "  Jacobian Evaluations %22.3f\n",
                 jacobian_evaluation_time_in_seconds);
-  StringAppendF(&report, "  Linear Solver       % 23.3e\n",
+  StringAppendF(&report, "  Linear Solver       %23.3f\n",
                 linear_solver_time_in_seconds);
-  StringAppendF(&report, "Minimizer           % 25.3e\n\n",
+  StringAppendF(&report, "Minimizer           %25.3f\n\n",
                 minimizer_time_in_seconds);
 
-  StringAppendF(&report, "Postprocessor        % 24.3e\n",
+  StringAppendF(&report, "Postprocessor        %24.3f\n",
                 postprocessor_time_in_seconds);
 
-  StringAppendF(&report, "Total               % 25.3e\n\n",
+  StringAppendF(&report, "Total               %25.3f\n\n",
                 total_time_in_seconds);
 
   StringAppendF(&report, "Termination:        %25s\n",

internal/ceres/solver_impl.cc

diff --git a/internal/ceres/solver_impl.cc b/internal/ceres/solver_impl.cc
index 9b56f28..a070ce6 100644
--- a/internal/ceres/solver_impl.cc
+++ b/internal/ceres/solver_impl.cc
@@ -256,6 +256,7 @@
 
   minimizer_options.evaluator = evaluator;
   scoped_ptr<SparseMatrix> jacobian(evaluator->CreateJacobian());
+
   minimizer_options.jacobian = jacobian.get();
   minimizer_options.inner_iteration_minimizer = inner_iteration_minimizer;
 
@@ -414,6 +415,7 @@
   event_logger.AddEvent("InitialEvaluate");
 
   original_program->SetParameterBlockStatePtrsToUserStatePtrs();
+  event_logger.AddEvent("SetParameterBlockPtrs");
 
   // If the user requests gradient checking, construct a new
   // ProblemImpl by wrapping the CostFunctions of problem_impl inside
@@ -438,8 +440,10 @@
       LOG(ERROR) << summary->error;
       return;
     }
+    event_logger.AddEvent("CheckOrdering");
     options.linear_solver_ordering =
         new ParameterBlockOrdering(*original_options.linear_solver_ordering);
+    event_logger.AddEvent("CopyOrdering");
   } else {
     options.linear_solver_ordering = new ParameterBlockOrdering;
     const ProblemImpl::ParameterMap& parameter_map =
@@ -449,10 +453,9 @@
          ++it) {
       options.linear_solver_ordering->AddElementToGroup(it->first, 0);
     }
+    event_logger.AddEvent("ConstructOrdering");
   }
 
-  event_logger.AddEvent("ConstructOrdering");
-
   // Create the three objects needed to minimize: the transformed program, the
   // evaluator, and the linear solver.
   scoped_ptr<Program> reduced_program(CreateReducedProgram(&options,
@@ -589,7 +592,6 @@
   summary->preprocessor_time_in_seconds =
       minimizer_start_time - solver_start_time;
 
-  event_logger.AddEvent("FinalInit");
   // Run the optimization.
   TrustRegionMinimize(options,
                       reduced_program.get(),
@@ -1068,7 +1070,7 @@
     return NULL;
   }
 
-  event_logger.AddEvent("RemovedFixedBlocks");
+  event_logger.AddEvent("RemoveFixedBlocks");
 
   if (transformed_program->NumParameterBlocks() == 0) {
     if (transformed_program->NumResidualBlocks() > 0) {

internal/ceres/wall_time.cc

diff --git a/internal/ceres/wall_time.cc b/internal/ceres/wall_time.cc
index 7de7e06..e63d20c 100644
--- a/internal/ceres/wall_time.cc
+++ b/internal/ceres/wall_time.cc
@@ -64,7 +64,7 @@
       last_event_time_(start_time_),
       events_("") {
   StringAppendF(&events_,
-                "\n%s\n                                  Delta  Cumulative\n",
+                "\n%s\n                                   Delta   Cumulative\n",
                 logger_name.c_str());
 }
 
@@ -86,10 +86,10 @@
   last_event_time_ = current_time;
 
   StringAppendF(&events_,
-                "  %25s : %8.3f   %8.3f\n",
+                "  %25s : %10.5f   %10.5f\n",
                 event_name.c_str(),
-                1000 * relative_time_delta,
-                1000 * absolute_time_delta);
+                relative_time_delta,
+                absolute_time_delta);
 }
 
 }  // namespace internal