 Perfect. Okay. Hi, I'm Steve Rostead. When I talk about cyclic test latency with tracing, I like there's three late the tracing talks today But before I go on I always have to do this smile everyone It's uh, this is what the actual thing called a camera. You can't make phone calls with it. So There we go, right doesn't run Android Perfect. Oh wait, you got a lot that light was in the way This way I'm used to actually the old The cameras I used to crank the yellow cameras that you disposable ones where you cranked I used to do that all the time with that So you didn't know if your selfies were good until like, you know a month later when it came back anyway Again cyclic test latency tracing so when I talk about mostly about the libraries I've written And how you could use that then analyze your trace and why things are wrong So quick overview hopefully everyone here. I should ask how many here people here that do not know about cyclic test I can't see. Hold on a second. So there's one hand a couple hands. So cyclic tests real quick overview We're invited to almost glacier over here It's basically a test that you know executes asleep. Ideally. We usually use nano sleep by default It does on wake up it checks the time it woke up And it basically compares when did it wake up to when it expected to wake up and then reports the difference Has several options you could do. It's very has a lot of features to it I always use it with just one set of options, but there's a lot of other people who do things you create histograms You know run in every CPU or run in separate things, whatever you can use even signals see how signals work And then you can make a break on a threshold so It is used by many people to see how the responsiveness of their real-time operating system Typical run. This is the options I usually use is this cyclic tests where it will run in the way those options the first option is the priority of the threads, so I say run everything as See or sorry priority 80 and then the next one is the interval of 250 microseconds so each thread is going to sleep for 250 microseconds over and over and over and over again and Default is one millisecond Dash a means okay set the affinity basically I want to spread it find out all the CPUs and run a thread on every Single CPU so and set the affinity so each thread is pinned onto a CPU while it's doing this Yeah, that's why it's available processors dash M is important You want to make sure it's M locked so you don't right now I don't want to worry about page faults faulting in that could slow things down so it does M lock all before it executes and finally I Guess it also has how difference What's the intervals microsecond the distance of the thread intervals from there? But anyway, there's a whole man page and everything I could read about it so Tracing cyclic tests because usually if something Fails you want to know why? so you want to trace it and Tracing or cycle tests has some helpful things you could say dash B Microseconds which basically says stop the trace if your latency is threshold is greater than x amount of time and dash dash Trace marks also tells cyclic test when this happens write that information into the ring buffer So you know in the ring buffer the tracing ring buffer in the kernel Where where the issue happened so that way it's easy, you know what CPU happened on and you can kind of find it so by adding that options and I ran this for a while and I ran this not on a real-time kernel I want to stress that because real-time kernel is actually getting quite stable and good You could run this a lot of times people run cyclic tests on the preempt RT kernel for weeks And it never hits the threshold, which is actually good. It means it works So I know that the non preempts real-time kernel or just you know the best thing is not a real-time kernel So you're going to have Latencies so I just said you know I'm for this test for to describe this. I'm not actually debugging something I just want to show you what happens if I run cyclic tests on the normal vanilla Linux kernel And I'm going to break it at a hundred microseconds So if a hundred microseconds it wakes up and it's longer than a hundred microseconds before actually runs break So this is actually normal on a normal Linux kernel So after I did this I did trace command show so basically trace cmd trace command is a utility I wrote that reads the tracing ring buffer from the Linux kernel and Trace command show everything we're using right now is this you can actually do this if you just go into The trace of S directory which is located in slash sys slash kernel slash tracing if you CD to that You could do basically everything trace command could do just from the kernel command line as The whole tracing infrastructure in links kernel was made so we could actually use it with busybox But I like to use trace cmd and especially since this talk is when we talk about the data file that it uses So I need to use it anyway. So everything's focused on trace cmd. It's also easier to show But when I did this it shows you the output of the trace file in The that trace of S directory and it shows you right there that what you'll see the line there that has What's called cyclic tests wrote into the kernel that it did hit lacy threshold It was 561 microseconds when it had the threshold of a hundred microseconds so So with trace in cyclic test when it first ran It actually added a bunch of events it enabled the events by itself It didn't require any external thing if you put the dash B it just enabled a bunch of events But it was really hard To control what events enabled and sometimes you want a new events and such So it couldn't keep up with the actual work that was going on in the tracing system So what we did was we ripped out all the Tracing infrastructure from cyclic tests and said screw it trace emd is made to enable all these Events it's more flexible. It keeps up with the tracing system Especially since the person who is the maintainer of the you know tracing system in the kernel also the maintainer of trace emd So we use that so we removed everything from there and but we kept the trace marker because that's actually very useful So Now it's expected if you're going to use tracing with Tracy Cyclic tests use trace command before and this is what it looks like So you do trace command start start just means just start the things don't read It's not going to actually write it to a file or anything. It just starts it the tracing infrastructure inside the kernel is a What's it called a overwrite ring buffer? So you don't need a reader. It's not a producer consumer It just will keep constantly overwrite and So you do that first and then you pass cyclic tests as the final parameter across trace command start will actually could execute The application as well and now when it breaks and the why here I just enabled a few events I'm able to sked switch event the sked waking event all timer events. So inside the Tracing current or this is or sorry the kernels tracing Structure there is individual events and all the individual events are grouped by like a system of events So here on trace AMD you could specify either an individual event or a system event And it will figure it out. So here like sked switch and sked waking are both individual events Timer is a subsystem. It enables all the timer events and IRQ I'm enabling all the IRQ events and IRQ vector events and then I kick off cyclic tests And now when I do trace command show you see a lot more data here This got clear. So I might have to need to read this So What do I do after that? So in the old days when I used to work for red hat I Had to debug a lot of instances because we were developed We're working of helping develop the real-time kernel for the red hat distribution when there was a bug When someone reported it we had or we ran cyclic tests for over like a week and every so often it would fail So we had to say okay. Why did it break that hundred microsecond threshold or so? We would then run tracing just like you saw and then I would always do trace command export Export you could if by default we'll just write to trace that that but here I want to give it a special name so I don't accidentally Delete it if I do another trace command export So I did dash o to write it to trace cycle that that so now it's Extracts all the data from the ring buffer and puts it into a dot-dap file So if I do a report it gives me all that data Dash L by the way shows the latency information, which is this part right over here That's the latency tracing information which the first number is the CPU that it's on the second one is D as if interrupts are Enable or disabled he means it's disabled and means that it's need rescheduled set So basically when a task in the kernel needs to be scheduled a flag gets set called need resched that means something Wants to run the scheduler should be called if not it's a latency H means you're in a hard real-time environment if it's a s it means a soft or sorry hard IRQ environment S means a soft IRQ environment and the this number is the preempt Whether or not preempted preemption is disabled or not One is yes, so it's preempt count. So that's nested the last number Which shouldn't is it there is migrate disable which is used only by a few things so Oh, so I noticed down here at the bottom You'll see the trace marker right it's memory it wrote it in there So it's still available in your output file right here, and I noticed that it's CPU one So now I only care about CPU one be a CPU one is where the problem is so here I go, okay trace coming report with dash dash CPU one which tells me I want only Only show me CPU one on my output. So it's a lot easier to see everything From here. I could see the sketch where the sketch switch took place What where? Where cyclic test got scheduled and the timestamp that it got scheduled that and I would go back So this is actually what I used to do manually when I was back at red hat I would just sit there look at the schedule look at when the waking happened then I go and like, okay Here's the timer that went off. So I look at it shows you the timer pointer So I said, okay, we're have to go back and find out. Where was that timer set? so Where it triggered because I could see back on the you know the last timer I could see where the cyclic test was woken up. So I have to then go look at the Timer pointer to go back find where the timer set where it was set and Also, it shows you the now which is what was how the HR timers programs the clock and then up in the start you'll see where it was set So analyzing tracing data is actually pretty straightforward. You know, we just kind of like walk through the events backwards To find out where the issues are But it can also be very tedious the once you start narrowing down the issue and so you enable more events and you do more it becomes quite tedious and you start looking more and more into it and You have to concentrate on everything that takes place and it starts skiing you get lost You have to take notes and such and like that but I Always said this should be automated. I kept doing this I found out that I was doing the exact same thing over and over and over again looking for the same things over and Over again, it seems like this sounds like it should be automation So I once told Clark Williams my task lead at Red Hat, you know what? I need to automate this Well, I finally got around to doing it yesterday. Sorry Saturday And I don't work for Red Hat anymore I Did it for this by the way I had a 12-hour layover in JFK on Saturday and that's where I started writing the code that's in this presentation So I wrote the code first and then yesterday on my 7-hour layover in Amsterdam. I wrote the presentation So introducing LibTraceCMD So this is what the main talk about is using LibTraceCMD, which is a way to read the tracing that daff file To for an analysis and you can do a bunch of things. I'm actually going to walk through how I did that It will eventually be able to write trace that daff files, but currently it doesn't It's also built on top of LibTraceFS and LibTraceEvent. LibTraceFS is everything that interacts with the Lib or the traceFS directory, which is how you enable all the tracing within the kernel LibTraceEvent is how you parse the events the raw data. So it gives you the information Inside the kernel there's format files or actually in the LibTraceFS You'll see format files to figure out how to use that format file to read The binary data from the ring buffer and the format file will tell you how to actually create that so you can read it in human form and all that information is and www.trace-cmd.org there's a nice little pony there a long story about the pony, but The man pages everything's hopefully well documented So this is the code I wrote on Saturday. So I started off with This shows you how easy this is. Okay. Hopefully you guys are familiar with C. This is written in C There is actually trace marker. I guess that actually is written as a Python back end for this So to open the file I just do okay, you create a trace command input structure a handle and you say trace command open the file Flags zero is just keep me the deep default operations. There's plugins. They're added so you don't care about flags But just open a file. That's how easy it is The tap is a handler. It's the trace event parser. It's part of the LibTraceEvent Directory, it's how to parse the raw events. You're gonna kind of need that so you when you do the open file The trace.dap file has all the formats and it will you could create a Handler on how to parse all the raw data that you're going to need later So you need to handle for that and then I call this init data because I have my own little data structure that I'm going to use for this program the data structure here is Simply just doors a bunch of events. So for every event that I had You'll see that the trace marker I want the sked sked switch event the sked waking event or wake-up event There's two of them. HR timer expire actually. Yeah The HR timer start events. Those are events within the timer group and also the fields how to parse the fields So I just this is just more of an information only type of thing You don't really need to know this you just kind of like okay I need this information so you just create a structure and I'll show you how easy it is kind of to fill it This is how easy as fill it so it looks like a lot But it's basically doing the same thing over thing all you do is like you say from the tap handler You say find the event like the first one is I know the print the trace markers the F trace print So I said give me the marker event Give me the sked switch event sked waking event sked wake-up event and here. I actually said just use one or the other Give me the PI just give me how to parse the PID so the tep find field will say from the waking wake-up directory Find the PID where the give me a descriptor on how to Extract the process ID that the wake-up event woke up So when the wake-up event triggers it'll have a process idea of who it's waking up This gives me the information on that then the things about the HR timer expires I want the expire the HR to remember that HR timer thing I had the pointer to the descriptor that I'm going to have to use to find the preview to match the start and the trigger of the HR timer event The timer now I want that now field that says this is when it expected So I want that now as well and same thing for the start and I want to know where the expires is because that's The expires event is when it expected to expire or where it set the clock to expire at this time So I'm going to use the now and expires to know the actual Be able to use that to actually convert it to nanoseconds or the timestamps that the tracer uses So next I do is I call this trace command iterate events reverse So basically I'm telling the go to the end of the trace.daff file and start walking backwards and for every single event Call this function called ftrace trace marker and then null and zero means I want these This is the CPU mask So if you put null and zero it means I want every event on every single CPU I'm way past my data field I had and this false here is do you want to continue where you left off? I want to start at the very end so I pass in false It'll jump me all the way to the very end of the file and start right here now once I execute this It's going to call this function for every single event So here's that trace marker event. So when I get this the first thing I do is okay it passes in the handle whoops and I'm going to get the tep field then I'm going to just get the marker from my data field and If the marker if this does not equal the marker that I'm looking for because right now I'm the first thing we look for is that Marker that cyclic test wrote into the kernel So I want to find that first so if it's not the marker I just say ignore it and then I'm way This is just a easy way of the trace seek file or this trace seek is also in the kernel It's a way to pass strings and with this tep print event Here this is a way to actually write the information from the marker so this will actually parse the Event of the print when you had the print it'll parse that string I remember that you that you saw the HR timer or the sorry the latency was greater than X That will write that into this C. Candler, and then I just say you know put in a Slash zero null pointer and then I'm going to look for that hit You know latency threshold if it doesn't include that this means that this is some other marker and This is not the string you're looking for so then once I say okay it has it I do a scan f to extract the the lat and threshold and I'm going to also record the CPU of the Where the event happened because I only care about the CPU that was on so right here I'm going to record the CPU record the lat record the threshold and Return one could return one or minus when you return a non-zero from this handler It tells the iterator to stop where it is so I'm done. I found my marker. I want it to stop Next thing I do is now. I know what CPU it is. I'm going to set the CPU mask. So I'm going to set the CPU say only Give me or only trace this CPU because the next time I actually put here You'll see CPU set CPU size now. It's going to iterate only on that CPU So now I'm ignoring all the other CPUs because I know where the problem is I'm just going to iterate on that one. So the next function I called was find sked So I'm looking for the sked switch. I want to know when cyclic test was Scheduled on again. I ignore anything. That's not the sketch switch marker and then once I found it I'm like, okay. I want to make sure that this is the well By the way, I extra to make this fit in the slides. I deleted all the error checking. So I did Find the value of the PID The next PID because it has to make sure it matches the PID of you know the sketch switch I made sure it actually was the PID I was looking for. So yes, it was that before whoops So I deleted the error case when it wasn't but I left in that code And then I want to record the time stamp on when the sketch will happen. So I record the sketch switch happening Next thing you do is I find the timer expires same thing this time. I just look for the I extract the timer expire code get or let's see from the time. Sorry. First I do is extract the What's it called the or I get the value of the HR timer pointer This is the pointer to the HR timer because I need that to find where it was initialized The timer now I look for the now remembering that Print statement or in the trace event for the timer. It had the mouse the now when it was I need that because right here I get the time expire. I get the time stamp of this event And now I want to be able to convert that now into the time stamp. So I just said, okay Give me subtract the now from the current time stamp and save that as a timer delta because I'm going to use that back in the start So now I know how to map where that now is to the actual trace data because I'm going to use that information later Then I'm going to iterate to find the wake-up that where the wake-up event happened same thing I'm doing this the same old thing. This is the most cut and paste from the same Functions, that's how I created these I just cut and paste make next one mod it tweak it. So I find the PID that's woken up and when it if it doesn't match ignore it So returning zero tells it to continue Otherwise, I found it. I'm just going to record the time stamp of the wake-up And then I do tell the thing to stop iterating Next thing finally, I'm going to find where that timer was enabled. So I go all the way back and say, okay same thing Skip over I find the HR timer if the HR timer matches the The HR timer from the other one if not continue This isn't the timer I'm looking for and then once I found the timer. I'm going to extract the expires from that You know subtract it from the timer delta. So this is actually the the time stamp according to the tracing trying time stamps When it was expected to trigger and then I of course I record when the start actually the time that actually it was enabled And then I'm going to print all this information for you So I just print out after I did all this I got all the information I want the expire You know when it was expected to expire when actually expired the jitter between that difference the wake-up time the difference When the wake-up time from when actually woke up or when the interrupt happened You know when it was scheduled the time from the schedule to the you know The wake-up and then the marker the marker from the schedule. So there, you know, I do this I run it boom it tells me it happened on CPU one, you know a threshold was a hundred the latency is 121 And then here's the expected by the way since I just wrote this on Saturday I didn't have time to format it nicely to put it into actual seconds because this is the actual nanoseconds In the timer usually I will parse this so you actually would be like eight something dot So this is actually the nanosecond time stamp that's in the trace data So it tells me all the expected it was only 853 nanoseconds off from what it was expected to go up and when it actually did go off. So that's pretty good The wake-up time was you know from the time that went off and woke up 376 nanoseconds really still pretty good Schedule time well that was pretty big 118 happened 118 Not microseconds from when it actually woke up and then here The schedule time So easy to automate But also means we could do a hell of a lot more once you start automation means we add to it So hey, we got software cues. What happens when we do about them? So let's just add more information about software cues I'm gonna make some of these software cue lists to record some information about it And then in that case it's going to record like the last time next time So this is just you don't really have to know it by the way. I'm gonna Show you how to get this code. This is up. I uploaded it So it just records the time when software cues were running I also have a way since the trace event is only a number of vectors I just said here's a map to the actual vector That's in the trace event to the actual what type of software cue it is, you know, whether it's a timer or see you Etc. Etc. Etc. Etc. And then I just inserted the initialization same thing don't write to go over this Just says initialize the events and then in the find sked thing I just said, okay put in this insert this handle software cue and if it's software cue event It returns that it was a software cue. So it's not a sked switch event So it doesn't it did the work for whether or not It doesn't need to do this type equal sked ID because they're already if this Found a software cue it knows that it's not so actually tells you to exit here. So in the handle software cue Here I get the information about the vector Whether it's a start start event or if it's the exit software cue exit event. I then Get the vector convert it and then I run these I don't actually have the commitment to add the code to my slides with the start timer and timer all it is It's just storing information of you know, recording when it started and when it When it exited So I could later print that information which just iterates the list of all the timers and Prince Here's the time that it was running and where it happened So now you'll see when I run this it'll say soft error cues from the wake up to the sked RCU ran one time for two point five microseconds the other one was Sked the sked RCU triggered for two point two micro microseconds one time. That's a total length So it was just it wasn't really Informative but just shows you that yes, you could do that in case it was an issue So it gives you an idea where things are Where I'm sure RTLA has the similar information for all that which you'll find out in the next talk But let's say we want more information I'm interested in locks because honestly when I've ever done these debugging locks was always the biggest issue for delays So can we trace locking? Of course we can so here I'm going to enable the function tracer and limit it to every single spin lock Spin unlock spin try lock spin or read lock read unlock read try locks write locks write try locks and write on locks I put mutexes in there, but they were kind of useless so these things actually disable preemption So I care about them So again, I threw in the information for the function tracer And I also put in this lock list thing that's going to be the same thing like that The RCU thing where it keeps track of time and also I have the stack that I put in so I could Locks are could be nested. So this kind of pushes a stack Ideally, I'm hoping that locks it doesn't have to happen But this code actually assumes that locks are released before like in order So if you grab a lock a B, you're going to release B then grab a and then release a It doesn't always happen the kernel and if that does like it that could break this But like I said, I wrote this in the 12 hour layover. So I didn't really have time to handle other cases So here we go I initialize the function tracing and then at the end of just after I went all the way up to Found this dark case now. I'm going to do trace command iterate events You notice there's no reverse in there. This means I'm going forward now So it's kind of like the there's a cursor in that handle handle that as you iterate through So it left off at the start event or at the start when it enabled the HR timer now only start going through all the events Forward still using only on that same CPU looking for all the locks that are grabbed and inside here I I have this fine locks which will now it also because I have all the timestamps at this point for when You know everything happened the markers and all that if I hit the marker timestamp. I'm done Okay, I don't don't need to trace anymore, but you know here. I put in the state am I Before the expires the timer expires the wake up the sketch switch So I record the state diamond and then I say okay handle locks and then this will put it depending on which lock was held I put in like a special state for What where to store it and whoops See here, yeah, I test the function I get the Okay, so the function pointer will tell me this The IP and the parent IP which I want both and then I do tep find function Which will tell the parser the lib trace event give me the function name for this Instruction pointer so I actually it could look at the IP address and tell you what function belongs He uses k all Sims which is stored in trace dot that and then I say okay If it's not then I call this find start lock function Which will search for all the things I like all this locks that start and if it finds it great If not look for the stop locks instead of flag whether it's a start or stop if it's a start function I just want to say okay. It's a it's one of the lock was just taken just push it and return and And return one here because it's not it's returning one back to This guy so it's not really doesn't know return anyway it returns there and Otherwise if it's to stop it says okay. This is where I care a lock was held during something I care about when the lock was released not really when it was grabbed But when it was released I could put more information about when it was grabbed to but right now I'm care about when it's released because that's in the time frame that I care about and then I pop the stacked I go and I find make sure that the lock matches the lock ID. I have a way of finding the IDs and Then I'm going to do the timers to put the timer and when the lock was started and lock was ended and This is by the way how to find this mice that's fine start lock by the way I have a lock array of all the types of locks That's just the beginning and then I do a search for if it matches one of these You know the raw the spin raw spin blah blah blah then okay, but finds it great break out Break out whoops and the stop Once the fine start lock will look for that underscore with a lock or a try that means to start the I didn't put in the slides for the fine stop lock because it's the exact same function except it looks for just unlock so at the end I print this information for each release and Finally this is what the print lock looks like just tells you like how long it was held for or what Where who took the lock what lock it was and the length of time and then finally when I run this I get all this information. So here's this locks taken from The release of start to it's called lock locks taken and released actually from the start to expected time so When this means that when the expected time triggered to come off This is the locks that were released and it's nothing really big that I care about if this is all again nanoseconds So it's not held for very long from the time from the expected time to the timer so When the the lock triggered to when the timer or took off there's only one lock and then here's From from the wake up to the sked It I find here if you look at this guy right here. I'll say yes this one. It's a lock was held for a hundred and sixty-eight Microseconds it was a raw spin lock and it was from this function So now it actually points to the function that has that lock that I need to go investigate So Let's see if we want to trace all events so We could probably do a lot more if we did that But for now, I'm just going to find when I've all events enabled just give me the biggest difference between two events So here instead of putting any events. I just put trace command has a special trigger dash e all just man's enable everything Believe it or not. It has preempt it preempt enable preempt disable trace events, but since trace events usually take about 100 in between 100 200 nanoseconds per event. It really doesn't have that big overhead It's a little bit of overhead, but if you notice the timings aren't that big difference, but after a while it did trigger and Here I quote what those things said okay record every every event. So basically it's I'm not going to explain every little detail here You want to look at the codes fine, but I'm so explain what this does it basically just keeps track of every event and then looks at the next event and if it finds a Margin that's greater than the last gap. It records it record and it does this See update buffer, which is that tep print event Which you saw earlier when we remember when we did we use this to find the print marker that it is to parse the latency the threshold and the The latency from the marker that was written by cyclic test But this thing says okay I'm going to record the calm the PID the latency time boom boom boom all this is how you print something that looks like Well, and then at the here. I'm going to print that information in the buffer, but if I run this here That line which is kind of useful. This looks just like a trace command output That's how that is this information here that was done as one of stresses again from this tep print event So tep print event allows you to pass in a normal String like you did but you could pet these are trigger or these are little Options to say hey, I want to extract from the record the calm of the name of the The process of the event the process ID the latency information and all that and print and that gives you actually Something that trace command would show it shows me, you know, 93 microseconds happened between these two events I look at it was from when interrupts were enabled to The next debt debt, but you'll notice here that In this location preemption was disabled here and there's a big gap I bet you preemption was disabled throughout whole time because preempt enable and disable were actually events that were traced but anyway, that's the talk I was meant 95 slides and This is the where you get the code. I'm going to upload these someplace I don't know is there a place to upload these slides for I'd never I didn't you probably had a link. Yeah Okay Send me and I can please okay. They sent you the link to because it's just right. I guess it's just it's just Google Docs, but yes Questions Please wait for the microphone. I know it's quite too much information Hello, and it was alone according to the last slides And question about the I I'm not sure I so I Want to know about the candidates the other task that is waiting for the locks Yes remember. I only had 12 hours to write this, right? No, actually. Yes, exactly One of the things I had I had have actually do Manually was to go find the lock owner and then try to do this now that would require Well, we now have F probes, which actually we have to update this so you actually extract the first argument of The lock so if I could find the the actual lock That's doing that throw that into the trace and then I could write this code to go iterate back and actually Just write the analysis saying okay I'm blocked on this lock who owns it and be able to read all the other CPUs at the same time yeah wait for yes, so who's waiting for it because I could also see who got had it Yeah, because I'll know when they released and that's something I also want to add to this But this isn't by the way this utility I'm more showing you what you could do So you could actually add this functionality From this code because right now I work for Chrome OS now. I don't really do much prove the real-time folks So when I was at red hat yes, I would have done this, but I'm not with red hat anymore So that's why I'm doing this is so I'm trying to encourage other people to implement it. Yeah, thank you. Thank you very much From what you did it looks like it would be helpful to write Some say Python binding for lip trace in the trace cruncher Search for VMware trace cruncher are good It already has bindings for Python. Okay. I just I'm afraid of snakes. I prefer oyster I do pearl I'm also it's cool. So I'm more comfortable. It was plaincy, but I know that yeah people are yes Using Python these days. Yep. So what is the scope? Okay? You had you may have mentioned this and I might have missed it But when you're doing the Delta between every event is that scoped? So like it's the Delta from every event on a particular CPU. Yeah, no Yes, actually I only looked for I was only looking at the CPU that I was on I still had it masked to that one CPU Okay What if you don't have it masked? What does it just show you every? Well, if you didn't mask it to all the CPUs you'd actually you could have your phone. Okay, so if I go back Where's that? So Oops wait, I did the all iterator. I didn't add it Not post I guess I forgot to put in the but anyway the where it calls I Try the find one of the iterators Yeah, so the iterator here I pass in the CPU mask and then you know the fine locks and fine locks It actually has the record and the CPU so here you could actually if you want to do your filtering Here you could do the CPU to see if you're filtering by the way It's in the man pages, but I just want to stress this if you notice that let me go back to where I actually found the actual CPU find trace marker I Use record CPU because the record has the CPU it's from okay, so this is where it could be a little confusing and When you do there's two iterators you can actually have more than one trace dot-dot file and Pass it into and there's actually a trace or trace command iterate events Multi where you pass an array of handler of trace that death files like so basically I use this for Tracing VMs so you could trace the host and several VMs and have them all interleaved if the time time syncing is done correctly Which trace may has values of that but in that case the CPU is actually a Unique identifier for every single CPU so if you're the second trace file So the first trace file had eight CPUs the second trace file CPU the CPU zero will be CPU eight in this function So do not always trust the CPU is actually the CPU that represents the CPU It actually is the unique identifier for the CPU if you have multiple if you have just if you're tracing one CPU Or one if you're only doing tracing one Trace that that file it will be the correct CPU, but if you have multiple ones, that's where you got bugs I know because I actually triggered it myself, but The but always use the record CPU that will the record always has a CPU that it knows for that trace that that file There's a question from a virtual attendee John. Are you going to send the code upstream to cyclic test? Well, actually well cyclic test. Oh, I think I know which John it is Okay, sir So hi John Yeah Well, wait, I didn't modify cyclic test at all. This is actually just reading the data from it I do you want a RT test maybe might want something like this Or RTLA, yes, we added to RTLA, but no cyclic test. I didn't modify cyclic test at all This is all trace command tracing right from the very beginning This one This is the update was actually this command here the trace command before it is what? Enable everything so cyclic test doesn't need to be modified. Any other questions? Hello, so can you tell again? What is the big difference between your tool and RTLA? Can RTLA also trace locks or is this a difference it will no, okay So the difference between RTLA and this I'm not showing a tool RTLA is a tool what I'm showing is a library. So what I just did I I created a tool as to for my presentation So I'm someone else wants to take this and do whatever they want with it or incorporate it into RTLA I'm just showing you the library interface RTLA uses trace of s now if it does if it starts recording trace that death files They could do the same thing So I'm just showing the library interfaces So the answer is there is no difference because RTLA if it wants to do it it can do it So it's not a competitor. This is just Showing you the infrastructure that RTLA uses. Yeah They're just replying on behalf of RTLA RTLA is somehow the continuation of the work that Stephen was doing and using the libraries and taking that to extreme optimization Yeah, that's it and using abstractions that we can lead generalize for the latency of the system even for the things that we didn't get on the sample I was wondering actually in the schedule We probably should have RTLA first and then this because this RTLA is like the tool and then this is kind of like Talk about some of the functionality that or some of the code that helps implement something like RTLA So basically you could use this to create RTLA and RTLA. Yeah, the end and that was the story. Yeah We need catch boxes. So are these libraries in the current source tree or where are they? I posted them Here's somewhere. Sorry with 98 slides. It's kind of here. It is right there. It's LibTrace MD LibTrace of s go to trace command org They'll see there's a git repository for each of these libraries Oh, I forgot to say one caveat about this whole thing The trace iterator Reverse is still in patchwork. It hasn't been put into LibTrace command So if you download this today, it won't work unless you go to patchwork the code that the iterator is there Actually, I wanted to write this code because if once it goes into the trace command I'm just like Linus about I don't break a bi so I a bi once it goes in library It's basically set in stone. So before I like to test things out a bit before I'll put up in patchwork. So Right now. I'm really really comfortable. So the next release will include this, but currently it said it's in patchwork It's not in LibTrace command But if you go to trace command org I think there's a link to the patchwork where you actually could find the LibTrace iterator or reverse and download it install it. Yes Talk about just in time development By the way, I wrote the trace command reverse for this talk. I Just wanted to clarify for this to work. You had to Reproduce the same latencies like three times because you were running Different parameters to grab more and more data So, oh, you mean about the effect of latency Actually, if you notice it like that's actually kind of try to mention that even why I did enabled all events Which actually shocks me that it was really rather I mean look at the average here the average. This is actually a true cut and paste from the me running it So the average was like nine eight nine ten These are microseconds For that was from the time that it expected to be woken up to when it actually woke up So went through the whole thing and let me go back to the very first one Okay, so went from three microseconds to eight to nine So that was because I enabled every event So, okay, so it's interesting here. We actually look at my presentation to find so this is with no events enabled It's through his average of three if I go Let's see where I started tracing here The average was four or five when I was enabling the sketch switch events and timers IRQs IRQ vectors So went up to it went up a microsecond and lazy So and then when I did the start doing locks I should made it I should point that out when I was doing that here Where's the lock here? It went to six microseconds when I enabled all the locks So it's so went from three to six so I added three microsecond latency overhead And it's a pretty big path that it's doing so that's pretty good and you're grabbing every single lock But the fact that it only went from six to eight with all events was actually it was pretty impressed by that With you enable a function tracing this six will probably turn to 20 Because it's tracing every single function If you function graph the 20 will turn to 50 Or more that's when you start increasing that break time by like exponential Was it? Oh, what did I run out? I ran it on just a normal i7 So it's it's several years old down though, but I think it said like three gigahertz 3.4 gigahertz i7 Any other questions? Well, if not, thank you very much