TipsAndTricks/ParsingProfiling

Ever wondered what bitbake does when parsing?

If you've ever wondered where bitbake spends its time during parsing, its now quite easy to find out!

Start with a clean cache by "rm tmp/cache -rf". You can then trigger bitbake's profiling mode with the "-P" option, so "bitbake -p -P". Bitbake will parse the recipes, then print a message saying "Processed parsing statistics saved to profile-parse.log.processed".

Internally, it enables profiling in each separate parsing thread, saving the data to files called profile-parse-Parser-1:X.log where X is the thread number. It then merges all the files together to form the processed output.

There are four sections to profile-parse.log.processed, the first shows a list of functions, ordered by "internal time" which tells us which function consumed the most time. Underneath this is a callgraph section, which shows which functions called those functions. This is useful where you see a function called many times and want to know where it was called from.

These two data items are then repeated but ordered by cumulative function time. This allows you to answer a different kind of question, where you're interested to learn more about the critical path and which functions all the time is spent in.

Interestingly, on my highly parallel machine I just tested this on, I see "389110629 function calls in 1334.486 seconds" and the top of the function time table reads:

  ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    6415  450.867    0.070  450.867    0.070 {method 'acquire' of '_multiprocessing.SemLock' objects}
 3403372   56.846    0.000  350.207    0.000 bitbake/lib/bb/data.py:332(build_dependencies)

which suggests in machines with many cores, we start to need to look at optimising the parsing queue lock since we're spending around a third of the overall time in there on this machine.