TipsAndTricks/InvestigatingBuildTime - Revision history

Leonardo Sandoval at 21:12, 28 February 2017

2017-02-28T21:12:45Z

← Older revision		Revision as of 21:12, 28 February 2017
Line 37:		Line 37:
	to either plot the top N recipes-task stat values		to either plot the top N recipes-task stat values

	$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s <BUILDSTATS> -N $N \| gnuplot -p		$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s <BUILDSTATS> -n $N \| gnuplot -p

	or sum stats values per task for all (world) recipes		or sum stats values per task for all (world) recipes

Leonardo Sandoval at 21:18, 15 November 2016

2016-11-15T21:18:51Z

← Older revision		Revision as of 21:18, 15 November 2016
Line 47:		Line 47:
	=== Results ===		=== Results ===

	[[~~File:utime.t.png]]~~		Preliminar results can be found [[MortyBuildstats\|here]]
	~~[[File:utime.ts.png]]~~
	~~[[File:stime.t.png]]~~
	~~[[File:stime.ts.png]]~~
	~~[[File:cutime.t.png]]~~
	~~[[File:cutime.ts.png]]~~
	~~[[File:cstime.t.png]]~~
	~~[[File:cstime.ts.png]]~~
	~~[[File:IO-wchar.t.png]]~~
	~~[[File:IO-wchar.ts.png]]~~
	~~[[File:IO-write_bytes.t.png]]~~
	~~[[File:IO-write_bytes.ts.png]]~~
	~~[[File:IO-syscr.t.png]]~~
	~~[[File:IO-syscr.ts.png]]~~
	~~[[File:IO-read_bytes.t.png]]~~
	~~[[File:IO-read_bytes.ts.png]]~~
	~~[[File:IO-rchar.t.png]]~~
	~~[[File:IO-rchar.ts.png]]~~
	~~[[File:IO-syscw.t.png]]~~
	~~[[File:IO-syscw.ts.png]]~~
	~~[[File:IO-cancelled_write_bytes.t.png]]~~
	~~[[File:IO-cancelled_write_bytes.ts.png]]~~
	~~[[File:rusage-ru_utime.t.png]]~~
	~~[[File:rusage-ru_utime.ts.png]]~~
	~~[[File:rusage-ru_stime.t.png]]~~
	~~[[File:rusage-ru_stime.ts.png]]~~
	~~[[File:rusage-ru_maxrss.t.png]]~~
	~~[[File:rusage-ru_maxrss.ts.png]]~~
	~~[[File:rusage-ru_minflt.t.png]]~~
	~~[[File:rusage-ru_minflt.ts.png]]~~
	~~[[File:rusage-ru_majflt.t.png]]~~
	~~[[File:rusage-ru_majflt.ts.png]]~~
	~~[[File:rusage-ru_inblock.t.png]]~~
	~~[[File:rusage-ru_inblock.ts.png]]~~
	~~[[File:rusage-ru_oublock.t.png]]~~
	~~[[File:rusage-ru_oublock.ts.png]]~~
	~~[[File:rusage-ru_nvcsw.t.png]]~~
	~~[[File:rusage-ru_nvcsw.ts.png]]~~
	~~[[File:rusage-ru_nivcsw.t.png]]~~
	~~[[File:rusage-ru_nivcsw.ts.png]]~~
	~~[[File:Child-rusage-ru_utime.t.png]]~~
	~~[[File:Child-rusage-ru_utime.ts.png]]~~
	~~[[File:Child-rusage-ru_stime.t.png]]~~
	~~[[File:Child-rusage-ru_stime.ts.png]]~~
	~~[[File:Child-rusage-ru_maxrss.t.png]]~~
	~~[[File:Child-rusage-ru_maxrss.ts.png]]~~
	~~[[File:Child-rusage-ru_minflt.t.png]]~~
	~~[[File:Child-rusage-ru_minflt.ts.png]]~~
	~~[[File:Child-rusage-ru_majflt.t.png]]~~
	~~[[File:Child-rusage-ru_majflt.ts.png]]~~
	~~[[File:Child-rusage-ru_inblock.t.png]]~~
	~~[[File:Child-rusage-ru_inblock.ts.png]]~~
	~~[[File:Child-rusage-ru_oublock.t.png]]~~
	~~[[File:Child-rusage-ru_oublock.ts.png]]~~
	~~[[File:Child-rusage-ru_nvcsw.t.png]]~~
	~~[[File:Child-rusage-ru_nvcsw.ts.png]]~~
	~~[[File:Child-rusage-ru_nivcsw.t.png]]~~
	~~[[File:Child-rusage-ru_nivcsw.ts.png~~]]

