bootchart2
CC Attribution 2.0 Belgium:
You are free to use, adapt and copy, distribute and transmit the work or content in adapted or unchanged form for any legal purpose as long as the work is attributed to the author in the manner specified by the author or licensor.
Meeks, Michael
A quick expose on boot time profiling tools, show-casing the slightly-less-lame: "bootchart2" - a new and improved boot time profiling tool, and other ways to speed things up." Which of the seven+ 'readahead' tools do you want, and why ? With a summary of recent fixes and wins in the area, and how to get involved with improving Linux boot performance.
 thing, it renders with Kyro to SVG and PNG, and it's a lot nicer. Then Scott James Rowling did a really good thing, canonical, great. They actually did something. And they rewrote the shell script, which is essentially the moral equivalent of this. I mean, there are more lines, but that's practically what it does. And he rewrote it in C, so it went a lot faster. So you could get better resolution, better granularity, which is cool. And then Bootchart2 came along, which was me. And I rewrote his collector for a couple of reasons. The first thing is the proc interfaces are not particularly good. So when is the process running? The information in proc, it's unclear to me what the granularity of that is, how long. The state information there doesn't seem to me to be very good, basically. And if something can run and then block, and seemingly it's not running, I don't know, some kernel guy would tell me, I'm sure. But there's a better interface, which is the task stats interface. And that gives you nanosecond accurate in theory time accounting. It's interesting, the nanosecond values go up in suspiciously uniform, large, into the chunks. But at least it's a lot better than it could be. And the interface is horribly blocked and unpleasant, and it doesn't work. And it's supposed to have task groups or something. So I guess if a process has multiple threads, but that doesn't work either. But if you wander through proc, you can actually get the information out at some hideous CPU cost, and you can do it at a relatively high frequency. And that's great. Task stat is on in virtually every kernel, except in Intel's mobile in where virtually everything is turned off, just in case it's useful. So it allows us to say better than that, which process has used how much CPU? So in the original boot chart, you could say, well, something seemed to be busy at this kind of time, but not tell me how much CPU was used by that process. So we can now answer that question. And Spoochart2 also integrates PyBoot chart GUI, it throws away the Java thing, and so you can have a much better coupling between those two beasts. So in the old world, we went from something like this, and in the new world, we go to something like this, where you see all of these lots of little tiny things which now aren't being thrown away because apparently they took no time. And so there's boot Udev, Udev, Udev, Udev, Udev, all of these tiny things and lots of very narrow, it's kind of new and differently broken. So that's great. And you notice that here, boot Udev was just taking no time. This is all gray, if you can't see it at the back. And that's at least slightly blue, which is progress, you see. There's a Tory bias underneath some of this, as you can tell. Anyhow, yeah, Witch in bulk has lots of lines. Yes, okay, so when you start seeing interesting things happening, there's all these tiny striations here. This guy is a really good guy. Look at this, the skin guy is taking serious CPU, you know? Doesn't actually do anything, or it's only here to set an environment variable, really, at this stage, but it really goes through it with Panache. I think it loads all of the language, you know, catalogs and other things. Anyway, so that needs fixing. The other thing that the original boot chart did, which was very zen, was that when lots of things were happening at once, it would change the alpha channel of the rendering. So we show you the percentage of CPU that was being used. So the media effect was, as soon as the CPU got remotely busy, everything became very blurry and transparent, you can see what was taking any time. So we turned that off and there was an instant win. So you know, you can see in this channel here, you know, when the CPU is really going at it across umpteen processes, actually you can see that they're all still doing something and try and get some idea of the sequencing. And of course, since it's accurate, you can also see holes. A nice feature that someone could hack for me would be to show nice holes that go vertically when the processor is stalled. And we see some of those. ACPI is causing some serious grief on some hardware. And you can see, you know, the same problem happens in CISFS three times. You know, we take a half a second delay, pulling a battery, we don't need to pull when Udev starts, when X starts, and when HAL starts. One and a half seconds of sleep. Very easy to see. It'd be nice to highlight that. Another thing that we can do, because we've got actual hard CPU time, how much time did it take at any given time, is draw cumulative charts of what's taking the CPU. So that's kind of fun. So here you can see, for whatever reason, we're starting Banshee at a boot and it's taking nearly 20% of the time. That's good, huh? Optimization opportunities. But you can also, you know, sort of start to rank these guys and you can see when they appear. It's unclear to me that it's very useful, but it looks pretty. So marketing is everything and so forth, you know. Another thing that's pretty good is kernel boot charting. So the old boot chart, actually this is a new boot chart, but the old boot chart suffered this too. You know, you would start because we knew when the kernel, you know, got going. This is kind of zero time. And then some very much later time, your boot chart actually started. And so this gap here was just a complete mystery. What happened? Who knows? And Ion came up with a really nice way of dealing with this, I guess, in it called debug stuff. I think it was him. Either way, he used it. And so then you can draw a nice graph and you can say, look, the kernel is booting in this period and this is the populated root FS, the visa of frame buffer in it, keyboard, blah, blah, blah, blah, software resume, which is just a beast of a, you know, like the seconds here are now this wide. So one, two, three, four, five, six, seven seconds, maybe, if I can count properly. Anyway, lots of seconds and that's the software resume. And of course there was nothing to resume. So, you know, it just carried on at the end. But you can also see some interesting things. So when the system has actually got started, this is Udev and the various things happening in either a RAM disk or, I don't know, main system, it's starting to do mod probes and module loads. You can see then the asynchronous and delayed init bits happening, I guess, in the kernel there. I don't understand any of that. I just pass the data and render it. Does that make sense, Greg? Perfect. I've never done something like this in the whole process. And why are you checking the area? Right. You check them all the way up. It really isn't the plot. It really wasn't the core. Nice, nice. It's, yeah, okay. But until you look at the rendering, you know, you have no idea why the kernel is taking eight seconds to start. It seems a reasonable thing to take eight seconds. I mean, you know, it's a lot of code, right? It should take eight seconds. And when you look at it, you realize it's really dumb. And this is, there's much more detail that's perhaps more useful for the kernel guys in terms of far more granular, you know, allocations of which functions and which initialization pieces are taking time and how that parallelizes and so on. And that's pretty nice. So all we do is we store it. We do a bit of a worse job of rendering it. But there's this pretty tool in the kernel here and you pipe your dmessage into this marvelous Perl script. You get an SVG file out and it looks pretty like that. And it tells you why your kernel is slow to start. So there are lots of schools of thought on how you should improve boot time and lots of elite hacks. And sometimes you have customers that come to us and say, oh, we've discovered if we put, you know, like 15 ampersands in all of these scripts, it starts much faster like this. And you're like, yeah, yeah, yeah. And it crashes as soon as you press a key, you know. Yeah, I mean, some of the race conditions are really exciting. One of the ones that I had was that you're setting terminal settings on the console. And one of the cunning settings is not to receive a signal when you press enter. Like normally when you press enter, you get a signal like sig, eh, whatever. And due to a race condition, we were starting X, which was turning off the sig air. And then we were turning it back on by restoring the console state. The symptom of this was that the first time you ran X and you hit enter, the X server crashed. But could we find it? No. We traced the whole system. I mean, you know, it took forever to work out. It's a feature, you know. It's one of those really nice features that dates back from 25 years ago that no one actually knows or cares about anymore. But you know, whatever, you have to turn it off. So all of these wonderful plans, you know, maybe you start Udev and you start Hal and Prowler with it and then you start X as well and something will go wrong on some machine somewhere. So, or network management. You can bring up network management much later. That's fine. But it turns out a whole load of apps that aren't really geared up for the network stack to appear, you know, in mid initialization or mid flight, which sucks. There are bugs. There's no point in not fixing them. But finding so many bugs at once can be, you know, challenging. So another thing that the people try and do to make it quicker is they think, well, what the problem is is we have all these shell scripts, you know. What we need to do is throw away the unit system and rewrite the unit system. And that's probably true. But one approach was to rewrite it all as a single shell script, you know. So everything happens in order, you know. It's beautiful. So we tried this. Mobile N Project did this. We tried it. I spent quite a while switching our actually already parallelized kind of make file based sort of in it process to use this. Cunning you obviously faster way. But it's actually no faster. It turns out that the cuts are elsewhere, you know. The thousand cuts are in each thing that you're starting up and the silly wrappers around them. So that was pretty serious. And yeah, I mean, it's just a lot of work profiling each piece and making it not suck. So mod probe, you know, was very slow. There was some big silly cache and I think Red Hat fixed that. Udev was also pretty slow. I think Cive has fixed that. Cosa. Colour module loading took some kind of monster lock that stopped anything happening. So you know, you could load lots of modules in parallel, of course, you know, until you actually wanted to load the module, which, you know, then they would all kind of serialize, I think. How, yeah, how has been doing incredibly inefficient things and still is, you know. I mean, but you know, something like a 10 line patch doubled the performance of how it starts up, which is previously two seconds of CPU or something. And there's another 50% in there that is not parsing a 600K file that we don't need to parse 23 times. Honestly, you know, I mean, if you want glory, you know, it's easy. It's easy here. But the answer is not doing all of this crazy stuff. It's just like taking a profile out to ordinary pieces of coding going, huh, that's dumb. Gcon. Similarly, you know, the XML parser, the guy that wrote it, didn't understand UTF-8 and did stuff in really silly ways. You know, and it still goes on. There's plenty of fat left, really. Another interesting thing is SSD, well, I guess IO. IO takes a lot of your life away if you're not very careful. And this is the famous five second mobile boot chart. I'd like to, you know, this is sort of historical, you know, interest here. Yeah. Does it boot in five seconds yet? No? Okay. So this was a high point. You know, XFC is obviously the future. And with an SSD life is very easy, it turns out. So SSDs are not only blazingly fast, which throws away, you know, much of your LASNC, but you can also do stupid things, seeking all over the place. So what you do is you start your huge SREADHead process, which is, I guess, down here. As you notice, the SREADHead process isn't actually doing anything because it's an old style boot chart. But what it's actually doing is batching full threads worth of IO requests for everything you need in order. And it does it in the background. So if you really need something and it wasn't in the profile, you get it. So that's SSD, which is all good. Hard disk, you have the opposite problem, that you really, really, really need to read linearly. So again, this is my SREADHead and, well, you instrument your entire boot process and you try and catch everything, not just the open syscalls, you catch execs and use them and various things. And then you, you know, you kind of chunk it into chunks that seem good to you, some, you know, mystic, mystical way. And then you read a whole lot to start with and you try and get ahead. Actually, I think this fail, but you try and get ahead of the system and then you let the CPU go and you say, go, and then you race ahead trying to catch up so that you're going to be ahead of it all the time so that when it needs, you know, the data, it's there. Yeah, it's quite exciting. Anyway, there's lots of different options, but it does make a difference. Here's, I think, relatively lame and relatively old screenshot of the 34 seconds. This is some open SUSEboot and there's down to 28 with, again, some different way of doing preload that's, I think, split into sections and stuff. I mean, the punchline is you can see that this disk is not, you know, this is a theoretical gigabit a second bandwidth to the disk, but reality is that you're getting, you know, like 14 megabytes a second peak out of it, you know, and that's, that's with the preloading. You know, so there's some serious problems in terms of getting data off disk. The great news is that you have a lot of choice here, you know, there's a lot of preloads out there. This is the SUSE one. I was just showing you the graph there and use a system tap, which is wonderful. This is Mark, no, he hasn't made it, but anyway, I have to advertise system tap because I like Mark. And yeah, that, this kind of module that traces the IO and the problem is not tracing the IO, but tracing the IO that wasn't your read ahead so that you don't incrementally build a bigger and bigger and bigger read ahead thing that becomes relevant. And then there's other versions. So Red Hat have a nice thing, the Intel had a nice thing, I think, placed loosely on the, on the Red Hat one, which is now dead. There's no updates for it. It works well on flash, but not hard disks. I'm going to have your read ahead, which is kind of Sread ahead cleaned up, working a bit better for hard disks, has unfortunately a disastrous copyright assignment policy very close to it. So I would abandon it and stand well away. Otherwise you'll get burnt. Blocking reads, yeah, yeah, so it, it, it also requires some, some hardcore kernel stuff. It actually opens every file that you're going to load in your system in one batch. It's like a loop from one to a thousand. Open all these files and it does some clever things. It looks at the, the XT3 filing system, actually most of, most of these look at the filing system and order by block positions. And you know, my preferred one is the one that I maintain, obviously, which is at the bottom and it's quicker. So at least for me on my kernel with my work set. So what else can we do? Yeah. See sometimes things are slow and you really don't know where, you know, there's a lot of CPU happening in this thing. Of course, a lot of tools that make that quite easy to do. You can run Valgrind on it, this kind of thing. But if it's a big mix of IO, latency and CPU, then it can be kind of hard to tell what's going wrong. And this is a really nice system called PR Crutl. And there's a prure set name thing consent to it. And then there's a, you know, a handful of characters. It likes to truncate whatever you're about to set it to. And the great thing is that you can change your process name and boot chart two will adapt. And actually this, this is all one process here, but I just switched names so that I could see which domains were taking what time inside it so you can slice and dice and see very easily what's going on. So my good friend, Ian, has come up with this amazing thing called Time Chart. You can read about it in this blog. It's integrated in the kernel. It provides the ultra, ultra high resolution, everything view of what's going on in your CPU. And you can render some multi-megabyte SVG file which can't be viewed on anything except inkscape version, whatever. And it will show you exactly what is happening on your CPU. I think there's always a trade off between meaningfulness and content. I don't know. I've not used this tool. I'm sure it's very good. It shows you things you can't find elsewhere, but it might be a bit of overkill when the problems are often quite banal. So other bits. Oh yeah. There's some magic stuff for SystemTap. Like I say, if you follow the links and the slides, you'll find magic SystemTap stuff that tells you what I.O. is happening, who's triggering it and so on, what processes are taking how much time and so on. It gets kind of overlaps. Sread ahead, at least mine dumps all the files and where all the data is coming from. Often. Turns out code. It's a big chunk of it. Use a bin likewise. All those files and et cetera. This is a Moblin stutter, which is really quite lean. As soon as the Moblin one. Like 2.8 meg of files and et cetera. Config files right at boot. And so it goes on. The X team, of course, like great big libraries as well. They have compilers and side compilers. No doubt to pop in there. So there you are. Bootchop too. Reaches the places that other beers don't. And there it is. There's plenty more to do. And packaging. And he's packaging for every distro. I put quite a bit of effort into actually making it work. Even with strange in it RDS and so on. I'd love to hear your experience if you want to get it working on your distro. How am I doing for time? Oh wow. That's pretty good. Okay. The other punchline is what? This was a gratuitous advert for Moblin and it's gone horribly wrong. Honestly, I'm distressed about that. You see, look, Moblin rocks gratuitous plug. It says so there. Let's try again. Hey, that's cool. So one of the lesser known things about OpenOffice is the slideshow is using a different rendering pipeline to the editing piece. Yeah, details. And Torsten, where is he? Anyway, good. Okay. So it is possible to boot fast. There is really lots of dumb stuff in there. How fast we really can boot is unclear. The promises vary between negative time, two seconds, five seconds, 10 seconds. What I can tell you is that we can ship a machine that will boot in 23 seconds from power on button when seven seconds is the BIOS with a hard disk in it. So we're getting pretty fast. And less is more or less. So if you take a whole load of stuff out, you can boot a lot faster, but at some stage you're going to have to do the work. So you can't do everything incredibly quickly. You can only really win by deferring work and doing this more intelligently. So thanks to all the people who did it, did the research, most do not me. Are there any questions? There must be some questions. Actually, I could do a demo of the tool. Dave, shut up. I'll just do the demo first. Is that all right? You know, here's a very good question, no doubt. But somewhere here, there was that thing that I just ran that was lurking. Perfect. Excellent. So one of the things we do just to scare people when they've seen an old boot chart is to double the size of the thing. So as soon as you run boot chart two, it looks as if you're twice as slow. That's great, isn't it? Which focuses your mind on accelerating yourself. And if that doesn't work or you managed to speed it up too much, you can actually horizontally zoom as well so that you can reinforce the fear to actually get you going. Here you see our 15-inch second boot, actually on a slightly slower machine. Great chunk of I.O. to start with. This is SREedahed Races the system here. And then the other guys really get going. We draw pretty red lines and things on as well. Actually, that came from SCARP, which is, I feel like, pretty red lines. It's good. And yeah, there we are. We get up pretty quick to the end zone. So that's nice. What else do we do? Oh yes, we have this cumulative foo at the bottom, which is quite fun, as I showed you I think before. And there's all sorts of bugs as well. Unfortunately, you can't see what Init was doing before you even started logging. But it at least tells you it took a whole lot of time before it got there. So there's a good graph here. What Init is doing with the CPU, I don't know. But it stops doing it pretty quickly. I mean, you can see that. So that's good. It's quite well restrained during the runtime. And yeah, so hopefully by looking at the gradient here, I mean, obviously the optimal graph is kind of aligned from the bottom here to the top right. You know, it's kind of linear with the CPU used all the time and preferably not very long. But yeah, it's not quite like that. So what else can we see? I.O. is much more visible, I guess. So when the read ahead screws up and we see red stuff happening, you actually see the red, which is kind of nice. What else? Let me see if I can show you something really silly. Actually, that was an MSI machine. Okay, let's... Yeah, I don't know what's happening. There's just too many boot charts as you can see. Take one a day, it keeps the doctor away. Oh, well. Yeah, so here's something pretty interesting happening in the kernel. I don't know. Yeah, that's... Yeah, well, who knows. Good thing we didn't have the kernel booting stuff turned on for that, hey? So you actually have to add extra parameters to the kernel boot line to do this. There's debug in it called... It's all documented in the read me. But so that's pretty good. What else? What else? Well, yeah, as I say, the vertical line thing would be really helpful to find some of these more stupid stuff. I'll try and find the stupid stuff. I think here is one. So Haldemon at this point is starting up, and this is the half a second sleep that the kernel does when we start reading the CISFS on this hardware. And you'll notice that if you look at the... If you look... If you keep your eyes fixed at that point, and then you look at this guy at the top, it wouldn't be nice to have a split pane so you could see this and then scroll this. Anyway, but there's a great dip in CPU use. In fact, nothing is happening around here really at all. It's just kind of gone. So that's lame. So that's the tool. I don't think I can show you anything else, David. What's your question? Shoot. Oh, there's a microphone. Right. Sorry. We have four minutes. Is that right? Is there any way to run boot chart at any time of boot time? Like let's say my computer is particularly slow that I can start up data collection and then analyze it over 10 minutes data. So you can do that. It can work very well in boot chart too. Since we did all the kernel passing, as soon as you do boot chart with the kernel debugging turned on, it goes, ah, let me show you the beginning of time and then much, much, much, much later. Let me show you what you're doing now. So yeah, that needs fixing. But yeah, there's no reason why not. And it should do a good job. Okay. There was one other thing. There was one of the things that used to annoy me about the boot chart. It's one of the reasons I turned it off is if I booted and then stayed in GDM for a while, there was some kind of a parameter that said keep going until the GNOME system. Right. You just set the accumulating. And I just set there. And so when I logged in, like it was everything blocked up for minutes while it was doing Cairo SVG. Oh, right. Because there's just such a huge image. It's rendering in the background. So that's good feedback. We should fix that. So many email. You know, so there are timeouts to this thing, but yeah, we can add some more timeouts. Why not? Why not? Yeah, that requires code to make it interactive, but that's a really good idea. Send me a patch. Definitely. I love it. I love it. What a good idea. Anyone else? Since it's a new rendering engine, do you have any chance to also add a network usage information in there since the logging demon at least in the old boot chart could track it? Yeah. Right. We certainly can. Could it track it? Yeah. Yeah, it can track it. It can track systems, yeah. Okay, yeah, that's pretty trivial. I mean, this graph rendering thing is pretty generic. It's easy enough to grab random stuff out of PROC and render it. Again, you know, patches are all, I don't have any network problems at boot, luckily. So I'm kind of do this myself. Anyone else? Something you've always wanted to know, you know? I don't know. Aha! Oh, you have to wait for the microphone. Otherwise, you know, I have to repeat it. Would it be difficult to adapt the system to analyze programs just instead of the separate steps, but just, let's say, a GUI program or some server program that's not very responsive to improve the performance of a program? Yes, I suppose so. Potentially it's helpful for looking at the system. There is another very good tool called SysProf. That's probably what you want to use for that. Okay. I was meant to put it in my slides. There are some nice patches now so that you can do a SysProf of the whole boot and you can see where Sloanus is, which allows you to micro-optimize entirely the wrong place, which is great. What? What? You know, malloc is really, really slow. You know, we've got to speed malloc up, you know? It's taking like half the time. Actually, you know, someone had the idea of speeding malloc up before you and you're not going to win. So why not just walk out while you're allocating all this memory and then freeing it? And you know, there's been a number of such optimizations. It's unfortunate. So my tip is when you find a performance bug, stick an F printf in, rerun it, and you will immediately understand why, you know, the human pattern recognizable. Yeah, yeah, yeah. Yeah, well, okay, SysProf works well with multi-threaded programs. It'll show you all the processes. So it'll show you X. If you're lucky, it'll show you the kernel. I think it'll take you down into the kernel if the thing's blocking them. And it's pretty cool. It's a really, really good tool. Time out, perfect. Thank you for your patience. Thank you. Thank you. Thank you.
 thing, it renders with Kyro to SVG and PNG, and it's a lot nicer.  Then Scott James Rowling did a really good thing, canonical, great.  They actually did something.  And they rewrote the shell script, which is essentially the moral equivalent of this.  I mean, there are more lines, but that's practically what it does.  And he rewrote it in C, so it went a lot faster.  So you could get better resolution, better granularity, which is cool.  And then Bootchart2 came along, which was me.  And I rewrote his collector for a couple of reasons.  The first thing is the proc interfaces are not particularly good.  So when is the process running?  The information in proc, it's unclear to me what the granularity of that is, how long.  The state information there doesn't seem to me to be very good, basically.  And if something can run and then block, and seemingly it's not running,  I don't know, some kernel guy would tell me, I'm sure.  But there's a better interface, which is the task stats interface.  And that gives you nanosecond accurate in theory time accounting.  It's interesting, the nanosecond values go up in suspiciously uniform, large,  into the chunks.  But at least it's a lot better than it could be.  And the interface is horribly blocked and unpleasant, and it doesn't work.  And it's supposed to have task groups or something.  So I guess if a process has multiple threads, but that doesn't work either.  But if you wander through proc, you can actually get the information out  at some hideous CPU cost, and you can do it at a relatively high frequency.  And that's great. Task stat is on in virtually every kernel,  except in Intel's mobile in where virtually everything is turned off,  just in case it's useful.  So it allows us to say better than that, which process has used how much CPU?  So in the original boot chart, you could say, well, something seemed to be busy  at this kind of time, but not tell me how much CPU was used by that process.  So we can now answer that question.  And Spoochart2 also integrates PyBoot chart GUI, it throws away the Java thing,  and so you can have a much better coupling between those two beasts.  So in the old world, we went from something like this,  and in the new world, we go to something like this,  where you see all of these lots of little tiny things  which now aren't being thrown away because apparently they took no time.  And so there's boot Udev, Udev, Udev, Udev, Udev, all of these tiny things  and lots of very narrow, it's kind of new and differently broken.  So that's great. And you notice that here, boot Udev was just taking no time.  This is all gray, if you can't see it at the back.  And that's at least slightly blue, which is progress, you see.  There's a Tory bias underneath some of this, as you can tell.  Anyhow, yeah, Witch in bulk has lots of lines.  Yes, okay, so when you start seeing interesting things happening,  there's all these tiny striations here.  This guy is a really good guy.  Look at this, the skin guy is taking serious CPU, you know?  Doesn't actually do anything, or it's only here to set an environment variable,  really, at this stage, but it really goes through it with Panache.  I think it loads all of the language, you know, catalogs and other things.  Anyway, so that needs fixing.  The other thing that the original boot chart did, which was very zen,  was that when lots of things were happening at once,  it would change the alpha channel of the rendering.  So we show you the percentage of CPU that was being used.  So the media effect was, as soon as the CPU got remotely busy,  everything became very blurry and transparent,  you can see what was taking any time.  So we turned that off and there was an instant win.  So you know, you can see in this channel here, you know,  when the CPU is really going at it across umpteen processes,  actually you can see that they're all still doing something  and try and get some idea of the sequencing.  And of course, since it's accurate, you can also see holes.  A nice feature that someone could hack for me  would be to show nice holes that go vertically when the processor is stalled.  And we see some of those. ACPI is causing some serious grief on some hardware.  And you can see, you know, the same problem happens in CISFS three times.  You know, we take a half a second delay, pulling a battery,  we don't need to pull when Udev starts, when X starts, and when HAL starts.  One and a half seconds of sleep.  Very easy to see. It'd be nice to highlight that.  Another thing that we can do, because we've got actual hard CPU time,  how much time did it take at any given time,  is draw cumulative charts of what's taking the CPU.  So that's kind of fun.  So here you can see, for whatever reason, we're starting Banshee at a boot  and it's taking nearly 20% of the time. That's good, huh?  Optimization opportunities.  But you can also, you know, sort of start to rank these guys  and you can see when they appear.  It's unclear to me that it's very useful, but it looks pretty.  So marketing is everything and so forth, you know.  Another thing that's pretty good is kernel boot charting.  So the old boot chart, actually this is a new boot chart,  but the old boot chart suffered this too.  You know, you would start because we knew when the kernel, you know, got going.  This is kind of zero time.  And then some very much later time, your boot chart actually started.  And so this gap here was just a complete mystery.  What happened? Who knows?  And Ion came up with a really nice way of dealing with this, I guess,  in it called debug stuff. I think it was him. Either way, he used it.  And so then you can draw a nice graph and you can say,  look, the kernel is booting in this period  and this is the populated root FS, the visa of frame buffer in it,  keyboard, blah, blah, blah, blah, software resume,  which is just a beast of a, you know, like the seconds here are now this wide.  So one, two, three, four, five, six, seven seconds, maybe, if I can count properly.  Anyway, lots of seconds and that's the software resume.  And of course there was nothing to resume. So, you know, it just carried on at the end.  But you can also see some interesting things.  So when the system has actually got started, this is Udev  and the various things happening in either a RAM disk or, I don't know, main system,  it's starting to do mod probes and module loads.  You can see then the asynchronous and delayed init bits happening, I guess, in the kernel there.  I don't understand any of that. I just pass the data and render it.  Does that make sense, Greg? Perfect.  I've never done something like this in the whole process.  And why are you checking the area?  Right.  You check them all the way up. It really isn't the plot.  It really wasn't the core.  Nice, nice.  It's, yeah, okay.  But until you look at the rendering, you know, you have no idea why the kernel  is taking eight seconds to start.  It seems a reasonable thing to take eight seconds.  I mean, you know, it's a lot of code, right? It should take eight seconds.  And when you look at it, you realize it's really dumb.  And this is, there's much more detail that's perhaps more useful for the kernel guys in  terms of far more granular, you know, allocations of which functions and which initialization  pieces are taking time and how that parallelizes and so on.  And that's pretty nice.  So all we do is we store it.  We do a bit of a worse job of rendering it.  But there's this pretty tool in the kernel here and you pipe your dmessage into this  marvelous Perl script.  You get an SVG file out and it looks pretty like that.  And it tells you why your kernel is slow to start.  So there are lots of schools of thought on how you should improve boot time and lots  of elite hacks.  And sometimes you have customers that come to us and say, oh, we've discovered if we  put, you know, like 15 ampersands in all of these scripts, it starts much faster like  this.  And you're like, yeah, yeah, yeah.  And it crashes as soon as you press a key, you know.  Yeah, I mean, some of the race conditions are really exciting.  One of the ones that I had was that you're setting terminal settings on the console.  And one of the cunning settings is not to receive a signal when you press enter.  Like normally when you press enter, you get a signal like sig, eh, whatever.  And due to a race condition, we were starting X, which was turning off the sig air.  And then we were turning it back on by restoring the console state.  The symptom of this was that the first time you ran X and you hit enter, the X server crashed.  But could we find it?  No.  We traced the whole system.  I mean, you know, it took forever to work out.  It's a feature, you know.  It's one of those really nice features that dates back from 25 years ago that no one actually  knows or cares about anymore.  But you know, whatever, you have to turn it off.  So all of these wonderful plans, you know, maybe you start Udev and you start Hal and  Prowler with it and then you start X as well and something will go wrong on some machine  somewhere.  So, or network management.  You can bring up network management much later.  That's fine.  But it turns out a whole load of apps that aren't really geared up for the network stack  to appear, you know, in mid initialization or mid flight, which sucks.  There are bugs.  There's no point in not fixing them.  But finding so many bugs at once can be, you know, challenging.  So another thing that the people try and do to make it quicker is they think, well, what  the problem is is we have all these shell scripts, you know.  What we need to do is throw away the unit system and rewrite the unit system.  And that's probably true.  But one approach was to rewrite it all as a single shell script, you know.  So everything happens in order, you know.  It's beautiful.  So we tried this.  Mobile N Project did this.  We tried it.  I spent quite a while switching our actually already parallelized kind of make file based  sort of in it process to use this.  Cunning you obviously faster way.  But it's actually no faster.  It turns out that the cuts are elsewhere, you know.  The thousand cuts are in each thing that you're starting up and the silly wrappers around  them.  So that was pretty serious.  And yeah, I mean, it's just a lot of work profiling each piece and making it not suck.  So mod probe, you know, was very slow.  There was some big silly cache and I think Red Hat fixed that.  Udev was also pretty slow.  I think Cive has fixed that.  Cosa.  Colour module loading took some kind of monster lock that stopped anything happening.  So you know, you could load lots of modules in parallel, of course, you know, until you  actually wanted to load the module, which, you know, then they would all kind of serialize,  I think.  How, yeah, how has been doing incredibly inefficient things and still is, you know.  I mean, but you know, something like a 10 line patch doubled the performance of how  it starts up, which is previously two seconds of CPU or something.  And there's another 50% in there that is not parsing a 600K file that we don't need to  parse 23 times.  Honestly, you know, I mean, if you want glory, you know, it's easy.  It's easy here.  But the answer is not doing all of this crazy stuff.  It's just like taking a profile out to ordinary pieces of coding going, huh, that's dumb.  Gcon.  Similarly, you know, the XML parser, the guy that wrote it, didn't understand UTF-8 and  did stuff in really silly ways.  You know, and it still goes on.  There's plenty of fat left, really.  Another interesting thing is SSD, well, I guess IO.  IO takes a lot of your life away if you're not very careful.  And this is the famous five second mobile boot chart.  I'd like to, you know, this is sort of historical, you know, interest here.  Yeah.  Does it boot in five seconds yet?  No?  Okay.  So this was a high point.  You know, XFC is obviously the future.  And with an SSD life is very easy, it turns out.  So SSDs are not only blazingly fast, which throws away, you know, much of your LASNC,  but you can also do stupid things, seeking all over the place.  So what you do is you start your huge SREADHead process, which is, I guess, down here.  As you notice, the SREADHead process isn't actually doing anything because it's an old  style boot chart.  But what it's actually doing is batching full threads worth of IO requests for everything  you need in order.  And it does it in the background.  So if you really need something and it wasn't in the profile, you get it.  So that's SSD, which is all good.  Hard disk, you have the opposite problem, that you really, really, really need to read linearly.  So again, this is my SREADHead and, well, you instrument your entire boot process and  you try and catch everything, not just the open syscalls, you catch execs and use them  and various things.  And then you, you know, you kind of chunk it into chunks that seem good to you, some,  you know, mystic, mystical way.  And then you read a whole lot to start with and you try and get ahead.  Actually, I think this fail, but you try and get ahead of the system and then you let the  CPU go and you say, go, and then you race ahead trying to catch up so that you're going  to be ahead of it all the time so that when it needs, you know, the data, it's there.  Yeah, it's quite exciting.  Anyway, there's lots of different options, but it does make a difference.  Here's, I think, relatively lame and relatively old screenshot of the 34 seconds.  This is some open SUSEboot and there's down to 28 with, again, some different way of doing  preload that's, I think, split into sections and stuff.  I mean, the punchline is you can see that this disk is not, you know, this is a theoretical  gigabit a second bandwidth to the disk, but reality is that you're getting, you know,  like 14 megabytes a second peak out of it, you know, and that's, that's with the preloading.  You know, so there's some serious problems in terms of getting data off disk.  The great news is that you have a lot of choice here, you know, there's a lot of preloads  out there.  This is the SUSE one.  I was just showing you the graph there and use a system tap, which is wonderful.  This is Mark, no, he hasn't made it, but anyway, I have to advertise system tap because I  like Mark.  And yeah, that, this kind of module that traces the IO and the problem is not tracing the IO,  but tracing the IO that wasn't your read ahead so that you don't incrementally build a bigger  and bigger and bigger read ahead thing that becomes relevant.  And then there's other versions.  So Red Hat have a nice thing, the Intel had a nice thing, I think, placed loosely on the,  on the Red Hat one, which is now dead.  There's no updates for it.  It works well on flash, but not hard disks.  I'm going to have your read ahead, which is kind of Sread ahead cleaned up, working a  bit better for hard disks, has unfortunately a disastrous copyright assignment policy very  close to it.  So I would abandon it and stand well away.  Otherwise you'll get burnt.  Blocking reads, yeah, yeah, so it, it, it also requires some, some hardcore kernel stuff.  It actually opens every file that you're going to load in your system in one batch.  It's like a loop from one to a thousand.  Open all these files and it does some clever things.  It looks at the, the XT3 filing system, actually most of, most of these look at the filing  system and order by block positions.  And you know, my preferred one is the one that I maintain, obviously, which is at the  bottom and it's quicker.  So at least for me on my kernel with my work set.  So what else can we do?  Yeah.  See sometimes things are slow and you really don't know where, you know, there's a lot  of CPU happening in this thing.  Of course, a lot of tools that make that quite easy to do.  You can run Valgrind on it, this kind of thing.  But if it's a big mix of IO, latency and CPU, then it can be kind of hard to tell what's  going wrong.  And this is a really nice system called PR Crutl.  And there's a prure set name thing consent to it.  And then there's a, you know, a handful of characters.  It likes to truncate whatever you're about to set it to.  And the great thing is that you can change your process name and boot chart two will  adapt.  And actually this, this is all one process here, but I just switched names so that I  could see which domains were taking what time inside it so you can slice and dice and see  very easily what's going on.  So my good friend, Ian, has come up with this amazing thing called Time Chart.  You can read about it in this blog.  It's integrated in the kernel.  It provides the ultra, ultra high resolution, everything view of what's going on in your  CPU.  And you can render some multi-megabyte SVG file which can't be viewed on anything except  inkscape version, whatever.  And it will show you exactly what is happening on your CPU.  I think there's always a trade off between meaningfulness and content.  I don't know.  I've not used this tool.  I'm sure it's very good.  It shows you things you can't find elsewhere, but it might be a bit of overkill when the  problems are often quite banal.  So other bits.  Oh yeah.  There's some magic stuff for SystemTap.  Like I say, if you follow the links and the slides, you'll find magic SystemTap stuff  that tells you what I.O. is happening, who's triggering it and so on, what processes are  taking how much time and so on.  It gets kind of overlaps.  Sread ahead, at least mine dumps all the files and where all the data is coming from.  Often.  Turns out code.  It's a big chunk of it.  Use a bin likewise.  All those files and et cetera.  This is a Moblin stutter, which is really quite lean.  As soon as the Moblin one.  Like 2.8 meg of files and et cetera.  Config files right at boot.  And so it goes on.  The X team, of course, like great big libraries as well.  They have compilers and side compilers.  No doubt to pop in there.  So there you are.  Bootchop too.  Reaches the places that other beers don't.  And there it is.  There's plenty more to do.  And packaging.  And he's packaging for every distro.  I put quite a bit of effort into actually making it work.  Even with strange in it RDS and so on.  I'd love to hear your experience if you want to get it working on your distro.  How am I doing for time?  Oh wow.  That's pretty good.  Okay.  The other punchline is what?  This was a gratuitous advert for Moblin and it's gone horribly wrong.  Honestly, I'm distressed about that.  You see, look, Moblin rocks gratuitous plug.  It says so there.  Let's try again.  Hey, that's cool.  So one of the lesser known things about OpenOffice is the slideshow is using a different rendering  pipeline to the editing piece.  Yeah, details.  And Torsten, where is he?  Anyway, good.  Okay.  So it is possible to boot fast.  There is really lots of dumb stuff in there.  How fast we really can boot is unclear.  The promises vary between negative time, two seconds, five seconds, 10 seconds.  What I can tell you is that we can ship a machine that will boot in 23 seconds from  power on button when seven seconds is the BIOS with a hard disk in it.  So we're getting pretty fast.  And less is more or less.  So if you take a whole load of stuff out, you can boot a lot faster, but at some stage  you're going to have to do the work.  So you can't do everything incredibly quickly.  You can only really win by deferring work and doing this more intelligently.  So thanks to all the people who did it, did the research, most do not me.  Are there any questions?  There must be some questions.  Actually, I could do a demo of the tool.  Dave, shut up.  I'll just do the demo first.  Is that all right?  You know, here's a very good question, no doubt.  But somewhere here, there was that thing that I just ran that was lurking.  Perfect.  Excellent.  So one of the things we do just to scare people when they've seen an old boot chart  is to double the size of the thing.  So as soon as you run boot chart two, it looks as if you're twice as slow.  That's great, isn't it?  Which focuses your mind on accelerating yourself.  And if that doesn't work or you managed to speed it up too much, you can actually horizontally  zoom as well so that you can reinforce the fear to actually get you going.  Here you see our 15-inch second boot, actually on a slightly slower machine.  Great chunk of I.O. to start with.  This is SREedahed Races the system here.  And then the other guys really get going.  We draw pretty red lines and things on as well.  Actually, that came from SCARP, which is, I feel like, pretty red lines.  It's good.  And yeah, there we are.  We get up pretty quick to the end zone.  So that's nice.  What else do we do?  Oh yes, we have this cumulative foo at the bottom, which is quite fun, as I showed you  I think before.  And there's all sorts of bugs as well.  Unfortunately, you can't see what Init was doing before you even started logging.  But it at least tells you it took a whole lot of time before it got there.  So there's a good graph here.  What Init is doing with the CPU, I don't know.  But it stops doing it pretty quickly.  I mean, you can see that.  So that's good.  It's quite well restrained during the runtime.  And yeah, so hopefully by looking at the gradient here, I mean, obviously the optimal  graph is kind of aligned from the bottom here to the top right.  You know, it's kind of linear with the CPU used all the time and preferably not very  long.  But yeah, it's not quite like that.  So what else can we see?  I.O. is much more visible, I guess.  So when the read ahead screws up and we see red stuff happening, you actually see the  red, which is kind of nice.  What else?  Let me see if I can show you something really silly.  Actually, that was an MSI machine.  Okay, let's...  Yeah, I don't know what's happening.  There's just too many boot charts as you can see.  Take one a day, it keeps the doctor away.  Oh, well.  Yeah, so here's something pretty interesting happening in the kernel.  I don't know.  Yeah, that's...  Yeah, well, who knows.  Good thing we didn't have the kernel booting stuff turned on for that, hey?  So you actually have to add extra parameters to the kernel boot line to do this.  There's debug in it called...  It's all documented in the read me.  But so that's pretty good.  What else?  What else?  Well, yeah, as I say, the vertical line thing would be really helpful to find some of these  more stupid stuff.  I'll try and find the stupid stuff.  I think here is one.  So Haldemon at this point is starting up, and this is the half a second sleep that the  kernel does when we start reading the CISFS on this hardware.  And you'll notice that if you look at the...  If you look...  If you keep your eyes fixed at that point, and then you look at this guy at the top,  it wouldn't be nice to have a split pane so you could see this and then scroll this.  Anyway, but there's a great dip in CPU use.  In fact, nothing is happening around here really at all.  It's just kind of gone.  So that's lame.  So that's the tool.  I don't think I can show you anything else, David.  What's your question?  Shoot.  Oh, there's a microphone.  Right.  Sorry.  We have four minutes.  Is that right?  Is there any way to run boot chart at any time of boot time?  Like let's say my computer is particularly slow that I can start up data collection  and then analyze it over 10 minutes data.  So you can do that.  It can work very well in boot chart too.  Since we did all the kernel passing, as soon as you do boot chart with the kernel debugging  turned on, it goes, ah, let me show you the beginning of time and then much, much, much,  much later.  Let me show you what you're doing now.  So yeah, that needs fixing.  But yeah, there's no reason why not.  And it should do a good job.  Okay.  There was one other thing.  There was one of the things that used to annoy me about the boot chart.  It's one of the reasons I turned it off is if I booted and then stayed in GDM for a while,  there was some kind of a parameter that said keep going until the GNOME system.  Right.  You just set the accumulating.  And I just set there.  And so when I logged in, like it was everything blocked up for minutes while it was doing  Cairo SVG.  Oh, right.  Because there's just such a huge image.  It's rendering in the background.  So that's good feedback.  We should fix that.  So many email.  You know, so there are timeouts to this thing, but yeah, we can add some more timeouts.  Why not?  Why not?  Yeah, that requires code to make it interactive, but that's a really good idea.  Send me a patch.  Definitely.  I love it.  I love it.  What a good idea.  Anyone else?  Since it's a new rendering engine, do you have any chance to also add a network usage  information in there since the logging demon at least in the old boot chart could track  it?  Yeah.  Right.  We certainly can.  Could it track it?  Yeah.  Yeah, it can track it.  It can track systems, yeah.  Okay, yeah, that's pretty trivial.  I mean, this graph rendering thing is pretty generic.  It's easy enough to grab random stuff out of PROC and render it.  Again, you know, patches are all, I don't have any network problems at boot, luckily.  So I'm kind of do this myself.  Anyone else?  Something you've always wanted to know, you know?  I don't know.  Aha!  Oh, you have to wait for the microphone.  Otherwise, you know, I have to repeat it.  Would it be difficult to adapt the system to analyze programs just instead of the separate  steps, but just, let's say, a GUI program or some server program that's not very responsive  to improve the performance of a program?  Yes, I suppose so.  Potentially it's helpful for looking at the system.  There is another very good tool called SysProf.  That's probably what you want to use for that.  Okay.  I was meant to put it in my slides.  There are some nice patches now so that you can do a SysProf of the whole boot and you  can see where Sloanus is, which allows you to micro-optimize entirely the wrong place,  which is great.  What?  What?  You know, malloc is really, really slow.  You know, we've got to speed malloc up, you know?  It's taking like half the time.  Actually, you know, someone had the idea of speeding malloc up before you and you're not  going to win.  So why not just walk out while you're allocating all this memory and then freeing it?  And you know, there's been a number of such optimizations.  It's unfortunate.  So my tip is when you find a performance bug, stick an F printf in, rerun it, and you will  immediately understand why, you know, the human pattern recognizable.  Yeah, yeah, yeah.  Yeah, well, okay, SysProf works well with multi-threaded programs.  It'll show you all the processes.  So it'll show you X.  If you're lucky, it'll show you the kernel.  I think it'll take you down into the kernel if the thing's blocking them.  And it's pretty cool.  It's a really, really good tool.  Time out, perfect.  Thank you for your patience.  Thank you.  Thank you.  Thank you.
