From 032f5e5158540bff0b668994088d10cf3705fc46 Mon Sep 17 00:00:00 2001 From: Jun Wu Date: Tue, 4 May 2021 18:26:23 -0700 Subject: [PATCH] eagerepo: add tracing messages Summary: Make it easier to check whether APIs in EagerRepo is called or not. Reviewed By: andll Differential Revision: D27955426 fbshipit-source-id: 27ca505c63596368cff98642de010b5b5717454c --- eden/scm/lib/eagerepo/Cargo.toml | 1 + eden/scm/lib/eagerepo/src/api.rs | 57 +++++++++++++++++++++++++--- eden/scm/tests/test-eager-exchange.t | 26 ++++++++++++- 3 files changed, 78 insertions(+), 6 deletions(-) diff --git a/eden/scm/lib/eagerepo/Cargo.toml b/eden/scm/lib/eagerepo/Cargo.toml index 2d98c79639..f45dd12398 100644 --- a/eden/scm/lib/eagerepo/Cargo.toml +++ b/eden/scm/lib/eagerepo/Cargo.toml @@ -14,6 +14,7 @@ http = "0.2" metalog = { path = "../metalog" } minibytes = { path = "../minibytes" } thiserror = "1.0" +tracing = "0.1" zstore = { path = "../zstore" } [dev-dependencies] diff --git a/eden/scm/lib/eagerepo/src/api.rs b/eden/scm/lib/eagerepo/src/api.rs index b648cf8919..831fe00a47 100644 --- a/eden/scm/lib/eagerepo/src/api.rs +++ b/eden/scm/lib/eagerepo/src/api.rs @@ -40,6 +40,8 @@ use futures::StreamExt; use http::StatusCode; use http::Version; use std::collections::HashSet; +use tracing::debug; +use tracing::trace; #[async_trait::async_trait] impl EdenApi for EagerRepo { @@ -53,6 +55,7 @@ impl EdenApi for EagerRepo { keys: Vec, _progress: Option, ) -> edenapi::Result> { + debug!("files {}", debug_key_list(&keys)); let mut values = Vec::with_capacity(keys.len()); for key in keys { let id = key.hgid; @@ -78,6 +81,7 @@ impl EdenApi for EagerRepo { _length: Option, _progress: Option, ) -> edenapi::Result> { + debug!("history {}", debug_key_list(&keys)); let mut values = Vec::new(); let mut visited: HashSet = Default::default(); let mut to_visit: Vec = keys; @@ -129,6 +133,7 @@ impl EdenApi for EagerRepo { attributes: Option, _progress: Option, ) -> edenapi::Result>> { + debug!("trees {}", debug_key_list(&keys)); let mut values = Vec::new(); let attributes = attributes.unwrap_or_default(); if attributes.child_metadata { @@ -175,6 +180,7 @@ impl EdenApi for EagerRepo { hgids: Vec, _progress: Option, ) -> edenapi::Result> { + debug!("revlog_data {}", debug_hgid_list(&hgids)); let mut values = Vec::new(); for id in hgids { let data = self.get_sha1_blob_for_api(id)?; @@ -193,6 +199,7 @@ impl EdenApi for EagerRepo { _repo: String, _progress: Option, ) -> edenapi::Result> { + debug!("clone_data"); let clone_data = self.dag().export_clone_data().await.map_err(map_dag_err)?; check_convert_to_hgid(clone_data.idmap.values())?; let clone_data = dag::CloneData { @@ -317,6 +324,7 @@ impl EdenApi for EagerRepo { _repo: String, hgids: Vec, ) -> edenapi::Result> { + debug!("commit_known {}", debug_hgid_list(&hgids)); let mut values = Vec::new(); for id in hgids { let known = self.get_sha1_blob(id).map_err(map_crate_err)?.is_some(); @@ -335,6 +343,11 @@ impl EdenApi for EagerRepo { heads: Vec, common: Vec, ) -> Result, EdenApiError> { + debug!( + "commit_graph {} {}", + debug_hgid_list(&heads), + debug_hgid_list(&common), + ); let heads = dag::Set::from_static_names(heads.iter().map(|v| Vertex::copy_from(v.as_ref()))); let common = @@ -365,6 +378,7 @@ impl EdenApi for EagerRepo { bookmarks: Vec, _progress: Option, ) -> edenapi::Result> { + debug!("bookmarks {}", debug_string_list(&bookmarks),); let mut values = Vec::new(); let map = self.get_bookmarks_map().map_err(map_crate_err)?; for name in bookmarks { @@ -383,11 +397,17 @@ impl EagerRepo { fn get_sha1_blob_for_api(&self, id: HgId) -> edenapi::Result { // Emulate the HTTP errors. match self.get_sha1_blob(id) { - Ok(None) => Err(EdenApiError::HttpError { - status: StatusCode::NOT_FOUND, - message: format!("{} cannot be found", id.to_hex()), - }), - Ok(Some(data)) => Ok(data), + Ok(None) => { + trace!(" not found: {}", id.to_hex()); + Err(EdenApiError::HttpError { + status: StatusCode::NOT_FOUND, + message: format!("{} cannot be found", id.to_hex()), + }) + } + Ok(Some(data)) => { + trace!(" found: {}, {} bytes", id.to_hex(), data.len()); + Ok(data) + } Err(e) => Err(EdenApiError::HttpError { status: StatusCode::INTERNAL_SERVER_ERROR, message: format!("{:?}", e), @@ -478,3 +498,30 @@ fn map_dag_err(e: dag::Error) -> EdenApiError { fn map_crate_err(e: crate::Error) -> EdenApiError { EdenApiError::Other(e.into()) } + +fn debug_key_list(keys: &[Key]) -> String { + debug_list(keys, |k| k.hgid.to_hex()) +} + +fn debug_hgid_list(ids: &[HgId]) -> String { + debug_list(ids, |i| i.to_hex()) +} + +fn debug_string_list(s: &[String]) -> String { + debug_list(s, |s| s.clone()) +} + +fn debug_list(keys: &[T], func: impl Fn(&T) -> String) -> String { + let limit = 5; + let msg = keys + .iter() + .take(limit) + .map(|k| func(k)) + .collect::>() + .join(", "); + if keys.len() > limit { + format!("{} and {} more", msg, keys.len() - limit) + } else { + msg + } +} diff --git a/eden/scm/tests/test-eager-exchange.t b/eden/scm/tests/test-eager-exchange.t index 10dafc1616..f6deb82fda 100644 --- a/eden/scm/tests/test-eager-exchange.t +++ b/eden/scm/tests/test-eager-exchange.t @@ -3,7 +3,7 @@ $ configure modern $ setconfig paths.default=eager:$TESTTMP/e1 ui.traceback=1 - $ export LOG=edenscm::mercurial::eagerpeer=trace + $ export LOG=edenscm::mercurial::eagerpeer=trace,eagerepo=trace Disable SSH: @@ -22,10 +22,13 @@ Push: $ hg push -r $C --to master --create pushing rev dc0947a82db8 to destination eager://$TESTTMP/e1 bookmark master + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict() + DEBUG eagerepo::api: commit_known dc0947a82db884575bb76ea10ac97b08536bfa03 TRACE edenscm::mercurial::eagerpeer: known dc0947a82db884575bb76ea10ac97b08536bfa03: False DEBUG edenscm::mercurial::eagerpeer: heads = [] searching for changes + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict() TRACE edenscm::mercurial::eagerpeer: adding blob 005d992c5dcf32993668f7cede29d296c494a5d9 TRACE edenscm::mercurial::eagerpeer: adding tree 41b34f08c1356f6ad068e9ab9b43d984245111aa @@ -34,23 +37,29 @@ Push: TRACE edenscm::mercurial::eagerpeer: adding tree 5a538d6dd01b4058a549747c7947ce2dbf29f2ae TRACE edenscm::mercurial::eagerpeer: adding commit dc0947a82db884575bb76ea10ac97b08536bfa03 DEBUG edenscm::mercurial::eagerpeer: flushed + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict() DEBUG edenscm::mercurial::eagerpeer: flushed DEBUG edenscm::mercurial::eagerpeer: pushkey bookmarks 'master': '' => 'dc0947a82db884575bb76ea10ac97b08536bfa03' (success) exporting bookmark master + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')]) $ hg push -r $B --allow-anon pushing to eager://$TESTTMP/e1 + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')]) + DEBUG eagerepo::api: commit_known 112478962961147124edd43549aedd1a335e44bf, dc0947a82db884575bb76ea10ac97b08536bfa03 TRACE edenscm::mercurial::eagerpeer: known 112478962961147124edd43549aedd1a335e44bf: False TRACE edenscm::mercurial::eagerpeer: known dc0947a82db884575bb76ea10ac97b08536bfa03: True searching for changes + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')]) TRACE edenscm::mercurial::eagerpeer: adding blob 35e7525ce3a48913275d7061dd9a867ffef1e34d TRACE edenscm::mercurial::eagerpeer: adding tree eb79886383871977bccdb3000c275a279f0d4c99 TRACE edenscm::mercurial::eagerpeer: adding commit 112478962961147124edd43549aedd1a335e44bf DEBUG edenscm::mercurial::eagerpeer: flushed + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')]) Pull: @@ -60,25 +69,40 @@ Pull: $ hg debugchangelog --migrate lazy $ hg pull -B master pulling from eager://$TESTTMP/e1 + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')]) + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')]) + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')]) + DEBUG eagerepo::api: commit_known + DEBUG eagerepo::api: commit_graph dc0947a82db884575bb76ea10ac97b08536bfa03 TRACE edenscm::mercurial::eagerpeer: graph node 426bada5c67598ca65036d57d9e4b64b0c1ce7a0 [] TRACE edenscm::mercurial::eagerpeer: graph node dc0947a82db884575bb76ea10ac97b08536bfa03 ['426bada5c67598ca65036d57d9e4b64b0c1ce7a0'] DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(phases, []) = sortdict() $ hg pull -r $B pulling from eager://$TESTTMP/e1 + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')]) + DEBUG eagerepo::api: commit_known 112478962961147124edd43549aedd1a335e44bf TRACE edenscm::mercurial::eagerpeer: known 112478962961147124edd43549aedd1a335e44bf: True + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')]) + DEBUG eagerepo::api: bookmarks master DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(bookmarks, ['master']) = sortdict([('master', 'dc0947a82db884575bb76ea10ac97b08536bfa03')]) + DEBUG eagerepo::api: commit_known dc0947a82db884575bb76ea10ac97b08536bfa03 TRACE edenscm::mercurial::eagerpeer: known dc0947a82db884575bb76ea10ac97b08536bfa03: True searching for changes + DEBUG eagerepo::api: commit_graph 112478962961147124edd43549aedd1a335e44bf, dc0947a82db884575bb76ea10ac97b08536bfa03 dc0947a82db884575bb76ea10ac97b08536bfa03 TRACE edenscm::mercurial::eagerpeer: graph node 112478962961147124edd43549aedd1a335e44bf ['426bada5c67598ca65036d57d9e4b64b0c1ce7a0'] DEBUG edenscm::mercurial::eagerpeer: listkeyspatterns(phases, []) = sortdict() $ hg log -Gr 'all()' -T '{desc} {remotenames}' + DEBUG eagerepo::api: revlog_data 112478962961147124edd43549aedd1a335e44bf, dc0947a82db884575bb76ea10ac97b08536bfa03, 426bada5c67598ca65036d57d9e4b64b0c1ce7a0 + TRACE eagerepo::api: found: 112478962961147124edd43549aedd1a335e44bf, 94 bytes + TRACE eagerepo::api: found: dc0947a82db884575bb76ea10ac97b08536bfa03, 94 bytes + TRACE eagerepo::api: found: 426bada5c67598ca65036d57d9e4b64b0c1ce7a0, 94 bytes o B │ │ o C remote/master