This series introduces trace events that can leak the latency of xsave and
xrstor instructions for the x86 platform to tell when XSAVE/XRSTOR are becoming
more or less expensive, and get the RFBM and XINUSE to figure out why.
We conducted extensive internal testing and compared several latency computation
methodologies. We believe it could be improved. Also included in the series is
a script for consuming trace logs that uses sqlite3 to display statistics data
such as max, min, latency, and 97% tail latency.
- Change from v4 to v5:
- Rebase patch to the most recent tag v6.1-rc2, no conflict.
- Change from v3 to v4:
- Rebase patch set to the latest tag v6.0-rc3, replacing
ALTERNATIVE_2 with ALTERNATIVE_3
- Change from v2 to v3:
- Move the script xsave-latency-trace.sh to folder tools/testing/fpu/
(Ingo Molnar)
- Change from v1 to v2:
- Reword the comments. (Laight, David; Mehta, Sohil)
- Rename all variable 'dtsc' to 'latency'. (Mehta, Sohil)
Yi Sun (2):
x86/fpu: Measure the Latency of XSAVE and XRSTOR
tools/testing/fpu: Add script to consume trace log of xsave latency
arch/x86/include/asm/trace/fpu.h | 35 ++++
arch/x86/kernel/fpu/xstate.h | 49 ++++-
tools/testing/fpu/xsave-latency-trace.sh | 227 +++++++++++++++++++++++
3 files changed, 306 insertions(+), 5 deletions(-)
create mode 100755 tools/testing/fpu/xsave-latency-trace.sh
--
2.34.1
Consume the trace log dumped by trace points x86_fpu_latency_xsave and
x86_fpu_latency_xrstor, calculate latency ranges for each RFBM and
XINUSE combination including min, max, average and 97% tail latency.
Add the average of 97% tail latency to remove the unreasonable
data which is introduced by interrupts or other noise. By adding the
experimental code disabling interrupts before the calculation of
latency, it's obvious to get the 3% tail latency has been filtered.
Make use of sqlite3 to make the data statistics more efficient and
concise. The output looks like following:
EVENTs RFBM XINUSE lat_min lat_max lat_avg lat_avg(97%)
---------------------- ------- ------ ------- ------- ------- ------------
x86_fpu_latency_xrstor 0x206e7 0x0 364 364 364 364
x86_fpu_latency_xrstor 0x206e7 0x202 112 1152 300 276
x86_fpu_latency_xsave 0x206e7 0x202 80 278 141 137
x86_fpu_latency_xsave 0x206e7 0x246 108 234 180 177
The XSAVE/XRSTOR latency trace log can be got by two ways:
1. Generated by Kernel debugfs
echo 1 > /sys/kernel/debug/tracing/events/x86_fpu/enable
cat /sys/kernel/debug/tracing/trace_pipe > trace-log
2. Generated by helper tool like 'trace-cmd'
trace-cmd record -e x86_fpu -F <command>
trace-cmd report > trace-log
Reviewed-by: Tony Luck <[email protected]>
Signed-off-by: Yi Sun <[email protected]>
diff --git a/tools/testing/fpu/xsave-latency-trace.sh b/tools/testing/fpu/xsave-latency-trace.sh
new file mode 100755
index 000000000000..d45563984fd6
--- /dev/null
+++ b/tools/testing/fpu/xsave-latency-trace.sh
@@ -0,0 +1,227 @@
+#!/bin/bash
+# SPDX-License-Identifier: GPL-2.0
+#
+# (c) 2022 Yi Sun <[email protected]>
+
+trace_log=$1
+trace_lat_log=".trace_lat_log"
+db_name="db_trace"
+db_file="${db_name}.db"
+table_raw="t_trace"
+table_tail="t_trace_tail"
+table_results="t_results"
+events="x86_fpu_latency_xsave|x86_fpu_latency_xrstor"
+
+# The regex for the trace log. The rough pattern:
+# (proc) (No.cpu) (flags) (timestamp): (tracepoint): latency:(123) RFBM:0x(123) XINUSE:0x(123)$
+# Fold the regex into 3 parts making it easier to read.
+regex1="([^\ ]*)[[:space:]]*\[([0-9]+)\][[:space:]]*(.....\ )?[[:space:]]*"
+regex2="([0-9.]*):[[:space:]]*([^\ :]*):.*latency:([0-9]*)[[:space:]]*"
+regex3="RFBM:(0x[0-9a-f]*)[[:space:]]*XINUSE:(0x[0-9a-f]*)$"
+
+function usage() {
+ echo "This script consumes the tracepoint data, and dumps out the"
+ echo "latency ranges for each RFBM combination."
+ echo "Usage:"
+ echo "$0 <trace-log>"
+ echo " trace-log:"
+ echo " Either generated by Kernel sysfs:"
+ echo " echo 1 > /sys/kernel/debug/tracing/events/x86_fpu/enable"
+ echo " cat /sys/kernel/debug/tracing/trace_pipe > trace-log"
+ echo ""
+ echo " Or generate by helper tool like 'trace-cmd':"
+ echo " trace-cmd record -e x86_fpu"
+ echo " trace-cmd report > trace-log"
+}
+
+# Check the dependent tools
+# {@}: a list of third-part tools
+function check_packages() {
+ for pack in "$@"; do
+ which $pack >& /dev/null
+ if [[ $? != 0 ]]; then
+ echo "Please install $pack before running this script."
+ exit 1
+ fi
+ done
+}
+
+# Run SQL command with sqlite3
+# ${*}: SQL command fed to sqlite3
+function SQL_CMD() {
+ sqlite3 $db_file "$*"
+}
+
+# Run SQL command with sqlite3 and format the output with headers and column.
+# ${*}: SQL command fed to sqlite3
+function SQL_CMD_HEADER() {
+ sqlite3 -column -header $db_file "$*"
+}
+
+# Create a table in the DB
+# ${1}： name of the table
+function create_table() {
+ if [[ "$1" == "" ]]; then
+ echo "Empty table name!"
+ exit 1
+ fi
+ SQL_CMD "create table $1 (
+ id INTEGER PRIMARY KEY AUTOINCREMENT,
+ process TEXT,
+ cpu INT,
+ timestamp FLOAT,
+ event_name TEXT,
+ lat INT,
+ RFBM INT,
+ XINUSE INT);"
+}
+
+# Round to the nearest whole number
+# ${1}: a float number
+# Output: integer
+function round() {
+ echo "scale=0; ($1+0.5)/1" | bc
+}
+
+# Insert a record in the trace table
+#
+# process cpu timestamp event_name lat RFBM XINUSE
+# $2 $3 $4 $5 $6 $7 $8
+
+function insert_line() {
+ if [[ "$1" == "" ]]; then
+ echo "Empty table name!"
+ exit 1
+ fi
+ SQL_CMD "INSERT INTO $1 (process, cpu, timestamp, event_name, lat, RFBM, XINUSE)
+ VALUES (\"$2\", $3, $4, \"$5\", $6, $7, $8);"
+}
+
+# Show the results of the trace statistics
+function get_latency_stat() {
+ SQL_CMD "create table $table_results (
+ id INTEGER PRIMARY KEY AUTOINCREMENT,
+ event_name TEXT,
+ RFBM INT,
+ XINUSE INT,
+ lat_min INT,
+ lat_max INT,
+ lat_avg INT,
+ lat_tail_avg INT);"
+
+ for((i=0; i<$cnt; i++));do
+ event_name=`get_comb_item $table_raw $i event_name`
+ RFBM=`get_comb_item $table_raw $i RFBM`
+ XINUSE=`get_comb_item $table_raw $i XINUSE`
+ lat_min=`get_comb_item $table_raw $i min\(lat\)`
+ lat_max=`get_comb_item $table_raw $i max\(lat\)`
+ lat_avg=`get_comb_item $table_raw $i avg\(lat\)`
+ lat_tail_avg=`get_comb_item $table_tail $i avg\(lat\)`
+
+ lat_avg=`round $lat_avg`
+ lat_tail_avg=`round $lat_tail_avg`
+
+ SQL_CMD "INSERT INTO $table_results
+ (event_name, RFBM,XINUSE, lat_min, lat_max, lat_avg, lat_tail_avg)
+ VALUES (\"$event_name\", $RFBM, $XINUSE, $lat_min, $lat_max,
+ $lat_avg, $lat_tail_avg);"
+ done
+
+ SQL_CMD_HEADER "select event_name[EVENTs],printf('0x%x',RFBM)[RFBM],
+ printf('0x%x',XINUSE)[XINUSE],lat_min,lat_max,lat_avg,
+ lat_tail_avg[lat_avg(97%)]
+ from $table_results;"
+}
+
+# Get the count of the combination of event_name, RFBM, XINUSE amount all lat trace records
+function get_combs_cnt() {
+ SQL_CMD "SELECT event_name, RFBM, XINUSE from $table_raw
+ group by event_name,RFBM,XINUSE;" | wc -l
+}
+
+# Get a specified combination from a table
+# ${1}: name of table
+# ${2}: the order of the combination of event_name, RFBM, XINUSE
+# ${3}: the items which are wanted to be shown
+function get_comb_item() {
+ table=$1
+ cnt=$2
+ col=$3
+ SQL_CMD "SELECT $col from $table group by event_name,RFBM,XINUSE limit $cnt,1;"
+}
+
+# Get count of the records in a given table
+# ${1}: name of the table
+function get_rows_cnt() {
+ table=$1
+ SQL_CMD "SELECT count(*) from $table;"
+}
+
+# Generate a new table from the raw trace table removing 3% tail traces.
+function gen_tail_lat() {
+ cnt=`get_combs_cnt`
+ create_table $table_tail
+
+ for((i=0; i<$cnt; i++));do
+ create_table t$i
+ event_name=`get_comb_item $table_raw $i event_name`
+ RFBM=`get_comb_item $table_raw $i RFBM`
+ XINUSE=`get_comb_item $table_raw $i XINUSE`
+
+ SQL_CMD "insert into t$i(process,cpu,timestamp,event_name,lat,RFBM,XINUSE)
+ select process,cpu,timestamp,event_name,lat,RFBM,XINUSE
+ from $table_raw where event_name=\"$event_name\" and RFBM=$RFBM and
+ XINUSE=$XINUSE ORDER BY lat ASC;"
+
+ row=`get_rows_cnt t$i`
+ row=`echo "scale=0; ($row*0.97 + 0.5)/1" | bc`
+
+ SQL_CMD "insert into $table_tail
+ (process,cpu,timestamp,event_name,lat,RFBM,XINUSE)
+ select process,cpu,timestamp,event_name,lat,RFBM,XINUSE
+ from t$i limit 0,$row;"
+ done
+
+}
+
+if [[ ! -e "$trace_log" || $# != 1 ]];then
+ usage
+ exit 1
+fi
+
+# Check dependency
+# Make sure having following packages
+check_packages sqlite3 bc wc cut
+
+# Filter trace log keeping latency related lines only
+grep -E "$events" $trace_log > $trace_lat_log
+cnt_lines=`wc -l $trace_lat_log | cut -d' ' -f1`
+# Remove the old db file if it existed before creating
+[[ -f $db_file ]] && rm -rf $db_file
+
+create_table $table_raw
+
+# Read each line from the temp file and insert into the table
+i=0
+while IFS= read -r line;
+do
+ ((i = i + 1))
+ echo -ne "(${i}/$cnt_lines) Importing trace log into database!\r"
+ if [[ "$line" =~ ${regex1}${regex2}${regex3} ]]; then
+ pname=${BASH_REMATCH[1]}
+ cpu=${BASH_REMATCH[2]}
+ ts=${BASH_REMATCH[4]}
+ ename=${BASH_REMATCH[5]}
+ lat=${BASH_REMATCH[6]}
+ ((rfbm=${BASH_REMATCH[7]}))
+ ((xinuse=${BASH_REMATCH[8]}))
+
+ insert_line $table_raw $pname $cpu $ts $ename $lat $rfbm $xinuse
+ fi
+done < $trace_lat_log
+
+gen_tail_lat
+get_latency_stat
+
+# Cleanup
+rm -rf $trace_lat_log $db_file
--
2.34.1