mononoke/unbundle_replay: also report recorded duration

Summary: This will make it easier to compare performance.

Differential Revision: D20674164

fbshipit-source-id: eb1a037b0b060c373c1e87635f52dd228f728c89

eden/mononoke/tests/integration/test-unbundle-replay-hg-recording.t

@@ -68,13 +68,14 @@ Replay the push. This will fail because the entry does not exist (we need run th
 Insert the entry. Note that in tests, the commit timestamp will always be zero.
 
   $ sqlite3 "$TESTTMP/monsql/sqlite_dbs" << EOS
-  > INSERT INTO pushrebaserecording(repo_id, onto, ontorev, bundlehandle, timestamps, ordered_added_revs) VALUES (
+  > INSERT INTO pushrebaserecording(repo_id, onto, ontorev, bundlehandle, timestamps, ordered_added_revs, duration_ms) VALUES (
   >   0,
   >   'master_bookmark',
   >   '26805aba1e600a82e93661149f2313866a221a7b',
   >   'handle123',
   >   '{"4afe8a7fa62cf8320c8c11191d4dfdaaed9fb28b": [0.0, 0], "461b7a0d0ccf85d1168e2ae1be2a85af1ad62826": [0.0, 0]}',
-  >   '["cbab85d064b0fbdd3e9caa125f8eeac0fb5acf6a", "7a8f33ce453248a6f5cc4747002e931c77234fbd"]'
+  >   '["cbab85d064b0fbdd3e9caa125f8eeac0fb5acf6a", "7a8f33ce453248a6f5cc4747002e931c77234fbd"]',
+  >   123
   > );
   > EOS
 
@@ -94,6 +95,7 @@ Check history again. We're back to where we were:
     "int": {
       "age_s": *, (glob)
       "pushrebase_completion_time_us": *, (glob)
+      "pushrebase_recorded_time_us": 123000,
       "time": *, (glob)
       "unbundle_completion_time_us": * (glob)
     },

eden/mononoke/unbundle_replay/schemas/pushrebaserecording.sql

@@ -15,5 +15,6 @@ CREATE TABLE `pushrebaserecording` (
   `bundlehandle` TEXT,
   `timestamps` TEXT NOT NULL,
   `replacements_revs` TEXT,
-  `ordered_added_revs` TEXT
+  `ordered_added_revs` TEXT,
+  `duration_ms` INTEGER
 );

eden/mononoke/unbundle_replay/src/hg_recording.rs

@@ -18,8 +18,9 @@ use sql::{queries, Connection};
 use sql_ext::SqlConstructors;
 use std::borrow::Cow;
 use std::collections::HashMap;
-use std::convert::TryFrom;
+use std::convert::{TryFrom, TryInto};
 use std::str::FromStr;
+use std::time::Duration;
 
 pub struct HgRecordingEntry {
     pub id: i64,
@@ -28,6 +29,7 @@ pub struct HgRecordingEntry {
     pub bundle: String,
     pub timestamps: HashMap<HgChangesetId, Timestamp>,
     pub revs: Vec<HgChangesetId>,
+    pub duration: Option<Duration>,
 }
 
 pub struct HgRecordingClient {
@@ -53,12 +55,20 @@ impl SqlConstructors for HgRecordingConnection {
     }
 }
 
-type EntryRow = (i64, String, String, Option<String>, String, String);
+type EntryRow = (
+    i64,
+    String,
+    String,
+    Option<String>,
+    String,
+    String,
+    Option<i64>,
+);
 
 queries! {
-    read SelectNextSuccessfulHgRecordingEntryById(repo_id: RepositoryId, min_id: i64) -> (i64, String, String, Option<String>, String, String) {
+    read SelectNextSuccessfulHgRecordingEntryById(repo_id: RepositoryId, min_id: i64) -> (i64, String, String, Option<String>, String, String, Option<i64>) {
         "
-        SELECT id, onto, ontorev, bundlehandle, timestamps, ordered_added_revs
+        SELECT id, onto, ontorev, bundlehandle, timestamps, ordered_added_revs, duration_ms
         FROM pushrebaserecording
         WHERE repo_id = {repo_id} AND id > {min_id} AND pushrebase_errmsg IS NULL AND conflicts IS NULL
         ORDER BY id ASC
@@ -66,9 +76,9 @@ queries! {
         "
     }
 
-    read SelectNextSuccessfulHgRecordingEntryByOnto(repo_id: RepositoryId, onto: BookmarkName, ontorev: HgChangesetId) -> (i64, String, String, Option<String>, String, String) {
+    read SelectNextSuccessfulHgRecordingEntryByOnto(repo_id: RepositoryId, onto: BookmarkName, ontorev: HgChangesetId) -> (i64, String, String, Option<String>, String, String, Option<i64>) {
         "
-        SELECT id, onto, ontorev, bundlehandle, timestamps, ordered_added_revs
+        SELECT id, onto, ontorev, bundlehandle, timestamps, ordered_added_revs, duration_ms
         FROM pushrebaserecording
         WHERE repo_id = {repo_id} AND onto LIKE {onto} AND ontorev LIKE LOWER(HEX({ontorev})) AND pushrebase_errmsg IS NULL AND conflicts IS NULL
         ORDER BY id ASC
@@ -135,9 +145,12 @@ impl HgRecordingClient {
             }
         };
 
-        let (id, onto, onto_rev, bundle, timestamps, revs) = entry;
+        let (id, onto, onto_rev, bundle, timestamps, revs, duration_ms) = entry;
         let onto = BookmarkName::try_from(onto.as_str())?;
         let onto_rev = HgChangesetId::from_str(&onto_rev)?;
+        let duration: Option<Duration> = duration_ms
+            .map(|d| Result::<_, Error>::Ok(Duration::from_millis(d.try_into()?)))
+            .transpose()?;
 
         let timestamps = serde_json::from_str::<HashMap<Cow<'_, str>, (f64, u64)>>(&timestamps)?;
         let timestamps = timestamps
@@ -164,6 +177,7 @@ impl HgRecordingClient {
             bundle,
             timestamps,
             revs,
+            duration,
         }))
     }
 }

eden/mononoke/unbundle_replay/src/main.rs

@@ -220,6 +220,7 @@ struct UnbundleComplete {
     timestamps: HashMap<ChangesetId, Timestamp>,
     changesets: HashSet<BonsaiChangeset>,
     unbundle_stats: FutureStats,
+    recorded_duration: Option<Duration>,
 }
 
 enum UnbundleOutcome {
@@ -274,6 +275,7 @@ async fn maybe_unbundle(
         onto_rev,
         target,
         timestamps,
+        recorded_duration,
     } = pushrebase_spec;
 
     // TODO: Run hooks here (this is where repo_client would run them).
@@ -337,6 +339,7 @@ async fn maybe_unbundle(
         timestamps,
         changesets,
         unbundle_stats,
+        recorded_duration,
     }))
 }
 
@@ -447,6 +450,7 @@ async fn do_main(
                 timestamps,
                 changesets,
                 unbundle_stats,
+                recorded_duration,
             } = unbundle_complete;
 
             let onto_rev = match onto_rev {
@@ -514,6 +518,12 @@ async fn do_main(
             if let Some(current_cs_id) = current_cs_id {
                 scuba.add("from_cs_id", current_cs_id.to_string());
             }
+            if let Some(recorded_duration) = recorded_duration {
+                scuba.add(
+                    "pushrebase_recorded_time_us",
+                    recorded_duration.as_micros_unchecked(),
+                );
+            }
             scuba.log();
 
             info!(

eden/mononoke/unbundle_replay/src/replay_spec.rs

@@ -17,6 +17,7 @@ use mononoke_types::{hash::Blake2, ChangesetId, RawBundle2Id, Timestamp};
 use slog::info;
 use std::collections::HashMap;
 use std::str::FromStr;
+use std::time::Duration;
 use tokio::process::Command;
 
 use crate::hg_recording::HgRecordingEntry;
@@ -88,6 +89,7 @@ pub struct PushrebaseSpec {
     pub onto_rev: Option<OntoRev>,
     pub target: Target,
     pub timestamps: HashMap<HgChangesetId, Timestamp>,
+    pub recorded_duration: Option<Duration>,
 }
 
 pub struct ReplaySpec<'a> {
@@ -117,6 +119,7 @@ impl ReplaySpec<'static> {
                 onto: entry.bookmark_name,
                 onto_rev: entry.from_changeset_id.map(OntoRev::Bonsai),
                 target: Target::bonsai(target),
+                recorded_duration: None,
             },
         })
     }
@@ -134,6 +137,7 @@ impl<'a> ReplaySpec<'a> {
             bundle,
             timestamps,
             revs,
+            duration,
         } = entry;
 
         let target = Target::hg(
@@ -154,6 +158,7 @@ impl<'a> ReplaySpec<'a> {
                 onto_rev: Some(OntoRev::Hg(onto_rev)),
                 target,
                 timestamps,
+                recorded_duration: duration,
             },
         })
     }