Add 'subscribe' benchmark

backend/telemetry_core/Cargo.toml

@@ -35,3 +35,8 @@ tokio-util = { version = "0.6", features = ["compat"] }
 [dev-dependencies]
 shellwords = "1.1.0"
 test_utils = { path = "../test_utils" }
+criterion = { version = "0.3.4", features = ["async", "async_tokio"] }
+
+[[bench]]
+name = "subscribe"
+harness = false

backend/telemetry_core/benches/subscribe.rs

@@ -0,0 +1,121 @@
+use common::node_types::BlockHash;
+use criterion::{criterion_group, criterion_main, Criterion};
+use serde_json::json;
+use test_utils::workspace::{ start_server, ServerOpts, CoreOpts, ShardOpts };
+use test_utils::feed_message_de::FeedMessage;
+use tokio::runtime::Runtime;
+use std::time::{Duration, Instant};
+
+/// This benchmark roughly times the subscribe function. Note that there's a lot of
+/// overhead in other areas, so even with the entire subscribe function commented out
+/// By benchmark timings are ~50ms (whereas they are ~320ms with the version of the
+/// subscribe handler at the time of writing).
+///
+/// If you want to use this benchmark, it's therefore worth commenting out the subscribe
+/// logic entirely and running this to give yourself a "baseline".
+pub fn benchmark_subscribe_speed(c: &mut Criterion) {
+    const NUMBER_OF_FEEDS: usize = 100;
+    const NUMBER_OF_NODES: usize = 10_000;
+
+    let rt = Runtime::new().expect("tokio runtime should start");
+
+    c.bench_function(
+        "subscribe speed: time till pong",
+        move |b| b.to_async(&rt).iter_custom(|iters| async move {
+
+            // Start a server:
+            let mut server = start_server(
+                ServerOpts {
+                    release_mode: true,
+                    log_output: false,
+                },
+                CoreOpts {
+                    ..Default::default()
+                },
+                ShardOpts {
+                    max_nodes_per_connection: Some(usize::MAX),
+                    max_node_data_per_second: Some(usize::MAX),
+                    worker_threads: Some(2),
+                    ..Default::default()
+                }
+            ).await;
+            let shard_id = server.add_shard().await.unwrap();
+
+            // Connect a shard:
+            let (mut node_tx, _) = server
+                .get_shard(shard_id)
+                .unwrap()
+                .connect_node()
+                .await
+                .expect("node can connect");
+
+            // Add a bunch of actual nodes on the same chain:
+            for n in 0..NUMBER_OF_NODES {
+                node_tx.send_json_text(json!({
+                    "id":n,
+                    "ts":"2021-07-12T10:37:47.714666+01:00",
+                    "payload": {
+                        "authority":true,
+                        "chain":"Polkadot", // No limit to #nodes on this network.
+                        "config":"",
+                        "genesis_hash": BlockHash::from_low_u64_ne(1),
+                        "implementation":"Substrate Node",
+                        "msg":"system.connected",
+                        "name": format!("Node {}", n),
+                        "network_id":"12D3KooWEyoppNCUx8Yx66oV9fJnriXwCcXwDDUA2kj6vnc6iDEp",
+                        "startup_time":"1625565542717",
+                        "version":"2.0.0-07a1af348-aarch64-macos"
+                    }
+                })).unwrap();
+            }
+
+            // Give those messages a chance to be handled. This, of course,
+            // assumes that those messages _can_ be handled this quickly. If not,
+            // we'll start to skew benchmark results with the "time taklen to add node".
+            tokio::time::sleep(Duration::from_millis(250)).await;
+
+            // Now, see how quickly a feed is subscribed. Criterion controls the number of
+            // iters performed here, but a lot of the time that number is "1".
+            let mut total_time = Duration::ZERO;
+            for _n in 0..iters {
+
+                // Start a bunch of feeds:
+                let mut feeds = server
+                    .get_core()
+                    .connect_multiple_feeds(NUMBER_OF_FEEDS)
+                    .await
+                    .expect("feeds can connect");
+
+                // Subscribe every feed to the chain:
+                for (feed_tx, _) in feeds.iter() {
+                    feed_tx.send_command("subscribe", "Polkadot").unwrap();
+                }
+
+                // Then, Ping a feed:
+                feeds[0].0.send_command("ping", "Finished!").unwrap();
+                let finished = FeedMessage::Pong { msg: "Finished!".to_owned() };
+
+                // Wait and see how long it takes to get a pong back:
+                let start = Instant::now();
+                loop {
+                    let msgs = feeds[0].1.recv_feed_messages_once().await.unwrap();
+                    if msgs.iter().find(|&m| m == &finished).is_some() {
+                        break;
+                    }
+                }
+                total_time += start.elapsed();
+
+                // shut down the feeds
+                for (mut feed_tx, _) in feeds {
+                    feed_tx.close().await.unwrap();
+                }
+            }
+
+            // The total time spent waiting for subscribes:
+            total_time
+        })
+    );
+}
+
+criterion_group!(benches, benchmark_subscribe_speed);
+criterion_main!(benches);

backend/telemetry_core/src/main.rs