Leonardo Sandoval at 21:04, 15 November 2016

2016-11-15T21:04:22Z

← Older revision		Revision as of 21:04, 15 November 2016
Line 44:		Line 44:

	The former produces a more granular plot and second a more general idea where the type is spent per task set.		The former produces a more granular plot and second a more general idea where the type is spent per task set.

	~~=== Setup ===~~

	~~curl -sSf \| bash~~

	=== Results ===		=== Results ===

	[[File:utime.t.png]][[File:utime.ts.png]]		[[File:utime.t.png]]
			[[File:utime.ts.png]]
	[[File:stime.t.png]]		[[File:stime.t.png]]
	[[File:stime.ts.png]]		[[File:stime.ts.png]]

Leonardo Sandoval at 20:45, 15 November 2016

2016-11-15T20:45:19Z

@@ Line 47: / Line 47: @@
 === Setup ===
- GPLIMAGE='set terminal png fontscale 1 size 1280,720'
+  curl -sSf | bash
 === Results ===
-==== Sum stats per task ====
+[[File:utime.t.png]][[File:utime.ts.png]]
+[[File:stime.t.png]]
-[[File:Stime-utime.task.png]]
+[[File:stime.ts.png]]
-[[File:IOrchar-IOwchar.task.png]]
+[[File:cutime.t.png]]
+[[File:cutime.ts.png]]
-==== Top N ====
+[[File:cstime.t.png]]
+[[File:cstime.ts.png]]
-[[File:Stime-utime.task-recipe.png]]
+[[File:IO-wchar.t.png]]
-[[File:IOrchar-IOwchar.task-recipe.png]]
+[[File:IO-wchar.ts.png]]

Leonardo Sandoval at 15:20, 15 November 2016

2016-11-15T15:20:14Z

← Older revision		Revision as of 15:20, 15 November 2016
Line 61:		Line 61:
	=== Results ===		=== Results ===

	==== ~~Time Results~~ ====		==== Sum stats per task ====

	~~bsplots "stime:utime"~~

	~~[[File:Stime-utime.task-recipe.png]]~~
	[[File:Stime-utime.task.png]]		[[File:Stime-utime.task.png]]
			[[File:IOrchar-IOwchar.task.png]]

	==== ~~IO Results~~ ====		==== Top N ====

	~~bsplots "IO rchar:IO wchar"~~

			[[File:Stime-utime.task-recipe.png]]
	[[File:IOrchar-IOwchar.task-recipe.png]]		[[File:IOrchar-IOwchar.task-recipe.png]]
	~~[[File:IOrchar-IOwchar.task.png]]~~

Leonardo Sandoval at 15:17, 15 November 2016

2016-11-15T15:17:26Z

← Older revision		Revision as of 15:17, 15 November 2016
Line 7:		Line 7:


	The <tt>buildstats</tt> data ~~produce~~ by the class with the same name ~~if included in <tt>USER_CLASSES</tt> variable~~		The <tt>buildstats</tt> data produced by the class with the same name provides '''process statistics''' for every recipe task.
	provides '''process statistics''' for every task. This data can offer insight of the time spent by the builder (<tt>bitbake</tt>) when		This data can offer insight of the time spent by the builder (<tt>bitbake</tt>) when
	constructing a particular target at process level. This article focus more on profiling than optimization, the former being		constructing a particular target at process level. This article focus more on profiling than optimization, the former being
	the base for the latter.		the base for the latter.
Line 39:		Line 39:
	$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s <BUILDSTATS> -N $N \| gnuplot -p		$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s <BUILDSTATS> -N $N \| gnuplot -p

	or sum ~~all~~ stats ~~for a particular~~ task for all (world) recipes		or sum stats values per task for all (world) recipes

	$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s <BUILDSTATS> -S \| gnuplot -p		$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s <BUILDSTATS> -S \| gnuplot -p

Leonardo Sandoval at 00:24, 15 November 2016

2016-11-15T00:24:33Z

