Merge branch '2023-02-10-update-trace-feature-to-work-with-trace-cmd'

To quote the author:
Since U-Boot's tracing feature was originally written, quite a few changes
have taken place in this domain. The original text format used by tracing
is still emitted by Linux, but a new trace-cmd tool has invented a binary
format which is now used by new tools, such as kernelshark.

With recent distributions and the move to Python 3, the old pybootchart
tool does not build or run. Unfortunately there is no 1:1 replacement for
the features that were provided by pybootchart, or at least it is not
obvious. Still, it makes sense to keep with the times.

This series updates proftool to use the new binary format, adding support
for function and funcgraph tracing, so that U-Boot's trace records can be
examined by trace-cmd and kernelshark.

This series also adds support for a flamegraph, which provides a visual
way to see which functions are called a lot, as well as which ones consume
the most time.

Some minor updates to the trace implementation within U-Boot are included,
to provide a little more information and to fix a few problems.

No unit tests are provided by proftool, but a functional test ensures that
sandbox can emit traces which can be processed by proftool, then parsed by
trace-cmd and that the timing of the various formats looks consistent.

26 files changed, 2347 insertions, 229 deletions

diff --git a/.azure-pipelines.yml b/.azure-pipelines.yml
index 5673bb7..947c400 100644
--- a/.azure-pipelines.yml
+++ b/.azure-pipelines.yml
@@ -2,7 +2,7 @@ variables:
   windows_vm: windows-2019
   ubuntu_vm: ubuntu-22.04
   macos_vm: macOS-12
-  ci_runner_image: trini/u-boot-gitlab-ci-runner:jammy-20221130-11Jan2023
+  ci_runner_image: trini/u-boot-gitlab-ci-runner:jammy-20230126-10Feb2023
   # Add '-u 0' options for Azure pipelines, otherwise we get "permission
   # denied" error when it tries to "useradd -m -u 1001 vsts_azpcontainer",
   # since our $(ci_runner_image) user is not root.
@@ -240,6 +240,11 @@ stages:
           TEST_PY_TEST_SPEC: "test_ofplatdata or test_handoff or test_spl"
         sandbox_flattree:
           TEST_PY_BD: "sandbox_flattree"
+        sandbox_trace:
+          TEST_PY_BD: "sandbox"
+          BUILD_ENV: "FTRACE=1 NO_LTO=1"
+          TEST_PY_TEST_SPEC: "trace"
+          OVERRIDE: "-a CONFIG_TRACE=y -a CONFIG_TRACE_EARLY=y -a CONFIG_TRACE_EARLY_SIZE=0x01000000"
         coreboot:
           TEST_PY_BD: "coreboot"
           TEST_PY_ID: "--id qemu"
@@ -362,6 +367,9 @@ stages:
           # the below corresponds to .gitlab-ci.yml "script"
           cd ${WORK_DIR}
           export UBOOT_TRAVIS_BUILD_DIR=/tmp/${TEST_PY_BD};
+          if [ -n "${BUILD_ENV}" ]; then
+              export ${BUILD_ENV};
+          fi
           tools/buildman/buildman -o ${UBOOT_TRAVIS_BUILD_DIR} -w -E -W -e --board ${TEST_PY_BD} ${OVERRIDE}
           cp ~/grub_x86.efi ${UBOOT_TRAVIS_BUILD_DIR}/
           cp ~/grub_x64.efi ${UBOOT_TRAVIS_BUILD_DIR}/
diff --git a/.gitattributes b/.gitattributes
index 1879a2d..d5931f0 100644
--- a/.gitattributes
+++ b/.gitattributes
@@ -4,3 +4,4 @@
 *.bmp binary
 *.ttf binary
 *.gz binary
+*.png binary
diff --git a/.gitignore b/.gitignore
index 3adf1fa..3a4d056 100644
--- a/.gitignore
+++ b/.gitignore
@@ -105,3 +105,6 @@ __pycache__
 # pylint files
 /pylint.cur
 /pylint.out/
+
+# moveconfig database
+/moveconfig.db
diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml
index aaf9d25..272d69e 100644
--- a/.gitlab-ci.yml
+++ b/.gitlab-ci.yml
@@ -2,7 +2,7 @@
 
 # Grab our configured image.  The source for this is found
 # in the u-boot tree at tools/docker/Dockerfile
-image: trini/u-boot-gitlab-ci-runner:jammy-20221130-11Jan2023
+image: trini/u-boot-gitlab-ci-runner:jammy-20230126-10Feb2023
 
 # We run some tests in different order, to catch some failures quicker.
 stages:
@@ -35,6 +35,9 @@ stages:
     # If we've been asked to use clang only do one configuration.
     - export UBOOT_TRAVIS_BUILD_DIR=/tmp/${TEST_PY_BD}
     - echo BUILD_ENV ${BUILD_ENV}
+    - if [ -n "${BUILD_ENV}" ]; then
+        export ${BUILD_ENV};
+      fi
     - tools/buildman/buildman -o ${UBOOT_TRAVIS_BUILD_DIR} -w -E -W -e
         --board ${TEST_PY_BD} ${OVERRIDE}
     - cp ~/grub_x86.efi $UBOOT_TRAVIS_BUILD_DIR/
@@ -268,6 +271,15 @@ sandbox_vpl test.py:
     TEST_PY_TEST_SPEC: "test_vpl_help or test_spl"
   <<: *buildman_and_testpy_dfn
 
+# Enable tracing and disable LTO, to ensure functions are not elided
+sandbox trace_test.py:
+  variables:
+    TEST_PY_BD: "sandbox"
+    BUILD_ENV: "FTRACE=1 NO_LTO=1"
+    TEST_PY_TEST_SPEC: "trace"
+    OVERRIDE: "-a CONFIG_TRACE=y -a CONFIG_TRACE_EARLY=y -a CONFIG_TRACE_EARLY_SIZE=0x01000000"
+  <<: *buildman_and_testpy_dfn
+
 evb-ast2500 test.py:
   variables:
     TEST_PY_BD: "evb-ast2500"
