Re: [hatari-devel] symbols not always loaded when entering debugger ?

[ Thread Index | Date Index | More lists.tuxfamily.org/hatari-devel Archives ]


Hi,

On 11/15/2017 06:33 PM, Matthias Arndt wrote:
Am Wed, 15 Nov 2017 11:53:06 +0100
schrieb Nicolas Pomarède <npomarede@xxxxxxxxxxxx>:

[Lots of valid statements]

I fully agree to the statements given. If I have a binary with symbols
and I get a crash (bombs) that throuw me into the debugger, I as a
developer expect to be able to debug into my programs with symbols.

I would like to be able backtrack from exception frame to the location
where the problem occured. Only if it leads me into function x() I am
already happy.

If you enable profiling and your debug symbols are good,
you get backtrace when you drop to debugger.  I used that
to get automatically backtraces to all places in BadMood
(Doom I/II) that process files during game play.

Profiler tracks all subroutine call instructions and their
returns, for addresses that have symbols for them.  Back
traces are just a side benefit from that.

I've attached my script for doing all kinds of profiling
for BadMood, in case you're interested on an example.


If you want backtraces without profiling support...

Do you have example code that can reliably walk the stack and
produce correct backtrace addresses?  On all 680x0 variants
(as they have different stack frames)?


	- Eero
#!/bin/bash
#
# Use Hatari profiler to get BadMood startup and several
# frame rendering related profile data, both for DSP & CPU,
# and post-process them.
#
# Requires:
# - TOS v4, BadMood program and WAD for it in $dir
# - Processed BadMood CPU & DSP symbols in $dir
# - Hatari v1.7, preferably latest Hatari from Mercurial
#   as some options don't work with v1.7
#
# Paths for these can be given in "profile.conf",
# see below.
#
# Profile data is saved to current directory, data
# post-processing results into $datadir subdirectory.
#
# TODO:
# - Option for specifying profile configuration file and
#   data output directory.
# - Wrapper script that gives specified config files to
#   this script and compares the profiling results against
#   given baseline profile.

# script debugging
#set -x

# ------ User specific setup ------

if [ -f profile.conf ]; then
	# shell script with same stuff as inside else part
	. profile.conf
else
	# directory where BM binary, symbols and TOS image are
	dir=../../autoprofile
	# old UAE CPU core
	fpu=""  # "--fpu-type 68882" for WinUAE
	hatari="hatari"
	# profile data postprocessor
	profiler="hatari_profile.py"
	# loop profile data postprocessor
	looper="hatari_spinloop.py"
	# directory for wad files
	waddir="../../autoprofile"
	# WAD file path/name
	wadfile="$waddir/doom1.wad"
	# BM command line options for above WAD
	cmdline=""
fi

# ------- Script argument handling ---------

worst_ini="profile-worst.ini"

