Koala performance analysis

[libertyeagle]

This discussion is used to track koala's performance analysis, identify bottlenecks and potential solutions. The performance analysis is currently conducted on wyj-debug branch.

[libertyeagle]

Preliminary analysis on engine mainloop exeuction time

When num_works > 0:

• RpcAdapaterEngine is about ~1050ns on both client and server side.
• MrpcEngine: 900-1000ns on client side, ~620ns on server side.

When num_works == 0:

• RpcAdapaterEngine is about 160-200ns on client side, 160-250ns on server side.
• MrpcEngine: 250-300ns on client side, 250-400ns on server side.

These numbers are measured using std::time::Instant::now().elapsed(), which it self has about ~20ns exeuction time.

[libertyeagle]

RpcAdapaterEngine break-down:
When there is work:

• check_input_queue: 700-800ns on client side, 850ns on server side
• check_transport_service: 920-950ns

[crazyboycjr]

Countermeasure for slow check_input_queue, change to crossbeam's channel.

[libertyeagle]

misc:

• ResourceTable.get(): 50ns, get mutex is costly.
• unmarshal_and_deliver_up: 550-1100ns

[crazyboycjr]

The 50ns consists of a hashtable lookup, spinlock acquirement, and cloning of an Arc. 50ns is actually pretty good. Consider using dashmap and eliminating the lock in special cases if necessary. I reckon that would be in the distant future.

[crazyboycjr]

Dynamic dispatching is more expensive than we thought. We may embed a MessageMeta into a dyn RpcMessage.

[crazyboycjr]

Copy when the message is small is better.

[libertyeagle]

One-way RPC hello performance
8192 messages:

• await/blocking: 76~77 Gbps
• 32 outstanding req queue: 91~92 Gbps

>=16384 messages:

• await/blocking: 72-73 Gbps
• 32 outstanding req queue: 83-84 Gbps

[libertyeagle]

channel performance (one-way):

hypercore pair

• crossbeam: 45.6 Mops/sec
• tokio: 14.8 Mops/sec
• flume: 20.4 Mops/sec

no affinity set:

• crossbeam: 21-41 Mops/sec
• tokio: 2.5 Mops/sec
• flume: 10 Mops/sec

[libertyeagle]

channel performance (round-trip):

hypercore pair

• crossbeam: 9.6 Mops/sec
• tokio: 4.3 Mops/sec
• flume: 0.8 Mops/sec

no affinity set:

• crossbeam: 2.3 Mops/sec
• tokio: 1.2 Mops/sec
• flume: 0.4 Mops/sec

[crazyboycjr]

also see #112 #113

[crazyboycjr]

minstant is very helpful. The overhead itself is super low (as low as 7-8 ns).

marshal_and_delivery_up is a time-consuming operation, it takes 1-4us to finish.

The overhead comes from two major sources

1. dropping span/guard has around 400-700 ns overhead EVEN IF the tracing is never enabled (easy to remove) DONE
2. write to rx_outputs()[0] has around 200-1000 ns overhead across different runs (this might be related to core affinity) (we just switch to a more performant implementation) DONE
3. unmarshal is around 90-150 ns which is actually low (this can be further optimized by improving query_app_addr).

[crazyboycjr]

The overhead of tokio queues also explains why it takes hundreds of nanoseconds for the runtime to switch among different engines.

[crazyboycjr]

The marshal for HelloRequest takes 200ns, for HelloReply it takes 100ns.
The crossbeam channel is faster and more stable than tokio channel, but the time may still vary from 100ns to 700ns across different runs.

[crazyboycjr]

Even using crossbeam channels, we can still have large latency. Maybe we should try different scheduling strategies (e.g., colocating mRPC engine and RpcAdapter).

[crazyboycjr]

On the other side, in check_input_queue

1. dropping span also takes long
2. marshal only takes 60ns, which is much faster than unmarshal, because there is no query_app_addr
3. post_send takes 600ns which is exactly what I was expecting (reducing 3 post_sends to 1 can reduce this part to 200ns)

[crazyboycjr]

post_send now only takes 300ns after fusing to one request.

[crazyboycjr]

Just removing all spans, avg: 13.698µs, min: 10.663µs, median: 12.512µs, p95: 16.703µs, p99: 17.444µs, max: 6.774174ms

[crazyboycjr]

Where there is no work
RpcAdapter mainloop: Timer { duras: [103ns, 749ns, 803ns, 1.036µs, 1.059µs] }
check_input_queue, check_transport_service, check_input_cmd_queue, check_incoming_connection, set_indicator.

