Scalability issue visible when the number of concurrent requests > 128

[pkolaczk]

# on latte master branch (cassandra_cpp):
$ target/release/latte run workloads/basic/read.rn -d 1000000 -t 2 --tag cassandra_cpp

# on scylla_driver_rebase branch:
$ target/release/latte run workloads/basic/read.rn -d 1000000 -t 2 --tag scylla -b read.Test_Cluster.4.0.1-SNAPSHOT.cassandra_cpp.p384.t2.c1.20211126.163116.json


CONFIG ═════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
                            ───────────── A ─────────────  ────────────── B ────────────     Change     
            Date            Fri, 26 Nov 2021               Fri, 26 Nov 2021                           
            Time            16:31:08 +0100                 16:33:03 +0100                             
         Cluster            Test Cluster                   Test Cluster                               
      C* version            4.0.1-SNAPSHOT                 4.0.1-SNAPSHOT                             
            Tags            cassandra_cpp                  scylla                                     
        Workload            read.rn                        read.rn                                    
────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
         Threads                    2                              2                          +0.0%     
     Connections                    1                              1                          +0.0%     
     Concurrency     [req]        384                            384                          +0.0%     
        Max rate    [op/s]                                                                            
          Warmup       [s]                                                                            
              └─      [op]          1                              1                          +0.0%     
        Run time       [s]                                                                            
              └─      [op]    1000000                        1000000                          +0.0%     
        Sampling       [s]        1.0                            1.0                          +0.0%     

LOG ════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
    Time  ───── Throughput ─────  ────────────────────────────────── Response times [ms] ───────────────────────────────────
     [s]      [op/s]     [req/s]         Min        25        50        75        90        95        99      99.9       Max
   0.000      137155      137155       0.645     3.923     4.895     6.227     7.915     9.391    12.663    17.263    23.727
   1.000      140517      140517       0.637     3.773     4.735     6.151     7.703     9.055    12.271    21.007    40.799
   2.000      137920      137920       1.092     3.715     4.707     6.167     8.159     9.503    15.359    28.223    39.071
   3.000      135219      135219       0.964     3.863     4.879     6.223     8.003     9.655    16.335    28.127    33.567
   4.000      138897      138897       0.780     3.799     4.819     6.367     8.031     9.055    11.487    18.319    31.967
   5.000      133410      133410       0.331     3.843     5.011     6.575     8.327     9.751    14.055    20.511    27.663
   6.000      137751      137751       0.587     3.799     4.787     6.227     8.163     9.431    12.511    27.423    42.399
   7.000      144696      144696       0.914     3.909     4.827     6.055     7.519     8.287    10.071    11.375    23.007

SUMMARY STATS ══════════════════════════════════════════════════════════════════════════════════════════════════════════════
                            ───────────── A ─────────────  ────────────── B ────────────     Change     P-value  Signif.
    Elapsed time       [s]      6.942                          7.271                          +4.7%     
        CPU time       [s]     12.746                         12.985                          +1.9%     
 CPU utilisation       [%]       23.0                           22.3                          -2.7%     
           Calls      [op]    1000000                        1000000                          +0.0%     
          Errors      [op]          0                              0                          +0.0%     
              └─       [%]        0.0                            0.0                          +0.0%     
        Requests     [req]    1000000                        1000000                          +0.0%     
              └─  [req/op]        1.0                            1.0                          +0.0%     
            Rows     [row]     500425                         499581                          -0.2%     
              └─ [row/req]        0.5                            0.5                          -0.2%     
         Samples                    7                              8                         +14.3%     
Mean sample size      [op]     142857                         125000                         -12.5%     
              └─     [req]     142857                         125000                         -12.5%     
     Concurrency     [req]      297.8                          360.0                         +20.9%     
              └─       [%]       77.5                           93.8                         +20.9%     
      Throughput    [op/s]     144068 ± 2123                  137543 ± 3159                   -4.5%     0.00011  **   
              ├─   [req/s]     144068 ± 2123                  137543 ± 3159                   -4.5%     0.00011  **   
              └─   [row/s]      72095 ± 1229                   68714 ± 1363                   -4.7%     0.00004  ***  
  Mean call time      [ms]      4.627 ± 0.103                  5.333 ± 0.120                 +15.2%     0.00000  *****
 Mean resp. time      [ms]      4.622 ± 0.103                  5.330 ± 0.120                 +15.3%     0.00000  *****


