[bootlin/training-materials updates] master: Boot time lab: measuring in software (aea9fd4d)
Michael Opdenacker
michael.opdenacker at bootlin.com
Sat May 18 17:42:49 CEST 2019
Repository : https://github.com/bootlin/training-materials
On branch : master
Link : https://github.com/bootlin/training-materials/commit/aea9fd4da6378ab8f8b3de72457a9953a6a53f77
>---------------------------------------------------------------
commit aea9fd4da6378ab8f8b3de72457a9953a6a53f77
Author: Michael Opdenacker <michael.opdenacker at bootlin.com>
Date: Sat May 18 17:42:49 2019 +0200
Boot time lab: measuring in software
Signed-off-by: Michael Opdenacker <michael.opdenacker at bootlin.com>
>---------------------------------------------------------------
aea9fd4da6378ab8f8b3de72457a9953a6a53f77
...ffmpeg-log-notification-after-first-frame.patch | 40 ++++++
.../boot-time-software-measurement.tex | 149 +++++++++++++++++++++
mk/boot-time.mk | 1 +
slides/boottime-measuring/boottime-measuring.tex | 12 +-
4 files changed, 196 insertions(+), 6 deletions(-)
diff --git a/lab-data/boot-time/rootfs/data/0001-ffmpeg-log-notification-after-first-frame.patch b/lab-data/boot-time/rootfs/data/0001-ffmpeg-log-notification-after-first-frame.patch
new file mode 100644
index 00000000..0d7bc382
--- /dev/null
+++ b/lab-data/boot-time/rootfs/data/0001-ffmpeg-log-notification-after-first-frame.patch
@@ -0,0 +1,40 @@
+From 0f944b031028f1226cda114fc7338e944c7a7e2e Mon Sep 17 00:00:00 2001
+From: Michael Opdenacker <michael.opdenacker at bootlin.com>
+Date: Fri, 17 May 2019 19:41:49 +0200
+Subject: [PATCH] ffmpeg log notification after first frame
+
+This writes to the application log after the first frame
+has been decoded and displayed.
+
+Signed-off-by: Michael Opdenacker <michael.opdenacker at bootlin.com>
+---
+ fftools/ffmpeg.c | 6 ++++++
+ 1 file changed, 6 insertions(+)
+
+diff --git a/fftools/ffmpeg.c b/fftools/ffmpeg.c
+index 01f04103cf..787e98948a 100644
+--- a/fftools/ffmpeg.c
++++ b/fftools/ffmpeg.c
+@@ -4659,6 +4659,7 @@ static int transcode(void)
+ InputStream *ist;
+ int64_t timer_start;
+ int64_t total_packets_written = 0;
++ static int framecounter=0;
+
+ ret = transcode_init();
+ if (ret < 0)
+@@ -4696,6 +4697,11 @@ static int transcode(void)
+ }
+
+ /* dump report by using the output first video and audio streams */
++ // Bootlin hack to signal when the first frame has been decoded
++ if (framecounter++==0) {
++ // Log on console
++ av_log(NULL, AV_LOG_INFO, "First frame decoded!\n");
++ }
+ print_report(0, timer_start, cur_time);
+ }
+ #if HAVE_THREADS
+--
+2.17.1
+
diff --git a/labs/boot-time-software-measurement/boot-time-software-measurement.tex b/labs/boot-time-software-measurement/boot-time-software-measurement.tex
new file mode 100644
index 00000000..b4e1df96
--- /dev/null
+++ b/labs/boot-time-software-measurement/boot-time-software-measurement.tex
@@ -0,0 +1,149 @@
+\subchapter{Measure boot time - Software solution}{Objective: measure
+boot time with software only solutions}
+
+During this lab, we will use techniques to measure boot time using only
+software solutions.
+
+\section{Timing messages on the serial console}
+
+Let's use \code{grabserial} to time all the messages received in the
+serial console, from the first stage bootloader to launching the final
+application.
+
+A prerequisite is to install the \code{python-serial} package:
+\begin{verbatim}
+sudo apt install python-serial
+\end{verbatim}
+
+Then download the \code{grabserial} executable from
+\url{https://github.com/tbird20d/grabserial}:
+
+\begin{verbatim}
+wget https://raw.githubusercontent.com/tbird20d/grabserial/master/grabserial
+sudo mv grabserial /usr/local/bin
+sudo chmod a+rx /usr/local/bin/grabserial
+\end{verbatim}
+
+We are now ready to time the messages in the serial console. First, exit
+from Picocom (\code{[Ctrl][a] [Ctrl][x]}). Then, power off your board,
+remove its USB power supply and run:
+
+\begin{verbatim}
+grabserial -d /dev/ttyUSB0 -t -e 30
+\end{verbatim}
+
+\begin{itemize}
+\item \code{-t} Displays the time when the first character of each line
+was received.
+\item \code{-e} Specifies the {\bf e}end time when \code{grabserial}
+will exit.
+\end{itemize}
+
+Now, insert the USB power cable and see the console messages with their
+timing information:
+
+\begin{verbatim}
+[0.000001 0.000001]
+[0.000235 0.000234] U-Boot SPL 2019.01 (May 17 2019 - 05:15:21 +0200)
+[0.058954 0.058719] Trying to boot from MMC1
+[0.128419 0.069465] Loading Environment from FAT... *** Warning - bad CRC, using default environment
+[0.153105 0.024686]
+[0.169676 0.016571] Loading Environment from MMC... OK
+[0.523465 0.353789]
+[0.523647 0.000182]
+[0.523722 0.000075] U-Boot 2019.01 (May 17 2019 - 05:15:21 +0200)
+...
+\end{verbatim}
+
+As you can see, the time to start U-Boot SPL can be neglected. We can
+the \code{U-Boot SPL} string as a reference point for timing. This way,
+we don't have to power off the board every time we wish to make a
+measurement. Resetting the board will be sufficient.
+
+So, let's run \code{grabserial} again:
+
+\begin{verbatim}
+grabserial -d /dev/ttyUSB0 -m "U-Boot SPL" -t -e 30
+\end{verbatim}
+
+\section{Timing the execution of the application}
+
+Bootlin prepared a patch to \code{ffmpeg} to issue a message in its logs
+after decoding and displaying the first frame. Let's instruct Buildroot
+to apply it!
+
+\begin{verbatim}
+mkdir -p board/beaglecam/patches/ffmpeg/
+cp ../data/0001-ffmpeg-*.patch board/beaglecam/patches/ffmpeg/
+\end{verbatim}
+
+Then, tell Builldroot to look for patches in this directory, by adding
+\code{board/beaglecam/patches} to the
+\code{BR2_GLOBAL_PATCH_DIR} configuration setting (through \code{make
+menuconfig} or by directly editing the \code{.config} file.
+
+Then, rebuild \code{ffmpeg}:
+
+\begin{verbatim}
+make ffmpeg-dirclean
+make
+\end{verbatim}
+
+Note that \code{make ffmpeg-rebuild} wouldn't be sufficient to apply a
+newly added patch.
+
+Let's add something else before updating the root filesystem image...
+
+\section{Timing the launching of the application}
+
+To measure the time the application takes to load and execute, it's also
+very useful to time the instant when the application is started.
+
+So, let's also modify \code{board/beaglecam/rootfs-overlay/etc/init.d/S50playvideo}
+to add the below line before running \code{ffmpeg}:
+
+\begin{verbatim}
+echo "Starting ffmpeg"
+\end{verbatim}
+
+Now we can update the root filesystem image:
+
+\begin{verbatim}
+make
+\end{verbatim}
+
+After reflashing the SD card, reset the board and check that you are
+getting the new message. You can now measure the time between starting
+\code{ffmpeg} and finishing processing the first frame.
+
+Thanks to the last message, we can now stop \code{grabserial} when it's
+received, replacing the \code{-e} argument:
+
+\begin{verbatim}
+grabserial -d /dev/ttyUSB0 -m "U-Boot SPL" -t -e 30 -q "First frame decoded"
+\end{verbatim}
+
+\section{Initial measurements}
+
+Now, take your calculator and fill the below table with the results from your experiments:
+
+\begin{tabular}{| l | l | r |}
+ \hline
+ Step & Duration & Description \\
+ \hline
+ \hline
+ U-Boot SPL & & Between \code{U-Boot SPL 2019.01} and \code{U-Boot 2019.01} \\
+ \hline
+ U-Boot & & Between \code{U-Boot 2019.01} and \code{Starting kernel} \\
+ \hline
+ Kernel & & Between \code{Starting kernel} and \code{Run /sbin/init} \\
+ \hline
+ Init scripts & & Between \code{Run /sbin/init} and \code{Starting ffmpeg} \\
+ \hline
+ Application & & Between \code{Starting ffmpeg} and \code{First frame decoded} \\
+ \hline
+ \hline
+ Total & & \\
+ \hline
+\end{tabular}
+
diff --git a/mk/boot-time.mk b/mk/boot-time.mk
index d42f8551..46b7cd96 100644
--- a/mk/boot-time.mk
+++ b/mk/boot-time.mk
@@ -27,6 +27,7 @@ BOOT_TIME_LABS = boot-time-goals \
boot-time-build-system \
boot-time-build-bootloader \
boot-time-build-kernel-and-start-system \
+ boot-time-software-measurement \
boottime-init-scripts \
boottime-application \
boottime-kernel \
diff --git a/slides/boottime-measuring/boottime-measuring.tex b/slides/boottime-measuring/boottime-measuring.tex
index 0dd9bd5d..4f51ea63 100644
--- a/slides/boottime-measuring/boottime-measuring.tex
+++ b/slides/boottime-measuring/boottime-measuring.tex
@@ -45,22 +45,22 @@
\column{0.65\textwidth}
\begin{itemize}
\item Serial ports over USB {\bf device} are fine if there's an on-board
- serial-to-USB chip directly connected to the CPU serial port (very frequent).
+ serial-to-USB chip directly connected to the CPU serial port (very frequent).
\item Attaching a USB-to-serial dongle to a USB {\bf host} port on
- the device won't do: USB is available much later and messages
- go through more complex software stacks (loss of time accuracy).
+ the device won't do: USB is available much later and messages
+ go through more complex software stacks (loss of time accuracy).
\item All development boards have a standard or USB serial port.
\end{itemize}
\column{0.35\textwidth}
- % From http://openclipart.org/detail/135721/usb-cable-by-gsagri04
- \includegraphics[width=\textwidth]{slides/boottime-measuring/GS_USB_Cable.pdf}
+ % From http://openclipart.org/detail/135721/usb-cable-by-gsagri04
+ \includegraphics[width=\textwidth]{slides/boottime-measuring/GS_USB_Cable.pdf}
\end{columns}
\end{frame}
\begin{frame}
\frametitle{grabserial}
\begin{itemize}
-\item From Tim Bird: \url{http://elinux.org/Grabserial}
+\item From Tim Bird: \url{https://elinux.org/Grabserial}
\item A Python script to add timestamps to messages coming from a
serial console.
\item Key advantage: starts counting very early (bootstrap and bootloader)
More information about the training-materials-updates
mailing list