trace tso

Signed-off-by: Ping Yu <[email protected]>

src/pd/timestamp.rs

@@ -20,13 +20,14 @@ use futures::prelude::*;
 use futures::task::AtomicWaker;
 use futures::task::Context;
 use futures::task::Poll;
-use log::debug;
-use log::info;
 use pin_project::pin_project;
 use tokio::sync::mpsc;
 use tokio::sync::oneshot;
 use tokio::sync::Mutex;
 use tonic::transport::Channel;
+use tracing::debug;
+use tracing::info;
+use tracing::instrument;
 
 use crate::internal_err;
 use crate::proto::pdpb::pd_client::PdClient;
@@ -63,6 +64,7 @@ impl TimestampOracle {
         Ok(TimestampOracle { request_tx })
     }
 
+    #[instrument(name = "TimestampOracle::get_timestamp", skip_all)]
     pub(crate) async fn get_timestamp(self) -> Result<Timestamp> {
         debug!("getting current timestamp");
         let (request, response) = oneshot::channel();

src/request/plan.rs

@@ -587,7 +587,12 @@ where
 
         let mut result = self.inner.execute().await?;
         let mut clone = self.clone();
+        let mut retry_cnt = 0;
         loop {
+            retry_cnt += 1;
+            let span = info_span!("ResolveLock::execute::retry", retry_cnt);
+            let _enter = span.enter();
+
             let locks = result.take_locks();
             if locks.is_empty() {
                 debug!("ResolveLock::execute ok");
@@ -602,6 +607,7 @@ where
             let pd_client = self.pd_client.clone();
             let live_locks = resolve_locks(locks, pd_client.clone()).await?;
             if live_locks.is_empty() {
+                debug!("ResolveLock::execute lock error retry (resolved)",);
                 result = self.inner.execute().await?;
             } else {
                 match clone.backoff.next_delay_duration() {
@@ -610,6 +616,10 @@ where
                         return Err(Error::ResolveLockError(live_locks));
                     }
                     Some(delay_duration) => {
+                        debug!(
+                            "ResolveLock::execute lock error retry (delay {:?})",
+                            delay_duration
+                        );
                         sleep(delay_duration).await;
                         result = clone.inner.execute().await?;
                     }

src/transaction/lock.rs

@@ -58,6 +58,11 @@ pub async fn resolve_locks(
                 ts.physical - Timestamp::from_version(lock.lock_version).physical
                     >= lock.lock_ttl as i64
             });
+    debug!(
+        "resolving locks: expired_locks {}, live_locks {}",
+        expired_locks.len(),
+        live_locks.len()
+    );
 
     // records the commit version of each primary lock (representing the status of the transaction)
     let mut commit_versions: HashMap<u64, u64> = HashMap::new();