From c9518750b2581950f6d6b9f592789b2e48385dc5 Mon Sep 17 00:00:00 2001
From: David Lutterkort <lutter@watzmann.net>
Date: Fri, 2 Apr 2021 12:58:58 -0700
Subject: [PATCH] WIP: Log more details about time taken in copying

---
 store/postgres/src/copy.rs | 19 +++++++++++++------
 1 file changed, 13 insertions(+), 6 deletions(-)

diff --git a/store/postgres/src/copy.rs b/store/postgres/src/copy.rs
index 9bf31fda1ef..44e194c3e4f 100644
--- a/store/postgres/src/copy.rs
+++ b/store/postgres/src/copy.rs
@@ -29,7 +29,7 @@ use diesel::{
 use graph::{
     components::store::EntityType,
     constraint_violation,
-    prelude::{info, o, BlockNumber, EthereumBlockPointer, Logger, StoreError},
+    prelude::{debug, info, o, BlockNumber, EthereumBlockPointer, Logger, StoreError},
 };
 
 use crate::{
@@ -433,7 +433,9 @@ impl TableState {
         Ok(())
     }
 
-    fn copy_batch(&mut self, conn: &PgConnection) -> Result<Status, StoreError> {
+    fn copy_batch(&mut self, conn: &PgConnection) -> Result<(Status, Duration), StoreError> {
+        let batch_start = Instant::now();
+
         fn is_cancelled(dst: &Site, conn: &PgConnection) -> Result<bool, StoreError> {
             use active_copies as ac;
 
@@ -447,7 +449,7 @@ impl TableState {
         let start = Instant::now();
 
         if is_cancelled(self.dst_site.as_ref(), conn)? {
-            return Ok(Status::Cancelled);
+            return Ok((Status::Cancelled, batch_start.elapsed()));
         }
 
         // Copy all versions with next_vid <= vid <= next_vid + batch_size - 1,
@@ -476,10 +478,10 @@ impl TableState {
         }
 
         if is_cancelled(self.dst_site.as_ref(), conn)? {
-            return Ok(Status::Cancelled);
+            return Ok((Status::Cancelled, batch_start.elapsed()));
         }
 
-        Ok(Status::Finished)
+        Ok((Status::Finished, batch_start.elapsed()))
     }
 }
 
@@ -608,13 +610,18 @@ impl Connection {
         let mut progress = CopyProgress::new(&self.logger, &state);
         progress.start();
 
+        let start = Instant::now();
         for table in state.tables.iter_mut().filter(|table| !table.finished()) {
             while !table.finished() {
-                let status = self.transaction(|conn| table.copy_batch(conn))?;
+                let (status, elapsed) = self.transaction(|conn| table.copy_batch(conn))?;
                 if status == Status::Cancelled {
                     return Ok(status);
                 }
                 progress.update(table);
+                debug!(&self.logger, "Finished batch";
+                    "table" => table.dst.object.as_str(),
+                    "batch_s" => elapsed.as_secs(),
+                    "total_s" => start.elapsed().as_secs());
             }
             progress.table_finished(table);
         }