Profiling - Revision history

Rpurdie: /* Usage of sync calls in the build */

2012-12-06T09:34:31Z

Usage of sync calls in the build

← Older revision		Revision as of 09:34, 6 December 2012
Line 61:		Line 61:
	$time bitbake core-image-sato		$time bitbake core-image-sato

	real 107m9.684s		real 107m9.684s
	user 517m13.090s		user 517m13.090s
	sys 54m38.850s		sys 54m38.850s

	$ time eatmydata bitbake core-image-sato		$ time eatmydata bitbake core-image-sato

	real 105m5.167s		real 105m5.167s
	user 521m47.480s		user 521m47.480s
	sys 54m27.170s		sys 54m27.170s

			(http://www.flamingspork.com/projects/libeatmydata/)

	$ time bitbake core-image-sato (with pseudo sync hack patch applied)		$ time bitbake core-image-sato (with pseudo sync hack patch applied)

	real 105m45.113s		real 105m45.113s
	user 520m4.430s		user 520m4.430s
	sys 54m54.060s		sys 54m54.060s

	So sync is maybe worth a 1% overall speed difference (thanks Tom Zanussi for the numbers).		So sync is maybe worth a 1% overall speed difference (thanks Tom Zanussi for the numbers).

Rpurdie at 09:33, 6 December 2012

2012-12-06T09:33:58Z

← Older revision		Revision as of 09:33, 6 December 2012
Line 54:		Line 54:

	We used to use psyco to spee dup python. It is no longer maintained, only works on 32 bit systems and didn't seem to give much of a speedup so we ended up dropping the support.		We used to use psyco to spee dup python. It is no longer maintained, only works on 32 bit systems and didn't seem to give much of a speedup so we ended up dropping the support.

			== Usage of sync calls in the build ==

			We'd wondered if sync calls in teh build were causing any problem. To test this we tried two things, one was libeatmydata and secondly adding the same functionality to pseudo. The results were:

			$time bitbake core-image-sato

			real 107m9.684s
			user 517m13.090s
			sys 54m38.850s

			$ time eatmydata bitbake core-image-sato

			real 105m5.167s
			user 521m47.480s
			sys 54m27.170s

			$ time bitbake core-image-sato (with pseudo sync hack patch applied)

			real 105m45.113s
			user 520m4.430s
			sys 54m54.060s

			So sync is maybe worth a 1% overall speed difference (thanks Tom Zanussi for the numbers).

	== Areas we know we can potentially do better ==		== Areas we know we can potentially do better ==

Rpurdie at 14:14, 21 November 2012

2012-11-21T14:14:01Z

@@ Line 53: / Line 53: @@
 One tip to keep in mind is watching the processor usage in top or in the buildstats. If the values are lower than you'd expect, its worth seeing if there is a kind of "forkbomb" behaviour going on. We've seen cases where subprocesses were being rapidly forked in tight loops which sucked performance. Reworking the code to avoid this lead to performance improvements.
-== Areas we know we can do better ==
+We used to use psyco to spee dup python. It is no longer maintained, only works on 32 bit systems and didn't seem to give much of a speedup so we ended up dropping the support.
 Currently we do a copy operation for do_install -> do_populate_sysroot since the files may be customised and we do a second copy operation at sstate install time since again, files may be edited. Since we can tell which files we edit, we could see if we can hardlink and only copy when we edit.
@@ Line 62: / Line 64: @@
 We build certain things when we don't need them such as doc generation in -native recipes. Adding PACKAGECONFIG[doc] options would be a good way to allow us to turn these off.

Rpurdie at 08:01, 20 November 2012

2012-11-20T08:01:32Z

← Older revision		Revision as of 08:01, 20 November 2012
Line 37:		Line 37:
	This is hard to measure but we have made worthwhile improvements in this area in the past. Bitbake takes significance advantage of "copy-on-write" behaviour both in the way it executes tasks and also the way the data store works internally.		This is hard to measure but we have made worthwhile improvements in this area in the past. Bitbake takes significance advantage of "copy-on-write" behaviour both in the way it executes tasks and also the way the data store works internally.

	So far the best results have been found using meliae. The best documentation of how to use this is in an email to bitbake-devel from Richard Purdie on 2012-02-18, subject "[bitbake-devel] Bitbake Memory Usage".		So far the best results have been found using meliae. The best documentation of how to use this is in an email to bitbake-devel from Richard Purdie on 2012-02-18, subject "[bitbake-devel] Bitbake Memory Usage". http://lists.linuxtogo.org/pipermail/bitbake-devel/2012-February/001864.html

	== Patterns and notes from experience ==		== Patterns and notes from experience ==

Rpurdie at 07:59, 20 November 2012

2012-11-20T07:59:05Z

← Older revision		Revision as of 07:59, 20 November 2012
Line 20:		Line 20:

	If a directory is specified as a third option, graphic files are saved to the directory in svg format. For large graphs, these can be split into a number of files using the "-n" option.		If a directory is specified as a third option, graphic files are saved to the directory in svg format. For large graphs, these can be split into a number of files using the "-n" option.

			== Buildstats ==

			The buildstats code writes out a data about processor and memory usage per task into the tmp/buildstats dirrectory if its enabled. We currently haven't done a large amount of analysis of that data.

	== Disk Usage ==		== Disk Usage ==
Line 33:		Line 37:
	This is hard to measure but we have made worthwhile improvements in this area in the past. Bitbake takes significance advantage of "copy-on-write" behaviour both in the way it executes tasks and also the way the data store works internally.		This is hard to measure but we have made worthwhile improvements in this area in the past. Bitbake takes significance advantage of "copy-on-write" behaviour both in the way it executes tasks and also the way the data store works internally.

	So far the best results have been found using meliae. ~~See the~~ "~~runqueue.py: Example memory analysis~~" ~~patch in poky-contrib~~.		So far the best results have been found using meliae. The best documentation of how to use this is in an email to bitbake-devel from Richard Purdie on 2012-02-18, subject "[bitbake-devel] Bitbake Memory Usage".

	== Patterns and notes from experience ==		== Patterns and notes from experience ==

	The biggest speedups in the parser we in places where there were insane numbers of function calls, often in tight loops. By improving the algorithms, the same work could be done with much less overhead and corresponding speedups to the system. these clearly show up when run under bitbake -P.		The biggest speedups in the parser were in places where there were insane numbers of function calls, often in tight loops. By improving the algorithms, the same work could be done with much less overhead and corresponding speedups to the system. these clearly show up when run under bitbake -P.

	Equally, where we keep computing particular values, caches have been shown to help massively and for better or worse, bitbake is littered with caches. Some of these are simple like the internal expansion cache in the datastore, some are more complex like the codeparser cache which has to deal with multithreading issues making its design challenging.		Equally, where we keep computing particular values, caches have been shown to help massively and for better or worse, bitbake is littered with caches. Some of these are simple like the internal expansion cache in the datastore, some are more complex like the codeparser cache which has to deal with multithreading issues making its design challenging.

	Several significant improvements in disk space usage were found where we were making copies of system data and moving files into place where possible helped significantly. We now also hardlink files instead of copying where we know they can't change.		Several significant improvements in disk space usage were found where we were making copies of system data and moving files into place where possible helped significantly. We now also hardlink files instead of copying where we know they can't change.

			For memory usage, we had issues where memory usage would spike after two bitbake runs. The issue was in the way the caches were pickled and unpickled where strings would no longer be "intern"'d. This lead to a spike in cache file size and then a spike in memory usage. We have a workaround in the code to ensure we keep strings as intern values.

			We've also made great improvements by simplifying dependencies. For example having getttext-minimal-native available to provide the gettext macros and disabling NLS on native packages was a good simplification.

			One tip to keep in mind is watching the processor usage in top or in the buildstats. If the values are lower than you'd expect, its worth seeing if there is a kind of "forkbomb" behaviour going on. We've seen cases where subprocesses were being rapidly forked in tight loops which sucked performance. Reworking the code to avoid this lead to performance improvements.

	== Areas we know we can do better ==		== Areas we know we can do better ==
Line 50:		Line 60:

	On tracing profiles, bb.debug features predominantly for some workloads. We need a better event registration mechanism so handlers can filter events at source, hence removing execution overhead.		On tracing profiles, bb.debug features predominantly for some workloads. We need a better event registration mechanism so handlers can filter events at source, hence removing execution overhead.

			We build certain things when we don't need them such as doc generation in -native recipes. Adding PACKAGECONFIG[doc] options would be a good way to allow us to turn these off.

Rpurdie at 18:48, 19 November 2012

2012-11-19T18:48:41Z

← Older revision		Revision as of 18:48, 19 November 2012
Line 34:		Line 34:

	So far the best results have been found using meliae. See the "runqueue.py: Example memory analysis" patch in poky-contrib.		So far the best results have been found using meliae. See the "runqueue.py: Example memory analysis" patch in poky-contrib.

			== Patterns and notes from experience ==

			The biggest speedups in the parser we in places where there were insane numbers of function calls, often in tight loops. By improving the algorithms, the same work could be done with much less overhead and corresponding speedups to the system. these clearly show up when run under bitbake -P.

			Equally, where we keep computing particular values, caches have been shown to help massively and for better or worse, bitbake is littered with caches. Some of these are simple like the internal expansion cache in the datastore, some are more complex like the codeparser cache which has to deal with multithreading issues making its design challenging.

			Several significant improvements in disk space usage were found where we were making copies of system data and moving files into place where possible helped significantly. We now also hardlink files instead of copying where we know they can't change.

			== Areas we know we can do better ==

			Currently we do a copy operation for do_install -> do_populate_sysroot since the files may be customised and we do a second copy operation at sstate install time since again, files may be edited. Since we can tell which files we edit, we could see if we can hardlink and only copy when we edit.

			If you clear the cache and parse using "bitbake -p -DD" you see a lot of messages about searching for files. Currently the files search paths are derived from overrides, it would be useful to remove some of the overrides we know we'll never use for FILESDIR/FILESPATH, hence speeding up the search operations.

			On tracing profiles, bb.debug features predominantly for some workloads. We need a better event registration mechanism so handlers can filter events at source, hence removing execution overhead.

Rpurdie at 18:38, 19 November 2012

2012-11-19T18:38:58Z

← Older revision		Revision as of 18:38, 19 November 2012
Line 32:		Line 32:

	This is hard to measure but we have made worthwhile improvements in this area in the past. Bitbake takes significance advantage of "copy-on-write" behaviour both in the way it executes tasks and also the way the data store works internally.		This is hard to measure but we have made worthwhile improvements in this area in the past. Bitbake takes significance advantage of "copy-on-write" behaviour both in the way it executes tasks and also the way the data store works internally.

			So far the best results have been found using meliae. See the "runqueue.py: Example memory analysis" patch in poky-contrib.

Rpurdie at 18:32, 19 November 2012

2012-11-19T18:32:53Z

← Older revision		Revision as of 18:32, 19 November 2012
Line 4:		Line 4:

	This provides a trace about where the bitbake server is spending its time. This used to be really great for profiling all aspects of bitbake. When the -P option is added to any usual commandline, bitbake will save out a profile.log file which contains the raw python profiling information and a "profile.log.processed" file which contains a human readable version of the trace information. The processed file contains four different views of the data, one after the other. One type of chart shows the time spent in functions, the second type of chart shows the same information but includes callgraph information so we you see where the functions were called from. These two charts are printed twice, firstly sorted by internal function time and secondly be cumulative function time.		This provides a trace about where the bitbake server is spending its time. This used to be really great for profiling all aspects of bitbake. When the -P option is added to any usual commandline, bitbake will save out a profile.log file which contains the raw python profiling information and a "profile.log.processed" file which contains a human readable version of the trace information. The processed file contains four different views of the data, one after the other. One type of chart shows the time spent in functions, the second type of chart shows the same information but includes callgraph information so we you see where the functions were called from. These two charts are printed twice, firstly sorted by internal function time and secondly be cumulative function time.

			For the actual tasks themselves there is a patch, "build.py: Dump out performance data of individual tasks" available in the poky-contrib tree which enables each task to dump out performance information. Its still pending to integrate this patch into the main tree in some form.

			The other big area where profiling is useful is during the parsing itself. Unfortunately this is a harder area to profile due to the parallelisation of parsing. We don't have a good way to profile this section of code at the moment.

	== Using pybootchart ==		== Using pybootchart ==

Rpurdie: /* Profiling the build system */

2012-11-19T17:09:18Z

Profiling the build system

← Older revision		Revision as of 17:09, 19 November 2012
Line 1:		Line 1:
	~~= Profiling~~ the build system =		Tips and tricks for profiling the build system

	== Using bitbake -P ==		== Using bitbake -P ==

Rpurdie: Created page with "= Profiling the build system = == Using bitbake -P == This provides a trace about where the bitbake server is spending its time. This used to be really great for profiling all ..."

2012-11-19T17:08:47Z

Created page with "= Profiling the build system = == Using bitbake -P == This provides a trace about where the bitbake server is spending its time. This used to be really great for profiling all ..."

New page

= Profiling the build system =

== Using bitbake -P ==

This provides a trace about where the bitbake server is spending its time. This used to be really great for profiling all aspects of bitbake. When the -P option is added to any usual commandline, bitbake will save out a profile.log file which contains the raw python profiling information and a "profile.log.processed" file which contains a human readable version of the trace information. The processed file contains four different views of the data, one after the other. One type of chart shows the time spent in functions, the second type of chart shows the same information but includes callgraph information so we you see where the functions were called from. These two charts are printed twice, firstly sorted by internal function time and secondly be cumulative function time.

== Using pybootchart ==

This tool allows visualisation of the build process and task execution. Firstly, you need to have enabled the buildstats class in your local build config (buildstats in USER_CLASSES in local.conf). You can then runa command like:

<poky checkout>/scripts/pybootchartgui/pybootchartgui.py build/tmp/buildstats/bash-qemux86-64/201211190818/

where the second argument is a path to a given buildstats file of the build you want to visualise. By default, tasks taking less than 8 seconds are not graphed to remove short "noise" from the graph. The -m commandline option can be used to change the minimum task length to filter with, "0" being no filtering.

Common tasks are colour coded to aid visualisation. The graph can also be panned and scaled. The tool is good at spotting bottlenecks in builds and allowing the user to appreciate where time is being spent during the build.

If a directory is specified as a third option, graphic files are saved to the directory in svg format. For large graphs, these can be split into a number of files using the "-n" option.

== Disk Usage ==

A simple "du" call can tell how much space a given build directory is taking up. Equally, the size of the sstate data or source downloads can also be measured. One thing to be aware of is we hardlink files to save disk space and increase performance.

Timing bitbake commands

Using commands in the form "time bitbake <options>" gives a good indication of how long a command takes and provides a simplistic way of measuring some aspects of performance.

== Python memory usage ==

This is hard to measure but we have made worthwhile improvements in this area in the past. Bitbake takes significance advantage of "copy-on-write" behaviour both in the way it executes tasks and also the way the data store works internally.