BUG#35983655 Report time overhead of checksum not only in the log

If the checksum option is enabled, dump/load/copy utilities will display
time it took to compute/verify the checksum.

Change-Id: Id6b1f227fd6d407a983737bf281db63ca774cf84
(cherry picked from commit 41eb66384d34e0a07806814ed39e308f7ccbb8fa)

Author: Paweł Andruszkiewicz

modules/util/dump/dumper.cc

@@ -950,6 +950,8 @@ class Dumper::Table_worker final {
     log_debug("%sComputing checksum of %s (%s)", m_log_id.c_str(),
               task.name.c_str(), task.id.c_str());
 
+    m_dumper->checksum_task_started();
+
     if (Dry_run::DISABLED == m_dumper->m_options.dry_run_mode()) {
       task.checksum->compute(
           m_session,
@@ -2003,31 +2005,41 @@ void Dumper::do_run() {
     create_schema_ddl_tasks();
     create_table_tasks();
 
-    if (!m_options.is_dry_run() && !m_worker_interrupt) {
-      auto msg = "Running data dump using " +
-                 std::to_string(m_options.threads()) + " thread";
+    if (!m_worker_interrupt) {
+      std::string msg;
 
-      if (m_options.threads() > 1) {
-        msg += 's';
-      }
+      if (!m_options.is_dry_run()) {
+        msg = "Running data dump using " + std::to_string(m_options.threads()) +
+              " thread";
+
+        if (m_options.threads() > 1) {
+          msg += 's';
+        }
 
-      msg += '.';
+        msg += '.';
+      }
 
       if (m_checksum) {
-        msg += " Checksumming enabled.";
+        if (!msg.empty()) {
+          msg += ' ';
+        }
+
+        msg += "Checksumming enabled.";
       }
 
-      current_console()->print_status(msg);
+      if (!msg.empty()) {
+        current_console()->print_status(msg);
+      }
 
-      if (m_options.show_progress() && m_options.dump_data()) {
+      if (!m_options.is_dry_run() && m_options.show_progress() &&
+          m_options.dump_data()) {
         current_console()->print_note(
             "Progress information uses estimated values and may not be "
             "accurate.");
       }
     }
 
     initialize_throughput_progress();
-    initialize_checksum_progress();
 
     maybe_push_shutdown_tasks();
     wait_for_all_tasks();
@@ -2918,6 +2930,14 @@ void Dumper::data_task_finished() {
   }
 }
 
+void Dumper::checksum_task_started() {
+  bool expected = false;
+
+  if (m_checksum_started.compare_exchange_strong(expected, true)) {
+    initialize_checksum_progress();
+  }
+}
+
 void Dumper::checksum_task_finished() { ++m_checksum_tasks_completed; }
 
 void Dumper::wait_for_all_tasks() {
@@ -3145,6 +3165,7 @@ void Dumper::create_table_tasks() {
   m_chunking_tasks_completed = 0;
   m_data_tasks_total = 0;
   m_data_tasks_completed = 0;
+  m_checksum_started = false;
   m_checksum_tasks_total = 0;
   m_checksum_tasks_completed = 0;
 
@@ -3921,6 +3942,11 @@ void Dumper::summarize() const {
                           m_data_dump_stage->duration().to_string());
   }
 
+  if (m_checksum_stage) {
+    console->print_status("Checksum duration: " +
+                          m_checksum_stage->duration().to_string());
+  }
+
   console->print_status("Total duration: " +
                         m_progress_thread.duration().to_string());
 
@@ -4062,7 +4088,7 @@ void Dumper::initialize_checksum_progress() {
   config.total = [this]() { return m_checksum_tasks_total.load(); };
   config.is_total_known = [this]() { return all_tasks_produced(); };
 
-  m_current_stage =
+  m_current_stage = m_checksum_stage =
       m_progress_thread.start_stage("Computing checksum", std::move(config));
 }
 

modules/util/dump/dumper.h

@@ -256,6 +256,8 @@ class Dumper {
 
   void data_task_finished();
 
+  void checksum_task_started();
+
   void checksum_task_finished();
 
   void wait_for_all_tasks();
@@ -484,6 +486,7 @@ class Dumper {
   std::atomic<uint64_t> m_chunking_tasks_completed;
   std::atomic<uint64_t> m_data_tasks_total;
   std::atomic<uint64_t> m_data_tasks_completed;
+  std::atomic<bool> m_checksum_started;
   std::atomic<uint64_t> m_checksum_tasks_total;
   std::atomic<uint64_t> m_checksum_tasks_completed;
   std::atomic<bool> m_main_thread_finished_producing_chunking_tasks;
@@ -496,6 +499,7 @@ class Dumper {
   mutable Progress_thread m_progress_thread;
   mutable Progress_thread::Stage *m_current_stage = nullptr;
   Progress_thread::Stage *m_data_dump_stage = nullptr;
+  Progress_thread::Stage *m_checksum_stage = nullptr;
 
   shcore::Synchronized_queue<std::shared_ptr<mysqlshdk::db::ISession>>
       m_session_pool;

modules/util/load/dump_loader.cc

@@ -2035,8 +2035,12 @@ void Dump_loader::show_summary() {
 
   if (!m_options.dry_run()) {
     if (m_checksum_tasks_completed) {
+      assert(m_checksum_tables_stage);
       console->print_info(shcore::str_format(
-          "%" PRIu64 " checksums were verified.", m_checksum_tasks_completed));
+          "%" PRIu64 " checksums were verified in %s.",
+          m_checksum_tasks_completed,
+          format_seconds(m_checksum_tables_stage->duration().seconds(), false)
+              .c_str()));
     }
 
     if (m_checksum_errors) {

unittest/scripts/auto/py_shell/scripts/util_copy_instance_norecord.py

@@ -664,7 +664,7 @@ def setup_db(account):
 
 #@<> WL15887-TSFR_4_1 - note about strip_definers {not __dbug_off and VER(>=8.2.0)}
 EXPECT_SUCCESS(__sandbox_uri2, { "compatibility": [ "strip_definers" ], "dryRun": True, "includeSchemas": [ schema_name ], "users": False, "showProgress": False })
-EXPECT_STDOUT_CONTAINS(f"NOTE: The 'targetVersion' option is set to {__mysh_version_no_extra}. This version supports the SET_ANY_DEFINER privilege, using the 'strip_definers' compatibility option is unnecessary.")
+EXPECT_STDOUT_CONTAINS(f"NOTE: The 'targetVersion' option is set to {__version}. This version supports the SET_ANY_DEFINER privilege, using the 'strip_definers' compatibility option is unnecessary.")
 
 #@<> WL15887-TSFR_5_1 - user/role with SET_ANY_DEFINER {not __dbug_off and VER(>=8.2.0)}
 for account in account_names:

unittest/scripts/auto/py_shell/scripts/util_copy_schemas_norecord.py

@@ -612,7 +612,7 @@ def setup_db(account):
 
 #@<> WL15887-TSFR_4_1 - note about strip_definers {not __dbug_off and VER(>=8.2.0)}
 EXPECT_SUCCESS(__sandbox_uri2, { "compatibility": [ "strip_definers" ], "dryRun": True, "showProgress": False }, schemas = [ schema_name ])
-EXPECT_STDOUT_CONTAINS(f"NOTE: The 'targetVersion' option is set to {__mysh_version_no_extra}. This version supports the SET_ANY_DEFINER privilege, using the 'strip_definers' compatibility option is unnecessary.")
+EXPECT_STDOUT_CONTAINS(f"NOTE: The 'targetVersion' option is set to {__version}. This version supports the SET_ANY_DEFINER privilege, using the 'strip_definers' compatibility option is unnecessary.")
 
 #@<> WL15887 - cleanup {not __dbug_off and VER(>=8.2.0)}
 src_session.run_sql("DROP SCHEMA IF EXISTS !;", [schema_name])

unittest/scripts/auto/py_shell/scripts/util_copy_tables_norecord.py

@@ -534,7 +534,7 @@ def setup_db(account):
 
 #@<> WL15887-TSFR_4_1 - note about strip_definers {not __dbug_off and VER(>=8.2.0)}
 EXPECT_SUCCESS(__sandbox_uri2, { "compatibility": [ "strip_definers" ], "dryRun": True, "showProgress": False }, schema = schema_name , tables = test_tables)
-EXPECT_STDOUT_CONTAINS(f"NOTE: The 'targetVersion' option is set to {__mysh_version_no_extra}. This version supports the SET_ANY_DEFINER privilege, using the 'strip_definers' compatibility option is unnecessary.")
+EXPECT_STDOUT_CONTAINS(f"NOTE: The 'targetVersion' option is set to {__version}. This version supports the SET_ANY_DEFINER privilege, using the 'strip_definers' compatibility option is unnecessary.")
 
 #@<> WL15887 - cleanup {not __dbug_off and VER(>=8.2.0)}
 src_session.run_sql("DROP SCHEMA IF EXISTS !;", [schema_name])

unittest/scripts/auto/py_shell/scripts/util_dump_and_load_norecord.py

@@ -2970,6 +2970,8 @@ def TEST_BOOL_OPTION(option):
 # WL15947-TSFR_2_4_3 - load an empty table
 wipeout_server(session2)
 EXPECT_NO_THROWS(lambda: util.load_dump(dump_dir, { "checksum": True, "resetProgress": True, "showProgress": False }))
+# BUG#35983655 - display duration of checksum verification
+EXPECT_STDOUT_CONTAINS(" checksums were verified in ")
 
 # WL15947-TSFR_2_4_2 - checksum existing tables without loading the data
 # this throws because both dumps were created with different contents (one had `where` option)

unittest/scripts/auto/py_shell/scripts/util_dump_instance_norecord.py

@@ -3855,7 +3855,8 @@ def setup_db():
 #@<> WL15947-TSFR_1_2_1_1 - checksum option set to true
 EXPECT_SUCCESS([ schema_name ], test_output_absolute, { "checksum": True, "showProgress": False })
 # checksums are generated
-EXPECT_STDOUT_CONTAINS("Checksum")
+# BUG#35983655 - display duration of checksum operation
+EXPECT_STDOUT_CONTAINS("Checksum duration:")
 # file is written
 EXPECT_TRUE(os.path.isfile(checksum_file))
 
@@ -3952,7 +3953,7 @@ def setup_db():
 
 #@<> WL15947 - dry run
 EXPECT_SUCCESS([ schema_name ], test_output_absolute, { "dryRun": True, "checksum": True, "includeTables": [ quote_identifier(schema_name, test_table_unique_null) ], "showProgress": False })
-EXPECT_STDOUT_CONTAINS("Computing checksum...")
+EXPECT_STDOUT_CONTAINS("Checksumming enabled.")
 
 #@<> WL15947 - cleanup
 session.run_sql("DROP SCHEMA IF EXISTS !;", [schema_name])

unittest/scripts/auto/py_shell/scripts/util_dump_schemas_norecord.py

@@ -2741,7 +2741,7 @@ def setup_db():
 
 #@<> WL15947 - dry run
 EXPECT_SUCCESS([ schema_name ], test_output_absolute, { "dryRun": True, "checksum": True, "includeTables": [ quote_identifier(schema_name, test_table_unique_null) ], "showProgress": False })
-EXPECT_STDOUT_CONTAINS("Computing checksum...")
+EXPECT_STDOUT_CONTAINS("Checksumming enabled.")
 
 #@<> WL15947 - cleanup
 session.run_sql("DROP SCHEMA IF EXISTS !;", [schema_name])

unittest/scripts/auto/py_shell/scripts/util_dump_tables_norecord.py

@@ -3436,7 +3436,7 @@ def setup_db():
 
 #@<> WL15947 - dry run
 EXPECT_SUCCESS(schema_name, [ test_table_unique_null ], test_output_absolute, { "dryRun": True, "checksum": True, "showProgress": False })
-EXPECT_STDOUT_CONTAINS("Computing checksum...")
+EXPECT_STDOUT_CONTAINS("Checksumming enabled.")
 
 #@<> WL15947 - cleanup
 session.run_sql("DROP SCHEMA IF EXISTS !;", [schema_name])