← Older revision		Revision as of 00:24, 15 November 2016
Line 60:		Line 60:

	=== Results ===		=== Results ===

			==== Time Results ====

	bsplots "stime:utime"		bsplots "stime:utime"

			[[File:Stime-utime.task-recipe.png]]
			[[File:Stime-utime.task.png]]

			==== IO Results ====

	bsplots "IO rchar:IO wchar"		bsplots "IO rchar:IO wchar"

			[[File:IOrchar-IOwchar.task-recipe.png]]
			[[File:IOrchar-IOwchar.task.png]]

Leonardo Sandoval at 00:09, 15 November 2016

2016-11-15T00:09:11Z

← Older revision		Revision as of 00:09, 15 November 2016
Line 52:		Line 52:
	OUT="set output '$STAT.task-recipe.png'"		OUT="set output '$STAT.task-recipe.png'"
	../scripts/contrib/bb-perf/buildstats-plot.sh -s "$STAT" -n 20 > input.gpl		../scripts/contrib/bb-perf/buildstats-plot.sh -s "$STAT" -n 20 > input.gpl
	gnuplot -e "$GPLIMAGE;$OUT" > input.gpl		gnuplot -e "$GPLIMAGE;$OUT" input.gpl
	OUT="set output '$STAT.task.png'"		OUT="set output '$STAT.task.png'"
	../scripts/contrib/bb-perf/buildstats-plot.sh -s "$STAT" -S > input.gpl		../scripts/contrib/bb-perf/buildstats-plot.sh -s "$STAT" -S > input.gpl
	gnuplot -e "$GPLIMAGE;$OUT" > input.gpl		gnuplot -e "$GPLIMAGE;$OUT" input.gpl
	}		}

Leonardo Sandoval at 00:07, 15 November 2016

2016-11-15T00:07:50Z

← Older revision		Revision as of 00:07, 15 November 2016
Line 1:		Line 1:
	== Investigating Build Time ==		== Draft: Investigating Build Time ==

			(Placeholder. Demonstrate use of buildstats and pybootchartgui)

			'''Current status''': The intention is to use the scripts under scripts/contrib/bb-perf to parse
			buildstat data and produce useful plots.

	~~(Placeholder. Demonstrate use of buildstats and pybootchartgui)~~

	The <tt>buildstats</tt> data produce by the class with the same name if included in <tt>USER_CLASSES</tt> variable		The <tt>buildstats</tt> data produce by the class with the same name if included in <tt>USER_CLASSES</tt> variable
Line 14:		Line 18:
	$ . oe-init-build-env		$ . oe-init-build-env
	$ bitbake world		$ bitbake world

	~~=== Build Machine ===~~

	~~Build time depends on the build machine HW and for this particular article we use a Linux box with the following characteristics:~~


	=== Buildstats ===		=== Buildstats ===

	~~There are~~ two set of process' ~~stat data~~: time and IO stats. For the moment, ~~the time stats to be used~~ are the following:		buildstats.bbclass stores mainly two set of process' stats: time and IO stats. For the moment, we are currently focusing on the following
			time data:

	* /proc/[pid]/stat: utime, stime		* /proc/[pid]/stat: utime, stime