bootchart2_FVm_Pzg4E50_2_0_2363.png bootchart2_FVm_Pzg4E50_2_2364_3359.png bootchart2_FVm_Pzg4E50_2_3360_4859.png bootchart2_FVm_Pzg4E50_2_4860_5219.png bootchart2_FVm_Pzg4E50_2_5220_6587.png bootchart2_FVm_Pzg4E50_2_6588_7643.png bootchart2_FVm_Pzg4E50_2_7644_8591.png bootchart2_FVm_Pzg4E50_2_8592_13367.png bootchart2_FVm_Pzg4E50_2_13368_15731.png bootchart2_FVm_Pzg4E50_2_15732_16487.png bootchart2_FVm_Pzg4E50_2_16488_17471.png bootchart2_FVm_Pzg4E50_2_17472_20231.png bootchart2_FVm_Pzg4E50_2_20232_24095.png bootchart2_FVm_Pzg4E50_2_24096_24299.png bootchart2_FVm_Pzg4E50_2_24300_27419.png bootchart2_FVm_Pzg4E50_2_27420_27707.png bootchart2_FVm_Pzg4E50_2_27708_28583.png bootchart2_FVm_Pzg4E50_2_28584_28655.png bootchart2_FVm_Pzg4E50_2_28656_30347.png bootchart2_FVm_Pzg4E50_2_30348_32219.png bootchart2_FVm_Pzg4E50_2_32220_35567.png bootchart2_FVm_Pzg4E50_2_35568_35675.png bootchart2_FVm_Pzg4E50_2_35676_36239.png bootchart2_FVm_Pzg4E50_2_36240_36399.png