[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