Line 30:		Line 29:
	* python resource module: Child rusage ru_utime, Child rusage ru_stime		* python resource module: Child rusage ru_utime, Child rusage ru_stime

	and the ~~following~~ IO stats:		and the IO stats:

	* /proc/[pid]/io: IO rchar, IO wchar		* /proc/[pid]/io: IO rchar, IO wchar
	* /proc/[pid]/io: IO read_bytes, IO write_bytes		* /proc/[pid]/io: IO read_bytes, IO write_bytes

	With this ~~separation of buildstats~~, ~~proceed running~~ the following script (once the <code>bitbake world</code> command has finished)		With this data, the following script (once the <code>bitbake world</code> command has finished) is used
	to plot the top N stat ~~consumers~~		to either plot the top N recipes-task stat values

	$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s <BUILDSTATS> -N $N \| gnuplot -p		$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s <BUILDSTATS> -N $N \| gnuplot -p

	~~In case we want~~ a ~~more general picture, getting data per~~ task ~~type instead of recipe's task, the script needs <code>-S</code>~~ (~~for Sum~~)		or sum all stats for a particular task for all (world) recipes
	~~argument~~

	$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s <BUILDSTATS> -S \| gnuplot -p		$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s <BUILDSTATS> -S \| gnuplot -p

			The former produces a more granular plot and second a more general idea where the type is spent per task set.

	=== ~~Results~~ ===		=== Setup ===

	~~$ IMAGE~~='set terminal png fontscale 1 size 1280,720; set output "IO-~~write_bytes:IO~~-~~read_bytes~~.~~png~~"'		GPLIMAGE='set terminal png fontscale 1 size 1280,720'
			function bsplots() {
			local STAT=$1
			OUT="set output '$STAT.task-recipe.png'"
			../scripts/contrib/bb-perf/buildstats-plot.sh -s "$STAT" -n 20 > input.gpl
			gnuplot -e "$GPLIMAGE;$OUT" > input.gpl
			OUT="set output '$STAT.task.png'"
			../scripts/contrib/bb-perf/buildstats-plot.sh -s "$STAT" -S > input.gpl
			gnuplot -e "$GPLIMAGE;$OUT" > input.gpl
			}

	~~==== utime and stime ====~~

	~~Time spent by a certain process can be obtain looking at the <tt>stime<</tt> and <tt>time</tt> corresponding to the amount of time the process~~		=== Results ===
	~~has been scheduled in kernel and user mode.~~

	~~$ IMAGE='set terminal png fontscale 1 size 1280,720; set output~~ "~~IO-write_bytes:IO-read_bytes.png"'~~		bsplots "stime:utime"
	~~$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s '~~stime:utime~~' -N 20 > input.gpl; gnuplot -e~~ "~~\'$IMAGE\'~~" ~~input.gpl~~		bsplots "IO rchar:IO wchar"
	~~$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s 'stime~~:~~utime' -S \| gnuplot -p~~

Leonardo Sandoval at 22:14, 14 November 2016

2016-11-14T22:14:49Z

← Older revision		Revision as of 22:14, 14 November 2016
Line 1:		Line 1:
	== Investigating Build Time ==		== Investigating Build Time ==

	Placeholder. Demonstrate use of buildstats and pybootchartgui		(Placeholder. Demonstrate use of buildstats and pybootchartgui)

			The <tt>buildstats</tt> data produce by the class with the same name if included in <tt>USER_CLASSES</tt> variable
			provides '''process statistics''' for every task. This data can offer insight of the time spent by the builder (<tt>bitbake</tt>) when
			constructing a particular target at process level. This article focus more on profiling than optimization, the former being
			the base for the latter.

			=== Setup ===

			$ cd poky
			$ git checkout -b morty origin/morty
			$ . oe-init-build-env
			$ bitbake world

			=== Build Machine ===

			Build time depends on the build machine HW and for this particular article we use a Linux box with the following characteristics:


			=== Buildstats ===

			There are two set of process' stat data: time and IO stats. For the moment, the time stats to be used are the following:


			* /proc/[pid]/stat: utime, stime
			* /proc/[pid]/stat: cutime, cstime
			* python resource module: rusage ru_utime, rusage ru_stime
			* python resource module: Child rusage ru_utime, Child rusage ru_stime

			and the following IO stats:

			* /proc/[pid]/io: IO rchar, IO wchar
			* /proc/[pid]/io: IO read_bytes, IO write_bytes

			With this separation of buildstats, proceed running the following script (once the <code>bitbake world</code> command has finished)
			to plot the top N stat consumers

			$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s <BUILDSTATS> -N $N \| gnuplot -p

			In case we want a more general picture, getting data per task type instead of recipe's task, the script needs <code>-S</code> (for Sum)
			argument

			$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s <BUILDSTATS> -S \| gnuplot -p


			=== Results ===

			$ IMAGE='set terminal png fontscale 1 size 1280,720; set output "IO-write_bytes:IO-read_bytes.png"'

			==== utime and stime ====

			Time spent by a certain process can be obtain looking at the <tt>stime<</tt> and <tt>time</tt> corresponding to the amount of time the process
			has been scheduled in kernel and user mode.

			$ IMAGE='set terminal png fontscale 1 size 1280,720; set output "IO-write_bytes:IO-read_bytes.png"'
			$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s 'stime:utime' -N 20 > input.gpl; gnuplot -e "\'$IMAGE\'" input.gpl
			$ ../scripts/contrib/bb-perf/buildstats-plot.sh -s 'stime:utime' -S \| gnuplot -p