RESPONSE TIMES [ms] ════════════════════════════════════════════════════════════════════════════════════════════════════════
                            ───────────── A ─────────────  ────────────── B ────────────     Change     P-value  Signif.
          Min                   0.344 ± 0.108                  0.728 ± 0.286                +111.7%     0.00260  *    
           25                   2.498 ± 0.090                  3.820 ± 0.079                 +52.9%     0.00000  *****
           50                   3.781 ± 0.107                  4.832 ± 0.117                 +27.8%     0.00000  *****
           75                   5.621 ± 0.189                  6.267 ± 0.175                 +11.5%     0.00000  **** 
           90                   8.105 ± 0.369                  8.021 ± 0.258                  -1.0%     0.55184       
           95                  10.405 ± 0.543                  9.359 ± 0.405                 -10.1%     0.00031  **   
           98                  14.847 ± 1.472                 11.281 ± 0.747                 -24.0%     0.00006  ***  
           99                  19.435 ± 3.130                 13.376 ± 2.164                 -31.2%     0.00028  **   
           99.9                28.216 ± 6.287                 22.519 ± 6.067                 -20.2%     0.05167       
           99.99               30.291 ± 3.934                 25.367 ± 6.235                 -16.3%     0.04922       
          Max                  34.476 ± 5.021                 33.786 ± 8.295                  -2.0%     0.81925       

So I ported current master of latte to scylladb driver, and I noticed a weird issue - minimum and average latencies are much higher than cassandra_cpp, and throughput is still a bit behind in this test (even though this test is short, this phenomenon exist also when running it for longer). I've run it a few times, also in reversed order and it is very repeatable. The difference is larger on single thread.

Are there any tuning options for the buffering thing you've added recently?

BTW: not sure why the number of returned rows is only half the number of queries, but that looks like a bug in the workload generation / definition; that's exactly same code on both sides, so shouldn't change the validity of this test.

[pkolaczk]

Interestingly, when I decrease the amount of concurrent requests from 384 to only 64, scylla_db now outperforms cassandra_cpp on almost every metric (except min latency). I just wonder, maybe the internal driver queue / buffer is too small?

[pkolaczk]

BTW: I'm not saying these latencies from scylla are worse - actually in REAL app I'd take lower tail latency over larger min latency every time. However, I'm just curious why I'm getting those numbers. Maybe there is an opportunity to improve something even more.

[pkolaczk]

Looking perf stats, one thing I notice is that scylla branch spends a lot more time in the system, and makes 2x more context switches:

master:

 Performance counter stats for './target/release/latte run workloads/basic/read.rn -d 1000000':

         13 215,82 msec task-clock                #    1,362 CPUs utilized          
            51 499      context-switches          #    3,897 K/sec                  
             1 432      cpu-migrations            #  108,355 /sec                   
             7 094      page-faults               #  536,781 /sec                   
    39 277 452 851      cycles                    #    2,972 GHz                    
    32 477 310 140      instructions              #    0,83  insn per cycle         
     6 607 178 073      branches                  #  499,945 M/sec                  
        70 631 696      branch-misses             #    1,07% of all branches        

       9,701747340 seconds time elapsed

      11,554137000 seconds user
       1,807549000 seconds sys

scylla-driver-rebase:

 Performance counter stats for './target/release/latte run workloads/basic/read.rn -d 1000000':

         13 170,58 msec task-clock                #    1,226 CPUs utilized          
           101 559      context-switches          #    7,711 K/sec                  
             4 966      cpu-migrations            #  377,052 /sec                   
             1 592      page-faults               #  120,875 /sec                   
    38 972 668 976      cycles                    #    2,959 GHz                    
    36 413 811 976      instructions              #    0,93  insn per cycle         
     6 182 693 111      branches                  #  469,432 M/sec                  
        53 918 503      branch-misses             #    0,87% of all branches        

      10,740003985 seconds time elapsed

      10,124568000 seconds user
       3,358842000 seconds sys

[pkolaczk]

Both runs 1000000 iterations of read.rn benchmark, single thread:

scylla-driver-rebase:
           127 260      syscalls:sys_enter_recvfrom  
            55 854      syscalls:sys_enter_sendto                                   
            75 392      syscalls:sys_enter_epoll_wait                                   

master:
            62 662      syscalls:sys_enter_read                                     
            10 492      syscalls:sys_enter_write                                    
            16 730      syscalls:sys_enter_writev  
            45 434      syscalls:sys_enter_epoll_wait                                   

