ssllatency.bt

#!/usr/bin/env bpftrace
// ssllatency	Trace SSL/TLS handshake for OpenSSL.
// 		For Linux, uses bpftrace and eBPF.
//
// ssllatency shows handshake latency stats and distribution.
//
// Example of usage:
//
// # wrk -t 1 -c 10 -d 1s -H 'Connection: close' https://localhost:443/0kb.bin
// Running 1s test @ https://localhost:443/0kb.bin
//   1 threads and 10 connections
//   Thread Stats   Avg      Stdev     Max   +/- Stdev
//     Latency   839.94us  323.68us   5.98ms   98.50%
//     Req/Sec     1.28k     9.05     1.29k    54.55%
//   1400 requests in 1.10s, 414.26KB read
//   Non-2xx or 3xx responses: 1400
// Requests/sec:   1272.97
// Transfer/sec:    376.67KB
//
// # ./ssllatency.bt
// Attaching 26 probes...
// Tracing SSL/TLS handshake... Hit Ctrl-C to end.
// ^C
// Latency distribution in microsecond:
//
// @hist[SSL_write]:
// [0, 200)            1401 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
// @hist[SSL_read]:
// [0, 200)            1401 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
// @hist[SSL_do_handshake]:
// [600, 800)          1359 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
// [800, 1000)           12 |                                                    |
// [1000, ...)           32 |@                                                   |
// @hist[rsa_ossl_private_decrypt]:
// [600, 800)          1359 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
// [800, 1000)           44 |@                                                   |
// @histF[SSL_do_handshake]:
// [0, 200)            1410 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
// @histF[SSL_read]:
// [0, 200)            2804 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
//
// @stat[SSL_read]: count 1401, average 2, total 2834
// @stat[SSL_write]: count 1401, average 5, total 7062
// @stat[rsa_ossl_private_decrypt]: count 1403, average 643, total 902780
// @stat[SSL_do_handshake]: count 1403, average 706, total 991605
//
// @statF[SSL_read]: count 2804, average 1, total 3951
// @statF[SSL_do_handshake]: count 1410, average 29, total 41964
//
// This output shows latency distribution for wrk benchmark which saturated
// one CPU core used by nginx server. wrk issued 1400 requests in 1.10s, and
// req/s is 1272. Server side RSA function is counted 1403 times averaging
// 643us latency. And there's same amount(1410/1403) of failed/successful
// SSL_do_handshake calls for the round trip. This is the default behavior.
//
// # wrk -t 1 -c 10 -d 1s -H 'Connection: close' https://localhost:443/0kb.bin
// Running 1s test @ https://localhost:443/0kb.bin
//   1 threads and 10 connections
//   Thread Stats   Avg      Stdev     Max   +/- Stdev
//     Latency   448.67us  148.67us   1.28ms   82.00%
//     Req/Sec     2.95k    43.03     2.99k    80.00%
//   2933 requests in 1.00s, 867.87KB read
//   Non-2xx or 3xx responses: 2933
// Requests/sec:   2930.53
// Transfer/sec:    867.14KB
//
// # ./ssllatency.bt
// Attaching 26 probes...
// Tracing SSL/TLS handshake... Hit Ctrl-C to end.
// ^C
// Latency distribution in microsecond:
//
// @hist[SSL_write]:
// [0, 200)            2933 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
// @hist[SSL_read]:
// [0, 200)            2933 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
// @hist[SSL_do_handshake]:
// [0, 200)            2941 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
// @histF[SSL_read]:
// [0, 200)            5873 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
// @histF[SSL_do_handshake]:
// [0, 200)            5884 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
//
// @stat[SSL_read]: count 2933, average 4, total 12088
// @stat[SSL_write]: count 2933, average 7, total 20683
// @stat[SSL_do_handshake]: count 2941, average 51, total 151149
//
// @statF[SSL_read]: count 5873, average 2, total 13942
// @statF[SSL_do_handshake]: count 5884, average 19, total 113061
//
// This is the hardware accelerated result by using async SSL and CPU crypto
// SIMD. req/s is more than doubled under same wkr workload. Peak throughput
// can be more than 3x if adding more wrk connections. Keep using same
// workload for comparison.
//
// libcrypto_mb.so is used instead of libcrypto.so, to batch process multiple
// async requests simultaneously by SIMD. As a result, wrk issued 2933 requests
// in 1s. Failed SSL_do_handshake calls has doubled(5884), and successful
// calls(2941) returned quickly(51us). This is expected from async routines.
//
// The above effect is based on the huge bottleneck of RSA which is very CPU
// intensive. If change to ECDSA, the overhead would be much less, and overall
// improvement is less obvious.
//
// Copyright (c) 2021 Tao Xu.
//
// 17-Dec-2021	Tao Xu	created this.

config = {
  missing_probes = ignore;
}

BEGIN
{
  printf("Tracing SSL/TLS handshake... Hit Ctrl-C to end.\n");
}

uprobe:libssl:SSL_read,
uprobe:libssl:SSL_write,
uprobe:libssl:SSL_do_handshake
{
  @start_ssl[tid] = nsecs;
  @func_ssl[tid] = func; // store for uretprobe
}

uretprobe:libssl:SSL_read,
uretprobe:libssl:SSL_write,
uretprobe:libssl:SSL_do_handshake
/has_key(@start_ssl, tid)/
{
  $lat_us = (nsecs - @start_ssl[tid]) / 1000;
  if (((int8)retval) >= 1) {
    @hist[@func_ssl[tid]] = lhist($lat_us, 0, 1000, 200);
    @stat[@func_ssl[tid]] = stats($lat_us);
  } else {
    @histF[@func_ssl[tid]] = lhist($lat_us, 0, 1000, 200);
    @statF[@func_ssl[tid]] = stats($lat_us);
  }
  delete(@start_ssl, tid);
  delete(@func_ssl, tid);
}

// need debug symbol for ossl local functions
uprobe:libcrypto:rsa_ossl_public_encrypt,
uprobe:libcrypto:rsa_ossl_public_decrypt,
uprobe:libcrypto:rsa_ossl_private_encrypt,
uprobe:libcrypto:rsa_ossl_private_decrypt,
uprobe:libcrypto:RSA_sign,
uprobe:libcrypto:RSA_verify,
uprobe:libcrypto:ossl_ecdsa_sign,
uprobe:libcrypto:ossl_ecdsa_verify,
uprobe:libcrypto:ecdh_simple_compute_key
{
  @start_crypto[tid] = nsecs;
  @func_crypto[tid] = func; // store for uretprobe
}

uretprobe:libcrypto:rsa_ossl_public_encrypt,
uretprobe:libcrypto:rsa_ossl_public_decrypt,
uretprobe:libcrypto:rsa_ossl_private_encrypt,
uretprobe:libcrypto:rsa_ossl_private_decrypt,
uretprobe:libcrypto:RSA_sign,
uretprobe:libcrypto:RSA_verify,
uretprobe:libcrypto:ossl_ecdsa_sign,
uretprobe:libcrypto:ossl_ecdsa_verify,
uretprobe:libcrypto:ecdh_simple_compute_key
/has_key(@start_crypto, tid)/
{
  $lat_us = (nsecs - @start_crypto[tid]) / 1000;
  @hist[@func_crypto[tid]] = lhist($lat_us, 0, 1000, 200);
  @stat[@func_crypto[tid]] = stats($lat_us);
  delete(@start_crypto, tid);
  delete(@func_crypto, tid);
}

END
{
  printf("\nLatency distribution in microsecond:");
}