[crazyboycjr]

Where there is work (server side)

[2022-06-27 05:26:58.111580  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [80ns, 866ns, 919ns, 1.127µs, 1.143µs] }
[2022-06-27 05:26:58.111590  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [85ns, 550ns, 601ns, 800ns, 817ns] }
[2022-06-27 05:26:58.111600  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [85ns, 2.434µs, 2.494µs, 2.672µs, 2.685µs] }
[2022-06-27 05:26:58.111610  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [1.438µs, 1.907µs, 1.959µs, 2.16µs, 2.177µs] }
[2022-06-27 05:26:58.111621  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [1.281µs, 1.676µs, 1.748µs, 1.945µs, 1.962µs] }
[2022-06-27 05:26:58.111630  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [90ns, 884ns, 934ns, 1.13µs, 1.146µs] }
[2022-06-27 05:26:58.111639  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [89ns, 548ns, 599ns, 801ns, 815ns] }
[2022-06-27 05:26:58.111650  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [91ns, 2.654µs, 2.716µs, 2.893µs, 2.909µs] }
[2022-06-27 05:26:58.111660  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [293ns, 767ns, 815ns, 1.008µs, 1.024µs] }
[2022-06-27 05:26:58.111670  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [1.271µs, 1.671µs, 1.743µs, 1.945µs, 1.962µs] }
[2022-06-27 05:26:58.111679  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [73ns, 843ns, 896ns, 1.089µs, 1.105µs] }
[2022-06-27 05:26:58.111688  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [81ns, 507ns, 558ns, 753ns, 770ns] }
[2022-06-27 05:26:58.111696  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [78ns, 514ns, 564ns, 761ns, 777ns] }
[2022-06-27 05:26:58.111707  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [78ns, 2.651µs, 2.71µs, 2.887µs, 2.903µs] }
[2022-06-27 05:26:58.111721  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [5.373µs, 5.825µs, 5.875µs, 6.065µs, 6.083µs] }
[2022-06-27 05:26:58.111731  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [134ns, 582ns, 632ns, 831ns, 845ns] }
[2022-06-27 05:26:58.111740  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [1.292µs, 1.688µs, 1.759µs, 1.955µs, 1.972µs] }

[crazyboycjr]

client side

[2022-06-27 05:26:58.543943  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [95ns, 647ns, 763ns, 941ns, 963ns] }
[2022-06-27 05:26:58.543953  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [76ns, 438ns, 522ns, 669ns, 681ns] }
[2022-06-27 05:26:58.543960  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [59ns, 360ns, 400ns, 530ns, 545ns] }
[2022-06-27 05:26:58.543969  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [56ns, 2.205µs, 2.247µs, 2.356µs, 2.368µs] }
[2022-06-27 05:26:58.543978  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [1.772µs, 2.059µs, 2.104µs, 2.231µs, 2.244µs] }
[2022-06-27 05:26:58.543986  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [148ns, 441ns, 485ns, 615ns, 628ns] }
[2022-06-27 05:26:58.543996  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [1.293µs, 1.706µs, 1.854µs, 2.005µs, 2.025µs] }
[2022-06-27 05:26:58.544007  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [102ns, 1.089µs, 1.169µs, 1.318µs, 1.331µs] }
[2022-06-27 05:26:58.544015  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [65ns, 396ns, 445ns, 583ns, 595ns] }
[2022-06-27 05:26:58.544024  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [58ns, 2.239µs, 2.283µs, 2.389µs, 2.402µs] }
[2022-06-27 05:26:58.544031  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [260ns, 545ns, 591ns, 724ns, 737ns] }
[2022-06-27 05:26:58.544039  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [1.237µs, 1.517µs, 1.577µs, 1.701µs, 1.714µs] }
[2022-06-27 05:26:58.544049  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [112ns, 992ns, 1.11µs, 1.287µs, 1.308µs] }
[2022-06-27 05:26:58.544061  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [74ns, 741ns, 846ns, 1.003µs, 1.019µs] }
[2022-06-27 05:26:58.544073  INFO src/koala/src/rpc_adapter/engine.rs:147] RpcAdapter mainloop: Timer { duras: [73ns, 2.385µs, 2.465µs, 2.574µs, 2.587µs] }

[crazyboycjr]

CQ polling is more expensive than I was expecting

But when I dig into it, CQ polling has a certain overhead. When there is no completion, ibv_poll_cq is 60-70ns, as expensive as getting the CQ. (40-60ns, and sometimes 220ns). (Also take a look at who is contending with get_cq). When there are completions, the cost will rise to 120ns, sometimes 200-300ns, or even microseconds on multiple completions.

