Illustration of task latency
We've done a lot of good work in optimising task execution and latency however I was looking at some of our build data and I think we still have work to do. The attached picture is a "bootchart" style picture showing the task execution at the start of a build. Each vertical division represents one second. As you can see, the fetch/patch tasks themselves run very quickly. Those markers are from the task entry/exit.
The worrying part is the empty space between the tasks which looks to be about 1.5 seconds in size *per task*. This is a scary amount of latency to be losing for task execution when you consider we have 4500 of these for our reference build.
More investigation is needed to figure out where this time is being spent but I'm guessing a significant fraction is in parsing the recipe of the task that is about to be executed. We need to confirm that but if that is the case but one possible optimisation is we should ensure we're not parsing every BBCLASSEXTEND variant of the recipe, just the one we want to run. I'm sure there are other ways we might be able to improve this too.
Cheers,
Richard
Quoted 12 lines · Richard Purdie
We've done a lot of good work in optimising task execution and latency however I was looking at some of our build data and I think we still have work to do. The attached picture is a "bootchart" style picture showing the task execution at the start of a build. Each vertical division represents one second. As you can see, the fetch/patch tasks themselves run very quickly. Those markers are from the task entry/exit.
The worrying part is the empty space between the tasks which looks to be about 1.5 seconds in size *per task*. This is a scary amount of latency to be losing for task execution when you consider we have 4500 of these for our reference build.
Quoted 7 lines
More investigation is needed to figure out where this time is being spent but I'm guessing a significant fraction is in parsing the recipe of the task that is about to be executed. We need to confirm that but if that is the case but one possible optimisation is we should ensure we're not parsing every BBCLASSEXTEND variant of the recipe, just the one we want to run. I'm sure there are other ways we might be able to improve this too.
To follow up on this, I added instrumentation to runqueue.py fork_off_task(). There are two things of note. On my laptop which is a much slower system than the one I showed in the benchmark (a quad core), the task overhead isn't 1+ seconds as shown in the graph but 0.4 seconds per task. I think the reason is there is a compile job running in parallel on the other graph which is starving new tasks of CPU.
The second thing of note is 95% of the 0.4 seconds are in the loadDataFull() call as suspected. I did notice that the logging changes around that point in the code can distort timings but the time is really being spent there.
Cheers,
Richard
Quoted 11 lines · Richard Purdie
To follow up on this, I added instrumentation to
runqueue.pyfork_off_task(). There are two things of note. On my laptop which is a much slower system than the one I showed in the benchmark (a quad core), the task overhead isn't 1+ seconds as shown in the graph but 0.4 seconds per task. I think the reason is there is a compile job running in parallel on the other graph which is starving new tasks of CPU.The second thing of note is 95% of the 0.4 seconds are in the
loadDataFull()call as suspected. I did notice that the logging changes around that point in the code can distort timings but the time is really being spent there.
I've dug into this a bit. When running a given task, it is parsing all bbclassextend variants again. I have a simple patch which fixes that which I'll cleanup and share.
What I also noticed which was more odd was that the first finalise() call was taking 0.2s, subsequent ones were taking 0.1s. It turns out that the parsercache which is used by the siggen code isn't functioning the way it should with a lot of cache misses. I think this is related to the parallel parsing and only saving out cached data from the core, not the individual recipes (i.e. the cache from the parser subthreads). I suspect we could get some performance improvement by fixing this.
Cheers,
Richard
Quoted 11 lines · Richard Purdie
I've dug into this a bit. When running a given task, it is parsing all bbclassextend variants again. I have a simple patch which fixes that which I'll cleanup and share.
What I also noticed which was more odd was that the first
finalise()call was taking 0.2s, subsequent ones were taking 0.1s. It turns out that the parsercache which is used by the siggen code isn't functioning the way it should with a lot of cache misses. I think this is related to the parallel parsing and only saving out cached data from the core, not the individual recipes (i.e. the cache from the parser subthreads). I suspect we could get some performance improvement by fixing this.
Fixes for the issues I noticed are in:
http://git.pokylinux.org/cgit/cgit.cgi/poky-contrib/log/?h=rpurdie/bboptimise
It turns out executing a function at process exit time with multiprocessing is quite tricky and I'm not 100% sure I'm using public API with the approach I've ended up using.
The speedups have a good feel to them and show the right things with benchmarks. It will be interesting to see how much affect they have on real world build time (which I'll test when I get home next week). They're also showing a significant reduction in parsing time.
I also noticed that skipped recipes were always being reparsed which is suboptimial and I've included a work in progress fix for that in the above branch too.
Cheers,
Richard