From 533df585fd858129b4c1275f18d1a34816deeb2a Mon Sep 17 00:00:00 2001 From: Peter Oberparleiter Date: Mon, 20 Sep 2021 11:26:07 +0200 Subject: [PATCH] scripts: Add tool for parsing sclp s390dbf logs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Add new tool named 'sclpdbf'. This script displays the contents of s390dbf sclp debug logs in human-readable format. Signed-off-by: Peter Oberparleiter Reviewed-by: Jan Höppner Signed-off-by: Jan Höppner --- README.md | 3 + scripts/Makefile | 3 +- scripts/sclpdbf | 1172 ++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 1177 insertions(+), 1 deletion(-) create mode 100755 scripts/sclpdbf diff --git a/README.md b/README.md index bf24f2b1..085f44ed 100644 --- a/README.md +++ b/README.md @@ -109,6 +109,9 @@ Package contents feature. Those traces are filtered with the zfcpdbf script, i.e. merge several traces, make it more readable etc. + * sclpdbf: + Display debug data for the sclp kernel component. + * scsi_logging_level: Create, get or set the logging level for the SCSI logging facility. diff --git a/scripts/Makefile b/scripts/Makefile index 1a33e319..7ce44e8f 100644 --- a/scripts/Makefile +++ b/scripts/Makefile @@ -1,6 +1,7 @@ include ../common.mak -SCRIPTS = dbginfo.sh zfcpdbf zipl-switch-to-blscfg scsi_logging_level +SCRIPTS = dbginfo.sh zfcpdbf zipl-switch-to-blscfg scsi_logging_level +SCRIPTS += sclpdbf MAN_PAGES = dbginfo.sh.1 zfcpdbf.1 zipl-switch-to-blscfg.1 all: diff --git a/scripts/sclpdbf b/scripts/sclpdbf new file mode 100755 index 00000000..e3a1e8ad --- /dev/null +++ b/scripts/sclpdbf @@ -0,0 +1,1172 @@ +#!/bin/bash +# +# sclpdbf - Tool to display sclp kernel traces +# +# Copyright IBM Corp. 2021 +# +# Usage: sclpdbf [TRACEFILE] [OPTIONS] +# +# Display the contents of the s390dbf kernel trace area for the sclp component +# in a human readable format. +# +# TRACEFILE may specify the name of a file containing the trace data in +# hex_ascii view format. If no TRACEFILE is specified, trace data of the +# currently running kernel is read from its default location at: +# +# /sys/kernel/debug/s390dbf/sclp/hex_ascii (default source) +# /sys/kernel/debug/s390dbf/sclp_err/hex_ascii (if -e is specified) +# +# OPTIONS +# -h, --help Print this help, then exit +# --version Print version information, then exit +# -v, --verbose Display verbose trace output +# -e, --errlog Display sclp error log instead of normal log +# -r, --raw Display log in raw format +# -s, --symtab SYMFILE Use symbol table in SYMFILE (default /proc/kallsyms) +# -S, --no-symtab Do not resolve kernel addresses to symbol names +# -f, --flush Flush current trace buffers +# -l, --level LEVEL Set tracing level to LEVEL (-1=off, 0 to 6) +# -p, --pages PAGES Set trace area size to PAGES +# -P, --no-pager Do not pipe trace output into pager + +TOOLPATH="$(readlink -f "${BASH_SOURCE[0]}")" +TOOLNAME="${0##*/}" + +DEBUGFS="/sys/kernel/debug" + +# Enable color usage and pager when writing to terminal +if [[ -t 1 ]] ; then + BOLD="\033[1m" + RED="\033[7;31m" + GREEN="\033[1;32m" + BLUE="\033[1;34m" + YELLOW="\033[33m" + RESET="\033[0m" + + PAGER="less -r" +else + PAGER="cat" +fi + +# List of known trace entry IDs +declare -A IDS=( + ["SRV1"]="handle_SRV1" + ["SRV2"]="handle_SRV2" + ["INT"]="handle_INT" + ["UNEX"]="handle_UNEX" + ["RQAD"]="handle_RQAD" + ["RQOK"]="handle_RQOK" + ["RQAB"]="handle_RQAB" + ["RQTM"]="handle_RQTM" + ["EVNT"]="handle_EVNT" + ["STCG"]="handle_STCG" + ["REG"]="handle_REG" + ["UREG"]="handle_UREG" + ["TMO"]="handle_TMO" + ["SYN1"]="handle_SYN1" + ["SYN2"]="handle_SYN2" +) + +# Symbolic names for SCLP request status +declare -a REQSTATUS=( + "FILLED" + "QUEUED" + "RUNNING" + "DONE" + "${RED}FAILED${RESET}" + "${RED}QUEUED_TIMEOUT${RESET}" +) + +# Symbolic names for SCLP command words +declare -A CMDWS=( + [0x00010001]="READ_CPU_INFO" + [0x00020001]="READ_SCP_INFO" + [0x00040001]="READ_STORAGE_INFO" + [0x00120001]="READ_SCP_INFO_FORCED" + [0x00770005]="READ_EVENT_DATA" + [0x00760005]="WRITE_EVENT_DATA" + [0x00780005]="WRITE_EVENT_MASK" +) + +# Symbolic names for RC values +declare -a RC=( + [0]="OK" + [5]="${RED}EIO${RESET}" + [16]="${RED}EBUSY${RESET}" + [22]="${RED}EINVAL${RESET}" +) + +# Colors to be used for hex dump display +FIELDCOLS=( + [0]="" + [1]="$BLUE" + [2]="$GREEN" +) + +# Color index for hex bytes in SCCB hex dump display +SCCBFIELDS="1 1 2 2 2 2 1 1" + +# Color index for hex bytes in event buffer hex dump display +EVNTFIELDS="1 1 2 1" + +# ASCII -> printable ASCII mapping table +ASCII='................................ !"#$%&'\''()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\]^_`abcdefghijklmnopqrstuvwxyz{|}~.................................................................................................................................' + +# EBCDIC 500 -> printable ASCII mapping table +EBCDIC='................................................................ .........[.<(+!&.........]$*);^-/.........,%_>?........p`:#@'\''=".abcdefghi.......jklmnopqr.......~stuvwxyz.................|....{ABCDEFGHI......}JKLMNOPQR......\.STUVWXYZ......0123456789......' + + +function print_help() { + local line started=0 + + while read -r line ; do + [[ $started -eq 0 && $line =~ Usage: ]] && started=1 + [[ $started -eq 1 && $line =~ ^$ ]] && break + [[ $started -eq 1 ]] && echo "${line:2}" + done < "$TOOLPATH" +} + +function print_version() { + local line + + echo "${TOOLNAME}: version %S390_TOOLS_VERSION%" + while read -r line ; do + [[ ! $line =~ Copyright ]] && continue + echo "${line:2}" + break + done < "$TOOLPATH" +} + +# +# die MSG +# +# Terminate with the specified error message and a non-zero exit code. +# +function die() { + local msg="$*" + + echo "Error: $msg" >&2 + exit 1 +} + +# +# indent NUM +# +# Indent all data read from stdin by NUM spaces. +# +function indent() { + local num=$1 spaces + + printf -v spaces "%*s" "$num" "" + sed -e "s/^/$spaces/g" +} + +# +# repeat STR NUM +# +# Print STR for NUM times. +# +function repeat() { + local str="$1" num="$2" + + eval "printf '$str%.0s' {1..$num}" +} + +# Trace file may be wrapped (4 5 6 1 2 3) - ensure ascending timestamp order +function sort_file() { + local filename="$1" + local before=() after=() area t data t_start line + + { + read -r area t_start data + after+=("$area $t_start $data") + + while read -r area t data ; do + # Look for wrap in time sequence + if [[ "$t" < "$t_start" ]] ; then + before+=("$area $t $data") + break + fi + after+=("$area $t $data") + done + + while read -r area t data ; do + before+=("$area $t $data") + done + } <"$filename" + + if [[ ${#before[@]} -gt 0 ]] ; then + printf "%s\n" "${before[@]}" + fi + + if [[ -n "$t_start" ]] ; then + printf "%s\n" "${after[@]}" + fi +} + +function check_tracefile() { + local file="$1" area ts level ex cpu caller data + + if [[ ! -e "$file" ]] ; then + die "Could not find trace data file $file" + fi + + if [[ ! -r "$file" ]] ; then + die "Missing access permissions for $file" + fi + + read -r area ts level ex cpu caller data <"$file" + + if [[ -z "$area" ]] ; then + echo "No traces found in $file" + exit 0 + fi + + if [[ -z "$ts" ]] || [[ -z "$level" ]] || [[ -z "$ex" ]] || + [[ -z "$cpu" ]] || [[ -z "$caller" ]] || [[ -z "$data" ]] ; then + die "Unrecognized trace data format in $file" + fi +} + +# +# print_ascii HEX +# +# Convert ASCII bytes in hexadecimal notation to printable ASCII. +# +function print_ascii() { + local hex="$1" asc + + printf -v asc '${ASCII:0x%s:1}' $hex + eval echo -n "$asc" +} + +# +# print_ebcdic HEX +# +# Convert EBCDIC bytes in hexadecimal notation to printable ASCII. +# +function print_ebcdic() { + local hex="$1" ebc + + printf -v ebc '${EBCDIC:0x%s:1}' $hex + eval echo -n "$ebc" +} + +# +# hex_to_num HEX START LEN CONV VAR +# +# Convert hex bytes in HEX starting at position START with length LEN to +# an integer. The result will be stored in VAR as hexadecimal number if CONV +# is 0, decimal if CONV is 1. +# +function hex_to_num() { + local _hex="$1" _start="$2" _len="$3" _conv="$4" _var="$5" _value _fmt + + # Remove spaces + _hex="${_hex// /}" + + # Extract relevant hex digits as decimal number + (( _start*=2 )) + (( _len*=2 )) + _value="0x${_hex:$_start:$_len}" + (( _value=_value )) + + # Store as requested output format + if [[ "$_conv" -eq 1 ]] ; then + _fmt="%d" + else + _fmt="0x%x" + fi + + printf -v "$_var" "$_fmt" "$_value" +} + +# +# is_id TAG +# +# Return 0 if TAG is a known trace tag, non-zero otherwise. +# +function is_id() { + local tag="$1" + + [[ -z "$tag" ]] && return 1 + [[ "$tag" =~ [^A-Z0-9] ]] && return 1 + [[ -n "${IDS[$tag]}" ]] +} + +# +# reqstatus NUM +# +# Convert the specified SCLP request status to a named representation. +# +function reqstatus() { + local num="$1" _var="$2" txt + + [[ -n "$_var" ]] && _var="-v $_var" + + txt="${REQSTATUS[$num]}" + + eval "printf $_var '${txt:-Unknown} ($num)'" +} + +# +# cmdwname CMDW +# +# Convert the specified SCLP command word to a symbolic name. +# +function cmdwname() { + local _cmdw="$1" _var="$2" c + + [[ -n "$_var" ]] && _var="-v $_var" + printf -v c "0x%08x" $(( _cmdw )) + + if [[ -n "${CMDWS[$c]}" ]] ; then + if [[ $OPT_VERBOSE -eq 1 ]] ; then + _cmdw="${CMDWS[$c]} ($_cmdw)" + else + _cmdw="${CMDWS[$c]}" + fi + fi + + eval "printf $_var \"$_cmdw\"" +} + +# +# rcname RC +# +# Convert the specified return code to a symbolic name. +# +function rcname() { + local _rc="$1" _var="$2" + + if [[ -n "${RC[$_rc]}" ]] ; then + if [[ $OPT_VERBOSE -eq 1 ]] ; then + _rc="${RC[$_rc]} ($_rc)" + else + _rc="${RC[$_rc]}" + fi + fi + + printf -v "$_var" "$_rc" +} + +# +# respcol RESP +# +# Add color to the specified SCCB response code +# +function respcol() { + local _resp="$1" _var="$2" _c + + _c=$(( _resp&0xff )) + if [[ $_c -ne 0x10 ]] && [[ $_c -ne 0x20 ]] && [[ $_c -ne 0 ]] ; then + _resp="$RED$_resp$RESET" + fi + + printf -v "$_var" "$_resp" +} + +# +# lencol LEN +# +# Add color to the specified SCCB length +# +function lencol() { + local _len="$1" _var="$2" + + if [[ $_len -lt 8 ]] ; then + _len="$RED$_len$RESET" + fi + + printf -v "$_var" "$_len" +} + +# +# sccbcol SCCB +# +# Add color to the specified SCCB address +# +function sccbcol() { + local _sccb="$1" _var="$2" + + if [[ $(( _sccb&0x7 )) -ne 0 ]] ; then + _sccb="$RED$_sccb$RESET" + fi + + printf -v "$_var" "$_sccb" +} + +# +# bitlist NUM +# +# Print list of bit numbers set in the 64 bit word specified by NUM. +# +function bitlist() { + local num="$1" _var="$2" list="" i c="" w=64 + + i=1 + while [[ $i -lt $w ]] ; do + if [[ $(( num&1<<(w-i) )) -ne 0 ]] ; then + list="$list$c$i" + c=',' + fi + (( i++ )) + done + + [[ -z "$list" ]] && list="-" + + eval "$_var='$list'" +} + + +function read_symtab() { + local filename="$1" symtab=() i + + echo "Reading symbol table from $OPT_SYMTAB" + readarray symtab <"$filename" + + for i in "${symtab[@]}" ; do + set -- $i + (( i=0x$1 )) + SYMS[$i]="$3" + done + + echo "Found ${#SYMS[@]} symbols" +} + +# +# get_sym ADDR +# +# Convert the specified kernel address to a symbolic name. +# +function get_sym() { + local _addr="$1" _var="$2" from to i + + [[ -n "$_var" ]] && _var="-v $_var" + + _addr=0x${_addr#0x} + + if [[ $OPT_NOSYM -eq 1 ]] ; then + eval printf $_var "0x%x" $_addr + return + fi + + from=$_addr + (( to=from-0x10000 )) + [[ $to -lt 1 ]] && to=1 + + i=$from + while [[ $i -ge $to ]] ; do + if [[ -z "${SYMS[$i]}" ]] ; then + (( i-- )) + continue + fi + + if [[ $_addr -eq $i ]] ; then + eval printf $_var "${SYMS[$i]}" + else + eval printf $_var "%s+0x%x" "${SYMS[$i]}" $(( _addr-$i )) + fi + return + done + + eval printf $_var "0x%x" $_addr +} + +# Print hex data in alternating colors to help visual grouping +function hex_color() { + local hex="$1" delim="$2" fields=($3) i byte currcol lastcol + + lastcol=0 + i=0 + for byte in $hex ; do + currcol="${fields[$i]}" + [[ -z "$currcol" ]] && currcol=0 + + if [[ "$currcol" -ne "$lastcol" ]] ; then + echo -en "$RESET${FIELDCOLS[$currcol]}" + fi + echo -n "$byte$delim" + + lastcol="$currcol" + (( i++ )) + done + echo -ne "$RESET" +} + +function handle_buffer() { + local name="$1" fields="$2" hex=("${@:3}") offset=0 v size + + [[ ${#hex[@]} -eq 0 ]] && return + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + for v in "${hex[@]}" ; do + hex_color "$v" "" "$fields" + echo -n " " + print_ascii "$v" + echo -n " " + print_ebcdic "$v" + echo + fields="" + done + return + fi + + [[ -n "$name" ]] && printf "\n%s:\n" "$name" + hex_to_num "${hex[0]}" 0 2 1 size + + printf "$BOLD%-4s %-48s %-16s %-16s$RESET\n" "OFF" "HEX" "ASCII" "EBCDIC" + + for v in "${hex[@]}" ; do + printf "%04x: " "$offset" + hex_color "$v" " " "$fields" + echo -n " " + print_ascii "$v" + echo -n " " + print_ebcdic "$v" + echo + fields="" + + (( offset+=16 )) + done + + if [[ -n "$size" ]] && [[ $offset -lt $size ]] ; then + (( size-=offset )) + echo "Truncated $size bytes" + fi +} + +function short() { + set -- $* + echo -en "$BOLD$1$RESET" + printf " %s" "${@:2}" +} + +function long() { + echo -e "$BOLD$*$RESET" +} + +function handle_SRV1() { + local hex1="$1" hex2=("${@:2}") cmdw sccb len response + + hex_to_num "$hex1" 4 4 0 cmdw + cmdwname "$cmdw" cmdw + hex_to_num "$hex1" 8 8 0 sccb + sccbcol "$sccb" sccb + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "SERVC cmd=$cmdw sccb=$sccb" + echo + handle_buffer "SCCB contents" "$SCCBFIELDS" "${hex2[@]}" | + indent 4 + return + fi + + hex_to_num "${hex2[0]}" 0 2 1 len + lencol "$len" len + hex_to_num "${hex2[0]}" 6 2 0 response + respcol "$response" response + + long "Service call about to be issued" + echo " SCLP command ....: $cmdw" + echo -e " SCCB address ....: $sccb" + echo -e " SCCB length .....: $len" + echo -e " SCCB response ...: $response" + + handle_buffer "SCCB contents" "$SCCBFIELDS" "${hex2[@]}" | indent 2 +} + +function handle_SRV2() { + local hex="$1" rc seq + + hex_to_num "$hex" 4 4 1 rc + rcname "$rc" rc + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "SERVC rc=$rc" + echo + return + fi + + hex_to_num "$hex" 8 8 1 seq + + long "Service call completed" + echo -e " Result code ...........: $rc" + echo " SRVC sequence number ..: $seq" +} + +function handle_INT() { + local hex1="$1" hex2=("${@:2}") parm32 pending sccb cmdw len response + + hex_to_num "$hex1" 4 4 1 parm32 + (( pending=parm32 & 0x3 )) + (( sccb=parm32 & 0xfffffff8 )) + printf -v sccb "0x%x" "$sccb" + sccbcol "$sccb" sccb + hex_to_num "$hex1" 12 4 0 cmdw + cmdwname "$cmdw" cmdw + hex_to_num "${hex2[0]}" 6 2 0 response + respcol "$response" response + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "INT pend=$pending sccb=$sccb resp=$response" + echo + handle_buffer "SCCB contents" "$SCCBFIELDS" "${hex2[@]}" | + indent 4 + return + fi + + hex_to_num "${hex2[0]}" 0 2 1 len + lencol "$len" len + + long "Interrupt received" + echo " Event pending indicator ..: $pending" + echo " Active command ...........: $cmdw" + echo -e " SCCB address .............: $sccb" + echo -e " SCCB length ..............: $len" + echo -e " SCCB response ............: $response" + + handle_buffer "SCCB contents" "$SCCBFIELDS" "${hex2[@]}" | indent 2 +} + +function handle_UNEX() { + local hex="$1" sccb + + hex_to_num "$hex" 4 4 0 sccb + sccbcol "$sccb" sccb + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "${RESET}${RED}UNEXPECTED${RESET} sccb=$sccb" + echo + return + fi + + long "${RESET}${RED}Unexpected SCCB completion${RESET}" + echo " SCCB address ...: $sccb" +} + +function handle_req() { + local hex="$1" + local sccb status response timeout start_count + + hex_to_num "$hex" 4 4 0 sccb + sccbcol "$sccb" sccb + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + echo -n "sccb=$sccb" + return + fi + + hex_to_num "$hex" 8 2 1 status + reqstatus "$status" status + hex_to_num "$hex" 10 2 0 response + respcol "$response" response + hex_to_num "$hex" 12 2 1 timeout + hex_to_num "$hex" 14 2 1 start_count + + echo -e "Request status ........: $status" + echo "Request timeout .......: $timeout" + echo "Request start count ...: $start_count" + echo -e "SCCB address ..........: $sccb" + echo -e "SCCB response .........: $response" +} + +function handle_RQAD() { + local hex="$1" sccb caller + + hex_to_num "$hex" 4 4 0 sccb + sccbcol "$sccb" sccb + hex_to_num "$hex" 8 8 0 caller + get_sym "$caller" caller + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "RQADD caller=$caller" + echo + return + fi + + long "Request is added" + echo -e " SCCB address...........: $sccb" + echo " Caller ................: $caller" +} + +function handle_RQOK() { + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "RQOK " + handle_req "$1" + echo + return + fi + + long "Request completed successfully" + + handle_req "$1" | indent 2 +} + +function handle_RQAB() { + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "${RESET}${RED}RQABORT${RESET} " + handle_req "$1" + echo + return + fi + + long "${RESET}${RED}Request was aborted${RESET}" + + handle_req "$1" | indent 2 +} + +function handle_RQTM() { + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "${RESET}${RED}RQTIMEOUT${RESET} " + handle_req "$1" + echo + return + fi + + long "${RESET}${RED}Request timed out${RESET}" + + handle_req "$1" | indent 2 +} + +function handle_EVNT() { + local hex="$1" hex2=("${@:2}") cb len type + + hex_to_num "$hex" 8 8 0 cb + get_sym "$cb" cb + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "EVENT callback=$cb" + echo + handle_buffer "Event buffer contents" "$EVNTFIELDS" \ + "${hex2[@]}" | indent 4 + return + fi + + hex_to_num "${hex2[0]}" 0 2 1 len + hex_to_num "${hex2[0]}" 2 1 1 type + + long "Dispatching event buffer" + echo " Receiving callback ......: $cb" + echo " Event buffer length .....: $len" + echo " Event type ..............: $type" + + handle_buffer "Event buffer contents" "$EVNTFIELDS" "${hex2[@]}" | + indent 2 +} + +function handle_STCG() { + local hex="$1" cb + + hex_to_num "$hex" 8 8 0 cb + get_sym $cb cb + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "STATECHANGE callback=$cb" + echo + return + fi + + long "Dispatching state change" + echo " Receiving callback ...: $cb" +} + +function handle_register() { + local hex="$1" receive send + + hex_to_num "$hex" 0 8 0 receive + bitlist "$receive" receive + hex_to_num "$hex" 8 8 0 send + bitlist "$send" send + + echo "Receive mask ...: $receive" + echo "Send mask ......: $send" +} + +function handle_REG() { + local hex1="$1" hex2="$2" retip + + hex_to_num "$hex1" 8 8 0 retip + get_sym "$retip" retip + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "LISTENERADD caller=$retip" + echo + return + fi + + long "Register event listener" + echo " Caller .........: $retip" + + handle_register "$hex2" | indent 2 +} + +function handle_UREG() { + local hex1="$1" hex2="$2" retip + + hex_to_num "$hex1" 8 8 0 retip + get_sym "$retip" retip + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "LISTENERDEL caller=$retip" + echo + return + fi + + long "Unregister event listener" + echo " Caller .........: $retip" + + handle_register "$hex2" | indent 2 +} + +function handle_TMO() { + local hex="$1" force + + hex_to_num "$hex" 4 4 1 force + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "${RESET}${RED}TIMEOUT${RESET} force=$force" + echo + return + fi + + long "${RESET}${RED}Timeout occurred${RESET}" + echo " Force restart ..: $force" +} + +function handle_SYN1() { + local hex="$1" state seq c cr + + hex_to_num "$hex" 4 4 1 state + hex_to_num "$hex" 8 8 1 seq + + if [[ $state -eq 0 ]] ; then + # Sync wait despite running state=idle + c="${RESET}${RED}" + cr="${RESET}" + fi + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "${c}SYNCWAIT_START${cr}" + echo + return + fi + + long "Synchronous wait start" + echo -e " SCLP running state ...... ...: ${c}$state${cr}" + echo " Sync wait sequence number ...: $seq" +} + +function handle_SYN2() { + local hex="$1" state c cr + + hex_to_num "$hex" 4 4 1 state + hex_to_num "$hex" 8 8 1 seq + + if [[ $state -eq 1 ]] ; then + # Sync wait exit despite running state=running + c="${RESET}${RED}" + cr="${RESET}" + fi + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "${c}SYNCWAIT_END${cr}" + echo + return + fi + + long "Synchronous wait end" + echo -e " SCLP running state ...... ...: ${c}$state${cr}" + echo " Sync wait sequence number ...: $seq" +} + +# +# handle_unknown LINES +# +# Handle unrecognized trace data. +# +function handle_unknown() { + local hex=("$@") + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + short "INCOMPLETE_ENTRY" + echo + handle_buffer "" "" "${hex[@]}" | indent 4 + else + long "Incomplete trace entry" + handle_buffer "Raw data" "" "${hex[@]}" | indent 2 + fi +} + +# +# print_ts +# +# Convert timestamp to date format, assuming local timezone. +# +function print_ts() { + local ts="$1" s ns + + s=${ts%:*} + ns=${ts#*:} + echo -n "$(date '+%Y-%m-%d %H:%M:%S' -d @"$s").$ns" +} + +# +# print_ts_diff NOW LAST +# +# Print delta between timestamps NOW and LAST. +# +function print_ts_diff() { + local now="$1" last="$2" _var="$3" + local now_s now_us last_s last_us dist_s dist_us + + [[ -z "$last" ]] && return + [[ -n "$_var" ]] && _var="-v $_var" + + now_s=${now%:*} + now_us=${now#*:} + last_s=${last%:*} + last_us=${last#*:} + + now_s=$(( 10#$now_s )) + now_us=$(( 10#$now_us )) + last_s=$(( 10#$last_s )) + last_us=$(( 10#$last_us )) + + (( dist_us=now_us-last_us )) + (( dist_s=now_s-last_s )) + if [[ $dist_us -lt 0 ]] ; then + (( dist_us+=1000000 )) + (( dist_s--)) + fi + + if [[ $dist_s -gt 3599 ]] ; then + eval printf $_var "+%dh%dm" "$((dist_s/3600 ))" "$(( (dist_s%3600)/60 ))" + elif [[ $dist_s -gt 59 ]] ; then + eval printf $_var "+%dm%ds" "$((dist_s/60 ))" "$(( dist_s%60 ))" + elif [[ $dist_s -gt 0 ]] ; then + eval printf $_var "+%d.%ds" $dist_s "$(( dist_us/100000 ))" + elif [[ $dist_us -gt 1000 ]] ; then + eval printf $_var "+%dms" "$(( dist_us/1000 ))" + else + eval printf $_var "+%dus" $dist_us + fi +} + +function header() { + local ts="$1" cpu="$2" caller="$3" ts2 tsdiff="" + + cpu=$(( 10#$cpu )) + + if [[ $OPT_VERBOSE -eq 0 ]] ; then + echo -ne "$YELLOW" + ts2=${ts//:/.} + print_ts_diff "$ts" "$LAST_TS" tsdiff + printf "%03d %-18s (%7s)" "$cpu" "$ts2" "$tsdiff" + echo -ne ": $RESET" + else + echo -ne "${YELLOW}CPU $cpu at " + print_ts "$ts" + if [[ -n "$LAST_TS" ]] ; then + printf " (" + print_ts_diff "$ts" "$LAST_TS" + printf ")" + fi + get_sym "$caller" caller + echo -e " at $caller$RESET" + echo -ne "$YELLOW" + repeat "=" 78 + echo -e "$RESET" + fi + LAST_TS="$ts" +} + +function handle_lines() { + local id="$1" fn + + shift + [[ $# -eq 0 ]] && return + + if [[ -z "$id" ]] ; then + fn="handle_unknown" + else + fn="${IDS[$id]}" + fi + + "$fn" "$@" + + [[ $OPT_VERBOSE -eq 1 ]] && echo +} + +# Read trace file in s390dbf hex_ascii format and convert to readable format +function process() { + local area ts level ex cpu caller data hex ascii id + local active_id lines=() once=0 + + while read -r area ts level ex cpu caller data ; do + hex="${data%% |*}" + ascii="${data#*| }" + + id=${ascii:0:4} + id=${id%%.*} + + if [[ "$once" != 1 ]] ; then + echo -n " Start time ...: " + print_ts "$ts" + printf "\n\n" + if [[ $OPT_VERBOSE -eq 0 ]] ; then + echo -en "$BOLD" + printf "%3s %18s (%7s): %s" \ + "CPU" "TIME" "DELTA" "TRACE ENTRY" + echo -e "$RESET" + fi + once=1 + fi + + if ! is_id "$id" ; then + if [[ -z "$active_id" ]] && + [[ "${#lines[@]}" -eq 0 ]]; then + header "$ts" "$cpu" "$caller" + fi + + # Add to data for active ID + lines+=("$hex") + + continue + fi + + # Handle previous data + handle_lines "$active_id" "${lines[@]}" + + active_id="$id" + header "$ts" "$cpu" "$caller" + lines=("$hex") + done + + # Handle final data + handle_lines "$active_id" "${lines[@]}" +} + + +# +# Main +# + +declare -a SYMS +declare TRACEFILE TRACEBASE TRACELEVEL TRACEPAGES LAST_TS SHORTOPTS LONGOPTS +declare OPT_VERBOSE OPT_SYMTAB OPT_NOSYM OPT_RAW OPTS + +TRACEBASE="$DEBUGFS/s390dbf/sclp" +TRACENAME="default log" +SHORTOPTS="vhs:fl:SePp:r" +LONGOPTS="help,version,verbose,symtab:,no-symtab,raw,flush,level:,pages:,no-pager,errlog" + +# Parse parameters +OPTS=$(getopt -o "$SHORTOPTS" -l "$LONGOPTS" -n "Usage error" -- "$@") || exit 1 + +eval set -- $OPTS + +OPT_VERBOSE=0 +OPT_SYMTAB="/proc/kallsyms" +OPT_NOSYM=0 +OPT_RAW=0 +OPT_NOTRACE=0 + +while [[ "$1" != "--" ]] ; do + case "$1" in + -h|--help) + print_help + exit 0 + ;; + --version) + print_version + exit 0 + ;; + -v|--verbose) + OPT_VERBOSE=1 + ;; + -s|--symtab) + [[ ! -e "$2" ]] && die "Cannot access symbol table file $2" + OPT_SYMTAB="$2" + shift + ;; + -S|--no-symtab) + OPT_NOSYM=1 + ;; + -r|--raw) + OPT_RAW=1 + ;; + -f|--flush) + echo "Flushing trace buffers for $TRACENAME" + if ! echo - > "$TRACEBASE/flush" ; then + die "Cannot flush trace buffer" + fi + OPT_NOTRACE=1 + ;; + -l|--level) + shift + echo "Setting trace level for $TRACENAME to $1" + if ! echo "$1" > "$TRACEBASE/level" ; then + die "Cannot set trace level" + fi + OPT_NOTRACE=1 + ;; + -p|--pages) + shift + echo "Setting trace size for $TRACENAME to $1 pages ($(($1*4))kb)" + if ! echo "$1" > "$TRACEBASE/pages" ; then + die "Cannot set trace size" + fi + OPT_NOTRACE=1 + ;; + -P|--no-pager) + PAGER="cat" + ;; + -e|--errlog) + TRACEBASE="$DEBUGFS/s390dbf/sclp_err" + TRACENAME="error log" + echo "Switching to $TRACENAME" + ;; + esac + shift +done +shift + +if [[ $OPT_NOTRACE -eq 1 ]] ; then + echo "Done" + exit 0 +fi + +if [[ $# -gt 0 ]] ; then + TRACEFILE="$(readlink -f "$1")" + [[ ! -e "$TRACEFILE" ]] && die "Cannot access $TRACEFILE: File not found" +else + TRACEFILE="$TRACEBASE/hex_ascii" + [[ ! -d "$DEBUGFS" ]] && die "Cannot access $DEBUGFS: Directory not found" + [[ ! -x "$DEBUGFS" ]] && die "Cannot read $DEBUGFS: Permission denied" + [[ ! -d "$TRACEBASE" ]] && die "Kernel is missing required support" + read TRACELEVEL <"$TRACEBASE/level" + read TRACEPAGES <"$TRACEBASE/pages" +fi + +check_tracefile "$TRACEFILE" + +if [[ $OPT_RAW -eq 1 ]] ; then + sort_file "$TRACEFILE" | $PAGER + exit 0 +fi + +if [[ $OPT_NOSYM -eq 0 ]] ; then + read_symtab "$OPT_SYMTAB" +fi + +{ + echo "Trace data:" + echo " Source .......: $TRACEFILE" + [[ -n "$TRACELEVEL" ]] && echo " Level ........: $TRACELEVEL" + [[ -n "$TRACEPAGES" ]] && + echo " Size .........: $TRACEPAGES pages ($((4*TRACEPAGES))kb)" + process < <(sort_file "$TRACEFILE") +} | $PAGER + +exit 0