 Welcome. My name is Steve Rosted. I work for VMware and I'm one of the reviewers for all printk patches that come through and I purposely made myself be a reviewer because I use printk extensively. It's one of the things I actually use to debug ftrace with and I wanted to be a reviewer so I could keep any crap out that I didn't want to think. And I always do my little selfie in front of everyone. Yeah, that was pretty good. Anyway, I have a lot of slides as those that know me or seen my talks before I usually sometimes make animation more than slot presentations. So first I'm going to start off with what is printk and I'm assumed that most everyone here knows what printk is. I mean, okay, anyone not know what printk is. Okay, one hand went up. Everyone else is afraid because I just said everyone knows printk so when I said no window or it goes raise your hand if you don't you're like wait everyone knows printk, I'm going to pretend I do too. So that's not really fair to say it that way but printk is basically the printf of the kernel. And when I first started doing kernel development within back in 98 for my masters, well actually it was going for my masters and one of the projects was working in the kernel and the people I was working with wanted, they said how do we print to debug our code that we're modifying and they put in include standard IO into the header file compiled and didn't understand why it didn't work. Everything in the kernel is self-contained. All functions are written within the kernel so there is no libc. So it's printf but I'm glad it's called printk. Some people said we should have called the printf and I'm like no I'm glad it's called printk and you always know a kernel developer when they do user space code because they always type printk and their code doesn't compile. So basically it's printk is a pretty obviously thing it's to use the display information show stack traces when your system crashes and panics. I went back and did a little archaeology or whatever you want to call it then into the Linux kernel history and I downloaded Linux 1.0 and I said what does printk look like there and it's actually not much different than it does today. First thing that happens is you copy if interrupts are on or off you save that's that first save flags means you know our interrupts enabled then clear you save it into flags variable and then you clear interrupts you then this is actually familiar code that's you've probably seen this in user space by the way that vs printf is implemented in the kernel there's no library there the va start is kind of a compiler thing so it doesn't need to be implemented but the vs printf has to be implemented and it's kind of strange because you look at the buff plus three and I love this comment true quality assurance so then this we go through this loop starting with buff plus three strange and we go into a buff end and then we signed our message the message we're going to print is going equal to p and then we check this thing called the message level what's this message level but if you notice it starts off at negative one so if message level is less than zero that means this is the first iteration of this loop where we check message run or message level and we check to see for this is this thing that just was passed to printk start with a lesson sign followed by with some number between zero and seven followed by a greater than sign if that's false we do this we say we create in that minus three which is why we have the plus three we now do a minus three and we write in the lesson sign default message log level minus one plus you know colon zero to get an actual number in there and put a greater than sign otherwise we just have the message jump over the the three characters that has that message level and then we say okay now p will now equal p one equals some number from zero to seven so we save that in our message level so when the loop comes around we know what to do this is the second half of printk it's not that big of a function i mean i have the full printk function from version 1.0 in two slides again we're going to start where p will left and go to the end and then we would look at the with this little thing does is the ring buffer log buff is the the ring buffer within the kernel in 1.0 and we did the old you know add the start plus the size and add it to a mask which has to be of course power of two and we when we copy whatever p is pointing to into that and we keep looping around here's a little luggage logic that does those normal ring buffers that you learned in school how to do if you have a fixed size array and you want to spin around you do the increments of the point the start pointer and the size and now if we hit a new line we're going to break out of this loop because our message is done we only do one message per line now here's that wire that message level came from we look at the message level and we look at the council log level which is something that the user space has given us saying this is how much we want to print and I'll talk about this later and if it's less than this user space number and there's actually a print function that will do something with this has those two have to be true then we're going to go ahead and call this code the temp records whatever is after that slash and or if it's zero so we're you know the log buff we're expecting the buffer here there might actually be a off by one bug here I'm not I didn't really look into it but it expects that we're at the end of our string and we look at the one plus of head one character forward and if that character or what what's called we're going to save that character because we've put in a null terminating character so we could call this council print function that hopefully exists no it does exist now it's not null and we'll pass the message to it and the message will end with the null character so it prints properly and now here and then we put it back the character that we swapped out with the null character now at this point here we check to see if it's a slash end because if it is a slash end we know we broke out of the loop without hitting an end of line we actually broke out because of slash end which means there probably there might be another message behind it so we set message level back to negative one and repeat the process after that loop finally done and we're done with all our messages we do this wake up of a task that's a log weight so print k basically does everything right from there that's done is somewhat the same of what we do today it has log levels it has a fixed size ring buffer it sends to some council and it wakes up some user space task if it's waiting on information that the kernel wants to print the log levels which were from back then today today they're still from zero to seven uh the lower the number the more likely it will print in fact current emerge will always print that's we um there's code to make sure that the log level is never less than one so the lowest log level you could put is uh one so it goes from one to eight if you put in eight that means print everything if you put in one it means just print when the system basically crashes so you can set this variable number on the kernel command line and there's also um uh what's called the kernel command line or um sys control i believe or proc file system somewhere log levels are usually when in the kernel if you look at the kernel you'll see something like print case uh parentheses current warning followed by some sort of string and that current warning is a defined of a like right there would be colon four um if you were to compile or run this preprocessor on your code but when you put in print k with the current warning on it it would the old way which show you with the lesson sign the north four the greater than sign followed by some um string which is why you saw that weird strange code in uh print k you don't have to put that in there remember back in the print k back here i may have shown up back there but let me see here um you'll see that it adds that default log message so if you leave it off that default message will be your log level that you have at that time told you have a lot of slides the new way is they don't do the lesson sign they use one character which is nice it's just you know the hex character one so it's not printable so it could now get defined by a single compare to check to say hey this has a log level if it's not there it's a message so the the ring buffer in the print k it's a fixed size um you could change the size on boot up with the kernel command line with log buff length uh it's been recently changed not recently but it's been changed since one oh from that simple ring buffer thing to a more complex uh actually passing in bright binary messages and such and now they contain a timestamp log the log level is actually stored as a binary thing um inside the um the print k ring buffer today as a message it has some metadata they can add to it and then the data string that you want attached to it today it's protected by spin locks so you can't call it from nmi what you do we do we can and where we have code coming up which we'll probably talk to in the next talk uh explain that by the way this is a two-part talk for some reason i submitted this talk to um elc slash os s and they accepted it twice and then he said could you make it twice this thing but thank god sir he's came here he's going to do the second half on this on wednesday which will be after a kernel summit tomorrow that where we're discussing the problems with print k and hopefully salve come up with a solution um of course print k is useless if it doesn't go anywhere if you write it into a memory log buffer it's kind of useless sitting there unless you have k exec k dump where you go and retrieve it which k exec k dump you can do that with with the utility crash but most likely you want to see this as it's going on so it's got to go someplace it's got to go to the monitor it's got to go to frame or frame buffers could go to the uh serial port network console there's even a braille console that you could get print k from um in today's logic uh print k uses two different things they use a spin lock and a console lock and i'm going to talk about that a little bit later and another problem with uh print k with nmi's at least is the councils themselves could have spin locks that you have to watch out for and worry about um when a task wakes up which does today we usually wake up syslog d or some other utility that might be on most machines today and that what some usually when you have these kernel messages going out you want to put them someplace you want to put them someplace where users could see them and don't have to actually use d message because d message is a fixed size ring buffer if you get too much information it blows it away so you want it recorded while it's still available then multi processors happen so back in uh january i did this whole get well actually it wasn't gonna get bisect because it was before it gets so i actually just kept downloading stable or not stable they're not even this is before stable existed but i downloaded a bunch of uh development trees and i did a bisect download finding where was the first time spin lock appeared in print k and i found it was in 19 january 1998 in 2180 a spin lock was introduced to print k that's the first time it was actually be able to run on a multi processor system and all print ks were serialized it did a spin lock in the beginning did all the prints wrote to the councils everything else and then finally released that print k but that doesn't scale it has issues and remember print k can be very slow especially going over serial port and back then you know that everything was uh you know 115,200 balls usually if you had to 96 balled you know 9600 balled uh modem it really was slow so when you have the print k if you had three print ks that went off at the same time and the first one got out got the got the print k lock and it did its printing and the second one's blocked has got to wait until the first one's done printing the third one that came off not only does that wait for the first one it has to wait for the second one wait to the third one and this could be bigger and bigger and bigger depending on how many CPUs you have which shows you why this doesn't scale and it basically while this happened so if you had uh eight CPUs doing like a print k that the print k could take easily 10 milliseconds if it's a slow modem or something like that but right there could you imagine your system with 10 CPUs tell you eight times 10 you know it gets up there pretty fast and it's well it's linear up there but um it could the system stops the whole system is locked up and that caused that people don't really like it when you're in the middle of playing uh some sort of video uh online video game or you're just about the you know quake or whatever you're just about to shoot the guy in your system locks up because everything's died to print and you get killed so the council uh lock semaphore was introduced in 2001 and 2410 it was added and it to we have two locks now we have a log buff lock the the the lock that protects that law the in-memory ring buffer is a spin lock a normal spin lock nothing different nothing special you grab the spin lock you write to the log buffer you release the spin lock everything's fine the council lock is just strange the first holder of the council lock does the printing everyone else just says okay thank you goodbye and this guy who has a council lock will do the printing for everyone so when you look at the the council lock isn't the big deal you can easily get the council lock the magic is in the council unlock so when you look into print k if you go into today and you look at print k and you look at you find council lock you'll see this thing you'll see this if statement right there where he says if council try lock council unlock you know if you look at that you're like wait a minute why what are you protecting what is the purpose of that that's because council unlock is a behemoth this is council unlock the code with a lot removed from it i stripped out all comments stripped out a bunch of stuff and in fact that for loop i condensed it down to nothing because there's a lot of work in there too uh when you do a council unlock first thing to do is is the council suspended if so release the semaphore and return do nothing else you're done then we say can the council schedule schedule like are we in a preemptible state if we are then we might be able to uh we could do a we check to see if something else wants to run on our cpu so while we're printing these messages uh we'll check every so often oh we should schedule out and let someone else run while we're holding the council lock which is interesting i have to do this so uh next we also want to see if we can use the council because councils this the councils can be turned off so then we have to unlock we do this for loop that go iterates through all the registered councils so you could have multiple councils you can have your video council you can have a ur you can have special devices each one this is a little uh a for loop that goes through each one of these everything you registered that you put on the kernel command line council equals blah blah blah but you do that multiple times and it's going to go iterate through each one of those writing the data out to each one one at a time each time checking to see if it could schedule if it was in a schedule context if preemption was disabled nope it's not going to do it's going to finish everything the council lock variable gets set when you get to lock it's a way to tell the rest of the kernel i the council is locked because there's logic in there that says oh if the council's locked uh-oh worn or let's worn on this that's usually if you do a search for this you'll find it like in the frame buffer code and such which is another big mess that i'm not going to talk about that's that's a full story itself this exclusive council was something i just discovered well today okay i'll talk about that later now finally you released the are you unlock the log buff because we had the log buff held on for when we were doing the uh some work and then we council and then grab the log buff and then we check to see if um this is this magic that says hey you know someone wrote code so because we could uh we do this retry which is look at the council sequence and see if there's something new there well listen we do this after we release the council lock and then if you notice below there and that's the other red thing is i say okay if retry is set we try to grab the council lock if we fail to grab the council lock we know someone else did and they'll do this work but no if we get the we're the lucky one that gets the council lock again that means that someone wrote more data and we go back and said oh you're the one so you fill it up and then eventually we're going to wake up whatever's waiting and to read the council data so today instead of having the whole system locked up we just lock up one CPU and if you have say 180 CPUs and you have a driver that just loves to tell everyone that hey i'm did a timer and said hey i'm alive like i keep alive something or there's some really drivers that seem to like to tell everyone something so it just it it wants to be known it wants to be loved yes this is a millennial driver hey my kids are millennials so i kind of agree with that uh no so you the first guy comes in just the right the lucky one that gets the council okay remember with the right log and that kind of turquoise ish whatever color and the way you want to call it uh that's where the log buff is held it's a spin lock so no one could do it same time so it's only those are that serialized that's fine but when you get the council try lock you keep running and you print your stuff well on task two on another cpu comes in does a right log and so you're like oh we got more data i'm gonna write this guy's out task three comes in does some more data oh got more data go right task two comes back oh i want to do another print k so you see this could go back on and that print k latency is unbounded it could go forever and this could happen inside an interrupt this could happen with interrupts disabled with a preemption disabled so a cpu is now hard locked live locked it's not a deadlock it's a live lock it's running it's doing work but it's not doing anything else but being the servant for all the other cpu's and what happens is you could have a watchdog timer go off saying hey interrupts haven't gone in the cpu in like seconds this cpu is locked up hard do a panic what does a panic do cause break going back to exclusive council it was added in march of 2011 uh what happened what they found out which was kind of weird if you had a on your kernel command line you know council equal tty one council equals tty mfd2 whatever that is council equals tty s0 early per k equals mrst they all are registering councils and this is actually i copied this from the uh change log that i found the code from git blame and each council when it registers it it will it resets when you register a council it resets the start counts start of the of the buffer back to the beginning and calls the council lock and the or it calls the council unlock to print everything out for that council well what was happening was you know you register a count you register the first guy it would there's a bunch of stuff in the print k and it would print out everything for on the tty one you register the next council it says oh reset it i need this new council to print everything else out so it will print everything else out but since that remember that council loop that went through all the councils well tty one would print out everything again and then that you get the second council the third register comes in or the third your tty s0 comes in and it says oh we have to register another one let's reset it and let's call tty one again now everything and council three and then early print k would come in so dty one just printed everything out four times so the solution was to make this exclusive council set so when you registered a council you put down exclusive council and say equal to the council you have so in that loop you're going through the exclusive council when you do the prince it was in there i said if i'm not the exclusive council skip me don't print me out we were going to be the one but in 2012 of may which isn't that much further away from when this was added the whole this is where we went from a ring buffer type of uh the normal simple memory ring buffer to that message layout because journal d needed some more information want needed more power on how to read from the kernel buffers so it needed more metadata need messages so it was rewritten and the code there the commissioning of a council no longer reset everything back so this exclusive council which so when you register something there's a race here now so if you register something now and print case are happening and then you jump into the print k unlock the only the exclusive council the one that just was registered would print anything all the other councils will miss that print k but i'm looking at it the code it's obsolete it shouldn't be there why is it still there because no one noticed it was obsolete until i did this presentation it was reviewing the slides so i went through it what's this for i'm like oh god some people say that the best way to do there's so many bugs have been fixed in the kernel by presentations the scheduler this is a fun one too um we want print k to work everywhere because you know that's our debug thing and of course when something goes wrong how do we let everyone know print k so in the scheduler a lot could go wrong if you ever seen that code it's quite complex there's a lot of checks and to make sure things are going as we think they are and if there's something's wrong or if you turn on debugging it will check stuff and if you have something that gets scheduled you're scheduling with an atomic it'll print something but print k holds a run queue lock and the run queue lock is the is the lock that prevents any scheduling to happen on that cpu and obviously it needs to do that because print the scheduler needs to look at tasks and doesn't want people to add new tasks to the cpu when it determines what tasks to run next so the run queue lock is very important it's also to protect like said you don't want to add new tasks to the scheduler if you're about to do the schedule so you can't do a wake up the problem is council unlock remember um it's a semaphore if there's something waiting on that council lock to say okay i'm waiting for you because it's not just print k that uses council lock there's other things the guy reading that wants to read the the log or the d message that blocks on council lock so it could get information as well and there's lots of things that could do council uses council lock and block so when you do the print k you do council unlock and you release the semaphore you do a wake up and right here you know you do your scheduler you have um you do some sort of spin lock on the run queue you do something called print k print k is going to do council unlock which wake up with does the release of the semaphore which wakes a process which grabs your run which if that process happens to be on the same cpu it grabs the run queue lock boom deadlock so to handle this case this is in the kernel this is there today we have something called print k sked which is now called print k deferred um it was originally uh had its own cpu buffers that would just kind of um the cpu buffers would it would write the stuff into the cpu buffers and then later on it would wake up and read these cpu buffers and then do the actual print ks on them uh i noticed i said this is kind of a waste to have these extra buffers in there because i noticed that i said you know the actual buff the the buffer to the print k is just protected by normal spin locks not this magic council lock and the spin locks only protect that buffer and you don't call anything else when you hold these special the spin locks so you can nest them inside a run queue lock i said you know instead of doing that print k just just grab the normal log buff lock write to the print k log buffer and then release it and then later on make sure that gets flushed out it used to the flushing used to happen on the next jiffy tick so if you're you know if you're no hurt or your hurts is set to 100 so 100 times a second a tick goes off and doesn't work so the if something happens then print k you know you have you got 100 uh what's it called 100 microsecond later whatever is or 100 divided by it's 10 hertz or something or 10 10 milliseconds i think 10 milliseconds later you would um oh am i watching i think i just hit 10 000 tubs i i i pace fit bit um so if 10 milliseconds later your print will happen so if something else happened and something crashes you won't get those prints in that 10 milliseconds so today we use irq work what irq work does is it sets up a flag inside if the architecture support it x86 does you set up a flag and says okay um we'll write to the buffer kill a kickoff irq work irq work we'll we'll basically send an ipi to itself to your cpu so as soon as interrupts are enabled again it will take it their cpu will take it to interrupt and then call the function that you assign and it will do the flushing but you still can't do the printing within the actual output to the councils within the runq lock that's today and wherever it was me nmi's are another fun thing you know print cake could happen in nmi and used to be it was a crapshoot um we had control m or l or sys control sorry sys request key m or l i can't remember what l sys request l that's m is memory sys request l so if you do uh echo l into slash prox sysrq dash trigger it sends an ipi to all the cpu's or and all the cpu's will trigger a nmi or actually not your ipi it sends off a trigger to trigger nmi's on every single cpu and what that does it will do a stack dump so basically if you find out your system's kind of like okay it's it's something's locked and one of the cpu's or you detect this in the kernel you could trigger a stack dump everywhere or you could do it from manually um so you can manually say do it's like let me see where where everything is where something's spinning i don't know why it's spinning so much call an nmi and it will it will send an nmi to that cpu and an nmi non-maskable interrupt for those that don't know which means it will always trigger um regardless if interrupts are enabled or disabled so when it calls the nmi the nmi will then do a stack dump and it shows you where everything is and it does that by print k in the old days we're we just we're careful about doing that because you could just set it off and if the print k happened to happen during a print k where while the console lock was held you could crash the system actually i'm asking you if it's l it's on my slide so one of the solutions from two four to four eleven was this awesome function called zap locks i think i believe we got rid of it which is sad because i just love the name um it sets this variable called oops in progress to one and it lets the system know i'm dying so don't worry about deadlocks don't worry about being consistent just get the information out why i'm dying so zap locks would kind of re-initialize uh the the buffer the spin locks although and re-initialize the console stem so if nmi goes off and says we're dying we're triggering something re-initialize anything so just in case i preempted the print k i'm going to turn whatever i preempted i'm like say no you don't own the lock anymore i'm going to run and write everything out it's works great except it's not aware of the console locks so if it happened to happen during one of the console spin locks you screwed anyway yeah a crapshoot so to handle the um the one situation where we use this request l um i took a i took the seek buffer that's used by trace uh ftrace and also use kind of like seek printing it's a way to pass a bunch of data from function to function or like string data so you could write to you could do like a print f or something and then pass it off to the next guy they could do a print f and you attach a lot of uh information like this i'll trace events work so i decided no if i make this i could probably use the nmi stuff so if you do sys request l it will write i could i've added a function pointer for print k to be able to switch per cpu so this when you did print k it didn't actually call the print k code it actually called a function uh a per cpu function pointer that would jump to the print k code now i was able to enter or set a way of when i went to nmi saying i'm doing a dump i'm going to switch it to this other function that's not going to write to the consoles but it's going to write to the seek buffer and at the end when it's after all the seek buffers are done and when the nmi is done it switches that per cpu pointer back to normal print f or print k and i have some other guy in a nice good context knowing that i can't preempt the console holder it will actually read all the nmi per cpu buffers and print it out nicely so there's no more deadlocks the way it worked was you do your sys request l sends all the triggers nmi's runs to seek buff and there then i had like said safe context for cpu so that's your visual of that simple well it doesn't sound normal nmi code because nmi code that determines oh we're about to crash or something like that we want that data out and we don't have the luxury of a safe context per se sort of so code is working on how to do that so if you have a panic or worn on or it's not it's really still a crapshoot so in four seven uh nmi v print k was created and what happened was when you turned into or whenever you enter to nmi and there's functions whenever you enter nmi uh there's a nmi enter code and there's a nmi exit code it would call print k nmi so the nmi entered would call print k nmi enter and then the nmi exit would call print k nmi exit and what that would do would switch that function pointer to be this nmi v print k which would do something different and then when the nmi happened it would write to the seek buff or a actually they now changed the buffer it used it the seek buffer wasn't they did a little bit more uh flexibility than what the seek buffer did so they added a little bit more lock or protection i guess atomic counters and stuff like that so uh the changes but it's basically same uh it's the exact same design where it writes to a pre-allocated buffer and at the end on the exit it switches it back and will then send it off through irq work so that when the nmi is done it will get to a safe um safe state where the nmi will or the irq work will flesh out all the nmi's the problem is with this is if the system locks up hard you don't get your data out if the nmi won't work uh i played with this a little bit and actually i found out was it would work mostly there's a case at least the latest stuff today will work um if all see if there's one cpu still alive and it will that one cpu could actually work but if all cpu's lock up or you're in a processor system you're screwed then someone noticed i think this more surrogate's work um what about a print k within a print k which can happen remember uh we could do warrenons anywhere uh so yes was it was this wait Freudian slip reminds me of the drunken patch where i turned void to vid on just changing um uh a comment and uh thomas collection was with me too when he acted and i sent out and i and um i got all i did the next day i got a message from andrew martin saying bah okay so what happens here on print k it does a console unlock does all your printing and then um it wakes up a pending task but for say something happened where when it did the wake up you had some code wrong and that wake up caused a warning for some reason it would cause print k it would do a try console try lock um remember we already upped the semaphore so it gets the lock because we only wake up after we release the semaphore so we do that we get the lock and it does a try lock but now it does the um tries to get this um wait oh sorry i have to go back let me re re change that when you unlock the semaphore the semaphore itself has a raw spin lock so it actually has a real spin lock so when you do the way it works is it does grabs the spin lock does the wake up and then it releases the spin lock within the semaphore code that's why there's a up you see the squealy bracket so you call the up so this we released the spit we released the um the quote unquote semaphore but now we're waking up the the next guy that's waiting on that semaphore so we have to wake up the waiter for the semaphore and then something happens where there's a print lock but then it goes and grabs that semaphore lock again and now it locks deadlock so you can actually deadlock within print k unfortunately locked up doesn't we we locked up requires validation and it could kind of detect this and i guess what happened was we kind of disabled locked up validation within print k we're just like we understand there's a deadlock here but you know if you do this every time you had a print k locked up was a hey you could have a possible deadlock and it would just stop you're done checking lock depth so the only way to get locked up to work is to turn off print k but then if it detected something you would never be able to know if it happened so that was a problem so print k has three different locks we have your log buff lock console lock and console lock and i said print k if it causes a deadlock it so if print k causes a deadlock because the console lock does something thing locked up also will print out a report and it uses print k which will itself so locked up itself can now cause a a deadlock itself which really would suck that your system would be running it would just die lock up and you like you enable print k or lock depth to figure out why it locked up and then print k itself caused the deadlock and then locked up try or no print you the lock depth would try to figure out that oh there's a deadlock here and it will print and then it would lock your system up without ever telling you what the problem was because it deadlocked before it could get the data out so in 411 a new functionality came which was called print k safe which was similar to the nmi print k and this required to manually mark areas and within the print k code that can possibly recurse on itself and deadlock and it would use a counter to uh determine like um unsafe reach to the it would increment before going to an unsafe region and decrement when i leave the unsafe region and if if um the value was greater than zero it would use a separate buffer it wouldn't or would do something different it would not do the normal print k it would not do the console lock because it says hey we're inside this um what's called if we go within print k we'd say um i'm turning my mind straight here that avoid totally threw me off so it would just actually work like nmi print k okay within inside the print k let's just leave that you could figure it out um see that would make my talk so much shorter you just figure it out here's my slides goodbye so print k uh was no longer a function pointer marisa was a function for the switch back and forth but it turned it to a single function as a multiplexer uh it uses a per se view context for flags of a counter and what it that's what's used to determine what function should be used and we had to make sure to prevent this uh log buff thing so um uh i guess uh i think it's done with any whenever you had to grab this log buff spin lock because that could cause one of the deluxe you had to use the print k safe and then decrement it outside the print log buff lock this way that's right because you'd need to do that for nmi's as well um and now the nmi code we don't use the the v print nmi or the nmi print k anymore this thing actually handles everything else so inside when the nmi triggers uh we look at this print k context that has that increment variable and if um we mask it against the the counter and if it's set that means we're in a um a location where log buff can lock up so we checked is log buff locked if it is we're going to say hey let's go into this nmi context otherwise if you know those cases are coming in we're going to into a nmi deferred context which goes back to the kind of the original way um and when we exit we just clear out the flags so now when we do um oh this is this is basically my english version of this of this code i forgot i did this um so if print k safe is active if counter mask is greater than zero then we're and log buff is locked then we're going to call the v print k nmi otherwise we call uh the vk print um so the v print k function now is this is what all print k get caused so it's not a memory said when you call print k print k now calls v print k directly it doesn't actually cause a function pointer it caused this uh multiplexer um it checks the context and compares it to uh the nmi mask and if it's set we're going to do the nmi otherwise we if if that's not true we check to see if the um we're in a nested low nested area uh position so we'll do the print k safe otherwise if we're in a divert context we're going print k and uh print k deferred otherwise print k default which is what print k did basically all the way back to version 1.0 well in the meantime like i said um system d likes to write to print k this is kind of like all the issues that we have to deal with for print k so i wanted to bring this up so user space can write into that fixed size memory ring buffer it uses an interface of proc k message and unfortunately what happens is you could have a case where you uh if user space goes crazier if there's a bug it just spits into the buffer and say if it had a bug because there was a kernel bug uh the kernel bug could have done something did a print k something worn on then system d could have said oh something's not right and spit a bunch of debugging in there and you just lost the worn on so this is one of the issues that we need to fix one thing that people love uh few developers really really love is early print k now one of the questions that is given on i guess the links foundation uh teaching kernel development is like when does print k not work well it actually does work well and that's at early boot up before the councils are registered before there's any council there there's no print k uh and if something dies during before councils are registered you just see a black screen on your machine when you boot it up where print k's are actually happening so we created um early print k which actually writes to the log buffer or whatever but actually what your early print k does is not only does it write to the log buffer it actually when you call print k it will write to whatever you said it's going to write to whether it's a serial vga or whatever it will do the right at suit it doesn't care about the buffers it will write to the log buffer but will also write straight to the council as well without grabbing locks early print k is basically a little version of it's like a tight version says just write to the council and if we blow everything if we if we mess up the buffers within the council whether it's a serial port or whatever so bad to be uh we don't care we just want data going out when it happens force it no locks uh just write data out um the serial port's rather easy to do because it's just a serial port where vga buffers could be kind of a more of a more complex thing but usually serial is the one that you do because of just the complexity of the output serial is really easy to write up but it's very slow which is a problem if everything you print your system stops until it prints out uh if you want early print k to exist after registered of councils because when the when councils are registered early print k will remove itself out because usually it was written just to be able to see the data before print k councils were there that's why it writes straight out instead of going worrying about councils so if you want your early print k to still be there because print k is messing up for all these issues i've already talked about you put comma keep behind in your kernel command line and it will stay there uh right now one of the code that's being worked on i think we have patches there's lots of patches out already is forced early print k to basically say don't bother with print k at all just recall early print k and actually it's one of those things print k goes in is let's just do that which might be part of the multiplexer unfortunately today is getting much much more difficult to find you aren't uh everyone here has a laptop anyone in this room that has your laptop has a serial interface not a single hand that's really sad this doesn't either it's really hard to debug your laptop if something crashes because or you this is where you do the camera take a picture of the last crash and you have to okay only see what you get which is a problem so we have to handle that other methods we could do network council there's a delayed print k that's been there forever too where it will actually every print k will go out will pause and so if you don't mind waiting a long time for the system to boot up because it prints it pauses a couple seconds for every print k that line that goes out count count how many print k lines are in your d message and then add a second for each one or something like that k exact gate up i love it i use that all the time that's how i get a lot of my data like i said it could read the the crash utility could read the log buffers for print k so summary um print k is a way to display information for you um those kernel events so if everything else like that wants the kernel wants to talk to you about it print k must retain serial order that's why log buff is a single buffer we have we talked about having multiple buffers and stuff like that but people want the order of the actual when the print k happened we want that in order with every all of the printer k's that happened out and ideally you want as much information possible before the machine dies other than that i don't know if i have time or not i don't too bad thank you