Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
From:   Yi Sun <yi.sun@intel.com>
To:     dave.hansen@intel.com, linux-kernel@vger.kernel.org, x86@kernel.org
Cc:     sohil.mehta@intel.com, tony.luck@intel.com, heng.su@intel.com,
        yi.sun@intel.com
Subject: [PATCH 2/2] scripts/x86: Add script to consume trace log of xsave latency
Date:   Sat, 23 Jul 2022 16:38:00 +0800
Message-Id: <20220723083800.824442-3-yi.sun@intel.com>
In-Reply-To: <20220723083800.824442-1-yi.sun@intel.com>
References: <20220723083800.824442-1-yi.sun@intel.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit
Precedence: bulk

Consume the trace log dumped by tracepoint 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
latency which are introduced by interrupts. By adding the experimental
code disabling interrupts before the calculation of the tsc delta,
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 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 <tony.luck@intel.com>
Signed-off-by: Yi Sun <yi.sun@intel.com>

diff --git a/scripts/x86/xsave-latency-trace.sh b/scripts/x86/xsave-latency-trace.sh
new file mode 100755
index 000000000000..d45563984fd6
--- /dev/null
+++ b/scripts/x86/xsave-latency-trace.sh
@@ -0,0 +1,227 @@
+#!/bin/bash
+# SPDX-License-Identifier: GPL-2.0
+#
+# (c) 2022 Yi Sun <yi.sun@intel.com>
+
+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