debug: Finalized heads

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

testing/integration-tests/src/light_client/mod.rs

@@ -39,19 +39,33 @@ type Client = LightClient<PolkadotConfig>;
 
 // Check that we can subscribe to non-finalized blocks.
 async fn non_finalized_headers_subscription(api: &Client) -> Result<(), subxt::Error> {
+    let now = std::time::Instant::now();
+
+    println!("In non_finalized_headers_subscription");
     let mut sub = api.blocks().subscribe_best().await?;
 
     let _block = sub.next().await.unwrap()?;
+    println!("First block took {:?}", now.elapsed());
+
     let _block = sub.next().await.unwrap()?;
+    println!("Second block took {:?}", now.elapsed());
+
     let _block = sub.next().await.unwrap()?;
+    println!("Third block took {:?}\n", now.elapsed());
 
     Ok(())
 }
 
 // Check that we can subscribe to finalized blocks.
 async fn finalized_headers_subscription(api: &Client) -> Result<(), subxt::Error> {
+    let now = std::time::Instant::now();
+
+    println!("In finalized_headers_subscription");
+
     let mut sub = api.blocks().subscribe_finalized().await?;
     let header = sub.next().await.unwrap()?;
+    println!("First block took {:?}", now.elapsed());
+
     let finalized_hash = api
         .backend()
         .latest_finalized_block_ref()
@@ -59,20 +73,34 @@ async fn finalized_headers_subscription(api: &Client) -> Result<(), subxt::Error
         .unwrap()
         .hash();
 
+    println!(
+        "Finalized hash: {:?} took {:?}",
+        finalized_hash,
+        now.elapsed()
+    );
+
     assert_eq!(header.hash(), finalized_hash);
+    println!("Check progress {:?}", now.elapsed());
 
     let _block = sub.next().await.unwrap()?;
+    println!("Second block took {:?}", now.elapsed());
     let _block = sub.next().await.unwrap()?;
+    println!("Third block took {:?}", now.elapsed());
     let _block = sub.next().await.unwrap()?;
+    println!("Fourth block took {:?}\n", now.elapsed());
 
     Ok(())
 }
 
 // Check that we can subscribe to non-finalized blocks.
 async fn runtime_api_call(api: &Client) -> Result<(), subxt::Error> {
+    let now = std::time::Instant::now();
+    println!("In runtime_api_call");
+
     let mut sub = api.blocks().subscribe_best().await?;
 
     let block = sub.next().await.unwrap()?;
+    println!("First block took {:?}", now.elapsed());
     let rt = block.runtime_api().await?;
 
     // get metadata via state_call. if it decodes ok, it's probably all good.
@@ -80,11 +108,16 @@ async fn runtime_api_call(api: &Client) -> Result<(), subxt::Error> {
         .call_raw::<(Compact<u32>, Metadata)>("Metadata_metadata", None)
         .await?;
 
+    println!("Made runtime API call in {:?}\n", now.elapsed());
+
     Ok(())
 }
 
 // Lookup for the `Timestamp::now` plain storage entry.
 async fn storage_plain_lookup(api: &Client) -> Result<(), subxt::Error> {
+    let now = std::time::Instant::now();
+    println!("In storage_plain_lookup");
+
     let addr = node_runtime::storage().timestamp().now();
     let entry = api
         .storage()
@@ -93,6 +126,8 @@ async fn storage_plain_lookup(api: &Client) -> Result<(), subxt::Error> {
         .fetch_or_default(&addr)
         .await?;
 
+    println!("Storage lookup took {:?}\n", now.elapsed());
+
     assert!(entry > 0);
 
     Ok(())
@@ -100,35 +135,52 @@ async fn storage_plain_lookup(api: &Client) -> Result<(), subxt::Error> {
 
 // Make a dynamic constant query for `System::BlockLenght`.
 async fn dynamic_constant_query(api: &Client) -> Result<(), subxt::Error> {
+    let now = std::time::Instant::now();
+    println!("In dynamic_constant_query");
+
     let constant_query = subxt::dynamic::constant("System", "BlockLength");
     let _value = api.constants().at(&constant_query)?;
 
+    println!("Dynamic constant query took {:?}\n", now.elapsed());
+
     Ok(())
 }
 
 // Fetch a few all events from the latest block and decode them dynamically.
 async fn dynamic_events(api: &Client) -> Result<(), subxt::Error> {
+    let now = std::time::Instant::now();
+    println!("In dynamic_events");
+
     let events = api.events().at_latest().await?;
 
     for event in events.iter() {
         let _event = event?;
+
+        println!("Event decoding took {:?}", now.elapsed());
     }
 
+    println!("Dynamic events took {:?}\n", now.elapsed());
+
     Ok(())
 }
 
 #[tokio::test]
 async fn light_client_testing() -> Result<(), subxt::Error> {
+    tracing_subscriber::fmt::init();
+
+    let now = std::time::Instant::now();
     let api: LightClient<PolkadotConfig> = LightClientBuilder::new()
         .build_from_url("wss://rpc.polkadot.io:443")
         .await?;
 
-    non_finalized_headers_subscription(&api).await?;
+    println!("Light client initialization took {:?}\n", now.elapsed());
+
+    // non_finalized_headers_subscription(&api).await?;
     finalized_headers_subscription(&api).await?;
-    runtime_api_call(&api).await?;
-    storage_plain_lookup(&api).await?;
-    dynamic_constant_query(&api).await?;
-    dynamic_events(&api).await?;
+    // runtime_api_call(&api).await?;
+    // storage_plain_lookup(&api).await?;
+    // dynamic_constant_query(&api).await?;
+    // dynamic_events(&api).await?;
 
     Ok(())
 }