 Go ahead. So hello, everyone. And indeed, I wonder whether I should actually be concerned or flattered that there are so many such an enormous attendance at this late hour of the day. But that's great, because then you can all help us to 3R system debug. So please pay attention. So system D provides a range of tools to debug and shut down problems, and shelling services, and also to optimize boot time. And while everything is documented quite well, I think it actually makes sense to see how these tools would look in action, and if you actually encounter a situation where your boot doesn't work. And I want to show you the first steps and the tools that you can use to dissect the problem, how to get to the root of it. And the idea is that this was supposed to be an interactive bof. So I show a particular scenario and hack around a little bit, show you the tools. And please never hesitate to ask questions to that scenario, or if you want to know some details about this, or what if this thing would look a little different, and so on. And I have prepared a couple of scenarios, and we just keep on walking through them until we either run out of time or out of Club Marta or, let's see. Let's first start with a relatively clean Debian installation from like two weeks ago, I think, when I prepared this VM. This is an XFZ installation. So you see the boot is relatively clean. We boot with quiet, so there are no messages, and it's reasonably fast. So this is the situation that we expect, no long hangs and so on. And LXDE doesn't have a shortcut for increasing the font size. Bad. So I think this should be moderate to a reasonable now. The first, sorry? Still not? How is that? What, Marta? Oh, OK. So maybe I don't make that full screen, but almost full screen so that we see the first character. Oh, that's all not assistant debug. Sorry? OK. So the first feature that I want to show is the journal. So System Decentralizes all logging that goes on in the system into the so-called journal, and you should think about it as a kind of a log database. So it's not just a simple text file unlike the old Varlog syslog. It is actually a full database which you can query, index, you can format it as you like. So which makes it very nice to debug problems with particular units or particular time spans and so on. If you just look at the journal without any other options, it pretty much looks like Varlog syslog. So it is formatted in exactly the same way for backwards compatibility reasons. So if you want, you can just uninstall our syslog and use the journal instead. And all the parsing tools, et cetera, should go along with that just fine. Except that it contains a lot more than the usual artist log. In particular, it contains all the kernel messages, and then what is particularly useful is that it also contains all the demons standard out in standard error. Unless, of course, they redirect their output to a depth null, but most demons don't. So you can see pretty well what's going on in the system. So the full journal is quite a bit of a mouthful, of course. So if we want to look at what's going on in a particular, with a particular service like D-Bus, we can say that too. With dash U, we can give it a particular unit name like D-Bus service. You don't actually need to type the service, but maybe it's a little less confusing. And then you only see the logs that D-Bus generated. And you see it's not just the logs, it's also a standard output from the demon, which is quite nice. And not only that, you can also filter by like a message priority. So you can say, don't give me the full SysLog, but only give me all messages that are at least warning. So you can say, priority, warning, and then if you want to debug, what's wrong with the system, you only really get the important bits and not all the technical battle from the kernel, which hardware detects and so on. But you can walk through the warnings and error messages, which gives you a much better idea of what goes on in the system. And in this particular case, the errors are marked in red, so it's even easier to spot them. Another useful thing is to only show messages which belong to a particular user. As I said, everything in the system is locked into the journal, including the user sessions. So I could also say, give me everything that is relevant to my Martin user here. And I get that. So there was a couple of system D messages here, which might be confusing, but please take into account that the session is also maintained, like every user has its own system D instance, which you can use to manage your session in pretty much the same way as you would manage the whole system. So you see it's not system D PID 1 here, but it's PID 443. So you can use it to figure out error messages from, say, GVFS or whatever goes on here. And you see these dash dash reboot lines here, which show you the boundaries between different reboots. And the useful thing to do is to restrict the output to the current boot only. Then you don't get all the bits that aren't relevant to the current boot. So you see this was the boot from... I mean you have to add here that. That's only working if you enable persistent journal. And I think you didn't mention that yet. And no, because the current boot always works. Sure. So that's locked into run by default. So in Debian, we don't enable persistent boot, persistent journaling, that is logging to VAR log journal. Because we install ArcSysLog by default, and we didn't want to rock the same stuff into two different places because it's just a waste. But you can enable persistent journal by pretty much just creating the VAR log journal directory. And then you can do nice things like show me the log from the previous boot, which is minus one. And then you see it's an older one. And you can also ask it like, which boots do you know about? So I created this VM in August 13 apparently, and the one from August 21, 18 o'clock, that's the current boot. And we can also combine all these. So you can say, give me the messages from user thousand, from current boot, which belong to, I don't know, GVFS servers, for example. So there was loads of options. The man page documents them very well. And another nice property is that you don't really need to worry about like block rotation or the thing overflowing your disk. So by default, it uses a dynamic size constraint. So I think 10% of available RAM or disk, depending on whether you use temporary or permanent journal. So it actually adjusts to the space that you have available. And it makes sure that if you have less than 15% of your disk space left, then it also starts returning away all messages. Right. So you keep about as much data as makes sense on your system without eating your disk, but you don't need to decide in advance, like I want to keep the last seven days of log data. Of course, you can change the configuration. So like it's the old time-based approach, but usually the defaults are fine. And if you want to see even more stuff in the journal, you can also apply the debug build boot option. And then the output gets really, really big. You can see all the individual state transitions, what system you think should happen now, what it's waiting on, what the job statuses are. But you can also, if you already have booted the machine and you don't want to get the large robustity for everything, is there 10 minutes left? Really? Wow, okay. I thought we had 45 minutes. 45 minutes. Yeah, I don't know. Poof. Okay, are there any questions up to this point? All right. So there is also the possibility to dynamically change the log level. So you can, you know, da, ever try typing in front of an audience. So you can dynamically change it. And from then on, if you do something like Cron, for example, then you see that you get, oops, yeah. Use minus F. Yeah, for example, you see, it shows you the command that it was executing and the pit file and whatnot. So that's, that might be helpful in some cases. And now I want to show you some typical problems that can happen when, like when you, for example, install the new package and it installs a new service on your system, which hooks into early boot, which is somehow messed up, which is I think where it becomes interesting for you as a package maintainer. So we now try to boot this. You see, there's not really that much going on. And that's bad, right? Because like there was no terminal and ah, okay. And now we finally got some error message. By the way, the usual timeout for system D is 90 seconds, which means like if you say this service has to be started on boot and it somehow fails to start, then after 90 seconds, system D will usually show you that error message for the purposes of the demo or it changed that to 10 seconds. Okay, but still this is early boot. So no VTs, what do we do? Let's hit the reset button. So pretty much, there's my keyboard. Hello keyboard. Okay. So pretty much the first thing you should do is drop the quiet so that you see a little more of what's going on. And then the pretty much most invaluable debugging tool that we have is the debug shell, which you can enable with giving the kernel the system D.debug shell option. And so this will start a root shell on VT9 which is done very, very early in the boot and it survives until the bitter end. So it's pretty much always available unless there was something really, really bad going on. So you see, I just hit out of nine. So we see we have a nice shell now. Unfortunately, there's still a bug in system D which clobbers your debug shell with the kernel debug messages, but yeah, that will be fixed at some point. So we can check. Oh, I figured you couldn't read this, right? Ah, that's bad. Hang on. See whether, is this any better? No. Ah, there'll be the reset. And oh, okay, I can't really increase the font size at this point, right? Ah, okay, so let's try to explain and shell less. So at least I can say I have a debug shell here and I can do all the system kittle or any kind of introspection commands that I want. So if I type system kittle list jobs, I see a list of running jobs and this one, for example, says blocker.servers which is type start and state running. So I see blocker.servers is running and it keeps being running and that seems to block everything because everything else is just in state waiting. So I could now go and introspect what this thing is doing. For example, type system kittle cat blocker.servers. I see that in xx.start, this is just doing a sleep 2000 and apparently not going anywhere. So now I could go and kill that job or fix that job, but... So list jobs is the first thing which you can do to see what is currently hanging. Well, I guess I'll show you the status that L in the running system so that you can actually see something. Okay, let's look at this here. So one thing you need to be aware of about the debug shell is that it gives you a root shell without a password query. So you shouldn't enable that option in your grub default configuration. You really should do that and only enable that on demand. Yeah, absolutely. This is, yeah. Sorry? What's the default? Well, it's of course off. So this is why before when I didn't boot the debug shell, you have no VT on the system because the blocker.servers, if you could have read it, it is a very early service which wants to boot in the equivalent of RCS.D. So it runs way before or like discs are, like around the time when discs are being mounted and way before there are skatties and all the fancy stuff. Another track which seems to be a common pitfall is if you have a broken FSTAP. That is, if FSTAP mentions some device which isn't there or cannot be mounted. I mentioned this on my talk yesterday. So Sys5 in it and upstart just happily ignored these situations but system D is stricter about this because in some cases it's really, really wrong and the system behaves in a weird way or even in an insecure way. If you forgot to forget to mount something which you really want. So for example, whoops. We have a couple of mounts here. Can we read this now? Yeah. And for example, we could break the UID of var which is here. Let's make this into an A. Okay. A common problem is that users reformat their swap space. So it changes the UID and that seems to happen quite often. And if we now boot this, we will see that again it takes a while because like in a hop-pack system it might be the swap eventually appears but no, it doesn't. We see here timed out waiting, well, well, I see it says timed out waiting for device, death disks, spy, uuid, blah, blah, blah, dot device. And if that happens then you will get, boh, bad. So I get a root shell here which essentially says welcome to emergency mode. And in that root shell again I can investigate what's wrong and well, I guess that's a little point of showing that here but that gives you a rescue shell before everything is mounted and you can again inspect system-cuttle list jobs or system-cuttle-fail to see the failed units. Oh, actually not. Uuid, okay. Well, you could look into the journal again and then you see, and there should be some swap, where is it? Okay, ignore this. So you get the root shell and you can hack into the system and fix the Uuid's or fix FSTub and so on. Yeah, please. I have one question. I had something like this. It's a Sando 7 machine that I changed booting with slash boot to a label in FSTub but forgot to set the label and I had it there that system-d would not start, would time out at 90 seconds and then drop me into a shell and I didn't get a network so I had to use an out-of-band management to get onto the machine and it didn't start the SSH demon cause the mount was not there. Now the mount isn't quite that important for normal operation of the machine. How is this handled in Debian? I think one has to add no fail to the FSTub to make it non-important but how is it in Debian that is starting off the network or of the SSH demon possible in that state or wouldn't it be possible? Well, it really depends. I mean, if you're slash user or slash bar fails then I'd say you don't really get very far. If it's some slash media mount or just where you keep on directories of course you could get far enough. I mean, this idea came up before that if you're dropped into rescue shell and you do use that server remotely via SSH that the rescue mode should start your network and start SSH and let you log in but it's hard to do that in a generic way. I guess you could hack that on your local server and provide something like that but I'm not sure if you can do that in a generic way to provide that because we don't really know what kind of networking system the user is using and if he's using network D if up down network manager or whatever and so it could be a bit hard to provide that out of the box. Right, so usually as you say like the default is fail which means that any partition you put into FSTub is required to boot so that's the kind of default assumption if you tell anyone anything else but it's perfect to mark slash media or so partition as no fail in which case system people complain but it will just happily go on but again, if you do this on slash user or var you will still get a broken state but a lot less explicit so it'll just behave weird or lots of services fail to start up. Yeah, I wouldn't put no fail to slash user or slash var. I don't think that would be a good idea. What I experienced then was that when the boot doesn't, when the slash boot wasn't I'd be able to mount it I try to start the SSH and it would time out again under 90 seconds and drop me into the emergency mode again instead of starting out SSH. So in the end, what I did is type us have been SSHD to start it manually and I would like if it would be able to even in this state of an emergency we shall at least start the SSH service. That's possible and what you were seeing is that SSHD declares dependency on it's a default service using default dependencies. So it depends on local FS target and if you start that and this dependency is not yet fulfilled it will try to, it will try that again but you can use dash dash ignore dependencies I think is the switch and then it will just queue the job without looking for any dependencies. So that should work. All right, okay, nothing. Question from me. So you just showed us we have a broken FS tab we enter in the root shell. So what if I fix the FS tab and want to continue with the boot? Oh just press control D and now that's actually not sufficient. You need to tell system D to re parse FS tab. You need to run system CTL, daemon reload. Oh it's daemon reload. Yes. Sorry, what do I have to run? Daemon reload. You need to do that and tell system D to re parse at CFS tab. It doesn't do it. Okay, well just reboot of course, but yeah. So at this point nothing really is mounted yet. So, well actually no. I mean it could be that your root partition is mounted so just hitting the power switch is a bit dangerous. So next I was actually going to show a boot deadlock and how to debug this but again since you can't read this on this beamer I guess I just skip that part and restrict like maybe first do the stuff that I can show in the graphical terminal. So for example, when I boot this VM, okay. Then we will notice that it takes significantly longer to boot. So we have quite a long hang here. Nothing happens. So it's not like it totally breaks your boot but something is clearly wrong here and we want to figure out what that is. Okay, 14, make it big. So there is the tool system, the analyze which is very useful in that. If you just call it like this, it will give you a summary of the time that it spends in the kernel and user space and if you put this on an EFI system, you will even see the time that it spends in the boot loader. Since this is not EFI, it just really can tell the kernel and not really the time that it spends from powering on to grab. And so that shows us we took 8.1 seconds in user space which does sound a bit long and we want to optimize that. So, oops. And then we could look at basically the path, the dependency path that is the critical chain that is if you sum up all the weights on this longest path then we would get up to this 8.1 seconds and we can see exactly when happens what. So we see that like system to user sessions, so the system was ready to accept logins at like 0.8 seconds but then our graphical user or graphical login manager LXDM only started at eight seconds so something is clearly wrong there. So we could take a look at the list of units which of those took the longest time and that's for system de-analyzed blame. That gives you a list of units in descending order and this shows us this expensive service took 7.3 seconds to start up. That's of course bad. And if you are more like a graphically oriented person, there's also a kind of a poor man's boot chart which is called, do you have a question, sorry? Okay, and there is a poor man's boot chart which is called system analyzed plot and that will generate you a nice SVG. Okay, that should look reasonably familiar. Of course, this one doesn't have a lot of details about CPU usage and IO weight and so on because you would actually need to insert some probes which slows down the whole boot. So the advantage here is that this is always available because you can pull this out of the journal and there is no overhead on getting this data on boot. So these just contain the units, no processes. And here we see this expensive service that took like 7.4 seconds to activate and LXDM service, et cetera is obviously blocking on those because, can you see this? So only if only when expensive service stops then multi-user and our login manager, et cetera start. And yeah, of course you now could look into what is this thing actually doing, expensive service and so on and I just gave it some, like lots of number crunching here. Just an interjection here, usually on all those commands tap completion should work if you have tap completion enabled and that should work for both Zshell and Bash, so. Yeah, that's right, so it knows all the verbs that these commands have and the options of those and so on. And running jobs and all that. Yeah, so for example, as shows you, all right. And if you want to drill down into more detail there's also the, like a more classical boot chat available. Ah, that's an interesting question. You should ask again. Oh yeah, I repeat the question. So how do you see, like how do you get like a shutdown chart? And I must say I haven't tried this yet, so I couldn't give you an offhand answer, but it's obviously very interesting. So do you have anything to know there? Well, if it takes really long, you could just start a debug shell, switch to TD9 and run, for example, system CTL running, for example, to see which jobs are currently running and blocking. Yeah, I did have a shutdown hang, but yeah, as I said, I skipped this because it's not really that useful to show it on this. But that's for the actual question. I don't think you can generate plots from the shutdown process, at least not to my knowledge. Right, okay. So, and again, my keyboard, okay. So for this scenario you had to cheat a little bit because for boot chart generation you actually need a kernel patch, not a kernel patch, sorry, you need the chat-scad kernel option enabled and that's not true under Debian kernels. So under Debian kernels, you can't currently produce those bootcharts. So I installed an Ubuntu kernel in this VM. We just have to bribe. So maybe there are some kernel maintainers in the room and it's, oops, oh, is it? One log, look, demo, okay. Oh, yeah, of course. So because generating a boot chart is actually rather expensive, you actually need to explicitly enable this, as I said. Oops, not that one. So you need to boot with the special option, like with a different init binary, which is lib, systemd, systemd boot chart. So you should be reasonably familiar with this from the original boot chart package. How did you enable that? It was similar, you can also specify the init equals and then point it to the boot chart binary. I think it was sbin, boot chart, d, whatever it was called. Takes a little time, there we are. So this should be much more familiar to you. So you see all the fancy graphs of CPU usage and the IO utilization with read and write. So you see the CPU block here is actually quite nice and compact, so there is not a lot of extra and unnecessary weighting going on. And now you have all the individual processes and you see when they become active and block the disk and so on. So we still see our DD command here, which is from our expensive service. So this took like almost five seconds and this is clearly something which we should optimize, yeah. Right, okay, all right. So another interesting debugging tool if you somehow can't really get to the machine, you want to debug is a serial console. So on the kernel command line option, you can redirect the entire console output to, for example, equals ggy as zero. And system D will parse the console equals options and redirect the console output of the kernel and get these to all of them. I'm not sure if you showed that, you can also increase the debug level on the kernel command line with that system D dot debug log level equals debug. And so you see output not in the VM, but we get it outside in the VM on our serial console. And now we can just plug in as usual and do stuff. Yeah, that's really useful if you have to investigate shutdown problems where you don't get the journal for all of the shutdown process. Right, or if it's a remote machine and you just have a kind of QMU KVM. Question? Can you use this if you're giving a talk where the QEMO view is not readable and you can use the serial output in the other terminal to make it readable? The system and the unit and the full container is kind of a continuum, but yeah. Does it answer your question or all right? Any other questions, right? Yeah, and you should also be aware that it doesn't provide full isolation. So it's not a replacement for a KVM, for example, as well. All right. Alexi is a bit better in that regard, but yeah. I think Leonard called it Trude on steroids. So you showed the nice little pretty charts, but a lot of times it doesn't necessarily is the best way to look at stuff for me. Is there a way to just get that same data in a log file, like every service that's started might have started more than X a bit? Yeah, that's pretty much what the journal actually is. So the, can you see this? So in fact, the system, the analyze plots or blame, everything that that does is really just look into the, look into the journal and you see starting, starting or start at, start at. So you see one, when the starting means a particular unit was started by system D and then start at means that the XX start or whatever it tries to do has finished and now it's running. So, and you see the timestamps here. So you can pull it all out of that if you want. Yeah, just wondering if there is just a simpler way to just pull out the service creation exit stop without, you know, gripping, starting and started and it. And the journal actually also uses micro precision time. Yeah. Microsecond precision. So if you use another output format, you could actually see the. Right, oopsie. What was that called like? All written down. Oh, dash over both. So you see that's really just a database. So there's lots of key value fields here and this is everything which is contained in the journal. So if you let us see what you can filter on and so on. All right. Next question. Two minutes left. So probably time for one more. Just a question. Can you afford the time out on boot? If I see there's something wrong, I know it won't get fixed. Do I have to watch it count up the seconds until the timeout runs out? Well, I mean, if the timeout runs out, usually boot just tries to go on without that service. Of course, if that's a crucial service, like you're, I don't know, at the TTY or whatnot or then it doesn't help you a lot. Of course, you could for the back shell and stop that unit. So that works. But of course on the production system, you don't just want to leave it like this. You need to do something to fix the problem. So there is no control C or something to interrupt the unit right now. I think there is, if you hit control out, delete, backspace, you can restart the system without having to wait for the timeouts to open. Right. But I mean, I thought you meant like... Yeah, sure, sure. Cancel the current unit only. No, that's not possible. And it means clear what you mean by current unit that could be like five units starting all at the same time. All right. Well, if you have any further questions, please mail us or talk to us. And we still have time, okay. Is there a tool to check out dependency and ordering in assistant units when the systems comes up? I know you want to be things in parallel, but that's not reality. There are some jobs that have to be ordered. The ordering documentation is complex and sometimes one just wants to try whether after and before and once and everything is correct. Okay, that's what I mean. Yeah, so there is a system cut list dependencies. It also has a dash dash reverse. So, which is pretty much, well, I hope it's what you are asking for if you got this all right. So you can tell us, so this tells us which unit weighed on Deba's service. And without this, this just tells you what does Deba's service depend on. And the green and red also tells you whether it's running or stopped. And also state and also restore are just like one shot units which just execute a command so they're not running. And there is also, what was it? So this by default shows the required. So Deba starts this other unit and for after and before, there's also a switch. What was it? Dash dash after, yeah, exactly. So this is not necessarily the same. It looks similar, of course, but before and after are ordering and requires is basically dependency, but without ordering constraints, which makes sense to, yeah, just split. Okay, I think we can all thank you for this very interesting and you can talk and yeah, let's have fun with that. This will be. Thank you.