diff --git a/common/board_f.c b/common/board_f.c
index 2b4edf3..f3c1ab5 100644
--- a/common/board_f.c
+++ b/common/board_f.c
@@ -290,7 +290,10 @@ static int setup_mon_len(void)
 {
 #if defined(__ARM__) || defined(__MICROBLAZE__)
 	gd->mon_len = (ulong)&__bss_end - (ulong)_start;
+#elif defined(CONFIG_SANDBOX) && !defined(__riscv)
+	gd->mon_len = (ulong)&_end - (ulong)_init;
 #elif defined(CONFIG_SANDBOX)
+	/* gcc does not provide _init in crti.o on RISC-V */
 	gd->mon_len = 0;
 #elif defined(CONFIG_EFI_APP)
 	gd->mon_len = (ulong)&_end - (ulong)_init;
diff --git a/common/board_r.c b/common/board_r.c
index c6c0c1a..e450033 100644
--- a/common/board_r.c
+++ b/common/board_r.c
@@ -797,6 +797,15 @@ static init_fnc_t init_sequence_r[] = {
 void board_init_r(gd_t *new_gd, ulong dest_addr)
 {
 	/*
+	 * The pre-relocation drivers may be using memory that has now gone
+	 * away. Mark serial as unavailable - this will fall back to the debug
+	 * UART if available.
+	 *
+	 * Do the same with log drivers since the memory may not be available.
+	 */
+	gd->flags &= ~(GD_FLG_SERIAL_READY | GD_FLG_LOG_READY);
+
+	/*
 	 * Set up the new global data pointer. So far only x86 does this
 	 * here.
 	 * TODO(sjg@chromium.org): Consider doing this for all archs, or
diff --git a/doc/develop/pics/flamegraph.png b/doc/develop/pics/flamegraph.png
new file mode 100644
index 0000000..dbdd27e
--- /dev/null
+++ b/doc/develop/pics/flamegraph.png
diff --git a/doc/develop/pics/flamegraph_timing.png b/doc/develop/pics/flamegraph_timing.png
new file mode 100644
index 0000000..b388b8b
--- /dev/null
+++ b/doc/develop/pics/flamegraph_timing.png
diff --git a/doc/develop/pics/flamegraph_zoom.png b/doc/develop/pics/flamegraph_zoom.png
new file mode 100644
index 0000000..38b6844
--- /dev/null
+++ b/doc/develop/pics/flamegraph_zoom.png
diff --git a/doc/develop/pics/kernelshark.png b/doc/develop/pics/kernelshark.png
new file mode 100644
index 0000000..3450c6b
--- /dev/null
+++ b/doc/develop/pics/kernelshark.png
diff --git a/doc/develop/pics/kernelshark_fg.png b/doc/develop/pics/kernelshark_fg.png
new file mode 100644
index 0000000..a54efd1
--- /dev/null
+++ b/doc/develop/pics/kernelshark_fg.png
diff --git a/doc/develop/trace.rst b/doc/develop/trace.rst
index 5c7802d..8425d84 100644
--- a/doc/develop/trace.rst
+++ b/doc/develop/trace.rst
@@ -15,12 +15,16 @@ Overview
 The trace feature uses GCC's instrument-functions feature to trace all
 function entry/exit points. These are then recorded in a memory buffer.
 The memory buffer can be saved to the host over a network link using
-tftpput or by writing to an attached memory device such as MMC.
+tftpput or by writing to an attached storage device such as MMC.
 
 On the host, the file is first converted with a tool called 'proftool',
 which extracts useful information from it. The resulting trace output
 resembles that emitted by Linux's ftrace feature, so can be visually
-displayed by pytimechart.
+displayed by kernelshark (see kernelshark_) and used with
+'trace-cmd report' (see trace_cmd_).
+
+It is also possible to produce a flame graph for use with flamegraph.pl
+(see flamegraph_pl_).
 
 
 Quick-start using Sandbox
@@ -30,7 +34,7 @@ Sandbox is a build of U-Boot that can run under Linux so it is a convenient
 way of trying out tracing before you use it on your actual board. To do
 this, follow these steps:
 
-Add the following to config/sandbox_defconfig
+Add the following to `config/sandbox_defconfig`:
 
 .. code-block:: c
 
@@ -75,7 +79,7 @@ a trace:
              16 maximum observed call depth
              15 call depth limit
           1,275,767 calls not traced due to depth
-    =>trace calls 0 e00000
+    =>trace calls 1000000 e00000
     Call list dumped to 00000000, size 0xae0a40
     =>print
     baudrate=115200
@@ -87,7 +91,7 @@ a trace:
     stdout=serial
 
     Environment size: 117/8188 bytes
-    =>host save host 0 trace 0 ${profoffset}
+    =>host save hostfs - 1000000 trace ${profoffset}
     11405888 bytes written in 10 ms (1.1 GiB/s)
     =>reset
 
@@ -96,18 +100,107 @@ Then run proftool to convert the trace information to ftrace format
 
 .. code-block:: console
 
-    $ ./sandbox/tools/proftool -m sandbox/System.map -p trace dump-ftrace >trace.txt
+    $ ./sandbox/tools/proftool -m sandbox/System.map -t trace dump-ftrace >trace.dat
 
-Finally run pytimechart to display it
+Finally run kernelshark to display it (note it only works with `.dat` files!):
 
 .. code-block:: console
 
-    $ pytimechart trace.txt
+    $ kernelshark trace.dat
 
-Using this tool you can zoom and pan across the trace, with the function
-calls on the left and little marks representing the start and end of each
+Using this tool you can view the trace records and see the timestamp for each
 function.
 
+.. image:: pics/kernelshark.png
+  :width: 800
+  :alt: Kernelshark showing function-trace records
+
+
+To see the records on the console, use trace-cmd:
+
+.. code-block:: console
+
+    $ trace-cmd report trace.dat | less
+    cpus=1
+          u-boot-1     [000]     3.116364: function:             initf_malloc
+          u-boot-1     [000]     3.116375: function:             initf_malloc
+          u-boot-1     [000]     3.116386: function:             initf_bootstage
+          u-boot-1     [000]     3.116396: function:                bootstage_init
+          u-boot-1     [000]     3.116408: function:                   malloc
+          u-boot-1     [000]     3.116418: function:                      malloc_simple
+          u-boot-1     [000]     3.116429: function:                         alloc_simple
+          u-boot-1     [000]     3.116441: function:                         alloc_simple
+          u-boot-1     [000]     3.116449: function:                      malloc_simple
+          u-boot-1     [000]     3.116457: function:                   malloc
+
+Note that `pytimechart` is obsolete so cannot be used anymore.
+
+There is a -f option available to select a function graph:
+
+.. code-block:: console
+
+    $ ./sandbox/tools/proftool -m sandbox/System.map -t trace -f funcgraph dump-ftrace >trace.dat
+
+Again, you can use kernelshark or trace-cmd to look at the output. In this case
+you will see the time taken by each function shown against its exit record.
+
+.. image:: pics/kernelshark_fg.png
+  :width: 800
+  :alt: Kernelshark showing function-graph records
+
+.. code-block:: console
+
+    $ trace-cmd report trace.dat | less
+    cpus=1
+              u-boot-1     [000]     3.116364: funcgraph_entry:        0.011 us   |    initf_malloc();
+              u-boot-1     [000]     3.116386: funcgraph_entry:                   |    initf_bootstage() {
+              u-boot-1     [000]     3.116396: funcgraph_entry:                   |      bootstage_init() {
+              u-boot-1     [000]     3.116408: funcgraph_entry:                   |        malloc() {
+              u-boot-1     [000]     3.116418: funcgraph_entry:                   |          malloc_simple() {
+              u-boot-1     [000]     3.116429: funcgraph_entry:        0.012 us   |            alloc_simple();
+              u-boot-1     [000]     3.116449: funcgraph_exit:         0.031 us   |            }
+              u-boot-1     [000]     3.116457: funcgraph_exit:         0.049 us   |          }
+              u-boot-1     [000]     3.116466: funcgraph_entry:        0.063 us   |        memset();
+              u-boot-1     [000]     3.116539: funcgraph_exit:         0.143 us   |        }
+
+Flame graph
+-----------
+
+Some simple flame graph options are available as well, using the dump-flamegraph
+command:
+
+.. code-block:: console
+
+    $ ./sandbox/tools/proftool -m sandbox/System.map -t trace dump-flamegraph >trace.fg
+    $ flamegraph.pl trace.fg >trace.svg
+
+You can load the .svg file into a viewer. If you use Chrome (and some other
+programs) you can click around and zoom in and out.
+
+.. image:: pics/flamegraph.png
+  :width: 800
+  :alt: Chrome showing the flamegraph.pl output
+
+.. image:: pics/flamegraph_zoom.png
+  :width: 800
+  :alt: Chrome showing zooming into the flamegraph.pl output
+
+
+A timing variant is also available, which gives an idea of how much time is
+spend in each call stack:
+
+.. code-block:: console
+
+    $ ./sandbox/tools/proftool -m sandbox/System.map -t trace dump-flamegraph -f timing >trace.fg
+    $ flamegraph.pl trace.fg >trace.svg
+
+Note that trace collection does slow down execution so the timings will be
+inflated. They should be used to guide optimisation. For accurate boot timings,
+use bootstage.
+
+.. image:: pics/flamegraph_timing.png
+  :width: 800
+  :alt: Chrome showing flamegraph.pl output with timing
 
 CONFIG Options
 --------------
@@ -138,6 +231,11 @@ CONFIG_TRACE_EARLY_SIZE
 CONFIG_TRACE_EARLY_ADDR
     Address of early trace buffer
 
+CONFIG_TRACE_CALL_DEPTH_LIMIT
+    Sets the limit on trace call-depth. For a broad view, 10 is typically
+    sufficient. Setting this too large creates enormous traces and distorts
+    the overall timing considerable.
+
 
 Building U-Boot with Tracing Enabled
 ------------------------------------
@@ -148,6 +246,26 @@ instrumenting from the command line instead of having to change board
 config files.
 
 
+Board requirements
+------------------
+
+Trace data collection relies on a microsecond timer, accessed through
+`timer_get_us()`. So the first thing you should do is make sure that
+this produces sensible results for your board. Suitable sources for
+this timer include high resolution timers, PWMs or profile timers if
+available. Most modern SOCs have a suitable timer for this.
+
+See `add_ftrace()` for where `timer_get_us()` is called. The `notrace`
+attribute must be used on each function called by `timer_get_us()` since
+recursive calls to `add_ftrace()` will cause a fault::
+
+   trace: recursion detected, disabling
+
+You cannot use driver model to obtain the microsecond timer, since tracing
+may be enabled before driver model is set up. Instead, provide a low-level
+function which accesses the timer, setting it up if needed.
+
+
 Collecting Trace Data
 ---------------------
 
@@ -155,21 +273,22 @@ When you run U-Boot on your board it will collect trace data up to the
 limit of the trace buffer size you have specified. Once that is exhausted
 no more data will be collected.
 
-Collecting trace data has an affect on execution time/performance. You
+Collecting trace data affects execution time and performance. You
 will notice this particularly with trivial functions - the overhead of
 recording their execution may even exceed their normal execution time.
 In practice this doesn't matter much so long as you are aware of the
 effect. Once you have done your optimizations, turn off tracing before
-doing end-to-end timing.
+doing end-to-end timing using bootstage.
 
 The best time to start tracing is right at the beginning of U-Boot. The
 best time to stop tracing is right at the end. In practice it is hard
 to achieve these ideals.
 
-This implementation enables tracing early in board_init_f(). This means
+This implementation enables tracing early in `board_init_r()`, or
+`board_init_f()` when `TRACE_EARLY` is enabled. This means
 that it captures most of the board init process, missing only the
 early architecture-specific init. However, it also misses the entire
-SPL stage if there is one.
+SPL stage if there is one. At present tracing is not supported in SPL.
 
 U-Boot typically ends with a 'bootm' command which loads and runs an
 OS. There is useful trace data in the execution of that bootm
@@ -179,39 +298,11 @@ the OS. In practical terms, U-Boot runs the 'fakegocmd' environment
 variable at this point. This variable should have a short script which
 collects the trace data and writes it somewhere.
 
-Trace data collection relies on a microsecond timer, accessed through
-timer_get_us(). So the first think you should do is make sure that
-this produces sensible results for your board. Suitable sources for
-this timer include high resolution timers, PWMs or profile timers if
-available. Most modern SOCs have a suitable timer for this. Make sure
-that you mark this timer (and anything it calls) with
-notrace so that the trace library can
-use it without causing an infinite loop.
-
-
-Commands
---------
-
-The trace command has variable sub-commands:
-
-stats
-    Display tracing statistics
-
-pause
-    Pause tracing
-
-resume
-    Resume tracing
-
-funclist [<addr> <size>]
-    Dump a list of functions into the buffer
-
-calls  [<addr> <size>]
-    Dump function call trace into buffer
+Controlling the trace
+---------------------
 
-If the address and size are not given, these are obtained from environment
-variables (see below). In any case the environment variables are updated
-after the command runs.
+U-Boot provides a command-line interface to the trace system for controlling
+tracing and accessing the trace data. See :doc:`../usage/cmd/trace`.
 
 
 Environment Variables
@@ -264,39 +355,94 @@ a trace log to address 10000000 and sends it to a host machine using
 TFTP. After this, U-Boot will boot the OS normally, albeit a little
 later.
 
+For a filesystem you may do something like::
+
+    trace calls 10000000 1000000;
+    save mmc 1:1 10000000 /trace ${profoffset}
+
+The trace buffer format is internal to the trace system. It consists of a
+header, a call count for each function site, followed by a list of trace
+records, once for each function call.
+
 
-Converting Trace Output Data
-----------------------------
+Converting Trace Output Data (proftool)
+---------------------------------------
 
 The trace output data is kept in a binary format which is not documented
-here. To convert it into something useful, you can use proftool.
+here. See the `trace.h` header file if you are interested. To convert it into
+something useful, you can use proftool.
 
 This tool must be given the U-Boot map file and the trace data received
-from running that U-Boot. It produces a text output file.
+from running that U-Boot. It produces a binary output file.
+
+It is also possible to provide a configuration file to indicate which functions
+should be included or dropped during conversion. This file consists of lines
+like::
+
+   include-func <regex>
+   exclude-func <regex>
 
-Options
+where <regex> is a regular expression matched against function names. It
+allows some functions to be dropped from the trace when producing ftrace
+records.
+
+Options:
+
+-c <config_file>
+    Specify the optional configuration file, to control which functions are
+    included in the output.
+
+-f <format>
+    Specifies the format to use (see below)
 
 -m <map_file>
-    Specify U-Boot map file
+    Specify U-Boot map file (`System.map`)
+
+-o <output file>
+    Specify the output filename
 
--p <trace_file>
-    Specify profile/trace file
+-t <trace_file>
+    Specify trace file, the data saved from U-Boot
+
+-v <0-4>
+    Specify the verbosity, where 0 is the minimum and 4 is for debugging.
 
 Commands:
 
-dump-ftrace
-    Write a text dump of the file in Linux ftrace format to stdout
+dump-ftrace:
+    Write a binary dump of the file in Linux ftrace format. Two options are
+    available:
+
+    function
+        write function-call records (caller/callee)
+
+    funcgraph
+        write function entry/exit records (graph)
+
+    This format can be used with kernelshark_ and trace_cmd_.
+
+dump-flamegraph
+    Write a list of stack records useful for producing a flame graph. Two
+    options are available:
 
+    calls
+        create a flamegraph of stack frames
+
+    timing
+        create a flamegraph of microseconds for each stack frame
+
+    This format can be used with flamegraph_pl_.
 
 Viewing the Trace Data
 ----------------------
 
-You can use pytimechart for this (sudo apt-get pytimechart might work on
-your Debian-style machine, and use your favourite search engine to obtain
-documentation). It expects the file to have a .txt extension. The program
-has terse user interface but is very convenient for viewing U-Boot
-profile information.
+You can use kernelshark_ for a GUI, but note that version 2.0.x was broken. If
+you have that version you could try building it from source.
 
+The file must have a .dat extension or it is ignored. The program has terse
+user interface but is very convenient for viewing U-Boot profile information.
+
+Also available is trace_cmd_ which provides a command-line interface.
 
 Workflow Suggestions
 --------------------
@@ -329,7 +475,9 @@ There are a few parameters in the code that you may want to consider.
 There is a function call depth limit (set to 15 by default). When the
 stack depth goes above this then no tracing information is recorded.
 The maximum depth reached is recorded and displayed by the 'trace stats'
-command.
+command. While it might be tempting to set the depth limit quite high, this
+can dramatically increase the size of the trace output as well as the execution
+time.
 
 
 Future Work
@@ -346,5 +494,10 @@ Some other features that might be useful:
 - Compression of trace information
 
 
-Simon Glass <sjg@chromium.org>
-April 2013
+.. sectionauthor:: Simon Glass <sjg@chromium.org>
+.. April 2013
+.. Updated January 2023
+
+.. _kernelshark: https://kernelshark.org/
+.. _trace_cmd: https://www.trace-cmd.org/
+.. _flamegraph_pl: https://github.com/brendangregg/FlameGraph/blob/master/flamegraph.pl
diff --git a/doc/usage/cmd/trace.rst b/doc/usage/cmd/trace.rst
new file mode 100644
index 0000000..3bdf4f0
--- /dev/null
+++ b/doc/usage/cmd/trace.rst
@@ -0,0 +1,163 @@
+.. SPDX-License-Identifier: GPL-2.0+:
+
+trace command
+=============
+
+Synopis
+-------
+
+::
+
+    trace stats
+    trace pause
+    trace resume
+    trace funclist [<addr> <size>]
+    trace calls [<addr> <size>]
+
+Description
+-----------
+
+The *trace* command is used to control the U-Boot tracing system. It allows
+tracing to be paused and resumed, shows statistics for traces and provides a
+way to dump out the trace information.
+
+
+trace stats
+~~~~~~~~~~~
+
+This display tracing statistics, as follows:
+
+function sites
+    Functions are binned as a way of reducing the amount of space needed to
+    hold all the function information. This is controlled by FUNC_SITE_SIZE in
+    the trace.h header file. The usual value is 4, which provides the finest
+    granularity (assuming a minimum instruction size of 4 bytes) which means
+    that every function can be resolved individually.
+
+function calls
+    Total number of function calls, including those which were not traced due
+    to buffer space. This count does not include functions which exceeded the
+    depth limit.
+
+untracked function calls
+    Total number of function calls which did not appear in the U-Boot image.
+    This can happen if a function is called outside the normal code area.
+
+traced function calls
+    Total number of function calls which were actually traced, i.e. are included
+    in the recorded trace data.
+
+dropped due to overflow
+    If the trace buffer was exhausted then this shows the number of records that
+    were dropped. Try reducing the depth limit or expanding the buffer size.
+
+maximum observed call depth
+    Maximum observed call depth while tracing.
+
+calls not traced due to depth
+    Counts the number of function calls that were not recorded because they
+    exceeded the maximum call depth.
+
+max function calls
+    Maximum number of function calls which can be recorded in the trace buffer,
+    given its size. Once `function calls` hits this value, recording stops.
+
+trace buffer
+    Address of trace buffer
+
+call records
+    Address of first trace record. This is near the start of the trace buffer,
+    after the function-call counts.
+
+
+trace pause
+~~~~~~~~~~~
+
+Pauses tracing, so that no more data is added to the trace buffer.
+
+
+trace resume
+~~~~~~~~~~~~
+
+Resumes tracing, so that new function calls are added to the trace buffer if
+there is sufficient space.
+
+
+trace funclist [<addr> <size>]
+~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+
+Dumps a list of functions into the provided buffer. The file uses a format
+specific to U-Boot: a header, following by the function offset and call count.
+
+If the address and size are not given, these are obtained from
+:ref:`develop/trace:environment variables`. In any case the environment
+variables are updated after the command runs.
+
+The resulting data should be written out to the host, e.g. using Ethernet or
+a filesystem. There are no tools provided to read this sdata.
+
+
+trace calls [<addr> <size>]
+~~~~~~~~~~~~~~~~~~~~~~~~~~~
+
+Dumps a list of function calls into the provided buffer. The file uses a format
+specific to U-Boot: a header, following by the list of calls. The proftool
+tool can be used to convert this information ready for further analysis.
+
+
+Example
+-------
+
+::
+
+    => trace stats
+            269,252 function sites
+         38,025,059 function calls
+                  3 untracked function calls
+          7,382,690 traced function calls
+                 17 maximum observed call depth
+                 15 call depth limit
+         68,667,432 calls not traced due to depth
+         22,190,112 max function calls
+
+    trace buffer 6c000000 call records 6c20de78
+    => trace resume
+    => trace pause
+
+This shows that resuming the trace causes the buffer to overflow::
+
+    => trace stats
+            269,252 function sites
+         49,573,694 function calls
+                  3 untracked function calls
+         22,190,112 traced function calls (8289848 dropped due to overflow)
+                 17 maximum observed call depth
+                 15 call depth limit
+         68,667,432 calls not traced due to depth
+         22,190,112 max function calls
+
+    trace buffer 6c000000 call records 6c20de78
+    => trace funcs 30000000 0x100000
+    Function trace dumped to 30000000, size 0x1e70
+
+This shows collecting and writing out the result trace data:
+
+::
+    => trace calls 20000000 0x10000000
+    Call list dumped to 20000000, size 0xfdf21a0
+    => save mmc 1:1 20000000 /trace ${profoffset}
+    File System is consistent
+    file found, deleting
+    update journal finished
+    File System is consistent
+    update journal finished
+    266281376 bytes written in 18584 ms (13.7 MiB/s)
+
+From here you can use proftool to convert it:
+
+.. code-block:: bash
+
+    tools/proftool -m System.map -t trace -o asc.fg dump-ftrace
+
+
+.. _`ACPI specification`: https://uefi.org/sites/default/files/resources/ACPI_6_3_final_Jan30.pdf
diff --git a/doc/usage/index.rst b/doc/usage/index.rst
index 13e6939..cde7dcb 100644
--- a/doc/usage/index.rst
+++ b/doc/usage/index.rst
@@ -84,6 +84,7 @@ Shell commands
    cmd/sm
    cmd/temperature
    cmd/tftpput
+   cmd/trace
    cmd/true
    cmd/ums
    cmd/ut
diff --git a/drivers/core/device.c b/drivers/core/device.c
index d9ce546..6e26b64 100644
--- a/drivers/core/device.c
+++ b/drivers/core/device.c
@@ -654,7 +654,8 @@ void *dev_get_priv(const struct udevice *dev)
 	return dm_priv_to_rw(dev->priv_);
 }
 
-void *dev_get_uclass_priv(const struct udevice *dev)
+/* notrace is needed as this is called by timer_get_rate() */
+notrace void *dev_get_uclass_priv(const struct udevice *dev)
 {
 	if (!dev) {
 		dm_warn("%s: null device\n", __func__);
diff --git a/drivers/timer/timer-uclass.c b/drivers/timer/timer-uclass.c
index bb71979..f4b871a 100644
--- a/drivers/timer/timer-uclass.c
+++ b/drivers/timer/timer-uclass.c
@@ -136,7 +136,7 @@ u64 timer_conv_64(u32 count)
 	return ((u64)gd->timebase_h << 32) | gd->timebase_l;
 }
 
-int notrace dm_timer_init(void)
+int dm_timer_init(void)
 {
 	struct udevice *dev = NULL;
 	__maybe_unused ofnode node;
diff --git a/include/timer.h b/include/timer.h
index d33a26e..311ce6b 100644
--- a/include/timer.h
+++ b/include/timer.h
@@ -9,11 +9,16 @@
 #define timer_get_ops(dev)	((struct timer_ops *)(dev)->driver->ops)
 
 /**
- * dm_timer_init() - initialize a timer for time keeping. On success
- * initializes gd->timer so that lib/timer can use it for future
- * referrence.
+ * dm_timer_init() - set up a timer for time keeping
  *
- * Return: 0 on success or error number
+ * Sets up gd->timer if the device is not already bound, making sure it is
+ * probed and ready for use
+ *
+ * On success, inits gd->timer so that lib/timer can use it for future reference
+ *
+ * Returns: 0 on success, -EAGAIN if driver model is not ready yet, -ENODEV if
+ * no timer could be found, other error if the timer could not be bound or
+ * probed
  */
 int dm_timer_init(void);
 
diff --git a/include/trace.h b/include/trace.h
index e7aee02..763d6d1 100644
--- a/include/trace.h
+++ b/include/trace.h
@@ -6,6 +6,8 @@
 #ifndef __TRACE_H
 #define __TRACE_H
 
+/* this file is included from a tool so uses uint32_t instead of u32, etc. */
+
 enum {
 	/*
 	 * This affects the granularity of our trace. We can bin function
@@ -15,14 +17,18 @@ enum {
 	 *
 	 * The value here assumes a minimum instruction size of 4 bytes,
 	 * or that instructions are 2 bytes but there are at least 2 of
-	 * them in every function.
+	 * them in every function. Given that each function needs a call to
+	 * __cyg_profile_func_enter() and __cyg_profile_func_exit() as well,
+	 * we cannot have functions smaller that 16 bytes.
 	 *
 	 * Increasing this value reduces the number of functions we can
 	 * resolve, but reduces the size of the uintptr_t array used for
 	 * our function list, which is the length of the code divided by
 	 * this value.
 	 */
-	FUNC_SITE_SIZE	= 4,	/* distance between function sites */
+	FUNC_SITE_SIZE	= 16,	/* distance between function sites */
+
+	TRACE_VERSION	= 1,
 };
 
 enum trace_chunk_type {
@@ -39,7 +45,11 @@ struct trace_output_func {
 /* A header at the start of the trace output buffer */
 struct trace_output_hdr {
 	enum trace_chunk_type type;	/* Record type */
-	size_t rec_count;		/* Number of records */
+	uint32_t version;		/* Version (TRACE_VERSION) */
+	uint32_t rec_count;		/* Number of records */
+	uint32_t spare;			/* 0 */
+	uint64_t text_base;		/* Value of CONFIG_TEXT_BASE */
+	uint64_t spare2;		/* 0 */
 };
 
 /* Print statistics about traced function calls */
@@ -63,7 +73,7 @@ int trace_list_functions(void *buff, size_t buff_size, size_t *needed);
 enum ftrace_flags {
 	FUNCF_EXIT		= 0UL << 30,
 	FUNCF_ENTRY		= 1UL << 30,
-	FUNCF_TEXTBASE		= 2UL << 30,
+	/* two more values are available */
 
 	FUNCF_TIMESTAMP_MASK	= 0x3fffffff,
 };
diff --git a/lib/Kconfig b/lib/Kconfig
index 06c873c..83e5edd 100644
--- a/lib/Kconfig
+++ b/lib/Kconfig
@@ -368,7 +368,7 @@ config TRACE_EARLY_SIZE
 config TRACE_EARLY_CALL_DEPTH_LIMIT
 	int "Early trace call depth limit"
 	depends on TRACE_EARLY
-	default 200
+	default 15
 	help
 	  Sets the maximum call depth up to which function calls are recorded
 	  during early tracing.
diff --git a/lib/abuf.c b/lib/abuf.c
index 1635d58..bd27046 100644
--- a/lib/abuf.c
+++ b/lib/abuf.c
@@ -6,11 +6,14 @@
  * Written by Simon Glass <sjg@chromium.org>
  */
 
+#ifndef USE_HOSTCC
 #include <common.h>
-#include <abuf.h>
 #include <malloc.h>
 #include <mapmem.h>
 #include <string.h>
+#endif
+
+#include <abuf.h>
 
 void abuf_set(struct abuf *abuf, void *data, size_t size)
 {
@@ -19,10 +22,26 @@ void abuf_set(struct abuf *abuf, void *data, size_t size)
 	abuf->size = size;
 }
 
+#ifndef USE_HOSTCC
 void abuf_map_sysmem(struct abuf *abuf, ulong addr, size_t size)
 {
 	abuf_set(abuf, map_sysmem(addr, size), size);
 }
+#else
+/* copied from lib/string.c for convenience */
+static char *memdup(const void *src, size_t len)
+{
+	char *p;
+
+	p = malloc(len);
+	if (!p)
+		return NULL;
+
+	memcpy(p, src, len);
+
+	return p;
+}
+#endif
 
 bool abuf_realloc(struct abuf *abuf, size_t new_size)
 {
diff --git a/lib/time.c b/lib/time.c
index 5252190..00f4a1a 100644
--- a/lib/time.c
+++ b/lib/time.c
@@ -70,15 +70,14 @@ extern unsigned long timer_read_counter(void);
 ulong notrace get_tbclk(void)
 {
 	if (!gd->timer) {
-#ifdef CONFIG_TIMER_EARLY
-		return timer_early_get_rate();
-#else
 		int ret;
 
+		if (IS_ENABLED(CONFIG_TIMER_EARLY))
+			return timer_early_get_rate();
+
 		ret = dm_timer_init();
 		if (ret)
 			return ret;
-#endif
 	}
 
 	return timer_get_rate(gd->timer);
@@ -90,15 +89,14 @@ uint64_t notrace get_ticks(void)
 	int ret;
 
 	if (!gd->timer) {
-#ifdef CONFIG_TIMER_EARLY
-		return timer_early_get_count();
-#else
 		int ret;
 
+		if (IS_ENABLED(CONFIG_TIMER_EARLY))
+			return timer_early_get_count();
+
 		ret = dm_timer_init();
 		if (ret)
 			panic("Could not initialize timer (err %d)\n", ret);
-#endif
 	}
 
 	ret = timer_get_count(gd->timer, &count);
diff --git a/lib/trace.c b/lib/trace.c
index b9dc6d2..1091a57 100644
--- a/lib/trace.c
+++ b/lib/trace.c
@@ -35,9 +35,11 @@ struct trace_hdr {
 	ulong ftrace_count;	/* Num. of ftrace records written */
 	ulong ftrace_too_deep_count;	/* Functions that were too deep */
 
-	int depth;
-	int depth_limit;
-	int max_depth;
+	int depth;		/* Depth of function calls */
+	int depth_limit;	/* Depth limit to trace to */
+	int max_depth;		/* Maximum depth seen so far */
+	int min_depth;		/* Minimum depth seen so far */
+	bool trace_locked;	/* Used to detect recursive tracing */
 };
 
 /* Pointer to start of trace buffer */
@@ -118,18 +120,6 @@ static void notrace add_ftrace(void *func_ptr, void *caller, ulong flags)
 	hdr->ftrace_count++;
 }
 
-static void notrace add_textbase(void)
-{
-	if (hdr->ftrace_count < hdr->ftrace_size) {
-		struct trace_call *rec = &hdr->ftrace[hdr->ftrace_count];
-
-		rec->func = CONFIG_TEXT_BASE;
-		rec->caller = 0;
-		rec->flags = FUNCF_TEXTBASE;
-	}
-	hdr->ftrace_count++;
-}
-
 /**
  * __cyg_profile_func_enter() - record function entry
  *
@@ -144,6 +134,14 @@ void notrace __cyg_profile_func_enter(void *func_ptr, void *caller)
 	if (trace_enabled) {
 		int func;
 
+		if (hdr->trace_locked) {
+			trace_enabled = 0;
+			puts("trace: recursion detected, disabling\n");
+			hdr->trace_locked = false;
+			return;
+		}
+
+		hdr->trace_locked = true;
 		trace_swap_gd();
 		add_ftrace(func_ptr, caller, FUNCF_ENTRY);
 		func = func_ptr_to_num(func_ptr);
@@ -154,9 +152,10 @@ void notrace __cyg_profile_func_enter(void *func_ptr, void *caller)
 			hdr->untracked_count++;
 		}
 		hdr->depth++;
-		if (hdr->depth > hdr->depth_limit)
+		if (hdr->depth > hdr->max_depth)
 			hdr->max_depth = hdr->depth;
 		trace_swap_gd();
+		hdr->trace_locked = false;
 	}
 }
 
@@ -170,8 +169,10 @@ void notrace __cyg_profile_func_exit(void *func_ptr, void *caller)
 {
 	if (trace_enabled) {
 		trace_swap_gd();
-		add_ftrace(func_ptr, caller, FUNCF_EXIT);
 		hdr->depth--;
+		add_ftrace(func_ptr, caller, FUNCF_EXIT);
+		if (hdr->depth < hdr->min_depth)
+			hdr->min_depth = hdr->depth;
 		trace_swap_gd();
 	}
 }
@@ -278,8 +279,11 @@ int trace_list_calls(void *buff, size_t buff_size, size_t *needed)
 
 	/* Update the header */
 	if (output_hdr) {
+		memset(output_hdr, '\0', sizeof(*output_hdr));
 		output_hdr->rec_count = upto;
 		output_hdr->type = TRACE_CHUNK_CALLS;
+		output_hdr->version = TRACE_VERSION;
+		output_hdr->text_base = CONFIG_TEXT_BASE;
 	}
 
 	/* Work out how must of the buffer we used */
@@ -318,11 +322,17 @@ void trace_print_stats(void)
 		printf(" (%lu dropped due to overflow)",
 		       hdr->ftrace_count - hdr->ftrace_size);
 	}
-	puts("\n");
-	printf("%15d maximum observed call depth\n", hdr->max_depth);
+
+	/* Add in minimum depth since the trace did not start at top level */
+	printf("\n%15d maximum observed call depth\n",
+	       hdr->max_depth - hdr->min_depth);
 	printf("%15d call depth limit\n", hdr->depth_limit);
 	print_grouped_ull(hdr->ftrace_too_deep_count, 10);
 	puts(" calls not traced due to depth\n");
+	print_grouped_ull(hdr->ftrace_size, 10);
+	puts(" max function calls\n");
+	printf("\ntrace buffer %lx call records %lx\n",
+	       (ulong)map_to_sysmem(hdr), (ulong)map_to_sysmem(hdr->ftrace));
 }
 
 void notrace trace_set_enabled(int enabled)
@@ -330,6 +340,17 @@ void notrace trace_set_enabled(int enabled)
 	trace_enabled = enabled != 0;
 }
 
+static int get_func_count(void)
+{
+	/* Detect no support for mon_len since this means tracing cannot work */
+	if (IS_ENABLED(CONFIG_SANDBOX) && !gd->mon_len) {
+		puts("Tracing is not supported on this board\n");
+		return -ENOTSUPP;
+	}
+
+	return gd->mon_len / FUNC_SITE_SIZE;
+}
+
 /**
  * trace_init() - initialize the tracing system and enable it
  *
@@ -339,16 +360,18 @@ void notrace trace_set_enabled(int enabled)
  */
 int notrace trace_init(void *buff, size_t buff_size)
 {
-	ulong func_count = gd->mon_len / FUNC_SITE_SIZE;
+	int func_count = get_func_count();
 	size_t needed;
 	int was_disabled = !trace_enabled;
 
+	if (func_count < 0)
+		return func_count;
 	trace_save_gd();
 
 	if (!was_disabled) {
 #ifdef CONFIG_TRACE_EARLY
+		ulong used, count;
 		char *end;
-		ulong used;
 
 		/*
 		 * Copy over the early trace data if we have it. Disable
@@ -357,12 +380,19 @@ int notrace trace_init(void *buff, size_t buff_size)
 		trace_enabled = 0;
 		hdr = map_sysmem(CONFIG_TRACE_EARLY_ADDR,
 				 CONFIG_TRACE_EARLY_SIZE);
-		end = (char *)&hdr->ftrace[min(hdr->ftrace_count,
-					       hdr->ftrace_size)];
+		count = min(hdr->ftrace_count, hdr->ftrace_size);
+		end = (char *)&hdr->ftrace[count];
 		used = end - (char *)hdr;
 		printf("trace: copying %08lx bytes of early data from %x to %08lx\n",
 		       used, CONFIG_TRACE_EARLY_ADDR,
 		       (ulong)map_to_sysmem(buff));
+		printf("%lu traced function calls", count);
+		if (hdr->ftrace_count > hdr->ftrace_size) {
+			printf(" (%lu dropped due to overflow)",
+			       hdr->ftrace_count - hdr->ftrace_size);
+			hdr->ftrace_count = hdr->ftrace_size;
+		}
+		puts("\n");
 		memcpy(buff, hdr, used);
 #else
 		puts("trace: already enabled\n");
@@ -372,23 +402,24 @@ int notrace trace_init(void *buff, size_t buff_size)
 	hdr = (struct trace_hdr *)buff;
 	needed = sizeof(*hdr) + func_count * sizeof(uintptr_t);
 	if (needed > buff_size) {
-		printf("trace: buffer size %zd bytes: at least %zd needed\n",
+		printf("trace: buffer size %zx bytes: at least %zx needed\n",
 		       buff_size, needed);
 		return -ENOSPC;
 	}
 
-	if (was_disabled)
+	if (was_disabled) {
 		memset(hdr, '\0', needed);
+		hdr->min_depth = INT_MAX;
+	}
 	hdr->func_count = func_count;
 	hdr->call_accum = (uintptr_t *)(hdr + 1);
 
 	/* Use any remaining space for the timed function trace */
 	hdr->ftrace = (struct trace_call *)(buff + needed);
 	hdr->ftrace_size = (buff_size - needed) / sizeof(*hdr->ftrace);
-	add_textbase();
+	hdr->depth_limit = CONFIG_TRACE_CALL_DEPTH_LIMIT;
 
 	puts("trace: enabled\n");
-	hdr->depth_limit = CONFIG_TRACE_CALL_DEPTH_LIMIT;
 	trace_enabled = 1;
 	trace_inited = 1;
 
@@ -403,10 +434,12 @@ int notrace trace_init(void *buff, size_t buff_size)
  */
 int notrace trace_early_init(void)
 {
-	ulong func_count = gd->mon_len / FUNC_SITE_SIZE;
+	int func_count = get_func_count();
 	size_t buff_size = CONFIG_TRACE_EARLY_SIZE;
 	size_t needed;
 
+	if (func_count < 0)
+		return func_count;
 	/* We can ignore additional calls to this function */
 	if (trace_enabled)
 		return 0;
@@ -414,7 +447,7 @@ int notrace trace_early_init(void)
 	hdr = map_sysmem(CONFIG_TRACE_EARLY_ADDR, CONFIG_TRACE_EARLY_SIZE);
 	needed = sizeof(*hdr) + func_count * sizeof(uintptr_t);
 	if (needed > buff_size) {
-		printf("trace: buffer size is %zd bytes, at least %zd needed\n",
+		printf("trace: buffer size is %zx bytes, at least %zx needed\n",
 		       buff_size, needed);
 		return -ENOSPC;
 	}
@@ -422,11 +455,11 @@ int notrace trace_early_init(void)
 	memset(hdr, '\0', needed);
 	hdr->call_accum = (uintptr_t *)(hdr + 1);
 	hdr->func_count = func_count;
+	hdr->min_depth = INT_MAX;
 
 	/* Use any remaining space for the timed function trace */
 	hdr->ftrace = (struct trace_call *)((char *)hdr + needed);
 	hdr->ftrace_size = (buff_size - needed) / sizeof(*hdr->ftrace);
-	add_textbase();
 	hdr->depth_limit = CONFIG_TRACE_EARLY_CALL_DEPTH_LIMIT;
 	printf("trace: early enable at %08x\n", CONFIG_TRACE_EARLY_ADDR);
 
diff --git a/test/py/tests/test_trace.py b/test/py/tests/test_trace.py
new file mode 100644
index 0000000..14584d1
--- /dev/null
+++ b/test/py/tests/test_trace.py
@@ -0,0 +1,304 @@
+# SPDX-License-Identifier: GPL-2.0
+# Copyright 2022 Google LLC
+# Written by Simon Glass <sjg@chromium.org>
+
+import os
+import pytest
+import re
+
+import u_boot_utils as util
+
+# This is needed for Azure, since the default '..' directory is not writeable
+TMPDIR = '/tmp/test_trace'
+
+# Decode a function-graph line
+RE_LINE = re.compile(r'.*\[000\]\s*([0-9.]*): func.*[|](\s*)(\S.*)?([{};])$')
+
+
+def collect_trace(cons):
+    """Build U-Boot and run it to collect a trace
+
+    Args:
+        cons (ConsoleBase): U-Boot console
+
+    Returns:
+        tuple:
+            str: Filename of the output trace file
+            int: Microseconds taken for initf_dm according to bootstage
+    """
+    cons.run_command('trace pause')
+    out = cons.run_command('trace stats')
+
+    # The output is something like this:
+    #    251,003 function sites
+    #  1,160,283 function calls
+    #          0 untracked function calls
+    #  1,230,758 traced function calls (341538 dropped due to overflow)
+    #         33 maximum observed call depth
+    #         15 call depth limit
+    #    748,268 calls not traced due to depth
+    #  1,230,758 max function calls
+
+    # Get a dict of values from the output
+    lines = [line.split(maxsplit=1) for line in out.splitlines() if line]
+    vals = {key: val.replace(',', '') for val, key in lines}
+
+    assert int(vals['function sites']) > 100000
+    assert int(vals['function calls']) > 200000
+    assert int(vals['untracked function calls']) == 0
+    assert int(vals['maximum observed call depth']) > 30
+    assert (vals['call depth limit'] ==
+            cons.config.buildconfig.get('config_trace_call_depth_limit'))
+    assert int(vals['calls not traced due to depth']) > 100000
+
+    out = cons.run_command('bootstage report')
+    # Accumulated time:
+    #           19,104  dm_r
+    #           23,078  of_live
+    #           46,280  dm_f
+    dm_f_time = [line.split()[0] for line in out.replace(',', '').splitlines()
+                 if 'dm_f' in line]
+
+    # Read out the trace data
+    addr = 0x02000000
+    size = 0x01000000
+    out = cons.run_command(f'trace calls {addr:x} {size:x}')
+    print(out)
+    fname = os.path.join(TMPDIR, 'trace')
+    out = cons.run_command(
+        'host save hostfs - %x %s ${profoffset}' % (addr, fname))
+    return fname, int(dm_f_time[0])
+
+
+def check_function(cons, fname, proftool, map_fname, trace_dat):
+    """Check that the 'function' output works
+
+    Args:
+        cons (ConsoleBase): U-Boot console
+        fname (str): Filename of trace file
+        proftool (str): Filename of proftool
+        map_fname (str): Filename of System.map
+        trace_dat (str): Filename of output file
+    """
+    out = util.run_and_log(
+        cons, [proftool, '-t', fname, '-o', trace_dat, '-m', map_fname,
+               'dump-ftrace'])
+
+    # Check that trace-cmd can read it
+    out = util.run_and_log(cons, ['trace-cmd', 'dump', trace_dat])
+
+    # Tracing meta data in file /tmp/test_trace/trace.dat:
+    #    [Initial format]
+    #            6        [Version]
+    #            0        [Little endian]
+    #            4        [Bytes in a long]
+    #            4096        [Page size, bytes]
+    #    [Header page, 205 bytes]
+    #    [Header event, 205 bytes]
+    #    [Ftrace format, 3 events]
+    #    [Events format, 0 systems]
+    #    [Kallsyms, 342244 bytes]
+    #    [Trace printk, 0 bytes]
+    #    [Saved command lines, 9 bytes]
+    #    1 [CPUs with tracing data]
+    #    [6 options]
+    #    [Flyrecord tracing data]
+    #    [Tracing clock]
+    #            [local] global counter uptime perf mono mono_raw boot x86-tsc
+    assert '[Flyrecord tracing data]' in out
+    assert '4096	[Page size, bytes]' in out
+    kallsyms = [line.split() for line in out.splitlines() if 'Kallsyms' in line]
+    # [['[Kallsyms,', '342244', 'bytes]']]
+    val = int(kallsyms[0][1])
+    assert val > 50000  # Should be at least 50KB of symbols
+
+    # Check that the trace has something useful
+    cmd = f"trace-cmd report {trace_dat} |grep -E '(initf_|initr_)'"
+    out = util.run_and_log(cons, ['sh', '-c', cmd])
+
+    # Format:
+    # unknown option 14
+    #      u-boot-1     [000]    60.805596: function:             initf_malloc
+    #      u-boot-1     [000]    60.805597: function:             initf_malloc
+    #      u-boot-1     [000]    60.805601: function:             initf_bootstage
+    #      u-boot-1     [000]    60.805607: function:             initf_bootstage
+    lines = [line.replace(':', '').split() for line in out.splitlines()]
+    vals = {items[4]: float(items[2]) for items in lines if len(items) == 5}
+    base = None
+    max_delta = 0
+    for timestamp in vals.values():
+        if base:
+            max_delta = max(max_delta, timestamp - base)
+        else:
+            base = timestamp
+
+    # Check for some expected functions
+    assert 'initf_malloc' in vals.keys()
+    assert 'initr_watchdog' in vals.keys()
+    assert 'initr_dm' in vals.keys()
+
+    # All the functions should be executed within five seconds at most
+    assert max_delta < 5
+
+
+def check_funcgraph(cons, fname, proftool, map_fname, trace_dat):
+    """Check that the 'funcgraph' output works
+
+    Args:
+        cons (ConsoleBase): U-Boot console
+        fname (str): Filename of trace file
+        proftool (str): Filename of proftool
+        map_fname (str): Filename of System.map
+        trace_dat (str): Filename of output file
+
+    Returns:
+        int: Time taken by the first part of the initf_dm() function, in us
+    """
+
+    # Generate the funcgraph format
+    out = util.run_and_log(
+        cons, [proftool, '-t', fname, '-o', trace_dat, '-m', map_fname,
+               'dump-ftrace', '-f', 'funcgraph'])
+
+    # Check that the trace has what we expect
+    cmd = f'trace-cmd report {trace_dat} |head -n 70'
+    out = util.run_and_log(cons, ['sh', '-c', cmd])
+
+    # First look for this:
+    #  u-boot-1     [000]   282.101360: funcgraph_entry:        0.004 us   |    initf_malloc();
+    # ...
+    #  u-boot-1     [000]   282.101369: funcgraph_entry:                   |    initf_bootstage() {
+    #  u-boot-1     [000]   282.101369: funcgraph_entry:                   |      bootstage_init() {
+    #  u-boot-1     [000]   282.101369: funcgraph_entry:                   |        dlmalloc() {
+    # ...
+    #  u-boot-1     [000]   282.101375: funcgraph_exit:         0.001 us   |        }
+    # Then look for this:
+    #  u-boot-1     [000]   282.101375: funcgraph_exit:         0.006 us   |      }
+    # Then check for this:
+    #  u-boot-1     [000]   282.101375: funcgraph_entry:        0.000 us   |    event_init();
+
+    expected_indent = None
+    found_start = False
+    found_end = False
+    upto = None
+
+    # Look for initf_bootstage() entry and make sure we see the exit
+    # Collect the time for initf_dm()
+    for line in out.splitlines():
+        m = RE_LINE.match(line)
+        if m:
+            timestamp, indent, func, brace = m.groups()
+            if found_end:
+                upto = func
+                break
+            elif func == 'initf_bootstage() ':
+                found_start = True
+                expected_indent = indent + '  '
+            elif found_start and indent == expected_indent and brace == '}':
+                found_end = True
+
+    # The next function after initf_bootstage() exits should be event_init()
+    assert upto == 'event_init()'
+
+    # Now look for initf_dm() and dm_timer_init() so we can check the bootstage
+    # time
+    cmd = f"trace-cmd report {trace_dat} |grep -E '(initf_dm|dm_timer_init)'"
+    out = util.run_and_log(cons, ['sh', '-c', cmd])
+
+    start_timestamp = None
+    end_timestamp = None
+    for line in out.splitlines():
+        m = RE_LINE.match(line)
+        if m:
+            timestamp, indent, func, brace = m.groups()
+            if func == 'initf_dm() ':
+                start_timestamp = timestamp
+            elif func == 'dm_timer_init() ':
+                end_timestamp = timestamp
+                break
+    assert start_timestamp and end_timestamp
+
+    # Convert the time to microseconds
+    return int((float(end_timestamp) - float(start_timestamp)) * 1000000)
+
+
+def check_flamegraph(cons, fname, proftool, map_fname, trace_fg):
+    """Check that the 'flamegraph' output works
+
+    This spot checks a few call counts and estimates the time taken by the
+    initf_dm() function
+
+    Args:
+        cons (ConsoleBase): U-Boot console
+        fname (str): Filename of trace file
+        proftool (str): Filename of proftool
+        map_fname (str): Filename of System.map
+        trace_fg (str): Filename of output file
+
+    Returns:
+        int: Approximate number of microseconds used by the initf_dm() function
+    """
+
+    # Generate the flamegraph format
+    out = util.run_and_log(
+        cons, [proftool, '-t', fname, '-o', trace_fg, '-m', map_fname,
+               'dump-flamegraph'])
+
+    # We expect dm_timer_init() to be called twice: once before relocation and
+    # once after
+    look1 = 'initf_dm;dm_timer_init 1'
+    look2 = 'board_init_r;initr_dm_devices;dm_timer_init 1'
+    found = 0
+    with open(trace_fg, 'r') as fd:
+        for line in fd:
+            line = line.strip()
+            if line == look1 or line == look2:
+                found += 1
+    assert found == 2
+
+    # Generate the timing graph
+    out = util.run_and_log(
+        cons, [proftool, '-t', fname, '-o', trace_fg, '-m', map_fname,
+               'dump-flamegraph', '-f', 'timing'])
+
+    # Add up all the time spend in initf_dm() and its children
+    total = 0
+    with open(trace_fg, 'r') as fd:
+        for line in fd:
+            line = line.strip()
+            if line.startswith('initf_dm'):
+                func, val = line.split()
+                count = int(val)
+                total += count
+    return total
+
+
+@pytest.mark.slow
+@pytest.mark.boardspec('sandbox')
+@pytest.mark.buildconfigspec('trace')
+def test_trace(u_boot_console):
+    """Test we can build sandbox with trace, collect and process a trace"""
+    cons = u_boot_console
+
+    if not os.path.exists(TMPDIR):
+        os.mkdir(TMPDIR)
+    proftool = os.path.join(cons.config.build_dir, 'tools', 'proftool')
+    map_fname = os.path.join(cons.config.build_dir, 'System.map')
+    trace_dat = os.path.join(TMPDIR, 'trace.dat')
+    trace_fg = os.path.join(TMPDIR, 'trace.fg')
+
+    fname, dm_f_time = collect_trace(cons)
+
+    check_function(cons, fname, proftool, map_fname, trace_dat)
+    trace_time = check_funcgraph(cons, fname, proftool, map_fname, trace_dat)
+
+    # Check that bootstage and funcgraph agree to within 10 microseconds
+    diff = abs(trace_time - dm_f_time)
+    print(f'trace_time {trace_time}, dm_f_time {dm_f_time}')
+    assert diff / dm_f_time < 0.01
+
+    fg_time = check_flamegraph(cons, fname, proftool, map_fname, trace_fg)
+
+    # Check that bootstage and flamegraph agree to within 10%
+    diff = abs(fg_time - dm_f_time)
+    assert diff / dm_f_time < 0.1
diff --git a/tools/Makefile b/tools/Makefile
index 041c437..e13effb 100644
--- a/tools/Makefile
+++ b/tools/Makefile
@@ -215,7 +215,10 @@ hostprogs-$(CONFIG_NETCONSOLE) += ncb
 
 hostprogs-$(CONFIG_ARCH_KIRKWOOD) += kwboot
 hostprogs-$(CONFIG_ARCH_MVEBU) += kwboot
+
 hostprogs-y += proftool
+proftool-objs = proftool.o lib/abuf.o
+
 hostprogs-$(CONFIG_STATIC_RELA) += relocate-rela
 hostprogs-$(CONFIG_RISCV) += prelink-riscv
 
diff --git a/tools/docker/Dockerfile b/tools/docker/Dockerfile
index 202a814..33e2bd2 100644
--- a/tools/docker/Dockerfile
+++ b/tools/docker/Dockerfile
@@ -2,7 +2,7 @@
 # This Dockerfile is used to build an image containing basic stuff to be used
 # to build U-Boot and run our test suites.
 
-FROM ubuntu:jammy-20221130
+FROM ubuntu:jammy-20230126
 MAINTAINER Tom Rini <trini@konsulko.com>
 LABEL Description=" This image is for building U-Boot inside a container"
 
@@ -173,7 +173,7 @@ RUN git clone git://git.savannah.gnu.org/grub.git /tmp/grub && \
 	true && \
 	rm -rf /tmp/grub
 
-RUN git clone git://git.qemu.org/qemu.git /tmp/qemu && \
+RUN git clone https://gitlab.com/qemu-project/qemu.git /tmp/qemu && \
 	cd /tmp/qemu && \
 	git submodule update --init dtc && \
 	git checkout v6.1.0 && \
@@ -213,6 +213,22 @@ RUN git clone https://github.com/stefanberger/swtpm /tmp/swtpm && \
 	make install && \
 	rm -rf /tmp/swtpm
 
+# Build trace-cmd
+RUN mkdir /tmp/trace && \
+    git clone https://git.kernel.org/pub/scm/libs/libtrace/libtraceevent.git /tmp/trace/libtraceevent && \
+    cd /tmp/trace/libtraceevent && \
+    make -j$(nproc) && \
+    sudo make install && \
+    git clone https://git.kernel.org/pub/scm/libs/libtrace/libtracefs.git /tmp/trace/libtracefs && \
+    cd /tmp/trace/libtracefs && \
+    make -j$(nproc) && \
+    sudo make install && \
+    git clone https://github.com/rostedt/trace-cmd.git /tmp/trace/trace-cmd && \
+    cd /tmp/trace/trace-cmd && \
+    make -j$(nproc) && \
+    sudo make install && \
+    rm -rf /tmp/trace
+
 # Create our user/group
 RUN echo uboot ALL=NOPASSWD: ALL > /etc/sudoers.d/uboot
 RUN useradd -m -U uboot
diff --git a/tools/proftool.c b/tools/proftool.c
index b66ea55..0893604 100644
--- a/tools/proftool.c
+++ b/tools/proftool.c
@@ -1,9 +1,15 @@
 // SPDX-License-Identifier: GPL-2.0+
 /*
- * Copyright (c) 2013 Google, Inc
+ * Copyright 2023 Google LLC
+ * Written by Simon Glass <sjg@chromium.org>
  */
 
-/* Decode and dump U-Boot profiling information */
+/*
+ * Decode and dump U-Boot trace information into formats that can be used
+ * by trace-cmd, kernelshark or flamegraph.pl
+ *
+ * See doc/develop/trace.rst for more information
+ */
 
 #include <assert.h>
 #include <ctype.h>
@@ -19,45 +25,240 @@
 
 #include <compiler.h>
 #include <trace.h>
+#include <abuf.h>
+
+#include <linux/list.h>
+
+/* Set to 1 to emit version 7 file (currently this doesn't work) */
+#define VERSION7	0
+
+/* enable some debug features */
+#define _DEBUG	0
+
+/* from linux/kernel.h */
+#define __ALIGN_MASK(x, mask)	(((x) + (mask)) & ~(mask))
+#define ALIGN(x, a)		__ALIGN_MASK((x), (typeof(x))(a) - 1)
 
-#define MAX_LINE_LEN 500
+/**
+ * container_of - cast a member of a structure out to the containing structure
+ * @ptr:	the pointer to the member.
+ * @type:	the type of the container struct this is embedded in.
+ * @member:	the name of the member within the struct.
+ *
+ * (this is needed by list.h)
+ */
+#define container_of(ptr, type, member) ({			\
+	const typeof( ((type *)0)->member ) *__mptr = (ptr);	\
+	(type *)( (char *)__mptr - offsetof(type,member) );})
 
 enum {
 	FUNCF_TRACE	= 1 << 0,	/* Include this function in trace */
+	TRACE_PAGE_SIZE	= 4096,		/* Assumed page size for trace */
+	TRACE_PID	= 1,		/* PID to use for U-Boot */
+	LEN_STACK_SIZE	= 4,		/* number of nested length fix-ups */
+	TRACE_PAGE_MASK	= TRACE_PAGE_SIZE - 1,
+	MAX_STACK_DEPTH	= 50,		/* Max nested function calls */
+	MAX_LINE_LEN	= 500,		/* Max characters per line */
+};
+
+/**
+ * enum out_format_t - supported output formats
+ *
+ * @OUT_FMT_DEFAULT: Use the default for the output file
+ * @OUT_FMT_FUNCTION: Write ftrace 'function' records
+ * @OUT_FMT_FUNCGRAPH: Write ftrace funcgraph_entry and funcgraph_exit records
+ * @OUT_FMT_FLAMEGRAPH_CALLS: Write a file suitable for flamegraph.pl
+ * @OUT_FMT_FLAMEGRAPH_TIMING: Write a file suitable for flamegraph.pl with the
+ * counts set to the number of microseconds used by each function
+ */
+enum out_format_t {
+	OUT_FMT_DEFAULT,
+	OUT_FMT_FUNCTION,
+	OUT_FMT_FUNCGRAPH,
+	OUT_FMT_FLAMEGRAPH_CALLS,
+	OUT_FMT_FLAMEGRAPH_TIMING,
+};
+
+/* Section types for v7 format (trace-cmd format) */
+enum {
+	SECTION_OPTIONS,
+};
+
+/* Option types (trace-cmd format) */
+enum {
+	OPTION_DONE,
+	OPTION_DATE,
+	OPTION_CPUSTAT,
+	OPTION_BUFFER,
+	OPTION_TRACECLOCK,
+	OPTION_UNAME,
+	OPTION_HOOK,
+	OPTION_OFFSET,
+	OPTION_CPUCOUNT,
+	OPTION_VERSION,
+	OPTION_PROCMAPS,
+	OPTION_TRACEID,
+	OPTION_TIME_SHIFT,
+	OPTION_GUEST,
+	OPTION_TSC2NSEC,
+};
+
+/* types of trace records (trace-cmd format) */
+enum trace_type {
+	__TRACE_FIRST_TYPE = 0,
+
+	TRACE_FN,
+	TRACE_CTX,
+	TRACE_WAKE,
+	TRACE_STACK,
+	TRACE_PRINT,
+	TRACE_BPRINT,
+	TRACE_MMIO_RW,
+	TRACE_MMIO_MAP,
+	TRACE_BRANCH,
+	TRACE_GRAPH_RET,
+	TRACE_GRAPH_ENT,
+};
+
+/**
+ * struct flame_node - a node in the call-stack tree
+ *
+ * Each stack frame detected in the trace is given a node corresponding to a
+ * function call in the call stack. Functions can appear multiple times when
+ * they are called by a different set of parent functions.
+ *
+ * @parent: Parent node (the call stack for the function that called this one)
+ * @child_head: List of children of this node (functions called from here)
+ * @sibling: Next node in the list of children
+ * @func: Function this node refers to (NULL for root node)
+ * @count: Number of times this call-stack occurred
+ * @duration: Number of microseconds taken to run this function, excluding all
+ * of the functions it calls
+ */
+struct flame_node {
+	struct flame_node *parent;
+	struct list_head child_head;
+	struct list_head sibling_node;
+	struct func_info *func;
+	int count;
+	ulong duration;
+};
+
+/**
+ * struct flame_state - state information for building the flame graph
+ *
+ * @node: Current node being processed (corresponds to a function call)
+ * @stack: Stack of call-start time for this function as well as the
+ * accumulated total time of all child calls (so we can subtract them from the
+ * function's call time. This is an 'empty' stack, meaning that @stack_ptr
+ * points to the next available stack position
+ * @stack_ptr: points to first empty position in the stack
+ * @nodes: Number of nodes created (running count)
+ */
+struct flame_state {
+	struct flame_node *node;
+	struct stack_info {
+		ulong timestamp;
+		ulong child_total;
+	} stack[MAX_STACK_DEPTH];
+	int stack_ptr;
+	int nodes;
 };
 
+/**
+ * struct func_info - information recorded for each function
+ *
+ * @offset: Function offset in the image, measured from the text_base
+ * @name: Function name
+ * @code_size: Total code size of the function
+ * @flags: Either 0 or FUNCF_TRACE
+ */
 struct func_info {
 	unsigned long offset;
 	const char *name;
 	unsigned long code_size;
-	unsigned long call_count;
 	unsigned flags;
-	/* the section this function is in */
-	struct objsection_info *objsection;
 };
 
+/**
+ * enum trace_line_type - whether to include or exclude a function
+ *
+ * @TRACE_LINE_INCLUDE: Include the function
+ * @TRACE_LINE_EXCLUDE: Exclude the function
+ */
 enum trace_line_type {
 	TRACE_LINE_INCLUDE,
 	TRACE_LINE_EXCLUDE,
 };
 
+/**
+ * struct trace_configline_info - information about a config-file line
+ *
+ * @next: Next line
+ * @type: Line type
+ * @name: identifier name / wildcard
+ * @regex: Regex to use if name starts with '/'
+ */
 struct trace_configline_info {
 	struct trace_configline_info *next;
 	enum trace_line_type type;
-	const char *name;	/* identifier name / wildcard */
-	regex_t regex;		/* Regex to use if name starts with / */
+	const char *name;
+	regex_t regex;
+};
+
+/**
+ * struct tw_len - holds information about a length value that need fix-ups
+ *
+ * This is used to record a placeholder for a u32 or u64 length which is written
+ * to the output file but needs to be updated once the length is actually known
+ *
+ * This allows us to write tw->ptr - @len_base to position @ptr in the file
+ *
+ * @ptr: Position of the length value in the file
+ * @base: Base position for the calculation
+ * @size: Size of the length value, in bytes (4 or 8)
+ */
+struct tw_len {
+	int ptr;
+	int base;
+	int size;
+};
+
+/**
+ * struct twriter - Writer for trace records
+ *
+ * Maintains state used when writing the output file in trace-cmd format
+ *
+ * @ptr: Current file position
+ * @len_stack: Stack of length values that need fixing up
+ * @len: Number of items on @len_stack
+ * @str_buf: Buffer of strings (for v7 format)
+ * @str_ptr: Current write-position in the buffer for strings
+ * @fout: Output file
+ */
+struct twriter {
+	int ptr;
+	struct tw_len len_stack[LEN_STACK_SIZE];
+	int len_count;
+	struct abuf str_buf;
+	int str_ptr;
+	FILE *fout;
 };
 
 /* The contents of the trace config file */
 struct trace_configline_info *trace_config_head;
 
+/* list of all functions in System.map file, sorted by offset in the image */
 struct func_info *func_list;
-int func_count;
-struct trace_call *call_list;
-int call_count;
+
+int func_count;			/* number of functions */
+struct trace_call *call_list;	/* list of all calls in the input trace file */
+int call_count;			/* number of calls */
 int verbose;	/* Verbosity level 0=none, 1=warn, 2=notice, 3=info, 4=debug */
-unsigned long text_offset;		/* text address of first function */
+ulong text_offset;		/* text address of first function */
+ulong text_base;		/* CONFIG_TEXT_BASE from trace file */
 
+/* debugging helpers */
 static void outf(int level, const char *fmt, ...)
 		__attribute__ ((format (__printf__, 2, 3)));
 #define error(fmt, b...) outf(0, fmt, ##b)
@@ -66,7 +267,6 @@ static void outf(int level, const char *fmt, ...)
 #define info(fmt, b...) outf(3, fmt, ##b)
 #define debug(fmt, b...) outf(4, fmt, ##b)
 
-
 static void outf(int level, const char *fmt, ...)
 {
 	if (verbose >= level) {
@@ -84,16 +284,34 @@ static void usage(void)
 		"Usage: proftool [-cmtv] <cmd> <profdata>\n"
 		"\n"
 		"Commands\n"
-		"   dump-ftrace\t\tDump out textual data in ftrace format\n"
+		"   dump-ftrace\t\tDump out records in ftrace format for use by trace-cmd\n"
+		"   dump-flamegraph\tWrite a file for use with flamegraph.pl\n"
 		"\n"
 		"Options:\n"
-		"   -c <cfg>\tSpecific config file\n"
+		"   -c <cfg>\tSpecify config file\n"
+		"   -f <subtype>\tSpecify output subtype\n"
 		"   -m <map>\tSpecify Systen.map file\n"
+		"   -o <fname>\tSpecify output file\n"
 		"   -t <fname>\tSpecify trace data file (from U-Boot 'trace calls')\n"
-		"   -v <0-4>\tSpecify verbosity\n");
+		"   -v <0-4>\tSpecify verbosity\n"
+		"\n"
+		"Subtypes for dump-ftrace:\n"
+		"   function - write function-call records (caller/callee)\n"
+		"   funcgraph - write function entry/exit records (graph)\n"
+		"\n"
+		"Subtypes for dump-flamegraph\n"
+		"   calls - create a flamegraph of stack frames\n"
+		"   timing - create a flamegraph of microseconds for each stack frame\n");
 	exit(EXIT_FAILURE);
 }
 
+/**
+ * h_cmp_offset - bsearch() function to compare two functions bny their offset
+ *
+ * @v1: Pointer to first function (struct func_info)
+ * @v2: Pointer to second function (struct func_info)
+ * Returns: < 0 if v1 offset < v2 offset, 0 if equal, > 0 otherwise
+ */
 static int h_cmp_offset(const void *v1, const void *v2)
 {
 	const struct func_info *f1 = v1, *f2 = v2;
@@ -101,6 +319,15 @@ static int h_cmp_offset(const void *v1, const void *v2)
 	return (f1->offset / FUNC_SITE_SIZE) - (f2->offset / FUNC_SITE_SIZE);
 }
 
+/**
+ * read_system_map() - read the System.map file to create a list of functions
+ *
+ * This also reads the text_offset value, since we assume that the first text
+ * symbol is at that address
+ *
+ * @fin: File to read
+ * Returns: 0 if OK, non-zero on error
+ */
 static int read_system_map(FILE *fin)
 {
 	unsigned long offset, start = 0;
@@ -150,8 +377,10 @@ static int read_system_map(FILE *fin)
 		if (func_count > 1)
 			func[-1].code_size = func->offset - func[-1].offset;
 	}
-	notice("%d functions found in map file\n", func_count);
+	notice("%d functions found in map file, start addr %lx\n", func_count,
+	       start);
 	text_offset = start;
+
 	return 0;
 }
 
@@ -163,13 +392,22 @@ static int read_data(FILE *fin, void *buff, int size)
 	if (!err)
 		return 1;
 	if (err != size) {
-		error("Cannot read profile file at pos %lx\n", ftell(fin));
+		error("Cannot read trace file at pos %lx\n", ftell(fin));
 		return -1;
 	}
 	return 0;
 }
 
-static struct func_info *find_func_by_offset(uint32_t offset)
+/**
+ * find_func_by_offset() - Look up a function by its offset
+ *
+ * @offset: Offset to search for, from text_base
+ * Returns: function, if found, else NULL
+ *
+ * This does a fast search for a function given its offset from text_base
+ *
+ */
+static struct func_info *find_func_by_offset(uint offset)
 {
 	struct func_info key, *found;
 
@@ -180,8 +418,17 @@ static struct func_info *find_func_by_offset(uint32_t offset)
 	return found;
 }
 
-/* This finds the function which contains the given offset */
-static struct func_info *find_caller_by_offset(uint32_t offset)
+/**
+ * find_caller_by_offset() - finds the function which contains the given offset
+ *
+ * @offset: Offset to search for, from text_base
+ * Returns: function, if found, else NULL
+ *
+ * If the offset falls between two functions, then it is assumed to belong to
+ * the first function (with the lowest offset). This is a way of figuring out
+ * which function owns code at a particular offset
+ */
+static struct func_info *find_caller_by_offset(uint offset)
 {
 	int low;	/* least function that could be a match */
 	int high;	/* greated function that could be a match */
@@ -206,6 +453,15 @@ static struct func_info *find_caller_by_offset(uint32_t offset)
 	return low >= 0 ? &func_list[low] : NULL;
 }
 
+/**
+ * read_calls() - Read the list of calls from the trace data
+ *
+ * The calls are stored consecutively in the trace output produced by U-Boot
+ *
+ * @fin: File to read from
+ * @count: Number of calls to read
+ * Returns: 0 if OK, -1 on error
+ */
 static int read_calls(FILE *fin, size_t count)
 {
 	struct trace_call *call_data;
@@ -222,16 +478,24 @@ static int read_calls(FILE *fin, size_t count)
 	call_data = call_list;
 	for (i = 0; i < count; i++, call_data++) {
 		if (read_data(fin, call_data, sizeof(*call_data)))
-			return 1;
+			return -1;
 	}
 	return 0;
 }
 
-static int read_profile(FILE *fin, int *not_found)
+/**
+ * read_trace() - Read the U-Boot trace file
+ *
+ * Read in the calls from the trace file. The function list is ignored at
+ * present
+ *
+ * @fin: File to read
+ * Returns 0 if OK, non-zero on error
+ */
+static int read_trace(FILE *fin)
 {
 	struct trace_output_hdr hdr;
 
-	*not_found = 0;
 	while (!feof(fin)) {
 		int err;
 
@@ -240,6 +504,7 @@ static int read_profile(FILE *fin, int *not_found)
 			break; /* EOF */
 		else if (err)
 			return 1;
+		text_base = hdr.text_base;
 
 		switch (hdr.type) {
 		case TRACE_CHUNK_FUNCS:
@@ -255,6 +520,14 @@ static int read_profile(FILE *fin, int *not_found)
 	return 0;
 }
 
+/**
+ * read_map_file() - Read the System.map file
+ *
+ * This reads the file into the func_list array
+ *
+ * @fname: Filename to read
+ * Returns 0 if OK, non-zero on error
+ */
 static int read_map_file(const char *fname)
 {
 	FILE *fmap;
@@ -272,28 +545,30 @@ static int read_map_file(const char *fname)
 	return err;
 }
 
-static int read_profile_file(const char *fname)
+/**
+ * read_trace_file() - Open and read the U-Boot trace file
+ *
+ * Read in the calls from the trace file. The function list is ignored at
+ * present
+ *
+ * @fin: File to read
+ * Returns 0 if OK, non-zero on error
+ */
+static int read_trace_file(const char *fname)
 {
-	int not_found = INT_MAX;
 	FILE *fprof;
 	int err;
 
 	fprof = fopen(fname, "rb");
 	if (!fprof) {
-		error("Cannot open profile data file '%s'\n",
+		error("Cannot open trace data file '%s'\n",
 		      fname);
 		return 1;
 	} else {
-		err = read_profile(fprof, &not_found);
+		err = read_trace(fprof);
 		fclose(fprof);
 		if (err)
 			return err;
-
-		if (not_found) {
-			warn("%d profile functions could not be found in the map file - are you sure that your profile data and map file correspond?\n",
-			     not_found);
-			return 1;
-		}
 	}
 	return 0;
 }
@@ -344,6 +619,7 @@ static void check_trace_config_line(struct trace_configline_info *item)
 	}
 }
 
+/** check_trace_config() - Check trace-config file, reporting any problems */
 static void check_trace_config(void)
 {
 	struct trace_configline_info *line;
@@ -353,30 +629,20 @@ static void check_trace_config(void)
 }
 
 /**
- * Check the functions to see if they each have an objsection. If not, then
- * the linker must have eliminated them.
+ * read_trace_config() - read the trace-config file
+ *
+ * This file consists of lines like:
+ *
+ * include-func <regex>
+ * exclude-func <regex>
+ *
+ * where <regex> is a regular expression matched against function names. It
+ * allows some functions to be dropped from the trace when producing ftrace
+ * records
+ *
+ * @fin: File to process
+ * Returns: 0 if OK, -1 on error
  */
-static void check_functions(void)
-{
-	struct func_info *func, *end;
-	unsigned long removed_code_size = 0;
-	int not_found = 0;
-
-	/* Look for missing functions */
-	for (func = func_list, end = func + func_count; func < end; func++) {
-		if (!func->objsection) {
-			removed_code_size += func->code_size;
-			not_found++;
-		}
-	}
-
-	/* Figure out what functions we want to trace */
-	check_trace_config();
-
-	warn("%d functions removed by linker, %ld code size\n",
-	     not_found, removed_code_size);
-}
-
 static int read_trace_config(FILE *fin)
 {
 	char buff[200];
@@ -400,8 +666,7 @@ static int read_trace_config(FILE *fin)
 		if (!*s || *s == '#')
 			continue;
 
-		line = (struct trace_configline_info *)calloc(1,
-							      sizeof(*line));
+		line = (struct trace_configline_info *)calloc(1, sizeof(*line));
 		if (!line) {
 			error("Cannot allocate config line\n");
 			return -1;
@@ -468,56 +733,621 @@ static int read_trace_config_file(const char *fname)
 	return err;
 }
 
-static void out_func(ulong func_offset, int is_caller, const char *suffix)
+/**
+ * tputh() - Write a 16-bit little-endian value to a file
+ *
+ * @fout: File to write to
+ * @val: Value to write
+ * Returns: number of bytes written (2)
+ */
+static int tputh(FILE *fout, unsigned int val)
 {
-	struct func_info *func;
+	fputc(val, fout);
+	fputc(val >> 8, fout);
 
-	func = (is_caller ? find_caller_by_offset : find_func_by_offset)
-		(func_offset);
+	return 2;
+}
 
-	if (func)
-		printf("%s%s", func->name, suffix);
-	else
-		printf("%lx%s", func_offset, suffix);
+/**
+ * tputl() - Write a 32-bit little-endian value to a file
+ *
+ * @fout: File to write to
+ * @val: Value to write
+ * Returns: number of bytes written (4)
+ */
+static int tputl(FILE *fout, ulong val)
+{
+	fputc(val, fout);
+	fputc(val >> 8, fout);
+	fputc(val >> 16, fout);
+	fputc(val >> 24, fout);
+
+	return 4;
 }
 
-/*
- * # tracer: function
- * #
- * #           TASK-PID   CPU#    TIMESTAMP  FUNCTION
- * #              | |      |          |         |
- * #           bash-4251  [01] 10152.583854: path_put <-path_walk
- * #           bash-4251  [01] 10152.583855: dput <-path_put
- * #           bash-4251  [01] 10152.583855: _atomic_dec_and_lock <-dput
+/**
+ * tputh() - Write a 64-bit little-endian value to a file
+ *
+ * @fout: File to write to
+ * @val: Value to write
+ * Returns: number of bytes written (8)
  */
-static int make_ftrace(void)
+static int tputq(FILE *fout, unsigned long long val)
+{
+	tputl(fout, val);
+	tputl(fout, val >> 32U);
+
+	return 8;
+}
+
+/**
+ * tputh() - Write a string to a file
+ *
+ * The string is written without its terminator
+ *
+ * @fout: File to write to
+ * @val: Value to write
+ * Returns: number of bytes written
+ */
+static int tputs(FILE *fout, const char *str)
+{
+	fputs(str, fout);
+
+	return strlen(str);
+}
+
+/**
+ * add_str() - add a name string to the string table
+ *
+ * This is used by the v7 format
+ *
+ * @tw: Writer context
+ * @name: String to write
+ * Returns: Updated value of string pointer, or -1 if out of memory
+ */
+static int add_str(struct twriter *tw, const char *name)
+{
+	int str_ptr;
+	int len;
+
+	len = strlen(name) + 1;
+	str_ptr = tw->str_ptr;
+	tw->str_ptr += len;
+
+	if (tw->str_ptr > abuf_size(&tw->str_buf)) {
+		int new_size;
+
+		new_size = ALIGN(tw->str_ptr, 4096);
+		if (!abuf_realloc(&tw->str_buf, new_size))
+			return -1;
+	}
+
+	return str_ptr;
+}
+
+/**
+ * push_len() - Push a new length request onto the stack
+ *
+ * @tw: Writer context
+ * @base: Base position of the length calculation
+ * @msg: Indicates the type of caller, for debugging
+ * @size: Size of the length value, either 4 bytes or 8
+ * Returns number of bytes written to the file (=@size on success), -ve on error
+ *
+ * This marks a place where a length must be written, covering data that is
+ * about to be written. It writes a placeholder value.
+ *
+ * Once the data is written, calling pop_len() will update the placeholder with
+ * the correct length based on how many bytes have been written
+ */
+static int push_len(struct twriter *tw, int base, const char *msg, int size)
+{
+	struct tw_len *lp;
+
+	if (tw->len_count >= LEN_STACK_SIZE) {
+		fprintf(stderr, "Length-stack overflow: %s\n", msg);
+		return -1;
+	}
+	if (size != 4 && size != 8) {
+		fprintf(stderr, "Length-stack invalid size %d: %s\n", size,
+			msg);
+		return -1;
+	}
+
+	lp = &tw->len_stack[tw->len_count++];
+	lp->base = base;
+	lp->ptr = tw->ptr;
+	lp->size = size;
+
+	return size == 8 ? tputq(tw->fout, 0) : tputl(tw->fout, 0);
+}
+
+/**
+ * pop_len() - Update a length value once the length is known
+ *
+ * Pops a value of the length stack and updates the file at that position with
+ * the number of bytes written between now and then. Once done, the file is
+ * seeked to the current (tw->ptr) position again, so writing can continue as
+ * normal.
+ *
+ * @tw: Writer context
+ * @msg: Indicates the type of caller, for debugging
+ * Returns 0 if OK, -1 on error
+ */
+static int pop_len(struct twriter *tw, const char *msg)
+{
+	struct tw_len *lp;
+	int len, ret;
+
+	if (!tw->len_count) {
+		fprintf(stderr, "Length-stack underflow: %s\n", msg);
+		return -1;
+	}
+
+	lp = &tw->len_stack[--tw->len_count];
+	if (fseek(tw->fout, lp->ptr, SEEK_SET))
+		return -1;
+	len = tw->ptr - lp->base;
+	ret = lp->size == 8 ? tputq(tw->fout, len) : tputl(tw->fout, len);
+	if (ret < 0)
+		return -1;
+	if (fseek(tw->fout, tw->ptr, SEEK_SET))
+		return -1;
+
+	return 0;
+}
+
+/**
+ * start_header() - Start a v7 section
+ *
+ * Writes a header in v7 format
+ *
+ * @tw: Writer context
+ * @id: ID of header to write (SECTION_...)
+ * @flags: Flags value to write
+ * @name: Name of section
+ * Returns: number of bytes written
+ */
+static int start_header(struct twriter *tw, int id, uint flags,
+			const char *name)
+{
+	int str_id;
+	int lptr;
+	int base;
+	int ret;
+
+	base = tw->ptr + 16;
+	lptr = 0;
+	lptr += tputh(tw->fout, id);
+	lptr += tputh(tw->fout, flags);
+	str_id = add_str(tw, name);
+	if (str_id < 0)
+		return -1;
+	lptr += tputl(tw->fout, str_id);
+
+	/* placeholder for size */
+	ret = push_len(tw, base, "v7 header", 8);
+	if (ret < 0)
+		return -1;
+	lptr += ret;
+
+	return lptr;
+}
+
+/**
+ * start_page() - Start a new page of output data
+ *
+ * The output is arranged in 4KB pages with a base timestamp at the start of
+ * each. This starts a new page, making sure it is aligned to 4KB in the output
+ * file.
+ *
+ * @tw: Writer context
+ * @timestamp: Base timestamp for the page
+ */
+static int start_page(struct twriter *tw, ulong timestamp)
+{
+	int start;
+	int ret;
+
+	/* move to start of next page */
+	start = ALIGN(tw->ptr, TRACE_PAGE_SIZE);
+	ret = fseek(tw->fout, start, SEEK_SET);
+	if (ret < 0) {
+		fprintf(stderr, "Cannot seek to page start\n");
+		return -1;
+	}
+	tw->ptr = start;
+
+	/* page header */
+	tw->ptr += tputq(tw->fout, timestamp);
+	ret = push_len(tw, start + 16, "page", 8);
+	if (ret < 0)
+		return ret;
+	tw->ptr += ret;
+
+	return 0;
+}
+
+/**
+ * finish_page() - finish a page
+ *
+ * Sets the lengths correctly and moves to the start of the next page
+ *
+ * @tw: Writer context
+ * Returns: 0 on success, -1 on error
+ */
+static int finish_page(struct twriter *tw)
+{
+	int ret, end;
+
+	ret = pop_len(tw, "page");
+	if (ret < 0)
+		return ret;
+	end = ALIGN(tw->ptr, TRACE_PAGE_SIZE);
+
+	/*
+	 * Write a byte so that the data actually makes to the file, in the case
+	 * that we never write any more pages
+	 */
+	if (tw->ptr != end) {
+		if (fseek(tw->fout, end - 1, SEEK_SET)) {
+			fprintf(stderr, "cannot seek to start of next page\n");
+			return -1;
+		}
+		fputc(0, tw->fout);
+		tw->ptr = end;
+	}
+
+	return 0;
+}
+
+/**
+ * output_headers() - Output v6 headers to the file
+ *
+ * Writes out the various formats so that trace-cmd and kernelshark can make
+ * sense of the data
+ *
+ * This updates tw->ptr as it goes
+ *
+ * @tw: Writer context
+ * Returns: 0 on success, -ve on error
+ */
+static int output_headers(struct twriter *tw)
+{
+	FILE *fout = tw->fout;
+	char str[800];
+	int len, ret;
+
+	tw->ptr += fprintf(fout, "%c%c%ctracing6%c%c%c", 0x17, 0x08, 0x44,
+			   0 /* terminator */, 0 /* little endian */,
+			   4 /* 32-bit long values */);
+
+	/* host-machine page size 4KB */
+	tw->ptr += tputl(fout, 4 << 10);
+
+	tw->ptr += fprintf(fout, "header_page%c", 0);
+
+	snprintf(str, sizeof(str),
+		 "\tfield: u64 timestamp;\toffset:0;\tsize:8;\tsigned:0;\n"
+		 "\tfield: local_t commit;\toffset:8;\tsize:8;\tsigned:1;\n"
+		 "\tfield: int overwrite;\toffset:8;\tsize:1;\tsigned:1;\n"
+		 "\tfield: char data;\toffset:16;\tsize:4080;\tsigned:1;\n");
+	len = strlen(str);
+	tw->ptr += tputq(fout, len);
+	tw->ptr += tputs(fout, str);
+
+	if (VERSION7) {
+		/* no compression */
+		tw->ptr += fprintf(fout, "none%cversion%c\n", 0, 0);
+
+		ret = start_header(tw, SECTION_OPTIONS, 0, "options");
+		if (ret < 0) {
+			fprintf(stderr, "Cannot start option header\n");
+			return -1;
+		}
+		tw->ptr += ret;
+		tw->ptr += tputh(fout, OPTION_DONE);
+		tw->ptr += tputl(fout, 8);
+		tw->ptr += tputl(fout, 0);
+		ret = pop_len(tw, "t7 header");
+		if (ret < 0) {
+			fprintf(stderr, "Cannot finish option header\n");
+			return -1;
+		}
+	}
+
+	tw->ptr += fprintf(fout, "header_event%c", 0);
+	snprintf(str, sizeof(str),
+		 "# compressed entry header\n"
+		 "\ttype_len    :    5 bits\n"
+		 "\ttime_delta  :   27 bits\n"
+		 "\tarray       :   32 bits\n"
+		 "\n"
+		 "\tpadding     : type == 29\n"
+		 "\ttime_extend : type == 30\n"
+		 "\ttime_stamp : type == 31\n"
+		 "\tdata max type_len  == 28\n");
+	len = strlen(str);
+	tw->ptr += tputq(fout, len);
+	tw->ptr += tputs(fout, str);
+
+	/* number of ftrace-event-format files */
+	tw->ptr += tputl(fout, 3);
+
+	snprintf(str, sizeof(str),
+		 "name: function\n"
+		 "ID: 1\n"
+		 "format:\n"
+		 "\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n"
+		 "\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n"
+		 "\tfield:unsigned char common_preempt_count;\toffset:3;\tsize:1;signed:0;\n"
+		 "\tfield:int common_pid;\toffset:4;\tsize:4;\tsigned:1;\n"
+		 "\n"
+		 "\tfield:unsigned long ip;\toffset:8;\tsize:8;\tsigned:0;\n"
+		 "\tfield:unsigned long parent_ip;\toffset:16;\tsize:8;\tsigned:0;\n"
+		 "\n"
+		 "print fmt: \" %%ps <-- %%ps\", (void *)REC->ip, (void *)REC->parent_ip\n");
+	len = strlen(str);
+	tw->ptr += tputq(fout, len);
+	tw->ptr += tputs(fout, str);
+
+	snprintf(str, sizeof(str),
+		 "name: funcgraph_entry\n"
+		 "ID: 11\n"
+		 "format:\n"
+		 "\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n"
+		 "\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n"
+		 "\tfield:unsigned char common_preempt_count;\toffset:3;\tsize:1;signed:0;\n"
+		 "\tfield:int common_pid;\toffset:4;\tsize:4;\tsigned:1;\n"
+		 "\n"
+		 "\tfield:unsigned long func;\toffset:8;\tsize:8;\tsigned:0;\n"
+		 "\tfield:int depth;\toffset:16;\tsize:4;\tsigned:1;\n"
+		"\n"
+		 "print fmt: \"--> %%ps (%%d)\", (void *)REC->func, REC->depth\n");
+	len = strlen(str);
+	tw->ptr += tputq(fout, len);
+	tw->ptr += tputs(fout, str);
+
+	snprintf(str, sizeof(str),
+		 "name: funcgraph_exit\n"
+		 "ID: 10\n"
+		 "format:\n"
+		 "\tfield:unsigned short common_type;\toffset:0;\tsize:2;\tsigned:0;\n"
+		 "\tfield:unsigned char common_flags;\toffset:2;\tsize:1;\tsigned:0;\n"
+		 "\tfield:unsigned char common_preempt_count;\toffset:3;\tsize:1;signed:0;\n"
+		 "\tfield:int common_pid;\toffset:4;\tsize:4;\tsigned:1;\n"
+		 "\n"
+		 "\tfield:unsigned long func;\toffset:8;\tsize:8;\tsigned:0;\n"
+		 "\tfield:int depth;\toffset:16;\tsize:4;\tsigned:1;\n"
+		 "\tfield:unsigned int overrun;\toffset:20;\tsize:4;\tsigned:0;\n"
+		 "\tfield:unsigned long long calltime;\toffset:24;\tsize:8;\tsigned:0;\n"
+		 "\tfield:unsigned long long rettime;\toffset:32;\tsize:8;\tsigned:0;\n"
+		 "\n"
+		 "print fmt: \"<-- %%ps (%%d) (start: %%llx  end: %%llx) over: %%d\", (void *)REC->func, REC->depth, REC->calltime, REC->rettime, REC->depth\n");
+	len = strlen(str);
+	tw->ptr += tputq(fout, len);
+	tw->ptr += tputs(fout, str);
+
+	return 0;
+}
+
+/**
+ * write_symbols() - Write the symbols out
+ *
+ * Writes the symbol information in the following format to mimic the Linux
+ * /proc/kallsyms file:
+ *
+ * <address> T <name>
+ *
+ * This updates tw->ptr as it goes
+ *
+ * @tw: Writer context
+ * Returns: 0 on success, -ve on error
+ */
+static int write_symbols(struct twriter *tw)
+{
+	char str[200];
+	int ret, i;
+
+	/* write symbols */
+	ret = push_len(tw, tw->ptr + 4, "syms", 4);
+	if (ret < 0)
+		return -1;
+	tw->ptr += ret;
+	for (i = 0; i < func_count; i++) {
+		struct func_info *func = &func_list[i];
+
+		snprintf(str, sizeof(str), "%016lx T %s\n",
+			 text_offset + func->offset, func->name);
+		tw->ptr += tputs(tw->fout, str);
+	}
+	ret = pop_len(tw, "syms");
+	if (ret < 0)
+		return -1;
+	tw->ptr += ret;
+
+	return 0;
+}
+
+/**
+ * write_options() - Write the options out
+ *
+ * Writes various options which are needed or useful. We use OPTION_TSC2NSEC
+ * to indicates that values in the output need to be multiplied by 1000 since
+ * U-Boot's trace values are in microseconds.
+ *
+ * This updates tw->ptr as it goes
+ *
+ * @tw: Writer context
+ * Returns: 0 on success, -ve on error
+ */
+static int write_options(struct twriter *tw)
+{
+	FILE *fout = tw->fout;
+	char str[200];
+	int len;
+
+	/* trace_printk, 0 for now */
+	tw->ptr += tputl(fout, 0);
+
+	/* processes */
+	snprintf(str, sizeof(str), "%d u-boot\n", TRACE_PID);
+	len = strlen(str);
+	tw->ptr += tputq(fout, len);
+	tw->ptr += tputs(fout, str);
+
+	/* number of CPUs */
+	tw->ptr += tputl(fout, 1);
+
+	tw->ptr += fprintf(fout, "options  %c", 0);
+
+	/* traceclock */
+	tw->ptr += tputh(fout, OPTION_TRACECLOCK);
+	tw->ptr += tputl(fout, 0);
+
+	/* uname */
+	tw->ptr += tputh(fout, OPTION_UNAME);
+	snprintf(str, sizeof(str), "U-Boot");
+	len = strlen(str);
+	tw->ptr += tputl(fout, len);
+	tw->ptr += tputs(fout, str);
+
+	/* version */
+	tw->ptr += tputh(fout, OPTION_VERSION);
+	snprintf(str, sizeof(str), "unknown");
+	len = strlen(str);
+	tw->ptr += tputl(fout, len);
+	tw->ptr += tputs(fout, str);
+
+	/* trace ID */
+	tw->ptr += tputh(fout, OPTION_TRACEID);
+	tw->ptr += tputl(fout, 8);
+	tw->ptr += tputq(fout, 0x123456780abcdef0);
+
+	/* time conversion */
+	tw->ptr += tputh(fout, OPTION_TSC2NSEC);
+	tw->ptr += tputl(fout, 16);
+	tw->ptr += tputl(fout, 1000);	/* multiplier */
+	tw->ptr += tputl(fout, 0);	/* shift */
+	tw->ptr += tputq(fout, 0);	/* offset */
+
+	/* cpustat - bogus data for now, but at least it mentions the CPU */
+	tw->ptr += tputh(fout, OPTION_CPUSTAT);
+	snprintf(str, sizeof(str),
+		 "CPU: 0\n"
+		 "entries: 100\n"
+		 "overrun: 43565\n"
+		 "commit overrun: 0\n"
+		 "bytes: 3360\n"
+		 "oldest event ts: 963732.447752\n"
+		 "now ts: 963832.146824\n"
+		 "dropped events: 0\n"
+		 "read events: 42379\n");
+	len = strlen(str);
+	tw->ptr += tputl(fout, len);
+	tw->ptr += tputs(fout, str);
+
+	tw->ptr += tputh(fout, OPTION_DONE);
+
+	return 0;
+}
+
+/**
+ * calc_min_depth() - Calculate the minimum call depth from the call list
+ *
+ * Starting with a depth of 0, this works through the call list, adding 1 for
+ * each function call and subtracting 1 for each function return. Most likely
+ * the value ends up being negative, since the trace does not start at the
+ * very top of the call stack, e.g. main(), but some function called by that.
+ *
+ * This value can be used to calculate the depth value for the first call,
+ * such that it never goes negative for subsequent returns.
+ *
+ * Returns: minimum call depth (e.g. -2)
+ */
+static int calc_min_depth(void)
 {
 	struct trace_call *call;
-	int missing_count = 0, skip_count = 0;
-	int i;
+	int depth, min_depth, i;
 
-	printf("# tracer: function\n"
-	      "#\n"
-	      "# entries-in-buffer/entries-written: 140080/250280   #P:4\n"
-	      "#\n"
-	      "#                              _-----=> irqs-off\n"
-	      "#                             / _----=> need-resched\n"
-	      "#                            | / _---=> hardirq/softirq\n"
-	      "#                            || / _--=> preempt-depth\n"
-	      "#                            ||| /     delay\n"
-	      "#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION\n"
-	      "#              | |       |   ||||       |         |\n");
+	/* Calculate minimum depth */
+	depth = 0;
+	min_depth = 0;
 	for (i = 0, call = call_list; i < call_count; i++, call++) {
-		struct func_info *func = find_func_by_offset(call->func);
-		ulong time = call->flags & FUNCF_TIMESTAMP_MASK;
+		switch (TRACE_CALL_TYPE(call)) {
+		case FUNCF_ENTRY:
+			depth++;
+			break;
+		case FUNCF_EXIT:
+			depth--;
+			if (depth < min_depth)
+				min_depth = depth;
+			break;
+		}
+	}
 
-		if (TRACE_CALL_TYPE(call) != FUNCF_ENTRY &&
-		    TRACE_CALL_TYPE(call) != FUNCF_EXIT)
-			continue;
+	return min_depth;
+}
+
+/**
+ * write_pages() - Write the pages of trace data
+ *
+ * This works through all the calls, writing out as many pages of data as are
+ * needed.
+ *
+ * @tw: Writer context
+ * @out_format: Output format to use
+ * @missing_countp: Returns number of missing functions (not found in function
+ * list)
+ * @skip_countp: Returns number of skipped functions (excluded from trace)
+ *
+ * Returns: 0 on success, -ve on error
+ */
+static int write_pages(struct twriter *tw, enum out_format_t out_format,
+		       int *missing_countp, int *skip_countp)
+{
+	ulong func_stack[MAX_STACK_DEPTH];
+	int stack_ptr;	/* next free position in stack */
+	int upto, depth, page_upto, i;
+	int missing_count = 0, skip_count = 0;
+	struct trace_call *call;
+	ulong last_timestamp;
+	FILE *fout = tw->fout;
+	int last_delta = 0;
+	int err_count;
+	bool in_page;
+
+	in_page = false;
+	last_timestamp = 0;
+	upto = 0;
+	page_upto = 0;
+	err_count = 0;
+
+	/* maintain a stack of start times for calling functions */
+	stack_ptr = 0;
+
+	/*
+	 * The first thing in the trace may not be the top-level function, so
+	 * set the initial depth so that no function goes below depth 0
+	 */
+	depth = -calc_min_depth();
+	for (i = 0, call = call_list; i < call_count; i++, call++) {
+		bool entry = TRACE_CALL_TYPE(call) == FUNCF_ENTRY;
+		struct func_info *func;
+		ulong timestamp;
+		uint rec_words;
+		int delta;
+
+		func = find_func_by_offset(call->func);
 		if (!func) {
 			warn("Cannot find function at %lx\n",
 			     text_offset + call->func);
 			missing_count++;
+			if (missing_count > 20) {
+				/* perhaps trace does not match System.map */
+				fprintf(stderr, "Too many missing functions\n");
+				return -1;
+			}
 			continue;
 		}
 
@@ -528,40 +1358,563 @@ static int make_ftrace(void)
 			continue;
 		}
 
-		printf("%16s-%-5d [000] ....  %lu.%06lu: ", "uboot", 1,
-		       time / 1000000, time % 1000000);
+		if (out_format == OUT_FMT_FUNCTION)
+			rec_words = 6;
+		else /* 2 header words and then 3 or 8 others */
+			rec_words = 2 + (entry ? 3 : 8);
+
+		/* convert timestamp from us to ns */
+		timestamp = call->flags & FUNCF_TIMESTAMP_MASK;
+		if (in_page) {
+			if (page_upto + rec_words * 4 > TRACE_PAGE_SIZE) {
+				if (finish_page(tw))
+					return -1;
+				in_page = false;
+			}
+		}
+		if (!in_page) {
+			if (start_page(tw, timestamp))
+				return -1;
+			in_page = true;
+			last_timestamp = timestamp;
+			last_delta = 0;
+			page_upto = tw->ptr & TRACE_PAGE_MASK;
+			if (_DEBUG) {
+				fprintf(stderr,
+					"new page, last_timestamp=%ld, upto=%d\n",
+					last_timestamp, upto);
+			}
+		}
+
+		delta = timestamp - last_timestamp;
+		if (delta < 0) {
+			fprintf(stderr, "Time went backwards\n");
+			err_count++;
+		}
+
+		if (err_count > 20) {
+			fprintf(stderr, "Too many errors, giving up\n");
+			return -1;
+		}
+
+		if (delta > 0x07fffff) {
+			/*
+			 * hard to imagine how this could happen since it means
+			 * that no function calls were made for a long time
+			 */
+			fprintf(stderr, "cannot represent time delta %x\n",
+				delta);
+			return -1;
+		}
+
+		if (out_format == OUT_FMT_FUNCTION) {
+			struct func_info *caller_func;
+
+			if (_DEBUG) {
+				fprintf(stderr, "%d: delta=%d, stamp=%ld\n",
+					upto, delta, timestamp);
+				fprintf(stderr,
+					"   last_delta %x to %x: last_timestamp=%lx, "
+					"timestamp=%lx, call->flags=%x, upto=%d\n",
+					last_delta, delta, last_timestamp,
+					timestamp, call->flags, upto);
+			}
+
+			/* type_len is 6, meaning 4 * 6 = 24 bytes */
+			tw->ptr += tputl(fout, rec_words | (uint)delta << 5);
+			tw->ptr += tputh(fout, TRACE_FN);
+			tw->ptr += tputh(fout, 0);	/* flags */
+			tw->ptr += tputl(fout, TRACE_PID);	/* PID */
+			/* function */
+			tw->ptr += tputq(fout, text_offset + func->offset);
+			caller_func = find_caller_by_offset(call->caller);
+			/* caller */
+			tw->ptr += tputq(fout,
+					 text_offset + caller_func->offset);
+		} else {
+			tw->ptr += tputl(fout, rec_words | delta << 5);
+			tw->ptr += tputh(fout, entry ? TRACE_GRAPH_ENT
+						: TRACE_GRAPH_RET);
+			tw->ptr += tputh(fout, 0);	/* flags */
+			tw->ptr += tputl(fout, TRACE_PID); /* PID */
+			/* function */
+			tw->ptr += tputq(fout, text_offset + func->offset);
+			tw->ptr += tputl(fout, depth); /* depth */
+			if (entry) {
+				depth++;
+				if (stack_ptr < MAX_STACK_DEPTH)
+					func_stack[stack_ptr] = timestamp;
+				stack_ptr++;
+			} else {
+				ulong func_duration = 0;
+
+				depth--;
+				if (stack_ptr && stack_ptr <= MAX_STACK_DEPTH) {
+					ulong start = func_stack[--stack_ptr];
+
+					func_duration = timestamp - start;
+				}
+				tw->ptr += tputl(fout, 0);	/* overrun */
+				tw->ptr += tputq(fout, 0);	/* calltime */
+				/* rettime */
+				tw->ptr += tputq(fout, func_duration);
+			}
+		}
+
+		last_delta = delta;
+		last_timestamp = timestamp;
+		page_upto += 4 + rec_words * 4;
+		upto++;
+		if (stack_ptr == MAX_STACK_DEPTH)
+			break;
+	}
+	if (in_page && finish_page(tw))
+		return -1;
+	*missing_countp = missing_count;
+	*skip_countp = skip_count;
+
+	return 0;
+}
 
-		out_func(call->func, 0, " <- ");
-		out_func(call->caller, 1, "\n");
+/**
+ * write_flyrecord() - Write the flyrecord information
+ *
+ * Writes the header and pages of data for the "flyrecord" section. It also
+ * writes out the counter-type info, selecting "[local]"
+ *
+ * @tw: Writer context
+ * @out_format: Output format to use
+ * @missing_countp: Returns number of missing functions (not found in function
+ * list)
+ * @skip_countp: Returns number of skipped functions (excluded from trace)
+ *
+ * Returns: 0 on success, -ve on error
+ */
+static int write_flyrecord(struct twriter *tw, enum out_format_t out_format,
+			   int *missing_countp, int *skip_countp)
+{
+	int start, ret, len;
+	FILE *fout = tw->fout;
+	char str[200];
+
+	tw->ptr += fprintf(fout, "flyrecord%c", 0);
+
+	/* trace data */
+	start = ALIGN(tw->ptr + 16, TRACE_PAGE_SIZE);
+	tw->ptr += tputq(fout, start);
+
+	/* use a placeholder for the size */
+	ret = push_len(tw, start, "flyrecord", 8);
+	if (ret < 0)
+		return -1;
+	tw->ptr += ret;
+
+	snprintf(str, sizeof(str),
+		 "[local] global counter uptime perf mono mono_raw boot x86-tsc\n");
+	len = strlen(str);
+	tw->ptr += tputq(fout, len);
+	tw->ptr += tputs(fout, str);
+
+	debug("trace text base %lx, map file %lx\n", text_base, text_offset);
+
+	ret = write_pages(tw, out_format, missing_countp, skip_countp);
+	if (ret < 0) {
+		fprintf(stderr, "Cannot output pages\n");
+		return -1;
 	}
+
+	ret = pop_len(tw, "flyrecord");
+	if (ret < 0) {
+		fprintf(stderr, "Cannot finish flyrecord header\n");
+		return -1;
+	}
+
+	return 0;
+}
+
+/**
+ * make_ftrace() - Write out an ftrace file
+ *
+ * See here for format:
+ *
+ * https://github.com/rostedt/trace-cmd/blob/master/Documentation/trace-cmd/trace-cmd.dat.v7.5.txt
+ *
+ * @fout: Output file
+ * @out_format: Output format to use
+ * Returns: 0 on success, -ve on error
+ */
+static int make_ftrace(FILE *fout, enum out_format_t out_format)
+{
+	int missing_count, skip_count;
+	struct twriter tws, *tw = &tws;
+	int ret;
+
+	memset(tw, '\0', sizeof(*tw));
+	abuf_init(&tw->str_buf);
+	tw->fout = fout;
+
+	tw->ptr = 0;
+	ret = output_headers(tw);
+	if (ret < 0) {
+		fprintf(stderr, "Cannot output headers\n");
+		return -1;
+	}
+	/* number of event systems files */
+	tw->ptr += tputl(fout, 0);
+
+	ret = write_symbols(tw);
+	if (ret < 0) {
+		fprintf(stderr, "Cannot write symbols\n");
+		return -1;
+	}
+
+	ret = write_options(tw);
+	if (ret < 0) {
+		fprintf(stderr, "Cannot write options\n");
+		return -1;
+	}
+
+	ret = write_flyrecord(tw, out_format, &missing_count, &skip_count);
+	if (ret < 0) {
+		fprintf(stderr, "Cannot write flyrecord\n");
+		return -1;
+	}
+
 	info("ftrace: %d functions not found, %d excluded\n", missing_count,
 	     skip_count);
 
 	return 0;
 }
 
+/**
+ * create_node() - Create a new node in the flamegraph tree
+ *
+ * @msg: Message to use for debugging if something goes wrong
+ * Returns: Pointer to newly created node, or NULL on error
+ */
+static struct flame_node *create_node(const char *msg)
+{
+	struct flame_node *node;
+
+	node = calloc(1, sizeof(*node));
+	if (!node) {
+		fprintf(stderr, "Out of memory for %s\n", msg);
+		return NULL;
+	}
+	INIT_LIST_HEAD(&node->child_head);
+
+	return node;
+}
+
+/**
+ * process_call(): Add a call to the flamegraph info
+ *
+ * For function calls, if this call stack has been seen before, this increments
+ * the call count, creating a new node if needed.
+ *
+ * For function returns, it adds up the time spent in this call stack,
+ * subtracting the time spent by child functions.
+ *
+ * @state: Current flamegraph state
+ * @entry: true if this is a function entry, false if a function exit
+ * @timestamp: Timestamp from the trace file (in microseconds)
+ * @func: Function that was called/returned from
+ *
+ * Returns: 0 on success, -ve on error
+ */
+static int process_call(struct flame_state *state, bool entry, ulong timestamp,
+			struct func_info *func)
+{
+	struct flame_node *node = state->node;
+	int stack_ptr = state->stack_ptr;
+
+	if (entry) {
+		struct flame_node *child, *chd;
+
+		/* see if we have this as a child node already */
+		child = NULL;
+		list_for_each_entry(chd, &node->child_head, sibling_node) {
+			if (chd->func == func) {
+				child = chd;
+				break;
+			}
+		}
+		if (!child) {
+			/* create a new node */
+			child = create_node("child");
+			if (!child)
+				return -1;
+			list_add_tail(&child->sibling_node, &node->child_head);
+			child->func = func;
+			child->parent = node;
+			state->nodes++;
+		}
+		debug("entry %s: move from %s to %s\n", func->name,
+		      node->func ? node->func->name : "(root)",
+		      child->func->name);
+		child->count++;
+		if (stack_ptr < MAX_STACK_DEPTH) {
+			state->stack[stack_ptr].timestamp = timestamp;
+			state->stack[stack_ptr].child_total = 0;
+		}
+		debug("%d: %20s: entry at %ld\n", stack_ptr, func->name,
+		      timestamp);
+		stack_ptr++;
+		node = child;
+	} else if (node->parent) {
+		ulong total_duration = 0, child_duration = 0;
+		struct stack_info *stk;
+
+		debug("exit  %s: move from %s to %s\n", func->name,
+		      node->func->name, node->parent->func ?
+		      node->parent->func->name : "(root)");
+		if (stack_ptr && stack_ptr <= MAX_STACK_DEPTH) {
+			stk = &state->stack[--stack_ptr];
+
+			/*
+			 * get total duration of the function which just
+			 * exited
+			 */
+			total_duration = timestamp - stk->timestamp;
+			child_duration = stk->child_total;
+
+			if (stack_ptr)
+				state->stack[stack_ptr - 1].child_total += total_duration;
+
+			debug("%d: %20s: exit at %ld, total %ld, child %ld, child_total=%ld\n",
+			      stack_ptr, func->name, timestamp,
+			      total_duration, child_duration,
+			      stk->child_total);
+		}
+		node->duration += total_duration - child_duration;
+		node = node->parent;
+	}
+
+	state->stack_ptr = stack_ptr;
+	state->node = node;
+
+	return 0;
+}
+
+/**
+ * make_flame_tree() - Create a tree of stack traces
+ *
+ * Set up a tree, with the root node having the top-level functions as children
+ * and the leaf nodes being leaf functions. Each node has a count of how many
+ * times this function appears in the trace
+ *
+ * @out_format: Output format to use
+ * @treep: Returns the resulting flamegraph tree
+ * Returns: 0 on success, -ve on error
+ */
+static int make_flame_tree(enum out_format_t out_format,
+			   struct flame_node **treep)
+{
+	struct flame_state state;
+	struct flame_node *tree;
+	struct trace_call *call;
+	int missing_count = 0;
+	int i, depth;
+
+	/* maintain a stack of start times, etc. for 'calling' functions */
+	state.stack_ptr = 0;
+
+	/*
+	 * The first thing in the trace may not be the top-level function, so
+	 * set the initial depth so that no function goes below depth 0
+	 */
+	depth = -calc_min_depth();
+
+	tree = create_node("tree");
+	if (!tree)
+		return -1;
+	state.node = tree;
+	state.nodes = 0;
+
+	for (i = 0, call = call_list; i < call_count; i++, call++) {
+		bool entry = TRACE_CALL_TYPE(call) == FUNCF_ENTRY;
+		ulong timestamp = call->flags & FUNCF_TIMESTAMP_MASK;
+		struct func_info *func;
+
+		if (entry)
+			depth++;
+		else
+			depth--;
+
+		func = find_func_by_offset(call->func);
+		if (!func) {
+			warn("Cannot find function at %lx\n",
+			     text_offset + call->func);
+			missing_count++;
+			continue;
+		}
+
+		if (process_call(&state, entry, timestamp, func))
+			return -1;
+	}
+	fprintf(stderr, "%d nodes\n", state.nodes);
+	*treep = tree;
+
+	return 0;
+}
+
+/**
+ * output_tree() - Output a flamegraph tree
+ *
+ * Writes the tree out to a file in a format suitable for flamegraph.pl
+ *
+ * This works by maintaining a string shared across all recursive calls. The
+ * function name for this node is added to the existing string, to make up the
+ * full call-stack description. For example, on entry, @str might contain:
+ *
+ *    "initf_bootstage;bootstage_mark_name"
+ *                                        ^ @base
+ *
+ * with @base pointing to the \0 at the end of the string. This function adds
+ * a ';' following by the name of the current function, e.g. "timer_get_boot_us"
+ * as well as the output value, to get the full line:
+ *
+ * initf_bootstage;bootstage_mark_name;timer_get_boot_us 123
+ *
+ * @fout: Output file
+ * @out_format: Output format to use
+ * @node: Node to output (pass the whole tree at first)
+ * @str: String to use to build the output line (e.g. 500 charas long)
+ * @maxlen: Maximum length of string
+ * @base: Current base position in the string
+ * @treep: Returns the resulting flamegraph tree
+ * Returns 0 if OK, -1 on error
+ */
+static int output_tree(FILE *fout, enum out_format_t out_format,
+		       const struct flame_node *node, char *str, int maxlen,
+		       int base)
+{
+	const struct flame_node *child;
+	int pos;
+
+	if (node->count) {
+		if (out_format == OUT_FMT_FLAMEGRAPH_CALLS) {
+			fprintf(fout, "%s %d\n", str, node->count);
+		} else {
+			/*
+			 * Write out the number of microseconds used by this
+			 * call stack. Since the time taken by child calls is
+			 * subtracted from this total, it can reach 0, meaning
+			 * that this function took no time beyond what its
+			 * children used. For this case, write 1 rather than 0,
+			 * so that this call stack appears in the flamegraph.
+			 * This has the effect of inflating the timing slightly,
+			 * but only by at most 1 microsecond per function,
+			 * assuming that is the timestamp resolution
+			 */
+			fprintf(fout, "%s %ld\n", str,
+				node->duration ? node->duration : 1);
+		}
+	}
+
+	pos = base;
+	if (pos)
+		str[pos++] = ';';
+	list_for_each_entry(child, &node->child_head, sibling_node) {
+		int len;
+
+		len = strlen(child->func->name);
+		if (pos + len + 1 >= maxlen) {
+			fprintf(stderr, "String too short (%d chars)\n",
+				maxlen);
+			return -1;
+		}
+		strcpy(str + pos, child->func->name);
+		if (output_tree(fout, out_format, child, str, maxlen,
+				pos + len))
+			return -1;
+	}
+
+	return 0;
+}
+
+/**
+ * make_flamegraph() - Write out a flame graph
+ *
+ * @fout: Output file
+ * @out_format: Output format to use, e.g. function counts or timing
+ * Returns 0 if OK, -1 on error
+ */
+static int make_flamegraph(FILE *fout, enum out_format_t out_format)
+{
+	struct flame_node *tree;
+	char str[500];
+
+	if (make_flame_tree(out_format, &tree))
+		return -1;
+
+	*str = '\0';
+	if (output_tree(fout, out_format, tree, str, sizeof(str), 0))
+		return -1;
+
+	return 0;
+}
+
+/**
+ * prof_tool() - Performs requested action
+ *
+ * @argc: Number of arguments (used to obtain the command
+ * @argv: List of arguments
+ * @trace_fname: Filename of input file (trace data from U-Boot)
+ * @map_fname: Filename of map file (System.map from U-Boot)
+ * @trace_config_fname: Trace-configuration file, or NULL if none
+ * @out_fname: Output filename
+ */
 static int prof_tool(int argc, char *const argv[],
-		     const char *prof_fname, const char *map_fname,
-		     const char *trace_config_fname)
+		     const char *trace_fname, const char *map_fname,
+		     const char *trace_config_fname, const char *out_fname,
+		     enum out_format_t out_format)
 {
 	int err = 0;
 
 	if (read_map_file(map_fname))
 		return -1;
-	if (prof_fname && read_profile_file(prof_fname))
+	if (trace_fname && read_trace_file(trace_fname))
 		return -1;
 	if (trace_config_fname && read_trace_config_file(trace_config_fname))
 		return -1;
 
-	check_functions();
+	check_trace_config();
 
 	for (; argc; argc--, argv++) {
 		const char *cmd = *argv;
 
-		if (0 == strcmp(cmd, "dump-ftrace"))
-			err = make_ftrace();
-		else
+		if (!strcmp(cmd, "dump-ftrace")) {
+			FILE *fout;
+
+			if (out_format != OUT_FMT_FUNCTION &&
+			    out_format != OUT_FMT_FUNCGRAPH)
+				out_format = OUT_FMT_FUNCTION;
+			fout = fopen(out_fname, "w");
+			if (!fout) {
+				fprintf(stderr, "Cannot write file '%s'\n",
+					out_fname);
+				return -1;
+			}
+			err = make_ftrace(fout, out_format);
+			fclose(fout);
+		} else if (!strcmp(cmd, "dump-flamegraph")) {
+			FILE *fout;
+
+			if (out_format != OUT_FMT_FLAMEGRAPH_CALLS &&
+			    out_format != OUT_FMT_FLAMEGRAPH_TIMING)
+				out_format = OUT_FMT_FLAMEGRAPH_CALLS;
+			fout = fopen(out_fname, "w");
+			if (!fout) {
+				fprintf(stderr, "Cannot write file '%s'\n",
+					out_fname);
+				return -1;
+			}
+			err = make_flamegraph(fout, out_format);
+			fclose(fout);
+		} else {
 			warn("Unknown command '%s'\n", cmd);
+		}
 	}
 
 	return err;
@@ -569,30 +1922,46 @@ static int prof_tool(int argc, char *const argv[],
 
 int main(int argc, char *argv[])
 {
+	enum out_format_t out_format = OUT_FMT_DEFAULT;
 	const char *map_fname = "System.map";
 	const char *trace_fname = NULL;
 	const char *config_fname = NULL;
+	const char *out_fname = NULL;
 	int opt;
 
 	verbose = 2;
-	while ((opt = getopt(argc, argv, "c:m:t:v:")) != -1) {
+	while ((opt = getopt(argc, argv, "c:f:m:o:t:v:")) != -1) {
 		switch (opt) {
 		case 'c':
 			config_fname = optarg;
 			break;
-
+		case 'f':
+			if (!strcmp("function", optarg)) {
+				out_format = OUT_FMT_FUNCTION;
+			} else if (!strcmp("funcgraph", optarg)) {
+				out_format = OUT_FMT_FUNCGRAPH;
+			} else if (!strcmp("calls", optarg)) {
+				out_format = OUT_FMT_FLAMEGRAPH_CALLS;
+			} else if (!strcmp("timing", optarg)) {
+				out_format = OUT_FMT_FLAMEGRAPH_TIMING;
+			} else {
+				fprintf(stderr,
+					"Invalid format: use function, funcgraph, calls, timing\n");
+				exit(1);
+			}
+			break;
 		case 'm':
 			map_fname = optarg;
 			break;
-
+		case 'o':
+			out_fname = optarg;
+			break;
 		case 't':
 			trace_fname = optarg;
 			break;
-
 		case 'v':
 			verbose = atoi(optarg);
 			break;
-
 		default:
 			usage();
 		}
@@ -601,6 +1970,13 @@ int main(int argc, char *argv[])
 	if (argc < 1)
 		usage();
 
+	if (!out_fname || !map_fname || !trace_fname) {
+		fprintf(stderr,
+			"Must provide trace data, System.map file and output file\n");
+		usage();
+	}
+
 	debug("Debug enabled\n");
-	return prof_tool(argc, argv, trace_fname, map_fname, config_fname);
+	return prof_tool(argc, argv, trace_fname, map_fname, config_fname,
+			 out_fname, out_format);
 }