usage ()
{
	cat << EOF
usage: ${0##*/} [options]

Options:
	-p	just re-post-process profile data

	-g	GEMDOS call tracing (from the beginning)
	-l	loop profiling for the game play
	-s	include resource load names & stack traces to hatari log
	-w	setup (interactive) worst frame profiling

By default profiling method is fully automated, it will start at
first shot fired, and end when player dies, at which point Hatari is
quit.

With "-w" option, user needs to start profiling at suitable moment
from the Hatari debugger with:
	parse $worst_ini

"-w" option requires Hatari development version, newer than v1.7.

Default profiling is intended for BadMood builds where timedemos work
and worst frame (-w) profiling for BadMood builds that have more
aggressive / behavior changing engine optimizations enabled i.e. are
intended for normal play.

Because of this, script tries to run doom_t1.ttp for automated
profiling, and doom_t3.ttp for worst frame profiling. "t3" means
TIMEBASE_CONTROL level 3 (BadMood makefile option).

ERROR: $1
EOF
	exit 1
}

no_run=0
do_loops=0
do_stack=0
do_worst=0
do_gemdos=0
doomtype="t4"
for arg in $*; do
	if [ $arg = "-w" ]; then
		do_worst=1
		doomtype="t4"
	elif [ $arg = "-s" ]; then
		do_stack=1
	elif [ $arg = "-p" ]; then
		no_run=1
	elif [ $arg = "-g" ]; then
		do_gemdos=1
	elif [ $arg = "-l" ]; then
		do_loops=1
	else
		usage "unknown option '$1'"
	fi
done

# --------- BadMood setup -----------

# BM binary to profile
bm="$dir/doom_${doomtype}.ttp"

# options file for BM
optfile="$dir/doom.def"

# BadMood CPU & DSP symbol information for Hatari
cpusym="$dir/doom_${doomtype}.sym"
dspsym="$dir/core.sym"

# name in BM dir to which given WAD file will be linked to
wadname="${wadfile##*/}"

# level play until this is taken to be level start,
# rest until death is normal play (where no loads
# should happen
#skipto="_P_LineAttack"
#skipto="_BM_A_Mux3x2"
skipto="_A_Chase"

# non-function labels that shouldn't be shown in the list
# because they're just confusing, and a comma separated list
# of BM interrupt entry point symbols
# (calls to them should be ignored in graphs & callcounts)
ignores="--ignore ascii_err_pwaddir --ignore-to _audio_mux_asm,framecounter,new_vbi,stabilizer_b,ikbd_handler,get_dx,get_dy"

# symbols for frame rendering start and end
render_start="r_begin"
render_end="r_end"

# check that files exist
if [ \! -f "$bm" ]; then
	echo "ERROR: BM binary ($bm) missing!"
	exit 1
fi
if [ \! -f "$cpusym" ]; then
	echo "ERROR: BM CPU symbols ($cpusym) missing!"
	exit 1
fi
if [ \! -f "$dspsym" ]; then
	echo "ERROR: BM DSP symbols ($dspsym) missing!"
	exit 1
fi
if [ \! -e "$wadfile" ]; then
	echo "ERROR: configured WAD for BM ($wadfile) missing!"
	exit 1
fi

ok="no"
cd $dir
# check all WAD file names recognized by Doom
for wad in doom2f.wad doom2.wad plutonia.wad tnt.wad doomu.wad doom.wad doom1.wad; do
	if [ -h "$wad" ]; then
		echo "Removing symlink to '$wad'"
		rm "$wad"
	fi
	if [ "$wad" = "$wadname" ]; then
		ok="yes"
	elif [ -e "$wad" ]; then
		echo "ERROR: remove '$dir/$wad', it may override symlink done by this script!"
		exit 1
	fi
done
if [ "$ok" = "no" ]; then
	echo "ERROR: given '$wadname' WAD file name isn't one recognized by BM!"
	exit 1
fi
if [ -f "$wadname" ]; then
	echo "$wadname already exists, not changing it."
else
	echo "symlinking $wadfile -> $wadname"
	ln -s "$wadfile" "$wadname"
fi
cd -

# BM options
# (it's really annoying that it doesn't support "-iwad" option like PrBoom)
echo "$cmdline" > $optfile

echo "Using '$cmdline' options for '$wadname':"
ls -l $dir/$wadname


# --------- Hatari setup -----------

# debugging options
trace="--conout 2" # "--bios-intercept --trace xbios,gemdos"
if [ $do_gemdos -eq 1 ]; then
	trace="$trace --trace gemdos"
fi

# need real TOS v4
tos="$dir/tos404.img"

# check that everything needed exist
if [ \! -f "$tos" ]; then
	echo "ERROR: TOS v4 image ($tos) missing!"
	exit 1
fi
if [ -z $(which "$hatari") ]; then
	echo "ERROR: Hatari ($hatari) missing!"
	exit 1
fi
if [ -z $(which "$profiler") ]; then
	echo "ERROR: Hatari profiler ($profiler) missing!"
	exit 1
fi


# --------- profiler automation chaining -----------

# where to store the results
datadir=data

# generated profile file prefixes
prof_start="badmood-startup"
prof_load="badmood-level-load"
prof_init="badmood-level-start"
prof_frames="badmood-all-frames"

prof_think="badmood-worst-think"
prof_render="badmood-worst-render"

# generated loop profile file names
prof_loop="badmood-loops.txt"

prof_think_loop="badmood-worst-think-loops.txt"
prof_render_loop="badmood-worst-render-loops.txt"

if [ $do_worst -eq 0 ]; then
	prefixes="$prof_start $prof_load $prof_init $prof_frames"
	loopers="$prof_loop"
else
	prefixes="$prof_start $prof_think $prof_render"
	loopers="$prof_think_loop $prof_render_loop"
fi
if [ $do_loops -eq 0 ]; then
	loopers=""
fi

# -------- generic breakpoint handlers ----------

# show resource names for BM resource calls
echo "m a0" > profile-resource.ini

# show GEMDOS call stack & return value
# ----
cat > profile-gemdos.ini << EOF
profile stack
b pc="NextPC" :once :quiet :noinit :file profile-d0.ini
EOF
cat > profile-d0.ini << EOF
e d0
EOF
# ----

# quit Hatari
cat > profile-quit.ini << EOF
profile off
dspprofile off
quit
EOF

# -------- generic breakpoints setup --------------

# Breakpoint can be set at program startup only after TOS is up,
# catch Fopen() for *.INF file after TOS has initialized
profsetup="profile-setup.ini"
# ----
cat > $profsetup << EOF
b GemdosOpcode = 0x3D :once :trace :file profile-breakpoint.ini
EOF
# ----

# First breakpoint at program startup will do real setup
# ----
cat > profile-breakpoint.ini << EOF
b pc = text :once :trace :file profile-symbols.ini
EOF
# ----

# At program startup load CPU symbols and set breakpoint
# for when rendering starts (=initialization ends)
# ----
cat > profile-symbols.ini << EOF
symbols $cpusym text
profile on

b pc=r_begin :once :trace :file profile-startup.ini
EOF
# ----

# Save data for BM initialization, load DSP symbols
# and enable DSP profiling & history
# ----
cat > profile-startup.ini << EOF
profile save ${prof_start}-CPU.txt

dspsymbols $dspsym
dspprofile on
history on
EOF
# ----

# ---------- automated profiling ----------

# chain breakpoint for gathering data for startup until
# level start
if [ $do_worst -eq 0 ]; then
cat >> profile-startup.ini << EOF
b pc=_P_RunThinkers :once :trace :file profile-load.ini
EOF
else
# start worst frame profiling from same point as
# "all" frames profiling is started
cat >> profile-startup.ini << EOF
b pc=$skipto :once :trace :file $worst_ini
EOF
fi

# save data for level loading and set breakpoint for
# first interesting ($skipto) event
# ----
cat > profile-load.ini << EOF
profile save ${prof_load}-CPU.txt
dspprofile save ${prof_load}-DSP.txt

b pc=$skipto :once :trace :file profile-shot.ini
EOF
# ----


# start spinloop profiling and set breakpoint for
# gathering data until either:
# - player dies
# - game demo mode changes
# ----
cat > profile-shot.ini << EOF
profile save ${prof_init}-CPU.txt
dspprofile save ${prof_init}-DSP.txt

b pc=_P_DeathThink :once :trace :quiet :file profile-frames.ini
b pc=_D_AdvanceDemo :once :trace :quiet :file profile-frames.ini
b pc=_I_Quit :once :trace :quiet :file profile-frames.ini
b pc=_G_CheckDemoStatus :once :trace :quiet :file profile-frames.ini
b pc=_BM_E_PlayerDeath :once :trace :quiet :file profile-frames.ini
EOF
# ----

if [ $do_loops -eq 1 ]; then
echo "profile loops $prof_loop 0 0" >> profile-shot.ini
fi

if [ $do_stack -eq 1 ]; then
# output loaded resource names and Fread stack traces
cat >> profile-shot.ini << EOF
trace gemdos
b GemdosOpcode = 0x3F :quiet :noinit :file profile-gemdos.ini
b pc = read_resource :quiet :noinit :file profile-resource.ini
b pc = load_resource :quiet :noinit :file profile-resource.ini
EOF
fi

# Save data for collected frames, and quit
# ----
cat > profile-frames.ini << EOF
profile save ${prof_frames}-CPU.txt
dspprofile save ${prof_frames}-DSP.txt

parse profile-quit.ini
EOF
# ----

# --------- worst frame profiling ---------------

# get some data to initialize instruction counter,
# which amount should be less than in average frame
# (from previous RunThinkers breakpoint to r_begin)
cat > $worst_ini << EOF
b pc=r_begin :trace :once :quiet :file profile-worst-init.ini
EOF

# start spinloop profiling and set breakpoints for:
# - catching frames on which CpuInstr for thinking part and
#   DspInstr for render part are larger than before
# - Clearing profile & CPU instructions counter on every frame
#   thinking and rendering starts
# - Quit when player dies or demo mode changes
#
# Note: clearing breakpoints need to created after other
# breakpoints so that they get processed after them.
# Otherwise they would clear profile data you want to save,
# instead of reseting data counters for next frame.
# ----
cat > profile-worst-init.ini << EOF
b pc=r_begin && CpuInstr > CpuInstr :trace :file profile-worst-think.ini
b pc=r_end && DspInstr > DspInstr :trace :file profile-worst-render.ini

b pc=r_begin :trace :file profile-worst-clear.ini
b pc=r_end :trace :file profile-worst-clear.ini

b pc=_P_DeathThink :once :trace :quiet :file profile-quit.ini
b pc=_D_AdvanceDemo :once :trace :quiet :file profile-quit.ini
b pc=_I_Quit :once :trace :quiet :file profile-quit.ini
b pc=_G_CheckDemoStatus :once :trace :quiet :file profile-quit.ini
b pc=BM_E_PlayerDeath :once :trace :quiet :file profile-quit.ini
EOF
# ----

if [ $do_loops -eq 1 ]; then
echo "profile loops $prof_loop 0 0" >> profile-worst-init.ini
fi

if [ $do_stack -eq 1 ]; then
# output loaded resource names and Fread stack traces
cat >> profile-worst-init.ini << EOF
trace gemdos
b GemdosOpcode = 0x3F :quiet :noinit :file profile-gemdos.ini
b pc = read_resource :quiet :noinit :file profile-resource.ini
b pc = load_resource :quiet :noinit :file profile-resource.ini
EOF
fi

# just show instruction count for this frame
# (file breakpoint implicitly also clears data)
echo "e CpuInstr" > profile-worst-clear.ini

# save the worst frame for thinking and copy loop data
cat > profile-worst-think.ini << EOF
profile save ${prof_think}-CPU.txt
dspprofile save ${prof_think}-DSP.txt
EOF

# save the worst frame for rendering and copy loop data
cat > profile-worst-render.ini << EOF
profile save ${prof_render}-CPU.txt
dspprofile save ${prof_render}-DSP.txt
EOF

# put worst loop info aside
if [ $do_loops -eq 1 ]; then
echo "rename ${prof_loop} ${prof_think_loop}" >> profile-worst-think.ini
echo "rename ${prof_loop} ${prof_render_loop}" >> profile-worst-render.ini
fi


# --------- actual profiling -----------

if [ $no_run -eq 0 ]; then

	# backup old files
	for file in $loopers; do
		mv $file $file.bak
	done
	for prefix in $prefixes; do
		for core in CPU DSP; do
			file=$prefix-$core.txt
			if [ -f $file ]; then
				mv $file $file.bak
			fi
		done
	done

	# BadMood needs 14MB of RAM and works fine with fast forwarding
	hatari_start="$hatari -c hatari.conf --monitor vga --natfeats yes -s 14 $trace --parse $profsetup --fast-forward yes --machine falcon $fpu --tos $tos $bm"
	hatari_log=hatari.log
	echo "$hatari_start 2> $hatari_log"
	echo "$hatari_start 2> $hatari_log" > $hatari_log
	$hatari_start 2>> $hatari_log
fi

# remove options file
#rm $optfile

# --------- post-processing -----------

# create directory for processed data
mkdir -p $datadir

# file missing or parsing errors
errors=0

# callgraph options, and what to do for nodes below given limit
limits="--emph-limit 2.0 --limit 0.5 --compact"
compaction="--compact --no-leafs --no-intermediate" # --only-subroutines"

# run profile post-processor, save results to datadir, show summary & errors
profile_process ()
{
	_prefix=$1
	_profile=$_prefix.txt
	_errors=$datadir/$_prefix-error.txt
	_processed=$datadir/$_prefix-result.txt

	if [ "$2" = "CPU" ]; then
		# CPU symbols are TEXT relative, and interrupt ones need to be ignored
		echo "$profiler -r $cpusym -p -g $ignores $limits $compaction -st $_profile > $_processed 2> $_errors"
		$profiler -r $cpusym -p -g $ignores $limits $compaction -st $_profile > $_processed 2> $_errors
	else
		# DSP symbols are absolute
		echo "$profiler -a $dspsym -p -g $limits -st $_profile > $_processed 2> $_errors"
		$profiler -a $dspsym -p -g $limits -st $_profile > $_processed 2> $_errors
	fi
	if [ $? -ne 0 ]; then
		errors=1
	fi
	mv $_prefix-*.dot $datadir/

	# results
	cat $_processed $_errors
}

# check that we actually got profile data & process it
profiled=""
for prefix in $prefixes; do
	for core in CPU DSP; do
		file=$prefix-$core.txt
		if [ \! -f $file ]; then
			echo "Note: no $core data for '$prefix' profile."
			continue
		fi
		profiled="$profiled $file"
		profile_process $prefix-$core $core
	done
	if [ "$errors" -gt 0 ]; then
		echo "Errors detected, quitting..."
		exit 1
	fi
done

# process loop profiles
looped=""
for file in $loopers; do
	if [ -f $file ]; then
		# can take a while for large loop files...
		echo "post-processing loop file '$file'..."
		$looper $file > $datadir/$file
		cat $datadir/$file
		looped="$looped $file"
	else
		echo "Warning: loop profile '$file' missing!"
	fi
done

echo "Hatari log:"
echo "- hatari.log ($(wc -l hatari.log) lines)"

echo "Profiling data:"
for i in $looped $profiled; do
	echo "- $i"
done
echo "Earlier & new post-processing results in $datadir/:"
ls $datadir

echo "DONE!"


Mail converted by MHonArc 2.6.19+ http://listengine.tuxfamily.org/