Reduce logging during incremental mapping (colmap#2420)

* Reduce IncrementalMapper logs to verbose * Reduce optimizer logging * Expose verbose level to Python * Enable verbose logging for the e2e test * Fix macOS CI * Remove logging in example.py * Add pycolmap.logging.verbose() * Switch PrintHeading1 to LOG(INFO)
theerawatramchuen · Feb 14, 2024 · 7357b38 · 7357b38
1 parent 2a594c0
commit 7357b38
Show file tree

Hide file tree

Showing 10 changed files with 60 additions and 54 deletions.
diff --git a/.github/workflows/build-mac.yaml b/.github/workflows/build-mac.yaml
@@ -40,6 +40,7 @@ jobs:
 
       - name: Setup Mac
         run: |
+          rm -f '/usr/local/bin/2to3*'  # Fix `brew link` error.
           brew install \
             cmake \
             ninja \

diff --git a/.github/workflows/build-ubuntu.yml b/.github/workflows/build-ubuntu.yml
@@ -250,7 +250,7 @@ jobs:
           mkdir eth3d_benchmark
           # Error thresholds in degrees and meters,
           # as the ETH3D groundtruth has metric scale.
-          python ./scripts/python/benchmark_eth3d.py \
+          GLOG_v=1 python ./scripts/python/benchmark_eth3d.py \
               --workspace_path ./eth3d_benchmark \
               --colmap_path ./build/src/colmap/exe/colmap \
               --dataset_names boulders,door \

diff --git a/src/colmap/controllers/incremental_mapper.cc b/src/colmap/controllers/incremental_mapper.cc
@@ -38,10 +38,10 @@ namespace {
 size_t TriangulateImage(const IncrementalMapperOptions& options,
                         const Image& image,
                         IncrementalMapper* mapper) {
-  LOG(INFO) << "=> Continued observations: " << image.NumPoints3D();
+  VLOG(1) << "=> Continued observations: " << image.NumPoints3D();
   const size_t num_tris =
       mapper->TriangulateImage(options.Triangulation(), image.ImageId());
-  LOG(INFO) << "=> Added observations: " << num_tris;
+  VLOG(1) << "=> Added observations: " << num_tris;
   return num_tris;
 }
 
@@ -61,7 +61,7 @@ void AdjustGlobalBundle(const IncrementalMapperOptions& options,
     custom_ba_options.solver_options.max_linear_solver_iterations = 200;
   }
 
-  PrintHeading1("Global bundle adjustment");
+  LOG(INFO) << "Global bundle adjustment";
   mapper->AdjustGlobalBundle(options.Mapper(), custom_ba_options);
 }
 
@@ -76,19 +76,18 @@ void IterativeLocalRefinement(const IncrementalMapperOptions& options,
                                   options.Triangulation(),
                                   image_id,
                                   mapper->GetModifiedPoints3D());
-    LOG(INFO) << "=> Merged observations: " << report.num_merged_observations;
-    LOG(INFO) << "=> Completed observations: "
-              << report.num_completed_observations;
-    LOG(INFO) << "=> Filtered observations: "
-              << report.num_filtered_observations;
+    VLOG(1) << "=> Merged observations: " << report.num_merged_observations;
+    VLOG(1) << "=> Completed observations: "
+            << report.num_completed_observations;
+    VLOG(1) << "=> Filtered observations: " << report.num_filtered_observations;
     const double changed =
         report.num_adjusted_observations == 0
             ? 0
             : (report.num_merged_observations +
                report.num_completed_observations +
                report.num_filtered_observations) /
                   static_cast<double>(report.num_adjusted_observations);
-    LOG(INFO) << StringPrintf("=> Changed observations: %.6f", changed);
+    VLOG(1) << StringPrintf("=> Changed observations: %.6f", changed);
     if (changed < options.ba_local_max_refinement_change) {
       break;
     }
@@ -101,10 +100,10 @@ void IterativeLocalRefinement(const IncrementalMapperOptions& options,
 
 void IterativeGlobalRefinement(const IncrementalMapperOptions& options,
                                IncrementalMapper* mapper) {
-  PrintHeading1("Retriangulation");
+  LOG(INFO) << "Retriangulation";
   CompleteAndMergeTracks(options, mapper);
-  LOG(INFO) << "=> Retriangulated observations: "
-            << mapper->Retriangulate(options.Triangulation());
+  VLOG(1) << "=> Retriangulated observations: "
+          << mapper->Retriangulate(options.Triangulation());
 
   for (int i = 0; i < options.ba_global_max_refinements; ++i) {
     const size_t num_observations =
@@ -117,7 +116,7 @@ void IterativeGlobalRefinement(const IncrementalMapperOptions& options,
         num_observations == 0
             ? 0
             : static_cast<double>(num_changed_observations) / num_observations;
-    LOG(INFO) << StringPrintf("=> Changed observations: %.6f", changed);
+    VLOG(1) << StringPrintf("=> Changed observations: %.6f", changed);
     if (changed < options.ba_global_max_refinement_change) {
       break;
     }
@@ -138,7 +137,7 @@ void ExtractColors(const std::string& image_path,
 
 void WriteSnapshot(const Reconstruction& reconstruction,
                    const std::string& snapshot_path) {
-  PrintHeading1("Creating snapshot");
+  LOG(INFO) << "Creating snapshot";
   // Get the current timestamp in milliseconds.
   const size_t timestamp =
       std::chrono::duration_cast<std::chrono::milliseconds>(
@@ -148,7 +147,7 @@ void WriteSnapshot(const Reconstruction& reconstruction,
   const std::string path =
       JoinPaths(snapshot_path, StringPrintf("%010d", timestamp));
   CreateDirIfNotExists(path);
-  LOG(INFO) << "=> Writing to " << path;
+  VLOG(1) << "=> Writing to " << path;
   reconstruction.Write(path);
 }
 
@@ -158,25 +157,25 @@ size_t FilterPoints(const IncrementalMapperOptions& options,
                     IncrementalMapper* mapper) {
   const size_t num_filtered_observations =
       mapper->FilterPoints(options.Mapper());
-  LOG(INFO) << "=> Filtered observations: " << num_filtered_observations;
+  VLOG(1) << "=> Filtered observations: " << num_filtered_observations;
   return num_filtered_observations;
 }
 
 size_t FilterImages(const IncrementalMapperOptions& options,
                     IncrementalMapper* mapper) {
   const size_t num_filtered_images = mapper->FilterImages(options.Mapper());
-  LOG(INFO) << "=> Filtered images: " << num_filtered_images;
+  VLOG(1) << "=> Filtered images: " << num_filtered_images;
   return num_filtered_images;
 }
 
 size_t CompleteAndMergeTracks(const IncrementalMapperOptions& options,
                               IncrementalMapper* mapper) {
   const size_t num_completed_observations =
       mapper->CompleteTracks(options.Triangulation());
-  LOG(INFO) << "=> Completed observations: " << num_completed_observations;
+  VLOG(1) << "=> Completed observations: " << num_completed_observations;
   const size_t num_merged_observations =
       mapper->MergeTracks(options.Triangulation());
-  LOG(INFO) << "=> Merged observations: " << num_merged_observations;
+  VLOG(1) << "=> Merged observations: " << num_merged_observations;
   return num_completed_observations + num_merged_observations;
 }
 
@@ -215,7 +214,7 @@ BundleAdjustmentOptions IncrementalMapperOptions::LocalBundleAdjustment()
 #if CERES_VERSION_MAJOR < 2
   options.solver_options.num_linear_solver_threads = num_threads;
 #endif  // CERES_VERSION_MAJOR
-  options.print_summary = true;
+  options.print_summary = false;
   options.refine_focal_length = ba_refine_focal_length;
   options.refine_principal_point = ba_refine_principal_point;
   options.refine_extra_params = ba_refine_extra_params;
@@ -237,12 +236,12 @@ BundleAdjustmentOptions IncrementalMapperOptions::GlobalBundleAdjustment()
   options.solver_options.max_linear_solver_iterations = 100;
   options.solver_options.logging_type =
       ceres::LoggingType::PER_MINIMIZER_ITERATION;
-  options.solver_options.minimizer_progress_to_stdout = true;
+  options.solver_options.minimizer_progress_to_stdout = false;
   options.solver_options.num_threads = num_threads;
 #if CERES_VERSION_MAJOR < 2
   options.solver_options.num_linear_solver_threads = num_threads;
 #endif  // CERES_VERSION_MAJOR
-  options.print_summary = true;
+  options.print_summary = false;
   options.refine_focal_length = ba_refine_focal_length;
   options.refine_principal_point = ba_refine_principal_point;
   options.refine_extra_params = ba_refine_extra_params;
@@ -327,7 +326,7 @@ void IncrementalMapperController::Run() {
 }
 
 bool IncrementalMapperController::LoadDatabase() {
-  PrintHeading1("Loading database");
+  LOG(INFO) << "Loading database";
 
   // Make sure images of the given reconstruction are also included when
   // manually specifying images for the reconstrunstruction procedure.
@@ -400,7 +399,7 @@ void IncrementalMapperController::Reconstruct(
 
       // Try to find good initial pair.
       if (options_->init_image_id1 == -1 || options_->init_image_id2 == -1) {
-        PrintHeading1("Finding good initial image pair");
+        LOG(INFO) << "Finding good initial image pair";
         const bool find_init_success = mapper.FindInitialImagePair(
             init_mapper_options, &image_id1, &image_id2);
         if (!find_init_success) {
@@ -422,8 +421,8 @@ void IncrementalMapperController::Reconstruct(
         }
       }
 
-      PrintHeading1(StringPrintf(
-          "Initializing with image pair #%d and #%d", image_id1, image_id2));
+      LOG(INFO) << StringPrintf(
+          "Initializing with image pair #%d and #%d", image_id1, image_id2);
       const bool reg_init_success = mapper.RegisterInitialImagePair(
           init_mapper_options, image_id1, image_id2);
       if (!reg_init_success) {
@@ -490,10 +489,9 @@ void IncrementalMapperController::Reconstruct(
         const image_t next_image_id = next_images[reg_trial];
         const Image& next_image = reconstruction->Image(next_image_id);
 
-        PrintHeading1(StringPrintf("Registering image #%d (%d)",
-                                   next_image_id,
-                                   reconstruction->NumRegImages() + 1));
-
+        LOG(INFO) << StringPrintf("Registering image #%d (%d)",
+                                  next_image_id,
+                                  reconstruction->NumRegImages() + 1);
         LOG(INFO) << StringPrintf("=> Image sees %d / %d points",
                                   next_image.NumVisiblePoints3D(),
                                   next_image.NumObservations());

diff --git a/src/colmap/estimators/bundle_adjustment.cc b/src/colmap/estimators/bundle_adjustment.cc
@@ -308,9 +308,8 @@ bool BundleAdjuster::Solve(Reconstruction* reconstruction) {
 
   ceres::Solve(solver_options, problem_.get(), &summary_);
 
-  if (options_.print_summary) {
-    PrintHeading2("Bundle adjustment report");
-    PrintSolverSummary(summary_);
+  if (options_.print_summary || VLOG_IS_ON(1)) {
+    PrintSolverSummary(summary_, "Bundle adjustment report");
   }
 
   TearDown(reconstruction);
@@ -583,9 +582,8 @@ bool RigBundleAdjuster::Solve(Reconstruction* reconstruction,
 
   ceres::Solve(solver_options, problem_.get(), &summary_);
 
-  if (options_.print_summary) {
-    PrintHeading2("Rig Bundle adjustment report");
-    PrintSolverSummary(summary_);
+  if (options_.print_summary || VLOG_IS_ON(1)) {
+    PrintSolverSummary(summary_, "Rig Bundle adjustment report");
   }
 
   TearDown(reconstruction, *camera_rigs);
@@ -815,9 +813,10 @@ void RigBundleAdjuster::ParameterizeCameraRigs(Reconstruction* reconstruction) {
   }
 }
 
-void PrintSolverSummary(const ceres::Solver::Summary& summary) {
+void PrintSolverSummary(const ceres::Solver::Summary& summary,
+                        const std::string& header) {
   std::ostringstream log;
-  log << "\n";
+  log << "\n" << header << ":\n";
   log << std::right << std::setw(16) << "Residuals : ";
   log << std::left << summary.num_residuals_reduced << "\n";
 

diff --git a/src/colmap/estimators/bundle_adjustment.h b/src/colmap/estimators/bundle_adjustment.h
@@ -256,6 +256,7 @@ class RigBundleAdjuster : public BundleAdjuster {
   std::unordered_set<double*> parameterized_quats_;
 };
 
-void PrintSolverSummary(const ceres::Solver::Summary& summary);
+void PrintSolverSummary(const ceres::Solver::Summary& summary,
+                        const std::string& header);
 
 }  // namespace colmap
diff --git a/src/colmap/estimators/generalized_pose.cc b/src/colmap/estimators/generalized_pose.cc
@@ -40,7 +40,7 @@
 #include "colmap/scene/camera.h"
 #include "colmap/sensor/models.h"
 #include "colmap/util/eigen_alignment.h"
-#include "colmap/util/misc.h"
+#include "colmap/util/logging.h"
 
 #include <Eigen/Core>
 #include <ceres/ceres.h>
@@ -277,9 +277,8 @@ bool RefineGeneralizedAbsolutePose(const AbsolutePoseRefinementOptions& options,
   ceres::Solver::Summary summary;
   ceres::Solve(solver_options, &problem, &summary);
 
-  if (options.print_summary) {
-    PrintHeading2("Pose refinement report");
-    PrintSolverSummary(summary);
+  if (options.print_summary || VLOG_IS_ON(1)) {
+    PrintSolverSummary(summary, "Pose refinement report");
   }
 
   if (problem.NumResiduals() > 0 && rig_from_world_cov != nullptr) {

diff --git a/src/colmap/estimators/pose.cc b/src/colmap/estimators/pose.cc
@@ -37,7 +37,7 @@
 #include "colmap/geometry/pose.h"
 #include "colmap/math/matrix.h"
 #include "colmap/sensor/models.h"
-#include "colmap/util/misc.h"
+#include "colmap/util/logging.h"
 #include "colmap/util/threading.h"
 
 namespace colmap {
@@ -295,9 +295,8 @@ bool RefineAbsolutePose(const AbsolutePoseRefinementOptions& options,
   ceres::Solver::Summary summary;
   ceres::Solve(solver_options, &problem, &summary);
 
-  if (options.print_summary) {
-    PrintHeading2("Pose refinement report");
-    PrintSolverSummary(summary);
+  if (options.print_summary || VLOG_IS_ON(1)) {
+    PrintSolverSummary(summary, "Pose refinement report");
   }
 
   if (problem.NumResiduals() > 0 && cam_from_world_cov != nullptr) {

diff --git a/src/colmap/estimators/pose.h b/src/colmap/estimators/pose.h
@@ -92,7 +92,7 @@ struct AbsolutePoseRefinementOptions {
   bool refine_extra_params = true;
 
   // Whether to print final summary.
-  bool print_summary = true;
+  bool print_summary = false;
 
   void Check() const {
     THROW_CHECK_GE(gradient_tolerance, 0.0);

diff --git a/src/pycolmap/estimators/absolute_pose.h b/src/pycolmap/estimators/absolute_pose.h
@@ -117,7 +117,6 @@ void BindAbsolutePoseEstimator(py::module& m) {
         AbsolutePoseRefinementOptions options;
         options.refine_focal_length = false;
         options.refine_extra_params = false;
-        options.print_summary = false;
         return options;
       }))
       .def_readwrite("gradient_tolerance",

diff --git a/src/pycolmap/main.cc b/src/pycolmap/main.cc
@@ -44,37 +44,47 @@ void BindLogging(py::module& m) {
       .def_readwrite_static("log_dir", &FLAGS_log_dir)
       .def_readwrite_static("logtostderr", &FLAGS_logtostderr)
       .def_readwrite_static("alsologtostderr", &FLAGS_alsologtostderr)
+      .def_readwrite_static("verbose_level", &FLAGS_v)
       .def_static(
           "set_log_destination",
           [](const Logging::LogSeverity severity, const std::string& path) {
             google::SetLogDestination(
                 static_cast<google::LogSeverity>(severity), path.c_str());
           })
+      .def_static(
+          "verbose",
+          [](const int level, const std::string& msg) {
+            if (VLOG_IS_ON(level)) {
+              const auto frame = GetPythonCallFrame();
+              google::LogMessage(frame.first.c_str(), frame.second).stream()
+                  << msg;
+            }
+          })
       .def_static(
           "info",
           [](const std::string& msg) {
-            auto frame = GetPythonCallFrame();
+            const auto frame = GetPythonCallFrame();
             google::LogMessage(frame.first.c_str(), frame.second).stream()
                 << msg;
           })
       .def_static("warning",
                   [](const std::string& msg) {
-                    auto frame = GetPythonCallFrame();
+                    const auto frame = GetPythonCallFrame();
                     google::LogMessage(
                         frame.first.c_str(), frame.second, google::GLOG_WARNING)
                             .stream()
                         << msg;
                   })
       .def_static("error",
                   [](const std::string& msg) {
-                    auto frame = GetPythonCallFrame();
+                    const auto frame = GetPythonCallFrame();
                     google::LogMessage(
                         frame.first.c_str(), frame.second, google::GLOG_ERROR)
                             .stream()
                         << msg;
                   })
       .def_static("fatal", [](const std::string& msg) {
-        auto frame = GetPythonCallFrame();
+        const auto frame = GetPythonCallFrame();
         google::LogMessageFatal(frame.first.c_str(), frame.second).stream()
             << msg;
       });
-Original file line number
+Diff line change
@@ Expand Up / @@ -40,6 +40,7 @@ jobs: @@
           - name: Setup Mac
             run: |
+              rm -f '/usr/local/bin/2to3*'  # Fix `brew link` error.
               brew install \
                 cmake \
                 ninja \
@@ Expand Down @@