FM / examples

/usr/share/doc/bpftrace/examples

Name	Size	Mode	Actions
bashreadline_example.txt	722	0644	edit dl rm
biolatency_example.txt	1790	0644	edit dl rm
biosnoop_example.txt	2056	0644	edit dl rm
biostacks_example.txt	1914	0644	edit dl rm
bitesize_example.txt	3003	0644	edit dl rm
capable_example.txt	2659	0644	edit dl rm
cpuwalk_example.txt	4919	0644	edit dl rm
dcsnoop_example.txt	4612	0644	edit dl rm
execsnoop_example.txt	1535	0644	edit dl rm
gethostlatency_example.txt	923	0644	edit dl rm
killsnoop_example.txt	846	0644	edit dl rm
loads_example.txt	864	0644	edit dl rm
mdflush_example.txt	1866	0644	edit dl rm
naptime_example.txt	844	0644	edit dl rm
oomkill_example.txt	1668	0644	edit dl rm
opensnoop_example.txt	2528	0644	edit dl rm
pidpersec_example.txt	1504	0644	edit dl rm
runqlat_example.txt	8632	0644	edit dl rm
runqlen_example.txt	980	0644	edit dl rm
setuids_example.txt	2441	0644	edit dl rm
ssllatency_example.txt	4510	0644	edit dl rm
sslsnoop_example.txt	1916	0644	edit dl rm
statsnoop_example.txt	2738	0644	edit dl rm
swapin_example.txt	549	0644	edit dl rm
syncsnoop_example.txt	541	0644	edit dl rm
syscount_example.txt	1144	0644	edit dl rm
tcpaccept_example.txt	1350	0644	edit dl rm
tcpconnect_example.txt	1085	0644	edit dl rm
tcpdrop_example.txt	1256	0644	edit dl rm
tcplife_example.txt	1597	0644	edit dl rm
tcpretrans_example.txt	1153	0644	edit dl rm
tcpsynbl_example.txt	940	0644	edit dl rm
threadsnoop_example.txt	1182	0644	edit dl rm
undump_example.txt	680	0644	edit dl rm
vfscount_example.txt	1199	0644	edit dl rm
vfsstat_example.txt	929	0644	edit dl rm
writeback_example.txt	1962	0644	edit dl rm
xfsdist_example.txt	3419	0644	edit dl rm

Edit: /usr/share/doc/bpftrace/examples/ssllatency_example.txt (4510B)

Demonstrations of ssllatency, the Linux bpftrace/eBPF version.

ssllatency traces OpenSSL handshake functions. It's the statistical summary
version of sslsnoop. This is useful for performance analysis with different
crypto algorithms or async SSL acceleration by CPU or offload device.
For example:

# 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.

cmd: