[PATCH blktests 0/3] introduce command trace feature

[PATCH blktests 0/3] introduce command trace feature

[Shin'ichiro Kawasaki]

Some blktests test cases have deep nesting, making their behavior
difficult to understand. For example, the nvme test group has many
helper functions that set sysfs attribute values and call nvme-cli
commands. Understanding these behaviors is essential for debugging test
case failures.

This series adds a new 'command trace' feature to blktests. The first
patch introduces a new --cmd-trace (or -t) option to record commands
executed during test runs. The second and third patches add a new helper
function _echo(), which traces both the value and file name of sysfs
attribute writes.

With this series, blktests users can use the option to generate a
.cmdtrace file that records all commands executed during a test case
run. By grepping the .cmdtrace file, users can check writes to sysfs
attributes and nvme-cli command invocations. The example below shows how
nvme targets are set up for the nvme/008 test case with rdma transport.

# NVMET_TRTYPES=rdma NVMET_BLKDEV_TYPES=device ./check --cmd-trace nvme/008
nvme/008 (tr=rdma bd=device) (create an NVMeOF host)         [passed]
    runtime  1.903s  ...  1.890s
# grep -e _echo -e "nvme " results/nodev_tr_rdma_bd_device/nvme/008.cmdtrace
+ _echo 0 /sys/kernel/config/nvmet/subsystems/blktests-subsystem-1/attr_allow_any_host
+ _echo /dev/loop0 /sys/kernel/config/nvmet/subsystems/blktests-subsystem-1/namespaces/1/device_path
+ _echo 91fdba0d-f87b-4c25-b80f-db7be1418b9e /sys/kernel/config/nvmet/subsystems/blktests-subsystem-1/namespaces/1/device_uuid
+ _echo 1 /sys/kernel/config/nvmet/subsystems/blktests-subsystem-1/namespaces/1/enable
++ _echo rdma /sys/kernel/config/nvmet/ports/0/addr_trtype
++ _echo 10.0.2.15 /sys/kernel/config/nvmet/ports/0/addr_traddr
++ _echo ipv4 /sys/kernel/config/nvmet/ports/0/addr_adrfam
++ _echo 4420 /sys/kernel/config/nvmet/ports/0/addr_trsvcid
++ nvme connect --traddr 10.0.2.15 --transport rdma --trsvcid 4420 --nqn blktests-subsystem-1 --hostnqn=nqn.2014-08.org.nvmexpress:uuid:0f01fb42-9f7f-4856-b0b3-51e60b8de349 --hostid=0f01fb42-9f7f-4856-b0b3-51e60b8de349 --output-format=json
+ nvme disconnect --nqn blktests-subsystem-1
+ _echo 0 /sys/kernel/config/nvmet/subsystems/blktests-subsystem-1/namespaces/1/enable


P.S. The idea of command trace came from the hallway discussion at LSFMMBPF
     2026 with John Meneghini and Daniel Wagner. Thanks!

Shin'ichiro Kawasaki (3):
  check: add --cmd-trace option
  common/rc: add _echo() function to trace sysfs attribute writes
  common/nvme, nvme/rc: use _echo() to trace sysfs attribute writes

 check         | 17 ++++++++++++++-
 common/nvme   | 34 ++++++++++++++---------------
 common/rc     |  6 ++++++
 tests/nvme/rc | 60 +++++++++++++++++++++++++--------------------------
 4 files changed, 68 insertions(+), 49 deletions(-)

-- 
2.54.0

[PATCH blktests 1/3] check: add --cmd-trace option

[Shin'ichiro Kawasaki]

Test cases that use helper functions can be difficult to understand due
to deep nesting. To make test execution easier to follow, add a new
--cmd-trace (or -t) option to record the commands executed during test
runs.

The trace is implemented using bash's xtrace feature. Enable xtrace with
`set -x` before each test case and redirect the trace output to a
`.cmdtrace` file in the result directory.

Signed-off-by: Shin'ichiro Kawasaki <shinichiro.kawasaki@wdc.com>
---
 check | 17 ++++++++++++++++-
 1 file changed, 16 insertions(+), 1 deletion(-)

diff --git a/check b/check
index c166fae..a68049b 100755
--- a/check
+++ b/check
@@ -458,7 +458,17 @@ _call_test() {
 
 		TIMEFORMAT="%Rs"
 		pushd . >/dev/null || return
+		if ((CMD_TRACE)); then
+			exec 8>"${seqres}.cmdtrace"
+			export BASH_XTRACEFD=8
+			set -x
+		fi
 		{ time "$test_func" >"${seqres}.out" 2>&1; } 2>"${seqres}.runtime"
+		if ((CMD_TRACE)); then
+			set +x
+			unset BASH_XTRACEFD
+			exec 8>&-
+		fi
 		TEST_RUN["exit_status"]=$?
 		popd >/dev/null || return
 		TEST_RUN["runtime"]="$(cat "${seqres}.runtime")"
@@ -1157,7 +1167,7 @@ Miscellaneous:
 
 _check_dependencies
 
-if ! TEMP=$(getopt -o 'do:q::x:c:h' --long 'device-only,quick::,exclude:,output:,config:,help' -n "$0" -- "$@"); then
+if ! TEMP=$(getopt -o 'do:q::x:c:th' --long 'device-only,quick::,exclude:,output:,config:,cmd-trace,help' -n "$0" -- "$@"); then
 	exit 1
 fi
 
@@ -1165,6 +1175,7 @@ eval set -- "$TEMP"
 unset TEMP
 
 LOADED_CONFIG=0
+CMD_TRACE=0
 OPTION_EXCLUDE=()
 while true; do
 	case "$1" in
@@ -1192,6 +1203,10 @@ while true; do
 			LOADED_CONFIG=1
 			shift 2
 			;;
+		'-t'|'--cmd-trace')
+			CMD_TRACE=1
+			shift
+			;;
 		'-h'|'--help')
 			usage out
 			;;
-- 
2.54.0

[PATCH blktests 2/3] common/rc: add _echo() function to trace sysfs attribute writes

[Shin'ichiro Kawasaki]

Many test cases write to sysfs attributes, and these writes are
important for understanding test behavior. However, bash's xtrace
feature does not record the target file in commands like `echo X > Y`;
it only records `echo X`.

To capture the write target, introduce `_echo()`, which writes its first
argument to the file specified by its second argument. This allows
xtrace to record the complete operation (e.g., `_echo X Y` instead of
just `echo X`).

Signed-off-by: Shin'ichiro Kawasaki <shinichiro.kawasaki@wdc.com>
---
 common/rc | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/common/rc b/common/rc
index d2c1d74..0941678 100644
--- a/common/rc
+++ b/common/rc
@@ -780,3 +780,9 @@ _min() {
 	done
 	echo "$ret"
 }
+
+# Echo a value to a file. This wrapper is used to trace sysfs attribute writes
+# when the --cmd-trace option is enabled.
+_echo() {
+	echo "$1" > "$2"
+}
-- 
2.54.0

[PATCH blktests 3/3] common/nvme, nvme/rc: use _echo() to trace sysfs attribute writes

[Shin'ichiro Kawasaki]

The previous commit introduced the helper function _echo(). Use it in
common/nvme and tests/nvme/rc to trace sysfs attribute writes.

Signed-off-by: Shin'ichiro Kawasaki <shinichiro.kawasaki@wdc.com>
---
 common/nvme   | 34 ++++++++++++++---------------
 tests/nvme/rc | 60 +++++++++++++++++++++++++--------------------------
 2 files changed, 46 insertions(+), 48 deletions(-)

diff --git a/common/nvme b/common/nvme
index 565de59..aa44ca6 100644
--- a/common/nvme
+++ b/common/nvme
@@ -570,18 +570,18 @@ _create_nvmet_port() {
 		traddr=$(_fc_traddr $port)
 		adrfam="fc"
 	fi
-	echo "${trtype}" > "${portcfs}/addr_trtype"
-	echo "${traddr}" > "${portcfs}/addr_traddr"
-	echo "${adrfam}" > "${portcfs}/addr_adrfam"
+	_echo "${trtype}" "${portcfs}/addr_trtype"
+	_echo "${traddr}" "${portcfs}/addr_traddr"
+	_echo "${adrfam}" "${portcfs}/addr_adrfam"
 	if [[ "${adrfam}" != "fc" ]] && \
 	   [[ "${adrfam}" != "loop" ]] ; then
-		echo "${trsvcid}" > "${portcfs}/addr_trsvcid"
+		_echo "${trsvcid}" "${portcfs}/addr_trsvcid"
 	fi
 	if [[ "${trtype}" == "tcp" ]] && \
 		   [[ "${tls}" != "none" ]]; then
-		echo "tls1.3" > "${portcfs}/addr_tsas"
+		_echo "tls1.3" "${portcfs}/addr_tsas"
 		if [[ "${tls}" != "required" ]]; then
-			echo "not required" > "${portcfs}/addr_treq"
+			_echo "not required" "${portcfs}/addr_treq"
 		fi
 	fi
 	echo "${port}"
@@ -601,7 +601,7 @@ _setup_nvmet_port_ana() {
 		fi
 		mkdir "${anaport}"
 	fi
-	echo "${anastate}" > "${anaport}/ana_state"
+	_echo "${anastate}" "${anaport}/ana_state"
 }
 
 _remove_nvmet_port() {
@@ -722,19 +722,19 @@ _create_nvmet_ns() {
 	subsys_path="${NVMET_CFS}/subsystems/${subsysnqn}"
 	ns_path="${subsys_path}/namespaces/${nsid}"
 	mkdir "${ns_path}"
-	printf "%s" "${blkdev}" > "${ns_path}/device_path"
+	_echo "$(printf "%s" "${blkdev}")" "${ns_path}/device_path"
 	if [[ -f "${ns_path}/resv_enable" && "${resv_enable}" = true ]] ; then
-		printf 1 > "${ns_path}/resv_enable"
+		_echo 1 "${ns_path}/resv_enable"
 	fi
 	if [[ -n "${uuid}" ]]; then
-		printf "%s" "${uuid}" > "${ns_path}/device_uuid"
+		_echo "$(printf "%s" "${uuid}")" "${ns_path}/device_uuid"
 	else
 		uuid=$(cat "${ns_path}/device_uuid")
 	fi
 	if (( grpid != 1 )); then
-		printf "%d" "${grpid}" > "${ns_path}/ana_grpid"
+		_echo "$(printf "%d" "${grpid}")" "${ns_path}/ana_grpid"
 	fi
-	printf 1 > "${ns_path}/enable"
+	_echo 1 "${ns_path}/enable"
 	echo "${uuid}"
 }
 
@@ -748,7 +748,7 @@ _setup_nvmet_ns_ana() {
 	if [[ ! -d "${ns_path}" ]]; then
 		return
 	fi
-	echo "${anagrpid}" > "${ns_path}/anagrpid"
+	_echo "${anagrpid}" "${ns_path}/anagrpid"
 }
 
 _create_nvmet_subsystem() {
@@ -786,7 +786,7 @@ _create_nvmet_subsystem() {
 
 	cfs_path="${NVMET_CFS}/subsystems/${subsystem}"
 	mkdir -p "${cfs_path}"
-	echo 0 > "${cfs_path}/attr_allow_any_host"
+	_echo 0 "${cfs_path}/attr_allow_any_host"
 	if [[ -z "${blkdev}" ]]; then
 		return 0
 	fi
@@ -825,10 +825,10 @@ _create_nvmet_host() {
 	mkdir "${host_path}"
 	_add_nvmet_allow_hosts "${nvmet_subsystem}" "${nvmet_hostnqn}"
 	if [[ "${nvmet_hostkey}" ]] ; then
-		echo "${nvmet_hostkey}" > "${host_path}/dhchap_key"
+		_echo "${nvmet_hostkey}" "${host_path}/dhchap_key"
 	fi
 	if [[ "${nvmet_ctrlkey}" ]] ; then
-		echo "${nvmet_ctrlkey}" > "${host_path}/dhchap_ctrl_key"
+		_echo "${nvmet_ctrlkey}" "${host_path}/dhchap_ctrl_key"
 	fi
 }
 
@@ -838,7 +838,7 @@ _remove_nvmet_ns() {
 	local subsys_path="${NVMET_CFS}/subsystems/${nvmet_subsystem}"
 	local nvmet_ns_path="${subsys_path}/namespaces/${nsid}"
 
-	echo 0 > "${nvmet_ns_path}/enable"
+	_echo 0 "${nvmet_ns_path}/enable"
 	rmdir "${nvmet_ns_path}"
 }
 
diff --git a/tests/nvme/rc b/tests/nvme/rc
index a8f80d8..c106359 100644
--- a/tests/nvme/rc
+++ b/tests/nvme/rc
@@ -223,12 +223,12 @@ _create_nvmet_passthru() {
 	local passthru_path="${subsys_path}/passthru"
 
 	mkdir -p "${subsys_path}"
-	echo 0 > "${subsys_path}/attr_allow_any_host"
+	_echo 0 "${subsys_path}/attr_allow_any_host"
 
 	_test_dev_nvme_ctrl > "${passthru_path}/device_path"
-	echo 1 > "${passthru_path}/enable"
+	_echo 1 "${passthru_path}/enable"
 	if [[ -f "${passthru_path}/clear_ids" ]]; then
-		echo 1 > "${passthru_path}/clear_ids"
+		_echo 1 "${passthru_path}/clear_ids"
 	fi
 }
 
@@ -237,7 +237,7 @@ _remove_nvmet_passhtru() {
 	local subsys_path="${NVMET_CFS}/subsystems/${nvmet_subsystem}"
 	local passthru_path="${subsys_path}/passthru"
 
-	echo 0 > "${passthru_path}/enable"
+	_echo 0 "${passthru_path}/enable"
 	rm -f "${subsys_path}"/allowed_hosts/*
 	rmdir "${subsys_path}"
 }
@@ -247,8 +247,7 @@ _set_nvmet_hostkey() {
 	local nvmet_hostkey="$2"
 	local cfs_path="${NVMET_CFS}/hosts/${nvmet_hostnqn}"
 
-	echo "${nvmet_hostkey}" > \
-	     "${cfs_path}/dhchap_key"
+	_echo "${nvmet_hostkey}" "${cfs_path}/dhchap_key"
 }
 
 _set_nvmet_ctrlkey() {
@@ -256,8 +255,7 @@ _set_nvmet_ctrlkey() {
 	local nvmet_ctrlkey="$2"
 	local cfs_path="${NVMET_CFS}/hosts/${nvmet_hostnqn}"
 
-	echo "${nvmet_ctrlkey}" > \
-	     "${cfs_path}/dhchap_ctrl_key"
+	_echo "${nvmet_ctrlkey}" "${cfs_path}/dhchap_ctrl_key"
 }
 
 _set_nvmet_hash() {
@@ -265,8 +263,7 @@ _set_nvmet_hash() {
 	local nvmet_hash="$2"
 	local cfs_path="${NVMET_CFS}/hosts/${nvmet_hostnqn}"
 
-	echo "${nvmet_hash}" > \
-	     "${cfs_path}/dhchap_hash"
+	_echo "${nvmet_hash}" "${cfs_path}/dhchap_hash"
 }
 
 _set_nvmet_dhgroup() {
@@ -274,8 +271,7 @@ _set_nvmet_dhgroup() {
 	local nvmet_dhgroup="$2"
 	local cfs_path="${NVMET_CFS}/hosts/${nvmet_hostnqn}"
 
-	echo "${nvmet_dhgroup}" > \
-	     "${cfs_path}/dhchap_dhgroup"
+	_echo "${nvmet_dhgroup}" "${cfs_path}/dhchap_dhgroup"
 }
 
 _enable_nvmet_ns() {
@@ -285,7 +281,7 @@ _enable_nvmet_ns() {
 	cfs_path="${NVMET_CFS}/subsystems/${subsysnqn}"
 	ns_path="${cfs_path}/namespaces/${nsid}"
 
-	echo 1 > "${ns_path}/enable"
+	_echo 1 "${ns_path}/enable"
 }
 
 _disable_nvmet_ns() {
@@ -295,7 +291,7 @@ _disable_nvmet_ns() {
 	cfs_path="${NVMET_CFS}/subsystems/${subsysnqn}"
 	ns_path="${cfs_path}/namespaces/${nsid}"
 
-	echo 0 > "${ns_path}/enable"
+	_echo 0 "${ns_path}/enable"
 }
 
 _set_nvmet_ns_uuid() {
@@ -473,8 +469,10 @@ _nvme_passthru_logging_setup()
 
 _nvme_passthru_logging_cleanup()
 {
-	echo "$ctrl_dev_passthru_logging" > /sys/class/nvme/"$2"/passthru_err_log_enabled
-	echo "$ns_dev_passthru_logging" > /sys/class/nvme/"$2"/"$1"/passthru_err_log_enabled
+	_echo "$ctrl_dev_passthru_logging" \
+	      /sys/class/nvme/"$2"/passthru_err_log_enabled
+	_echo "$ns_dev_passthru_logging" \
+	      /sys/class/nvme/"$2"/"$1"/passthru_err_log_enabled
 }
 
 _nvme_err_inject_setup()
@@ -495,55 +493,55 @@ _nvme_err_inject_cleanup()
         local a
 
         for a in /sys/kernel/debug/"$1"/fault_inject/*; do
-                echo "${NS_DEV_FAULT_INJECT_SAVE[${a}]}" > "${a}"
+                _echo "${NS_DEV_FAULT_INJECT_SAVE[${a}]}" "${a}"
         done
 
         for a in /sys/kernel/debug/"$2"/fault_inject/*; do
-                echo "${CTRL_DEV_FAULT_INJECT_SAVE[${a}]}" > "${a}"
+                _echo "${CTRL_DEV_FAULT_INJECT_SAVE[${a}]}" "${a}"
         done
 }
 
 _nvme_enable_err_inject()
 {
-        echo "$2" > /sys/kernel/debug/"$1"/fault_inject/verbose
-        echo "$3" > /sys/kernel/debug/"$1"/fault_inject/probability
-        echo "$4" > /sys/kernel/debug/"$1"/fault_inject/dont_retry
-        echo "$5" > /sys/kernel/debug/"$1"/fault_inject/status
-        echo "$6" > /sys/kernel/debug/"$1"/fault_inject/times
+        _echo "$2" /sys/kernel/debug/"$1"/fault_inject/verbose
+        _echo "$3" /sys/kernel/debug/"$1"/fault_inject/probability
+        _echo "$4" /sys/kernel/debug/"$1"/fault_inject/dont_retry
+        _echo "$5" /sys/kernel/debug/"$1"/fault_inject/status
+        _echo "$6" /sys/kernel/debug/"$1"/fault_inject/times
 }
 
 _nvme_disable_err_inject()
 {
-        echo 0 > /sys/kernel/debug/"$1"/fault_inject/probability
-        echo 0 > /sys/kernel/debug/"$1"/fault_inject/times
+        _echo 0 /sys/kernel/debug/"$1"/fault_inject/probability
+        _echo 0 /sys/kernel/debug/"$1"/fault_inject/times
 }
 
 _nvme_enable_passthru_admin_error_logging()
 {
-	echo on > /sys/class/nvme/"$1"/passthru_err_log_enabled
+	_echo on /sys/class/nvme/"$1"/passthru_err_log_enabled
 }
 
 _nvme_enable_passthru_io_error_logging()
 {
-	echo on > /sys/class/nvme/"$2"/"$1"/passthru_err_log_enabled
+	_echo on /sys/class/nvme/"$2"/"$1"/passthru_err_log_enabled
 }
 
 _nvme_disable_passthru_admin_error_logging()
 {
-	echo off > /sys/class/nvme/"$1"/passthru_err_log_enabled
+	_echo off /sys/class/nvme/"$1"/passthru_err_log_enabled
 }
 
 _nvme_disable_passthru_io_error_logging()
 {
-	echo off > /sys/class/nvme/"$2"/"$1"/passthru_err_log_enabled
+	_echo off /sys/class/nvme/"$2"/"$1"/passthru_err_log_enabled
 }
 
 _nvme_reset_ctrl() {
-	echo 1 > /sys/class/nvme/"$1"/reset_controller
+	_echo 1 /sys/class/nvme/"$1"/reset_controller
 }
 
 _nvme_delete_ctrl() {
-	echo 1 > /sys/class/nvme/"$1"/delete_controller
+	_echo 1 /sys/class/nvme/"$1"/delete_controller
 }
 
 # Check whether the version of the fio is greater than or equal to $1.$2.$3
-- 
2.54.0

Re: [PATCH blktests 2/3] common/rc: add _echo() function to trace sysfs attribute writes

[Daniel Wagner]

On Wed, May 13, 2026 at 08:23:25PM +0900, Shin'ichiro Kawasaki wrote:
> +# Echo a value to a file. This wrapper is used to trace sysfs attribute writes
> +# when the --cmd-trace option is enabled.
> +_echo() {
> +	echo "$1" > "$2"
> +}

Stupid question, can't we override the echo function, something like this:

echo() {
    builtin echo "$@"
    builtin echo "$@" >> "/tmp/debug_log.txt"
}

Re: [PATCH blktests 2/3] common/rc: add _echo() function to trace sysfs attribute writes

[Bart Van Assche]

On 5/13/26 7:05 AM, Daniel Wagner wrote:
> On Wed, May 13, 2026 at 08:23:25PM +0900, Shin'ichiro Kawasaki wrote:
>> +# Echo a value to a file. This wrapper is used to trace sysfs attribute writes
>> +# when the --cmd-trace option is enabled.
>> +_echo() {
>> +	echo "$1" > "$2"
>> +}
> 
> Stupid question, can't we override the echo function, something like this:
> 
> echo() {
>      builtin echo "$@"
>      builtin echo "$@" >> "/tmp/debug_log.txt"
> }

How can this work since the sysfs/debugfs/configfs attribute is not an
argument of the echo command?

Thanks,

Bart.

Re: [PATCH blktests 1/3] check: add --cmd-trace option

[Bart Van Assche]

On 5/13/26 4:23 AM, Shin'ichiro Kawasaki wrote:
> diff --git a/check b/check
> index c166fae..a68049b 100755
> --- a/check
> +++ b/check
> @@ -458,7 +458,17 @@ _call_test() {
>   
>   		TIMEFORMAT="%Rs"
>   		pushd . >/dev/null || return
> +		if ((CMD_TRACE)); then
> +			exec 8>"${seqres}.cmdtrace"
> +			export BASH_XTRACEFD=8
> +			set -x
> +		fi

Hmm ... my experience is that set -x breaks most tests.

Thanks,

Bart.

Re: [PATCH blktests 2/3] common/rc: add _echo() function to trace sysfs attribute writes

[Bart Van Assche]

On 5/13/26 4:23 AM, Shin'ichiro Kawasaki wrote:
> +# Echo a value to a file. This wrapper is used to trace sysfs attribute writes

Echo -> Write
file -> sysfs/debugfs/configfs attribute
sysfs -> sysfs/debugfs/configfs

> +# when the --cmd-trace option is enabled.
> +_echo() {
> +	echo "$1" > "$2"
> +}

If this is only used to write into sysfs/debugfs/configfs, there are 
probably better names for this function than _echo, e.g. _set_attr(),
_write_attr() or _write_sys_attr().

Should "echo" or "echo -n" be used in the above shell function?

Thanks,

Bart.