 Hello, Michael from this working welcome to another talk for me about one of my favorite tools of Linux, which I'm really using a lot Sometimes every day at least every week, but today I want to talk about different aspects about tracing getting timestamps doing time animals just things like that Yeah, I'm doing The outline of the talk is really Showing where you get the documentation from how extra I tried to do a very short introduction to stress who has never used as stress before Okay, so but I try to keep sorry No, I wouldn't say that then it's the perfect talk for you knowing that you missed that Tool for a lot of things, but I try to keep the introduction very short last time I gave the talk the 45 minutes I feel over when I did the introduction I Did it a little lot of open source even at school time in the early 80s and late 70s My first open source experience was potting tech in 1996 to our university wave for we had Linux and all the fun things I got addicted to Unix in 87 already but only the proprietary Unix is because in Germany we didn't have source licenses and I was playing even the very first Intel Intel PC processor not the earlier ones and I was found the assembly model horrible and even the 386 and I didn't like it and in 92 I bought a Intel PC just to get Linux running on it because then I had my own source code Yes, and it was an x86 caught him for quite a while writing graphics driver for his free chips until I left University and Meanwhile, I'm I was was addicted to doing low-level hardware things Drivers by any means whatever it's not working get it working for me friends University now for In my first shop for customers and now for Bosch our own project and doing everything but windows and using a lot of open source Still trying to at least file back bugs or improvements, but it's not going that much anymore Unfortunately, so where do you get information from S-Trace? There's a wonderful one page about that S-Trace is using the P-Trace system call I won't show that this P-Trace is used for all the debugging you can control a second process You can say stop it run it do a lot of interesting things with it If you're a little bit used to S-Trace, you also might think about writing your own tooling things with just the P-Trace call It's quite interesting for the month page things in Unix who's not aware of the man command Then even that talk is for you. It's you get all the documentation for example now for section 2 The right command because we are the S-Trace and P-Trace is all about the interface between user processes and kernel You can trace the system calls There's a second tool, which is not on that slide. Maybe it's coming It's L-Trace the library trace thing where you can trace from your program into shut library call So all the lip see things print F F open whatever which is in the user space There you get even more Output and it's even more difficult to understand things, but now I'm concentrating on S-Trace how to Trace all the system calls which are interesting for us and where you can see a little bit what your program is doing What the Linux kernel is doing and how to understand things The web page from S-Trace is S-Trace.io They get also a lot of informations and I learned quite a lot by one of the contributors or that contributor I don't know exactly Guy from Greece Dimitri live in at least gave a lot of interesting talks at Fostum One of the nice conference we had conferences in Brussels every start of the year and start of February for other aspects About S-Trace I gave some talks almost 10 years ago And you can find the papers also on this with that URL or now with the slides and The one is for understanding the S-Trace system call thing and what it can do for you and Expanding a little bit and giving examples in the second one is using S-Trace to understand what your shell your command line interface is doing then you can specific specifically look on What's the best doing if you enter command with and without quotes with star without star and you can Directly see what happens and learn a little bit at least for me It's always easy if I see something then I can understand and learn things so that's for and also learning how the shell things are working It can be quite useful Or at least about giving talks for that and explaining how it's working and how we can see if why things happen so Very short introduction to S-Trace the easy method is you say S-Trace whatever command and run it and When I'm in presentation mode, I cannot cut and paste things, but if you use the slides you can do that so let's see So I can do things like that S-Trace some echo command and hello bill bow and whatever you get a lot of output Already and scrolling up. Where did I start it? Where's my go here's the SR one command Do that and right again So this is S-Trace command and you would get all the system calls the first one is exec Vee you please execute that Binary with those command line arguments and then you can see how it's loading the shared library lip see something I have the wrong classes here. You can see opening in the lip see and Whatever Have a look at that Interpret that and then just pick the things which you're interested in right now We're interesting about echo does some output and you will notice down here. There's a right call Say our right system call. This is why I also put the man page for right section to the system call and the right system call needs three parameters file descriptor the string and How many bytes there are yeah Up to you. So this is the right system Or it's getting messy and It will tell our please write from that memory area string the first 21 characters Then it's jumping into the colonel colonel does the right this is why not now the string comes in and Then it returns from the colonel and says Okay, here. This is the return from the colonel and it said the right system call returns 21 I've written 21 bytes for you There could be a different return code if you try to write on a disk and the disk is full it's a Zero I didn't write anything or if the device does not work whatever you should write into pipe Maybe not all the data is going into pipe. So and we can see it's reading some things The very basics There are some examples and in the papers you find a lot of things. So method one is just s trace some command If I do the same thing I Like running almost every command with time in front because I wonder how long does it take to start my edit? How long does it take to compile programs if I do that s trace time, whatever? Then the output looks completely different and if I look here We always can have a look what happens if I do that without this s trace command and it says hello We bow and it says blah blah blah a lot of timing and CPU or whatever if I do the same with s trace we will see a Lot of timing real blah backslash t is a top going to the next columns some more numbers user If you look carefully we don't see any right hello be bow anymore This is because this command is only tracing the time command and time will create a Child process should be able to see that somewhere on top So some other is a clone call and it forks the process and in the clone Sorry, I can't pick it right now and only that second So I see the sick child when it really are here exactly. Oh, thank you very much So the clone will just create a second process. We get the process number here and in that process It will do the echo and the right which I've seen before but you don't see that because it's only tracing the time command If I want to see all the process the first very important option is dash f follow child processes and Whenever you don't know just put it to about everything because if you don't know if it's executing subcommands or whatever its threats and If you do that and and we are lucky somewhere how we can see the hello bill bow again This is now now since we are running Trace on multiple commands. It will show all this is process ID blah blah blah whatever and and you see And then you have to have a careful look on for which process. It's doing Then that you can separate where the output is coming from And so this is output from the first try process We don't have only the single one and this is now returning to the main process We don't see any process ID to my surprise doesn't matter. So First method strs Almost always use the dash f option and run your commands and see how it's going The second method is you can do a dash p processes ID So if something is already running your servers, whatever you just can attach to it and Can just watch it also if that process has sub threats and whatever I always use minus f And you can just stop in the first case if you press control C You will stop the command itself. So if it's running for a long time, it's Then you will kill the command and everything if you just attach your process with as such minus p You can press control C. You stop the strs, but your command your server your database, whatever is still continue So that's quite nice also If for example startup is very time-consuming or whatever you don't want to trace everything but odc SSH server single connection. So something is not working. Then you can attach to the SSH demon But you don't have to do that while it's starting up or whatever your topics are Attaching to other processes in general only works if you start the process in your same terminal because there is some Colonel protection mechanism in the meantime and there's a proxies whatever variable p-trace You have to look into that variable if you I can't show it right now because yeah, I've opened up that thing I can and I cannot do cut and paste you so if that thing is not non-zero and you have a second terminal, so I Would do something like that Just give me the processes process ID for this terminal And I would do an strs my dash p for 3070 then in most of the distributions you will get an permission denied error because this terminal is not allowed to Trace any processes from any other terminal or whatever your as a regular user. You're only allowed to trace your own things anyway so once the using is always do Zulu Root is allowed to do everything Then you can do the attachment, but that's tedious and you don't want to run all these things that's rude And the correct way now, I'm not sure if it's correct or not the better way might be you write zero to that Colonel variable and then At least all your comments from your user are allowed to trace and debug themselves Might be helpful Still you cannot trace commands from other Users from route whatever so if you try to trace something from route from other users You always have to be rude yourself. So but it's if you get errors here with dash p Use that change that variable So far we have seen strs is outputting everything to the terminal. It's quite useful I always like start like that to get an idea What is the thing doing what I might be interested in how I can filter things so One method is you dash o output file you write everything to a terminal To do a file. Sorry, then your file is called output dot strs. Whatever choose your names my strs commas files are always called Up a case o one two three four whatever if it's uppercase. Oh, it's an strs file What happened here, okay, yeah outputs The same as before if I just do a strs-output tool I only get the program itself no children if I do The dash f option all the children things we will see the output in details shortly, hopefully You get a single output file if you Use the option f twice no matter if it's dash f dash f or you can combine them almost all in one dash ff thing then you will get Not a single output file Second time but you get something like that So here I was working and this one is a single output file It was called you odd dot three s output file or with double f you get a single file with the process ID attached for every single process or threat or whatever that can be quite useful So you have everything combined and depending on what you're looking for and how you want to analyze things It's important to understand the differences and especially for the timestamps and other things. It's We'll see There are a few options which help you how much information you will get Read the man page for all the options. That's really an player round and depending what you're looking for That dash v is more verbose. Maybe I can show that one very quickly some of the Where the echo whatever command Next slide will show that I can do with dash oops With dash e I can just ask for tracing single X Single or multiple colon Commands but everything And if I do that on a regular base you can see it's trying exec ve and it looks so this is an option for example to See how the path look up Works and now it's trying to find echo in dot cargo bin whatever local bin and until it finally finds an Exec succeeds. This is a one-point, but it shows Here only that there are 159 variables for whatever. This is the environment and if you have a very long argument list then it also won't show up everything and this is what the option dash V is for being verbose We can also do that like that we can combine options and even the f and whatever so Saving some Followed children and they think and now with verbose for example, you get the full environment and the full command line And things that actually if you look closely, it's not completely full because it says session dot dot dot because All strings will be abbreviated all filenames if you long file names It's still a problem that it only shows the first or not 20 whatever character. So if you're more Another System call where it's useful having the verbose option is for all the start options if it's looking for status information on files if it looking is the file there With start you get the file size the permissions and all the things They will be shown in the s trace output because it's a lot of buggy things then only if you use a dash V for the strings We just noticed on the not all Not all strings are shown completely with a lot of dot dot dot things Then you can also do that's what I very often as some larger number depending on you so for this strings I think 999 is a large number you can for other strings if you want to trace the whole reading and writing of files or Your network traffic traffic whatever Now there are no dots anymore. And this is when I double click on that. This is a single command line So this is now our start of a single command and to be because it's only doing that exact being here. It's not You see it's a huge thing because these are the hundred fifty nine whatever Environment variables can be useful for tracing that thing since the which sub processes For example changes your path if it's not working well because you see then also path for everything right into a file look for things Sometimes if you want to play with the strings, which I want to do later also can be useful if there's binary stuff We could have seen that before if we Open the libc and read things binary things will be output in octal with backslash Zero one two three in a very confusing for me confusing syntax Which is a little bit different to what this C standard is doing and for that reason I Found few years ago There's an option that all the binary things you can also get hexadecimal, which is a little bit easier to refine It's still outputs the regular Things like backslash n backslash g whatever and do you see anything with binaries here here? Record partner things will be backslash x always two digits then so it's easier to parse and read in some cases and if you do double x Then all the output is completely in hex even the printable ask you things Sometimes quite good for transferring things So a lot of options and you can set them multiple times I think even verbose is possible to do it twice and just different things what I already showed a little bit If you looked at that and you can run that s trace output for hours and look at it What I'm looking for what I'm waiting for what what's the event or write it to file and analyze it S trace can slow down your processes because it's intercepting all system calls and it's intercepting And when being called and coming back and if you do that To a process which does a lot of IO huge database server it can slow down things If you realize what you're interested in for example only file lookups, and I only want to see One example would have been for this conference just using s trace with a single command line thing to get s bomb lists for What you're compiling of which files are affected You just can use s trace dash e file so you can say I want to have the read and write system calls I will do that in a minute a few minutes You get only read and write system calls for getting data and Outputting data things e is a meta file name meta function name You will get a trace for all Colonel calls which have file names involved open start looking for things Everything we find also change mod Change directory everything this file name so that's quite useful if you do that You get about all information You want to have if a process is looking for config files if it's opening things if you know that you're running Into a method for doing s bomb So I only want to know which files are really compiled into my tool This is exactly what I'm doing for my project because I had to invent those tools long time ago and we have a Different hardware configurations and things and I really Running the whole make processes through s trace Only tracing the open calls. That's not too much overhead because all the other things are without s trace And it's not doing adding anything for if for the system cause you're not tracing You can say s trace dash e open Which was working nice for a long time you get all the open and never forget minus f because your make is making Subprocesses and the compiler is making sub processes But so it is now only for the selecting system calls You can say minus f minus e open when you get all the open calls in modern Linux systems You won't get a lot of output anymore because typically they are not using the open system call anymore, but open at Modern things like we are not doing fork anymore, but we're doing clone things like that so With oh, you can also say open comma open at you can like read and write But you're never sure if next year there will be another open call and in the meantime, it's possible to provide Regular expressions also for that's not doing a search on regular expressions and this is quite nice You can say minus e slash open just use everything with open anything will also do open or whatever So might be too many system calls trace, but if it's open 32 open 64 open whatever You will get them all Same is true for the stud things if it only tried to figure out What your process is trying to find files which then do not exist you can say Get all the stud files or stud 64 or everything with start and whatever When you do the full tracing you see what's available then you can pick you also can exclude things With an exclamation mark and say trace everything But if you notice there's a single system call which comes very often This is the only thing which Interfers and you can't read the rest the remaining output. They get it just forget Some tracing few texts whatever Now we're coming to timing this time So file operation things like that read the papers a lot of There's more explanation and some examples how what you can do this time I want to play a little bit with time stems and I do not want to click here for timing that three important options T T and R so lowercase T uppercase T because there was anyone T for timing and relative We'll show that in a second for you get some time stamps. You get a more detailed time step You get an even more detailed time stamp Uppercase T will show how long it's in the kernel and R is a relative time stamp The years before if you did My list stopped here because you if you did mine did minus our give me the relative times Have you only got the relative times them to the T the absolute times and vanished and now when I prepared that talk Start of the year and thought about that thing. I was very surprised that now you can mix absolute and relative times I'm sure that's great because All information I studied physics and if you measure things also if you measure timing Try to get as much information as you can and filter out later and learn from it and try to understand things and When I only had either relative for absolute timestamp Well, it's clear you take the absolute timestamp and use your own tool to calculate Delta's and things like that, but now we get that offer free. That's nice So let's do a very quick play with these things. So What's the last command so now I'm only curious about the timing so Let you see that once With minus T You just get ours minutes seconds For a quick command. It's not very interesting If you do T twice, it's getting much better then you get ours minutes seconds and Microseconds, that's quite good But if you run it for a very long time, you don't know is it 12 o'clock today 12 o'clock tomorrow So if sometimes I run things for hours days, whatever and I do then later Timing analysis plots, whatever this is all and it's hard to pause ours minutes seconds Getting useful number. So this is why you can put the lower case T three times And then it should cut just get the Unix and Linux time. This is all these are the seconds from start of Unix live Seconds since 1970 with microseconds is a quite nice resolution quick hint if you have something like that and See that dates later. You don't know how to get back from that It's also You can say please the date command can a lot of Can do a lot of good things for you and So if I date minus D At sign and any magic number and you get just the date in Unix in your time zone Where you run has have been running those trace data that can be quite useful so back to Triple G So this is what I typically do because then I just can pick those numbers calculate things make differences Whatever, it's the easiest thing our case team Nothing happened with the times But if you look closely now, we got a new column at the very end in Angle brackets and it will tell you how many microseconds the kernel Call has been taken from calling the kernel to return and that can be quite interesting and helpful So uppercase T you get the time within kernel We'll use that in a few minutes. Yes, and To just show the last one So only the relative time sometimes it's sufficient It will just tell you that that MAP was running 300 microseconds after the close If you're looking for where did we get some delays? Now this is not a Sleep for 0.3 seconds that is not taking too much time And if I write that things to an an output file Just look at the output file so we have the timestamps and everything then you just can go for Sort numeric your output file for the relative timestamps and pick the very last ones and we find Something took 0.3 seconds before that close from something to close Something took a long time and then you can look in your output again And look how this is from last thing it to it took 0.3 seconds and the last thing was the clock nano sleep Ah, no no big surprise. This is my 0.3 seconds if you do that With the s trace getting more information because that's the kind of everything which I do always do so you could have been Three triple and whatever and they are everything and looking at that thing again. I would sort now for That's now the relative thing is in the third column because we have the absolute timestamp plus relative and whatever and oops, and now if you do sort by third column We get the same and then we notice Blah blah blah close and we can now look in the output file for the absolute spot could have been that as more relative timestamps like this and it will show us here and Also, we can see that this kernel called the clock nano sleep whatever Has been staying for 0.3 seconds in the kernel. So it would also have been possible sometimes helpful the point is Here we see What's taking a long time in the kernel? so I can do sort Say in my my tabulating thing is now opening anchor bracket. So my keyboard is wrong and my glasses are wrong Yes use the tabular for The angle bracket and now please sort for second column This is not working if you have something which is reading and writing XML files But in general, they're not too many opening and closing angle brackets. If I do that now Now we really get the time in kernel Because it have could happen that you have a long time in user space before you do the next call Yeah, you just count from one to one billion whatever then the time between the calls is long, but you're doing real user work whatever that is and Here you can see Which system call really stayed the longest time in the kernel Back Fun, I don't demonstrate it. So You can use now you can trace things you see exactly when which system call is happening and in my old company where a department doing a lot of 3d Graphics and they've been very busy compiling things so their compile time running on a big Silicon graphics machine took one or two hours, whatever and Since while this was running they couldn't do anything but drinking coffee and in that later I have seen that wonderful xkcd comic and What they did what what I did for them is one time with a very small example here You can just look at that. I traced my latex command running those slides put everything with Full strings relative time same only the rights to the terminal getting all the x things whatever to PDF latex S trace output. I can show that one Yes, so this then No wrong terminal second time So this looks like that what we just have seen it's even longer lines it's the process ID the time from the last right and what it has written and And This almost looks like C code except for the semicolons at the end are missing it says I did that so you can Just use your favorite whatever formatting tool and reformat that that you get the semicolons at the end of the right lines and Get that one and then the output will look like that And it's real C code which comes out And With the first number I just do there's a system called you sleep doing microsecond sleep This is exactly the numbers which we got for the relative timestamps multiplied by One million and then you can call you sleep wait for until it's time for the doing the next right then you can just Whatever My C program for that is just you stand up head of Maine and include that s trace modified s trace things And if I run that It was run at the same speed as it was doing before then so you can use that for being happy with X KCD, but once we had real useful use it for that where we had a specific Timing panel which showed up where a database failed and over network calls and we haven't been able to Easily debug that because it was a long time going there and after a while it showed up it's a timing problem that we are running in race conditions and I've been running s trace on a real client Getting that timing and I have been able to reply the same timing Which made it much much easier triggering the buck and then you had a nice method to analyze problems So this is all you just can do there I'm still compiling and it looks real like real and your CB is not doing that So your machine is not too noisy and you can do other things. Okay How much time do I have left 10 50 minutes very quick What it helped me recently so you find that on the slides. I want to show it in life I'm doing a lot of hardware work and he has real Hardware trace from something this is serial interface is sending some serial bytes to a microcontroller doing some work and giving the protocol back and Colleagues are using that it so this is the microcontroller. I'm working on the real and this here It's misused as an SPI bridge. So this is the real work to control our ASIC and This is a protocol. We should do other things than just SPI bridging But for testing, this is fine. They have a side channel and can do a single Transfer another single transfer problem is this is horribly slow. So running the whole Setting up the whole hardware is about 17,000 of these SPI cycles And if I go in here, it will tell you one of these serial send a command wait for the wait for the other This is the small yellow spot and return it and then for whatever reason it's always waiting 15 milliseconds in the very low thing So that's with a nice logic analysis, which I like a lot problem was what's happening here in this 15 milliseconds And this is all the lower thing. So the series stuff is running in Linux using a regular serial USB serial cable and it's in Python and we have a lot of automatic system testing and the colleagues came Around and said yeah weeks before it was much much faster. Now something happened. It's got slower. No specific numbers Okay, let's have a look at it and now it takes more than four minutes setting up the system for minutes is too long I learned that before it was only a factor of two or four Faster not that much. Yeah, they changed Python libraries, whatever and it was a little bit unclear What happened? We tried to revert the Python libraries. It didn't help As trace. Let's just have a look and get an idea of what happened here And here you can here you can see the output of a stress which are now show on the problem is here I cannot click in that PDF thing and show you what happens and then get to the right time and again this was here So and now I have two options This is about the timing what happens and I wanted to show you now the decision getting a single trace output everything in one Thing or running the same stuff a second time and seeing which process doing what and Why it might be helpful doing the one way or the other so this is now what's going on And I just look for all the reads and writes because I'm just sending some data and And looking for a good spot where it happens. So this is here is something this is oh, no, it's not a right Which I'm looking for I Nice Yeah, this is now the real protocol things with some binary CREP so I'm sending some write command On file descriptor 64. This is our binary stuff going to the microcontroller the micro does something and The problem is the read since everything goes into the same s trace output We have to start looking a little bit a little bit earlier so one thread starts a read command waiting for output coming back from that protocol thing then we send the right command and we are waiting for the return of the things and Here it says read resume because now I've done and it's very important then looking at the process ID So the read started at With that process ID quite often I really use less or whatever and filter odd things The bad thing is in my mind that it says are I'm reading from file descriptor 64 That's nice if it resumes and says are now I got the data You don't see the file descriptor anymore if you're going to pick out all Communication on file descriptor 64 you won't spot those files and sometimes it's easy Useful that you can match what I sent out on either here for the Siri interface or also if you do the same on a network sockets With send and receive same problem that is getting intercepted and also if you look through that It's hard sometimes understand what a single thread is doing But you get a good time sequence we come to that in a second again if I look at the second example What? for whatever Now there's there are a lot lot of threads running here because it's heightened and You're not completely sure Which are the interesting ones so you can for example look who is doing how many reads and writes Here's one thread is doing a lot of read 300 whatever read and There's also one thread doing a lot of rights So just looking into those two that was the right thing here he was Not so right was easy with the other one. So let's have a look at the read example Dum-dum-dum read it's this process Then I can see the full readings, but I don't see how stuff is written So it's not I see either the one or the other you can try to combine those things The nice thing is if you have absolute timestamps You just can Sort all the things even just all process because the other are not doing things just sort them numerically dot-four and Combine them and then you're getting sorted by time again Let's get them all Okay, let's look for all the reads and writes again Dum-dum-dum and now the nice thing is I got the things by timestamps and it says our readers here writers here Readers here writers here looks reasonable and The read is not split anymore because now since it's writing to a separate file you get the full read string whenever it returns Be careful with that easy method So it's working quite nice if it's doing independent things and out of time in this read and write protocol thing That I was very confused at looking at the things. I just have to check if I can show you now Here it's working us point is our protocol has a sequencing number in the middle So this is the packet number be eight be eight be nine be nine in this example read starts before we're writing something With absolute timestamps and it's working fine I've a different example Maybe we manage that for networking where the threads behave a little bit different And you always get the start of the reach comma start of the system call as the absolute timestamp. So when S-trace is your calling as a read it will take that timestamp and It can happen in my second example for networking that It first transmits something and then the send in the timing of how sent and receive are getting Started is different and if you saw that then the send and receive Commands change. So be very careful looking at those things What's because now what I want to show you? This S-trace shows that the read takes 15 milliseconds So the relative timestamp doesn't show it This is only now we merged things and you just get the relative timestamps for everything in a single thread The relative timestamps make more sense if you have a single file and get a real absolute list of all things going on in your whole process tree, but we see in both methods if you look at that The read really takes 15 milliseconds And if I look at the hardware All the bytes arrived and so here the read should Finalize and say okay, I have everything and takes 15 milliseconds and this is the whole 15 milliseconds We are waiting before we can send the next thing. It's not any Python code. Whatever really the read takes all the time Okay, then it was clear why messing around with Python packages and material did not tell but did not bring the Good performance, which wasn't that good either when I have seen the real numbers Not sure if I get the right thing The send and return things if you want to have the real so far receiving information is always most of the time at least You want to know when the data really Came in so if this is what I have this example for maybe we can do that in a break later No, I do it now So this this is my wonderful IOT device from a hackers conference recently There's some Python code running on it on deaf TV So this is here in the face and we just get right. This is a very small micro Python thing printing temperature pressure and other things This is quite nice, but unfortunately even it has an ESP 32 It doesn't have a battery backup real-time clock. So it doesn't have a reasonable timestamp. And if you want to Get those output This is what s trace can do for you. Okay, and I just say, okay Let's do I want to have the timestamp things and I only want to know the Read calls when the data comes in something like that, let's try that and So we have a read call and now I get the things with Absolute time set for my computer and it's messing around a little bit So just forget about that output on the terminal. It's easy That it's easier to read The And then my string sizes are too long again. So I have to do as 999 give me the full data and now if it timestamp and everything and so for example Making long story short Write those things in an output file So that should be sufficient for now and And In now I have an absolute timestamp and some temperature data and some pressure data and whatever and whenever I want to look in those data Typically my regular tool is Knew plot and I can say plot That file using first column for the timestamp and I always have to go second column third column fourth column Six column number six for the pressure for example a lot of things happen here so a little and If I'm not sure if this is the peak looks like there's some other thing I could test now I'll just say get only those lines which started with tests for whatever and Now I get some graphics about pressure on whatever so I have absolute timestamps. I can run all input devices put it to a file figure out later Where the time sim came out just now can look at that also very useful Method just getting timestamps for data coming in and analyzing them later and putting to database whatever So in this case we notice okay, the read call is really the problem and As soon as if you then do all the math for what I've just shown here It has if you see all the read call starts here You add the time in read you will notice this is exactly where the next right goes out So there is no time left for doing Python any user mode Calculations whatever so Python was very fast So getting that faster we had to look for the serial interface and things and whatever and Looking a little bit in the internet. We learned that for the FTDI serial interfaces you have a latency timer which you can able and disable and by default It's enabled and it's just waiting 16 milliseconds if there's more data That it's more efficient and so if you do high-speed transfer high-speed transfers And you're waiting for a few more characters. Then you have less read calls. That's quite nice If you disable that and write zero to it, then you will see exactly here in the lower part of it I also can show that here and then magically all this 15 milliseconds go away so we send a packet we do a little bit on the microcode all we remove a packet and Almost Immediately we will do the next theory interface thing. So everything squeezed together In the early days because it was so slow The colleagues always argued and also I did argue because our microcode was running before at a mega about and to mega about and for Other reasons and an other serial interface not that one Colleagues change it to 115 kilobytes because the other interface wasn't able to run any faster They said how we have to have higher board raises it as long as I look at that timing picture speeding up that part of the serial protocol racing board rates doesn't make sense because We have to understand the gaps in between Thanks to as stress we understood them and now we're in the position that we and this is quite easy in that hardware we can change on both sides But it was Friday late evening already Changed the board right to mega about this will give us another factor of eight Speeding up that protocol altogether by a factor of 60 to 80 and then it's running quite fast And I've heard from colleagues that now the start of this thing done in 11 seconds instead of four minutes And they can use that for doing more system testing What's the timing? It's done spec So the last example I would have prepared These are now with sockets and system calls There you can find the raw data again with s trace Here I've written things to Multiple files you six dot whatever with double F And if you look for the send and receive timestamps You get all the sense in one file all the receives to other files And if this is where it happened if I sought them by time Here I cut I clipped off a few of the Unix timestamp digit Otherwise, it wouldn't have fit in the slides in that font size. This is why it's not 169 whatever absolute timestamp, but it's an absolute time stamp anyway and sorting that together Finally, you will see here that the receive comes first and so this is The receive will receive the packet with packet ID AC before it's being sent out. So I Got totally confused. This is talking to us That server is running in Python getting a web request do something for us This communication is going to a second Python server, which has the real hardware Connection through a different interface Not that serial interface. We've seen here that all the hardware is different and that's running all on an embedded Linux system and The colleague also came here. It's slowed down and we don't know why and whatever Not what we have seen in a serial interface and then when I looked at the details I didn't understand how can I receive something which an answer for the pack ever for for the command Number AC where the scent goes later and then here I receive something for the command ad Where I sent out the command reason for that one was that really we get the absolute timestamps when the receive is started and In that thread only after starting to receive command The send is being done and it's just sorting bluntly for the absolute time some doesn't work But also here we see that receive waits for nine milliseconds So there's a little bit indication and I really have to add these nine milliseconds is starting time and This is what I did On command line. I like doing things like that in with AWK. So it's horrible AWK Whatever, I just get the number from the last thing added to the column number one added together. Then if you saw that all Then you notice then now I first sent that command with sequence AC and A little bit later. I receive it and we can have a look at the absolute timestamps If I just sort out All these timestamps from different files then the relative timestamps don't make too much sense anymore With another AWK command, I just can use the absolute things in front now. These are the read now it's always when the read or send returns for the send it's Below a millisecond. So that is very fast. It doesn't matter but here the read took nine milliseconds for delaying 12 milliseconds 12 milliseconds things like that and If I redo the relative timestamps, I also can see what's taking time. It's really in the receive which is waiting a long time and In absolute timestamps the send is only done 12 milliseconds after receive has been received. So in this case, it's not the receive really Doing the delay even it's waiting for 12 milliseconds but it's only because it got started directly after the last sent and Looking at the relative timestamps from these are the only system codes which are running and are relevant I can see here now that then after receiving data it took 12 milliseconds before I sent the next command and Again, this is code which happens in Python Now if you dig in Okay, so this is all I wanted to show you For for questions, I think we also can meet outside and have a coffee or whatever So thank you for listening. Thank you for being here Sorry for being late again At least I showed all the topics and so if we can play around with send and strays and whatever outside