Add iteration and time reporting for inner iterations. Also 1. Remove an inadvertent LOG(INFO) from trust_region_minimizer.cc 2. Refactor some of the code in FullReport to reduce duplication across line search and trust region minimizers. 3. Consistent capitalization. Change-Id: I9078b1704efab23d2858530636f524e60c7d9016
diff --git a/include/ceres/solver.h b/include/ceres/solver.h index 8f394ea..d339bcc 100644 --- a/include/ceres/solver.h +++ b/include/ceres/solver.h
@@ -599,6 +599,7 @@ int num_successful_steps; int num_unsuccessful_steps; + int num_inner_iteration_steps; // When the user calls Solve, before the actual optimization // occurs, Ceres performs a number of preprocessing steps. These @@ -620,6 +621,7 @@ double linear_solver_time_in_seconds; double residual_evaluation_time_in_seconds; double jacobian_evaluation_time_in_seconds; + double inner_iteration_time_in_seconds; // Preprocessor summary. int num_parameter_blocks; @@ -649,20 +651,22 @@ vector<int> linear_solver_ordering_given; vector<int> linear_solver_ordering_used; + bool inner_iterations_given; + bool inner_iterations_used; + + vector<int> inner_iteration_ordering_given; + vector<int> inner_iteration_ordering_used; + PreconditionerType preconditioner_type; TrustRegionStrategyType trust_region_strategy_type; DoglegType dogleg_type; - bool inner_iterations; SparseLinearAlgebraLibraryType sparse_linear_algebra_library; LineSearchDirectionType line_search_direction_type; LineSearchType line_search_type; int max_lbfgs_rank; - - vector<int> inner_iteration_ordering_given; - vector<int> inner_iteration_ordering_used; }; // Once a least squares problem has been built, this function takes
diff --git a/internal/ceres/solver.cc b/internal/ceres/solver.cc index ea9ff1f..5acbbfd 100644 --- a/internal/ceres/solver.cc +++ b/internal/ceres/solver.cc
@@ -91,6 +91,7 @@ fixed_cost(-1.0), num_successful_steps(-1), num_unsuccessful_steps(-1), + num_inner_iteration_steps(-1), preprocessor_time_in_seconds(-1.0), minimizer_time_in_seconds(-1.0), postprocessor_time_in_seconds(-1.0), @@ -98,6 +99,7 @@ linear_solver_time_in_seconds(-1.0), residual_evaluation_time_in_seconds(-1.0), jacobian_evaluation_time_in_seconds(-1.0), + inner_iteration_time_in_seconds(-1.0), num_parameter_blocks(-1), num_parameters(-1), num_effective_parameters(-1), @@ -114,9 +116,10 @@ num_linear_solver_threads_used(-1), linear_solver_type_given(SPARSE_NORMAL_CHOLESKY), linear_solver_type_used(SPARSE_NORMAL_CHOLESKY), + inner_iterations_given(false), + inner_iterations_used(false), preconditioner_type(IDENTITY), trust_region_strategy_type(LEVENBERG_MARQUARDT), - inner_iterations(false), sparse_linear_algebra_library(SUITE_SPARSE), line_search_direction_type(LBFGS), line_search_type(ARMIJO) { @@ -184,9 +187,8 @@ num_residuals, num_residuals_reduced); } - // TODO(sameeragarwal): Refactor this into separate functions. - if (minimizer_type == TRUST_REGION) { + // TRUST_SEARCH HEADER StringAppendF(&report, "\nMinimizer %19s\n", "TRUST_REGION"); if (linear_solver_type_used == SPARSE_NORMAL_CHOLESKY || @@ -194,12 +196,12 @@ (linear_solver_type_used == ITERATIVE_SCHUR && (preconditioner_type == CLUSTER_JACOBI || preconditioner_type == CLUSTER_TRIDIAGONAL))) { - StringAppendF(&report, "\nSparse Linear Algebra Library %15s\n", + StringAppendF(&report, "\nSparse linear algebra library %15s\n", SparseLinearAlgebraLibraryTypeToString( sparse_linear_algebra_library)); } - StringAppendF(&report, "Trust Region Strategy %19s", + StringAppendF(&report, "Trust region strategy %19s", TrustRegionStrategyTypeToString( trust_region_strategy_type)); if (trust_region_strategy_type == DOGLEG) { @@ -227,7 +229,7 @@ "N/A", "N/A"); } - StringAppendF(&report, "Threads: % 25d% 25d\n", + StringAppendF(&report, "Threads % 25d% 25d\n", num_threads_given, num_threads_used); StringAppendF(&report, "Linear solver threads % 23d% 25d\n", num_linear_solver_threads_given, @@ -244,7 +246,14 @@ used.c_str()); } - if (inner_iterations) { + if (inner_iterations_given) { + StringAppendF(&report, + "Use inner iterations %20s %20s\n", + inner_iterations_given ? "True" : "False", + inner_iterations_used ? "True" : "False"); + } + + if (inner_iterations_used) { string given; StringifyOrdering(inner_iteration_ordering_given, &given); string used; @@ -254,57 +263,8 @@ given.c_str(), used.c_str()); } - - if (termination_type == DID_NOT_RUN) { - CHECK(!error.empty()) - << "Solver terminated with DID_NOT_RUN but the solver did not " - << "return a reason. This is a Ceres error. Please report this " - << "to the Ceres team"; - StringAppendF(&report, "Termination: %20s\n", - "DID_NOT_RUN"); - StringAppendF(&report, "Reason: %s\n", error.c_str()); - return report; - } - - StringAppendF(&report, "\nCost:\n"); - StringAppendF(&report, "Initial % 30e\n", initial_cost); - if (termination_type != NUMERICAL_FAILURE && - termination_type != USER_ABORT) { - StringAppendF(&report, "Final % 30e\n", final_cost); - StringAppendF(&report, "Change % 30e\n", - initial_cost - final_cost); - } - - StringAppendF(&report, "\nNumber of iterations:\n"); - StringAppendF(&report, "Successful % 20d\n", - num_successful_steps); - StringAppendF(&report, "Unsuccessful % 20d\n", - num_unsuccessful_steps); - StringAppendF(&report, "Total % 20d\n", - num_successful_steps + num_unsuccessful_steps); - - 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.3f\n", - jacobian_evaluation_time_in_seconds); - StringAppendF(&report, " Linear Solver %23.3f\n", - linear_solver_time_in_seconds); - StringAppendF(&report, "Minimizer %25.3f\n\n", - minimizer_time_in_seconds); - - StringAppendF(&report, "Postprocessor %24.3f\n", - postprocessor_time_in_seconds); - - StringAppendF(&report, "Total %25.3f\n\n", - total_time_in_seconds); - - StringAppendF(&report, "Termination: %25s\n", - SolverTerminationTypeToString(termination_type)); } else { - // LINE_SEARCH + // LINE_SEARCH HEADER StringAppendF(&report, "\nMinimizer %19s\n", "LINE_SEARCH"); if (line_search_direction_type == LBFGS) { StringAppendF(&report, "Line search direction %19s(%d)\n", @@ -321,52 +281,72 @@ StringAppendF(&report, "\n"); StringAppendF(&report, "%45s %21s\n", "Given", "Used"); - StringAppendF(&report, "Threads: % 25d% 25d\n", + StringAppendF(&report, "Threads % 25d% 25d\n", num_threads_given, num_threads_used); - if (termination_type == DID_NOT_RUN) { - CHECK(!error.empty()) - << "Solver terminated with DID_NOT_RUN but the solver did not " - << "return a reason. This is a Ceres error. Please report this " - << "to the Ceres team"; - StringAppendF(&report, "Termination: %20s\n", - "DID_NOT_RUN"); - StringAppendF(&report, "Reason: %s\n", error.c_str()); - return report; - } - - StringAppendF(&report, "\nCost:\n"); - StringAppendF(&report, "Initial % 30e\n", initial_cost); - if (termination_type != NUMERICAL_FAILURE && - termination_type != USER_ABORT) { - StringAppendF(&report, "Final % 30e\n", final_cost); - StringAppendF(&report, "Change % 30e\n", - initial_cost - final_cost); - } - - StringAppendF(&report, "\nNumber of iterations: % 20d\n", - static_cast<int>(iterations.size() - 1)); - - 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.3f\n", - jacobian_evaluation_time_in_seconds); - StringAppendF(&report, "Minimizer %25.3f\n\n", - minimizer_time_in_seconds); - - StringAppendF(&report, "Postprocessor %24.3f\n", - postprocessor_time_in_seconds); - - StringAppendF(&report, "Total %25.3f\n\n", - total_time_in_seconds); - - StringAppendF(&report, "Termination: %25s\n", - SolverTerminationTypeToString(termination_type)); } + if (termination_type == DID_NOT_RUN) { + CHECK(!error.empty()) + << "Solver terminated with DID_NOT_RUN but the solver did not " + << "return a reason. This is a Ceres error. Please report this " + << "to the Ceres team"; + StringAppendF(&report, "Termination: %20s\n", + "DID_NOT_RUN"); + StringAppendF(&report, "Reason: %s\n", error.c_str()); + return report; + } + + StringAppendF(&report, "\nCost:\n"); + StringAppendF(&report, "Initial % 30e\n", initial_cost); + if (termination_type != NUMERICAL_FAILURE && + termination_type != USER_ABORT) { + StringAppendF(&report, "Final % 30e\n", final_cost); + StringAppendF(&report, "Change % 30e\n", + initial_cost - final_cost); + } + + StringAppendF(&report, "\nMinimizer iterations % 16d\n", + num_successful_steps + num_unsuccessful_steps); + StringAppendF(&report, "Successful steps % 14d\n", + num_successful_steps); + StringAppendF(&report, "Unsuccessful steps % 14d\n", + num_unsuccessful_steps); + if (inner_iterations_used) { + StringAppendF(&report, "Steps with inner iterations % 14d\n", + num_inner_iteration_steps); + } + + StringAppendF(&report, "\nTime (in seconds):\n"); + StringAppendF(&report, "Preprocessor %25.3f\n", + preprocessor_time_in_seconds); + + StringAppendF(&report, "\n Residual evaluation %23.3f\n", + residual_evaluation_time_in_seconds); + StringAppendF(&report, " Jacobian evaluation %23.3f\n", + jacobian_evaluation_time_in_seconds); + + if (minimizer_type == TRUST_REGION) { + StringAppendF(&report, " Linear solver %23.3f\n", + linear_solver_time_in_seconds); + } + + if (inner_iterations_used) { + StringAppendF(&report, " Inner iterations %23.3f\n", + inner_iteration_time_in_seconds); + } + + StringAppendF(&report, "Minimizer %25.3f\n\n", + minimizer_time_in_seconds); + + StringAppendF(&report, "Postprocessor %24.3f\n", + postprocessor_time_in_seconds); + + StringAppendF(&report, "Total %25.3f\n\n", + total_time_in_seconds); + + StringAppendF(&report, "Termination: %25s\n", + SolverTerminationTypeToString(termination_type)); return report; };
diff --git a/internal/ceres/solver_impl.cc b/internal/ceres/solver_impl.cc index 56993c8..76e9c92 100644 --- a/internal/ceres/solver_impl.cc +++ b/internal/ceres/solver_impl.cc
@@ -536,8 +536,7 @@ } } } - - event_logger.AddEvent("CreateIIM"); + event_logger.AddEvent("CreateInnerIterationMinimizer"); // The optimizer works on contiguous parameter vectors; allocate some. Vector parameters(reduced_program->NumParameters()); @@ -1264,6 +1263,8 @@ const Program& program, const ProblemImpl::ParameterMap& parameter_map, Solver::Summary* summary) { + summary->inner_iterations_given = true; + scoped_ptr<CoordinateDescentMinimizer> inner_iteration_minimizer( new CoordinateDescentMinimizer); scoped_ptr<ParameterBlockOrdering> inner_iteration_ordering; @@ -1306,9 +1307,9 @@ return NULL; } - summary->inner_iterations = true; + summary->inner_iterations_used = true; + summary->inner_iteration_time_in_seconds = 0.0; SummarizeOrdering(ordering_ptr, &(summary->inner_iteration_ordering_used)); - return inner_iteration_minimizer.release(); }
diff --git a/internal/ceres/trust_region_minimizer.cc b/internal/ceres/trust_region_minimizer.cc index ab0f44b..3206dec 100644 --- a/internal/ceres/trust_region_minimizer.cc +++ b/internal/ceres/trust_region_minimizer.cc
@@ -319,6 +319,8 @@ } else { // Check if performing an inner iteration will make it better. if (inner_iterations_are_enabled) { + ++summary->num_inner_iteration_steps; + double inner_iteration_start_time = WallTimeInSeconds(); const double x_plus_delta_cost = new_cost; Vector inner_iteration_x = x_plus_delta; Solver::Summary inner_iteration_summary; @@ -347,10 +349,12 @@ // Disable inner iterations once the relative improvement // drops below tolerance. if (!inner_iterations_are_enabled) { - LOG(INFO) << "Disabling inner iterations. Progress : " - << inner_iteration_relative_progress; + VLOG(2) << "Disabling inner iterations. Progress : " + << inner_iteration_relative_progress; } } + summary->inner_iteration_time_in_seconds += + WallTimeInSeconds() - inner_iteration_start_time; } }
diff --git a/internal/ceres/wall_time.cc b/internal/ceres/wall_time.cc index e63d20c..85c4417 100644 --- a/internal/ceres/wall_time.cc +++ b/internal/ceres/wall_time.cc
@@ -86,7 +86,7 @@ last_event_time_ = current_time; StringAppendF(&events_, - " %25s : %10.5f %10.5f\n", + " %30s : %10.5f %10.5f\n", event_name.c_str(), relative_time_delta, absolute_time_delta);