@@ -60,9 +60,8 @@ struct Opts {
     #[structopt(long, default_value = "10")]
     feed_timeout: u64,
     /// Number of worker threads to spawn. If "0" is given, use the number of CPUs available
-    /// on the machine. Note that the tokio runtime performance seems to degrade when this number
-    /// gets too high.
-    #[structopt(long, default_value = "8")]
+    /// on the machine.
+    #[structopt(long, default_value = "0")]
     worker_threads: usize,
 }
 

backend/telemetry_core/tests/e2e_tests.rs

@@ -37,7 +37,7 @@ use std::time::Duration;
 use test_utils::{
     assert_contains_matches,
     feed_message_de::{FeedMessage, NodeDetails},
-    workspace::{start_server, start_server_debug, CoreOpts, ShardOpts},
+    workspace::{start_server, start_server_debug, ServerOpts, CoreOpts, ShardOpts},
 };
 
 /// The simplest test we can run; the main benefit of this test (since we check similar)
@@ -68,7 +68,7 @@ async fn feed_ping_responded_to_with_pong() {
     let server = start_server_debug().await;
 
     // Connect a feed:
-    let (mut feed_tx, mut feed_rx) = server.get_core().connect_feed().await.unwrap();
+    let (feed_tx, mut feed_rx) = server.get_core().connect_feed().await.unwrap();
 
     // Ping it:
     feed_tx.send_command("ping", "hello!").unwrap();
@@ -283,7 +283,7 @@ async fn feeds_told_about_chain_rename_and_stay_subscribed() {
         .unwrap();
 
     // Connect a feed and subscribe to the above chain:
-    let (mut feed_tx, mut feed_rx) = server.get_core().connect_feed().await.unwrap();
+    let (feed_tx, mut feed_rx) = server.get_core().connect_feed().await.unwrap();
     feed_tx
         .send_command("subscribe", "Initial chain name")
         .unwrap();
@@ -453,7 +453,7 @@ async fn feed_can_subscribe_and_unsubscribe_from_chain() {
     }
 
     // Connect a feed
-    let (mut feed_tx, mut feed_rx) = server.get_core().connect_feed().await.unwrap();
+    let (feed_tx, mut feed_rx) = server.get_core().connect_feed().await.unwrap();
 
     let feed_messages = feed_rx.recv_feed_messages().await.unwrap();
     assert_contains_matches!(feed_messages, AddedChain { name, node_count: 1 } if name == "Local Testnet 1");
@@ -526,7 +526,7 @@ async fn feed_can_subscribe_and_unsubscribe_from_chain() {
 async fn node_banned_if_it_sends_too_much_data() {
     async fn try_send_data(max_bytes: usize, send_msgs: usize, bytes_per_msg: usize) -> bool {
         let mut server = start_server(
-            false,
+            ServerOpts::default(),
             CoreOpts::default(),
             ShardOpts {
                 // Remember, this is (currently) averaged over the last 10 seconds,
@@ -576,7 +576,7 @@ async fn node_banned_if_it_sends_too_much_data() {
 #[tokio::test]
 async fn slow_feeds_are_disconnected() {
     let mut server = start_server(
-        false,
+        ServerOpts::default(),
         // Timeout faster so the test can be quicker:
         CoreOpts {
             feed_timeout: Some(1),
@@ -669,7 +669,7 @@ async fn slow_feeds_are_disconnected() {
 #[tokio::test]
 async fn max_nodes_per_connection_is_enforced() {
     let mut server = start_server(
-        false,
+        ServerOpts::default(),
         CoreOpts::default(),
         // Limit max nodes per connection to 2; any other msgs should be ignored.
         ShardOpts {
@@ -689,7 +689,7 @@ async fn max_nodes_per_connection_is_enforced() {
         .unwrap();
 
     // Connect a feed.
-    let (mut feed_tx, mut feed_rx) = server.get_core().connect_feed().await.unwrap();
+    let (feed_tx, mut feed_rx) = server.get_core().connect_feed().await.unwrap();
 
     // We'll send these messages from the node:
     let json_msg = |n| {

backend/telemetry_core/tests/soak_tests.rs

@@ -42,7 +42,7 @@ use std::sync::atomic::{AtomicUsize, Ordering};
 use std::sync::Arc;
 use std::time::Duration;
 use structopt::StructOpt;
-use test_utils::workspace::{start_server, CoreOpts, ShardOpts};
+use test_utils::workspace::{start_server, ServerOpts, CoreOpts, ShardOpts};
 
 /// A configurable soak_test runner. Configure by providing the expected args as
 /// an environment variable. One example to run this test is:
@@ -74,7 +74,10 @@ pub async fn soak_test() {
 /// the results should be pretty reproducible.
 async fn run_soak_test(opts: SoakTestOpts) {
     let mut server = start_server(
-        true,
+        ServerOpts {
+            release_mode: true,
+            ..Default::default()
+        },
         CoreOpts {
             worker_threads: opts.core_worker_threads,
             ..Default::default()
@@ -257,7 +260,10 @@ pub async fn realistic_soak_test() {
 /// circumstances
 async fn run_realistic_soak_test(opts: SoakTestOpts) {
     let mut server = start_server(
-        true,
+        ServerOpts {
+            release_mode: true,
+            ..Default::default()
+        },
         CoreOpts {
             worker_threads: opts.core_worker_threads,
             ..Default::default()