libwebsockets/READMEs/README.detailed-latency.md

lws detailed latency

Introduction

lws has the capability to make detailed latency measurements and report them in realtime to a specified callback.

A default callback is provided that renders the data as text in space-separated format suitable for gnuplot, to a specified file.

Configuring

Enable LWS_WITH_DETAILED_LATENCY at cmake.

Create your context with something similar to this

#if defined(LWS_WITH_DETAILED_LATENCY)
	info.detailed_latency_cb = lws_det_lat_plot_cb;
	info.detailed_latency_filepath = "/tmp/lws-latency-results";
#endif

lws_det_lat_plot_cb is provided by lws as a convenience to convert the stuct data provided at the callback interface to space-separated text data that is easy to process with shell commands and gnuplot.

lws_det_lat_plot_cb format

728239173547 N 23062 0 0 23062 0 0 0
728239192554 C 18879 0 0 18879 0 0 0
728239217894 T 25309 0 0 25309 0 0 0
728239234998 r 0 0 0 0 271 172 256
728239250611 r 0 0 0 0 69 934 4096
728239255679 w 19 122 18 159 20 80 80
728239275718 w 20 117 15 152 18 80 80
728239295578 w 10 73 7 90 7 80 80
728239315567 w 9 67 5 81 7 80 80
728239335745 w 23 133 9 165 14 80 80
...

Each event is shown in 9 columns

• unix time in us
• event type
  • N = Name resolution
  • C = TCP Connection
  • T = TLS negotiation server
  • t = TLS negotiation client
  • r = Read
  • w = Write
• us duration, for w time client spent waiting to write
• us duration, for w time data spent in transit to proxy
• us duration, for w time proxy waited to send data
• as a convenience, sum of last 3 columns above
• us duration, time spent in callback
• last 2 are actual / requested size in bytes

Processing captured data with ministat

Eg, to summarize overall latencies on all captured writes

 $ cat /tmp/lws-latency-results | grep " w " | cut -d' ' -f6 | ministat
...
    N           Min           Max        Median           Avg        Stddev
x 1000            43           273           141       132.672     32.471693

Processing captured data with gnuplot

Gnuplot plotting script

Create a gnuplot script, eg myscript.gp

reset
set term pngcairo enhanced nocrop font "OpenSans, 12" size 800,600#output terminal and file
set output "lws-latency.png"
#set yrange [0:10000]
#to put an empty boundary around the
#data inside an autoscaled graph.
set offset graph 0.05,0.05,0.05,0.0
set style fill transparent solid 0.5 #fillstyle
set tics out nomirror
set xlabel "event"
set ylabel "latency (us)"
set format x ""
set title "Write latency"
set key invert reverse Right inside nobox
set key autotitle columnheader
set style data histogram
set style histogram rowstacked
set style fill solid border -1
set boxwidth 0.75
set style fill solid 1.00 noborder
set tic scale 0
set grid ytics lc rgb "#505050"
unset border
unset xtics

plot '/tmp/1' \
	   using ($3 + $4 + $5):xtic(1)         w boxes lt rgbcolor "blue"  title 'prox wr wait', \
	'' using ($3 + $4):xtic(1)         w boxes lt rgbcolor "green" title 'txfr to prox', \
	'' using 3:xtic(1) w boxes lt rgbcolor "red"   title 'cli wri wait'

gnuplot invocation

 $ cat /tmp/lws-latency-results | grep " w " \>/tmp/1 ; gnuplot myscript.gp && eog lws-latency.png