Althouth there is a huge improvement since 0.3.0, it looks like scylla driver still makes significantly more syscalls than cassandra_cpp. Looks like it splits data into smaller chunks and the system overhead is higher.

Can we have an option to configure scylla driver to make bigger batches when high throughput is more important than latency? Or when simply when a high number of concurrent requests are scheduled (many pending calls to Session::execute)?

I noticed there is a hardcoded buffer size of 8196 bytes in your code. I was wondering - does the size of that buffer affect batching behaviour? Maybe it would make sense to expose its size in the options?

BTW: On a fixed rate test I'm getting a lot better latencies from scylla driver, in particular p75-p99.9.

[psarna]

Indeed, increasing buffer sizes will increase throughput at the cost of latency, up to a point. The whole idea is to find a sweet spot for your workload and hardware, and you're right that it's not currently possible in scylla-rust-driver, because the sizes are hardcoded. I was planning to push a patch that makes the sizes configurable - I'll put it higher on my priority list and push a pull request early next week.

[pkolaczk]

Cool, let me quickly fork it then and check if changing that buffer size makes any difference first ;)

[psarna]

Sure. Btw, no need to fork the repo - once I send a pull request to a branch, you can specify a git branch as dependency in Cargo.toml: scylla = {git = "https://github.com/scylladb/scylla-rust-driver", branch="some-branch"}

[pkolaczk]

I increased the buffers size to 32k and can't see any change in the numbers of recvfrom nor sendto calls. Huh.

[pkolaczk]

What is the policy of flushing those buffers? Also what controls the frequency of reading from socket into the read buffer? Maybe it reads so frequently that there isn't enough data in the socket to read?

[pkolaczk]

So I guess this is this is the main loop:

      while let Some(mut task) = task_receiver.recv().await {
            let mut num_requests = 0;
            let mut total_sent = 0;
            while let Some(stream_id) = Self::alloc_stream_id(handler_map, task.response_handler) {
                let mut req = task.serialized_request;
                req.set_stream(stream_id);
                let req_data: &[u8] = req.get_data();
                total_sent += req_data.len();
                num_requests += 1;
                write_half.write_all(req_data).await?;
                task = match task_receiver.try_recv() {
                    Ok(t) => t,
                    Err(_) => break,
                }
            }
            trace!("Sending {} requests; {} bytes", num_requests, total_sent);
            write_half.flush().await?;
        }

After enabling logging, I noticed this only initially sends a full buffer with requests, and then it quickly drops down to sending low numbers of requests:

Sending 128 requests; 5888 bytes
Sending 128 requests; 5888 bytes                                               
Sending 128 requests; 5888 bytes
Sending 40 requests; 1840 bytes
Sending 268 requests; 12328 bytes
Sending 75 requests; 3450 bytes
Sending 1 requests; 46 bytes
Sending 40 requests; 1840 bytes
Sending 1 requests; 46 bytes
Sending 1 requests; 46 bytes
Sending 2 requests; 92 bytes
Sending 1 requests; 46 bytes
Sending 2 requests; 92 bytes
Sending 1 requests; 46 bytes
Sending 1 requests; 46 bytes
Sending 1 requests; 46 bytes
Sending 384 requests; 17664 bytes
Sending 101 requests; 4646 bytes
Sending 231 requests; 10626 bytes
Sending 154 requests; 7084 bytes
Sending 1 requests; 46 bytes
Sending 1 requests; 46 bytes
Sending 53 requests; 2438 bytes
Sending 43 requests; 1978 bytes
Sending 1 requests; 46 bytes
Sending 1 requests; 46 bytes
Sending 1 requests; 46 bytes
Sending 1 requests; 46 bytes

The client app uses buffer_unordered to limit the number of pending request futures. So, once it hits that limit (384 futures by default), it stops sending more requests to the driver and waits for some of the pending ones to finish. Now after some time Cassandra responds and a query result arrives. Because all of this is so low-latency here on the Rust side, the driver picks the result near instantly and the number of pending request futures drops by just 1 or a few, but not by 384 (this is what I see in the logs) and the writer loops now gets to spin another cycle. But it only gets a few tasks to process, so it runs out of tasks long before the buffer fills up, and flushes whatever was buffered.

Hence, the buffer size does not matter that much - the driver is very "eager" - whatever comes it jumps to process it and doesn't let things accumulate.

BTW: This problem was realized by the creators of DataStax C++ driver and there is a configurable delay (default 200 µs), where the driver waits for more requests in order to fill up the buffer - so if the buffer doesn't fill up, it adds at worst those 200 µs to the latency, but saves many syscalls by potentially batching more queries at once.

If you wish I can try to implement such configurable delay if time permits this weekend (could be turned off by default so it wouldn't cause any regression for latency sensitive workloads).

[psarna]

Of course, all contributors are welcome. We'll probably want to preserve current behavior as default, but allowing the driver to explicitly accumulate the requests for X microseconds sounds like a very nice tuning option.

[pkolaczk]

I've spent a bit of time today on this, and there is something weird going on, but I haven't figured that out yet. :(

Because there I couldn't find anything to do async sleep with submillisecond timing in tokio, my first attempt was to just spin on tokio::task::yield_now().await for ~200 µs or until I get the buffer filled up to at least 8k - well, that did reduce the number of write syscalls, but increased the number of epoll calls, and overall performance and cpu utilisation was beasically the same.

while let Some(mut task) = task_receiver.recv().await {
            let start_time = Instant::now();
            let mut num_requests = 0;
            let mut total_sent = 0;
            'outer: while let Some(stream_id) =
                Self::alloc_stream_id(handler_map, task.response_handler)
            {
                let mut req = task.serialized_request;
                req.set_stream(stream_id);
                let req_data: &[u8] = req.get_data();
                total_sent += req_data.len();
                num_requests += 1;
                write_half.write_all(req_data).await?;
                task = loop {
                    match task_receiver.try_recv() {
                        Ok(t) => break t,
                        Err(_) => {
                            if Instant::now() - start_time < tokio::time::Duration::from_micros(200) && total_sent < 8196
                            {
                                tokio::task::yield_now().await;
                            } else {
                                break 'outer;
                            }
                        }
                    }
                }
            }

Then I tried blocking with std::time::sleep, just for an experiment (I know it is totally not acceptable to do so - but I'm just breaking things to learn better how they work ;)), and this time it reduced the amount of syscalls significantly, it reduced a bit CPU usage, but the overall throughput stayed the same. Still couldn't match the throughput I am getting with cassandra_cpp.

So I conclude, maybe those syscalls are a red herring and the real issue is somewhere else (or there is no problem and I'm nitpicking and 100k max throughput vs 120k with 1 thread is not such a big difference, and with 4 threads it's only a tad slower).

However, I tried one more thing - what happens if I increase the number of concurrent queries to a crazy value, on the latte side. It is easy to do so with -p. And there I've found something big:

 ./target/release/latte run workloads/basic/read.rn -d 1000000 -p 4096

     Concurrency     [req]     4071.6                                                                 
              └─       [%]       99.4                                                                 
      Throughput    [op/s]      23979 ± 1508                                                          
              ├─   [req/s]      23979 ± 1508                                                          
              └─   [row/s]      23979 ± 1508  

Wait, what?! 24k req/s? 5x lower?
Interestingly, during this test my local cassandra node sits half idle, top reports Cassandra using about 160% of a core (out of 4 physical cores), and total CPU is about 60-70% idle.
The queue is full on the latte side, there are 4071 pending requests on average at the moment of scheduling a new request.

Let's try that with master branch using cassandra_cpp:

./target/release/latte run workloads/basic/read.rn -d 1000000 -p 4096

     Concurrency     [req]     1742.2                                                                 
              └─       [%]       42.5                                                                 
      Throughput    [op/s]     131797 ± 6877                                                          
              ├─   [req/s]     131797 ± 6877                                                          
              └─   [row/s]     131797 ± 6877         

Now Cassandra is also a lot more loaded, gets about 450-500% of a core, total idle is about 15-20% (still weird why, but it was always like that, so that might be a problem in Cassandra).

So overall - it looks like there is a bottleneck somewhere when a crazy number of futures is outstanding. Can you try with -p 4096 (or even higher values) and check if you also reproduce that? Generally the higher you go, the throughput drops more, while with cassandra_cpp the throughput first goes up, then it flattens, but does not drop - further increasing the number of concurrent requests only increases the latency.

[pkolaczk]

Seems to be inversely linear. Going from 4096 to 8152 concurrent queries halves the throughput near exactly. I'm using single threaded tokio runtime here so it is likely not a classic thread contention.