self.resource().cq_table.get_dp(&cq_handle.0)? This might be a problem when there are multiple threads in the client applications (e.g., all-to-all mt). To mitigate this issue, consider using dashmap.

get_ops is stable. 10ns (i.e., 1ns) most of the time.

[crazyboycjr]

An updated result from the client. After fusing the small request, check_input_queue is faster. Now the overhead mainly comes from check_transport_service.

[2022-06-28 16:04:04.169318  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [56ns, 677ns, 782ns, 1.017µs] }
[2022-06-28 16:04:04.169327  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [85ns, 554ns, 672ns, 894ns] }
[2022-06-28 16:04:04.169336  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [87ns, 571ns, 672ns, 896ns] }
[2022-06-28 16:04:04.169346  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [66ns, 1.896µs, 1.979µs, 2.214µs] }
[2022-06-28 16:04:04.169354  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [240ns, 729ns, 846ns, 1.079µs] }
[2022-06-28 16:04:04.169363  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [745ns, 1.114µs, 1.215µs, 1.421µs] }
[2022-06-28 16:04:04.169373  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [79ns, 748ns, 858ns, 1.089µs] }
[2022-06-28 16:04:04.169382  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [71ns, 516ns, 620ns, 841ns] }
[2022-06-28 16:04:04.169391  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [56ns, 514ns, 624ns, 861ns] }
[2022-06-28 16:04:04.169401  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [88ns, 1.866µs, 1.956µs, 2.179µs] }
[2022-06-28 16:04:04.169411  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [277ns, 838ns, 941ns, 1.171µs] }
[2022-06-28 16:04:04.169420  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [742ns, 1.128µs, 1.227µs, 1.446µs] }
[2022-06-28 16:04:04.169430  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [79ns, 757ns, 849ns, 1.069µs] }
[2022-06-28 16:04:04.169440  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [52ns, 477ns, 574ns, 817ns] }
[2022-06-28 16:04:04.169448  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [66ns, 507ns, 619ns, 834ns] }
[2022-06-28 16:04:04.169457  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [60ns, 557ns, 673ns, 895ns] }
[2022-06-28 16:04:04.169466  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [58ns, 527ns, 620ns, 876ns] }
[2022-06-28 16:04:04.169476  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [60ns, 1.832µs, 1.931µs, 2.163µs] }
[2022-06-28 16:04:04.169487  INFO src/koala/src/rpc_adapter/engine.rs:146] RpcAdapter mainloop: Timer { duras: [1.409µs, 1.857µs, 1.939µs, 2.184µs] }

[crazyboycjr]

mRPC engine mainloop:

            // 400-900ns
            if let Progress(n) = self.check_customer()? {
                nwork += n;
            }
            // timer.tick();

            // no work: 100-150ns
            // has work: 300-600ns
            if let Progress(n) = self.check_input_queue()? {
                nwork += n;
            }
            // timer.tick();

            // 80-100ns
            if let Status::Disconnected = self.check_cmd().await? {
                self.wait_meta_pool_free().await?;
                return Ok(());
            }
            // timer.tick();

            // 50ns
            self.check_new_incoming_connection()?;
            self.indicator.as_ref().unwrap().set_nwork(nwork);

In check_customer, the most time-consuming operation is Vec::with_capacity(BUF_LEN), which is stably 300ns and sometimes 5us, 10us. This conforms with the observation from the flamegraph.

[crazyboycjr]

Need to remove all Vec::with_capacity(BUF_LEN), using a pre-allocated buffer.

[crazyboycjr]

Two places in src/mrpc/src/stub.rs, one in src/koala/src/transport/rdma/engine.rs, and one in src/koala/src/mrpc/engine.rs.

[crazyboycjr]

done

[crazyboycjr]

ReclaimRecvBuf is a super-slow operation. This operation may not be on the critical path.

There are several potential ways to reduce this overhead.

1. post_recv mr_handles in batch
2. use just one mr_handle for each connection, but the mr_handle is partitioned into 128 small regions (This also benefits startup time)
3. for RPC requests received by server, piggyback the RecliamRecvBuf along with an RpcMessage. However, this optimization might not easily apply because we have a 64-byte limitation on each unit in the shm-channel. Moreover, we already reclaim memory in batch.

Fusing small messages into one work request also helps.

[crazyboycjr]

SgList using smallvec

[libertyeagle]

will use smallvec actually be better? #134

[crazyboycjr]

Not sure, maybe what we need is a custom allocator. But now, SgList should not be the major source of overhead.