All along the dwatch tower
CC Attribution 3.0 Unported:
You are free to use, adapt and copy, distribute and transmit the work or content in adapted or unchanged form for any legal purpose as long as the work is attributed to the author in the manner specified by the author or licensor.
Teske, Devin
I would like to present a new utility called dwatch that I added to FreeBSD 12.0 Using dwatch, in this talk you will learn how to: Watch processes entering system CPU scheduler Print arguments being passed to functions Easily watch multiple probes simultaneously Globally watch all function traversal from every process/thread Filter output by user or group, including the ability to use regex Watch jail activity Use patterns or regular expressions to match on executable name(s), pid, etc. Look for a particular path being created, removed, accessed, etc. Watch interprocess communication signaling Log network data events Schedule timed samplings for events of interest Dump process trees for processes triggering a probe Watch child processes Show commands being executed in realtime Write modules to centralize logic into easy-to-access profiles Share modules with each other and help your community More... With dwatch, using DTrace has never been so fun and painless.
 Alright, okay. So today we're going to talk about three things, there's three sections to my talk. So we're going to talk about detrace. That's kind of important because my tool, my new tool that I'm going to introduce today which took five years to write, not just off and on, five years to write, and I actually am building ports off of it now. So dWatch is going to make your life easier if you want to use detrace. And we have ports which will give you additional functionality which is just amazing. So let's get into it. So on the topic of detrace I'm going to, most importantly, it's got a mascot. What can it do? A brief history and then we're going to get right into the thick of using detrace. So this is the mascot. It's, detrace solves so many problems, it's like getting a pony and a unicorn. And well, you can do flame graphs. This is what most people think of when they think of detrace. But I'm going to show you, you can do more. So we have a Gorse visualization. Gorse is a visualizer written by Andrew Caldwell. It's open source. It's a GitHub and it takes version control logs or a custom log format which I'm abusing in order to do much more than just version control logs. And it's wonderful. You'll get a live demo. We can trap arguments, syscalls and functions and do so much more with detrace. And of course we can snoop on all the things, even our slides. For those who don't know, famous rapper. So, Solaris 10 is when detrace was born. You know, we were not the first to adopt it. We did not invent it and we will not be the last to adopt it. Right there in the middle, 2009. FreeBSD 7.1. I think everybody in this room has at least one freeBSD system that has detrace installed in the base, ready to go. Unless you like running things older than 7.1. And the co-creator of detrace has these little bullet points to share. It has its own language. It's a subset of C. And it's kind of Oc-like. It has a micro virtual machine. Code is actually compiled. The D language is compiled. And it has a conservative pro point selection. And in the next slide you're going to see what conservative means. Essentially it means you have to be explicit. You have to tell it what you want. It won't figure it out for you. So, before you use detrace, you have to know what a probe is. That's the most important thing about detrace. What is a probe? And this is the simplest detrace syntax you can possibly use that actually produces meaningful results. Arguably, meaningful is interpreted differently. It's not until you get into an intermediate, an advanced, and expert detrace syntax, which still we are in the realm of a one-liner. We haven't even gone into writing a script yet that I have to kind of break you in. So a probe is a column separated to string. And it represents a kernel or a userland point to trace. You can trace one, more, or any number. And so it's separated by the provider, the module, the function, and the name. Providers are the top level. Providers provide modules. Modules provide functions and functions provide names. It's not always the case. Sometimes you have a provider that doesn't actually have any submodules or functions, just names. But at the top level, it's all providers. There's 26. Get to know them. So now we have detrace-n of valid probe. This valid probe says, watch all of the VFS create events. Now, arguably, you don't get much information. This is almost practically worthless, this very basic syntax. All you get is you get the CPU that the probe fires on, the ID, which is shorthand. So notice that you only get the function and the name. If you want the provider and module, you can use the ID. You can say detrace-li, the ID, and it will show you the exact full probe. And if you break it down, there is actually a couple probes that you can use to say all probes. And that is colon or colon, colon, colon, colon. Now, I'm doing something in these slides that you might want to key in on, which is that every time something is a provider, it's red, every time something is a module, it's blue, and every time something is a function, it's green, and every time it's a name, it's purple. So not every output is colorized in the way that you see it on my slides. I'm trying to help you parse these walls of text. And within a probe, you can actually just omit an entry between colons to say wildcard. I want all of those things. So this first example would be I want all of the VFS VUP creates. Well, that's only one. So this is really just like shorthand because I'm too lazy to type VUP. And you can say star. But you probably don't want to say star if you are only putting a star because then you have to quote it because what if your shell finds a file name matching that pattern and expands it? You can also put the star anywhere in there to mean all attributes, all reads, all writes, whatever. So here's that in use. Show me all of the functions in the VFS provider as I enter them. I want to see what functions I'm hitting. Again, this is arguably not really that helpful because all I'm getting is a CPU that the probe fires on, the ID of the probe, the function name, and the entry. But we're getting closer to something usable. And now an example on multiple probes, you just separate them with comma. So not only can you have wildcards, patterns, you can have multiple probes that select different things separated by commas. And so the very bottom one there, if I say VFS colon, colon, colon, comma, says colon, colon, why would I do that? I want to see the VFS and the SysCalls interleaved. That's 2324 probes. So that's what this looks like. So now the first one, I octal, that's a SysCall. Lookup. That's a VFS. VOPLookup. Lock 1, that's in the VFS provider and I octal, of course, is a SysCall. So here you can actually see how they fire in order. Which is nice. Although Pay attention to the CPU. OK, so the next thing I break you into is there's not just dash n. Almost every one liner you find on the internet is going to have dash n probe. You don't have to limit yourself to dash n probe and a four tuple separated by three colons. You can actually have what it allows is three tuples and less. Imagine only specifying two colons. Imagine not having any colons. Wouldn't that be nice? Detrace allows it. So if you say traditionally dash n name, it will take a four tuple, but it will also take a name. Dash n tick is actually equivalent to dash n colon colon colon tick. Dash n colon colon colon create comma on CPU. It knows that the first one is fully qualified. The last one is not. And so internally, it will translate this to prop colon colon colon create comma colon colon colon on CPU. There's other examples, like if you want to watch the function named log, dash f log is synonymous with dash n colon colon log colon that selector. There's dash m for watching a whole module. There's dash p for watching a whole provider. So if I want to watch all of the ZFS functions, just cart launch, and I don't care what the provider is. Here it is. Dash m ZFS. Synonymous. CPU ID function and name. So some good functions here. Arc available memory, none. Arc adjust, multi list, get random index, SPA, get random. Good stuff. So then you might be interested to then ask detrace to show you the probes, because maybe you don't want to sit there and wait for it to fire. So if you just say dash ln colon, you'll get all the probes, 64,000 plus. It depends on the OS you're on. We are always adding new ones. We have an army of free VC developers constantly adding new probes. And also there are some dynamically generated probes off of unstable providers, like the function boundary tracer, which we have a function for every function in the kernel. So if you say dash lp syscall, you'll see all the probes under the syscall provider. I've truncated the middle here, but you see it starts off with syscall frebius d32. There's actually two modules here. There's a frebius d32 if you want to watch the 32 bit entries or the 64. But if you want to watch both, just put the colons together and say I want to watch syscall colon colon, whatever it is you're looking for. Just if you want to watch both 32 and 64. Earlier I had mentioned that, for example, like when you get an output and you're not sure what the provider in the module was, you can use that ID. It's not worthless. Ask dtrace to list that by ID. Oh, OK. So that was vfs vop is locked entry. So now the next thing you learn is actions. Because isn't it more useful to actually ask dtrace to emit something more than just that bare bones information? So this looks like that. And you have to be careful is that the probe and the action have to be a single rv element passed to dtrace. And so here, I'm going to mention to you that earlier we weren't passing action. There's a default action. Much like AUK has a default action of printing the line if you don't put any curlies. dtrace, on the other hand, its default action is to print four globals. And you do need the curlies all the time if you're going to what's that statement was actually? The curlies in AUK, for example, if you're familiar with AUK, if you put curlies that are empty, there's no action executed for the line. This is unlike dtrace where the stuff in the curlies is actually augmented, not replacing. So when you ask for additional things in an action bounded by curlies, give it a probe, or multiple probes, similarly by commas, you can ask for these default things plus the things you ask for. There's a dash q flag, which I'm not even going to cover. It's not worth it. It's just 10-second blurb here. Dash q will not print those four globals. And then you have full control over what's printed. But here's all the globals that you don't get that you could ask for. There's a little teaser here. It's like, so yeah, the probe provider, the probe module, the executable name, the time stamp, the wall time stamp, the PID, UID, GID, and recently we added JID, the thread ID, and the best one, per thread, which has everything you would ever want. And so here, let's use an action. So when I hit any sys call, entry or return, print the executable name. So here, again, just a reminder, if I'm not really colored purple and green on your terminal, it's just for you. This is all black text. But here we get detrace, turn server, just co-turn, stuff like that. So we're getting closer to something that's usable. And the previously mentioned dash f, which turns on flow indent, allows you to see an incrementing and decrementing stack. But you only get the function when you turn on dash f. The default action is to print only two globals, cp and function. But here we've given it an action to say, print the thread name. All right, so in zio root, we're going to do a trim. And we're still doing that trim all the way through the list create. So now we have to introduce verbose listing, which, yeah, it's great to be able to ask for some of these globals. But how about some specific information that's actually unique to that probe? How do you know what is available by arguments for the probe? Detrace dash lv in the probe, whether it be function vop is locked, or a full four tuple quad with a dash n. Of course, I've truncated my get-off, because that's what I like to do. And I've given you a little recipe here that, yeah, the output is longer. I really only want to zero in on the args, just so I can fit it all on one side. So vop is locked. Entry has a vnode and this opaque args list. The return, again, has the same vnode, which may have changed, just a minor note. And vop is locked args, opaque. And int, which is probably the return. So cross-reference with the man page. So here I'm going to walk you over the next two slides, actually extracting information from kill to man to kill. So to put this all together, to bring it home, ask detrace what the args are. It tells you that syscall colon freebsd colon kill colon entry, that approach, until you put it together in your mind, gives you an integer for arg0 and an integer for arg1. According to the man page, that's a pit and a signal. And that's kind of cute, too, is that you are now revealed that a pint is an int. And of course an int is an int. So now with an action, just a probe and action, we're going to print the pit and the signal. And so here, I didn't pass dash q, so I get four regular globals and the information I asked for. Pit and signal. Side note, what's a negative pit? A pit grouping. So predicates, aka test conditions. This is your final education on the syntax, which is, it's probe conditionally slash detrace code slash, which is a condition that when is true, will execute the actions. So now the action's only when you want them. So the next step, let's give us ourselves a very simple example. Here, I'm going to watch prop colon colon colon exec, which fires every time a program is executed, whether successfully or not. If the executable name is bash, print the pit that was forked. And now this arguably isn't that very useful, because what am I going to do with a CPU, an ID, a function name, and the word fork and a pit? We're going to watch take this and make it much nicer. So let's review. In detrace, we have a probe type, most commonly dash n. Then in a single RV probe, that's non-negotiable. Optionally test and optionally actions. You do need the curlies, whether you have an action or not, if you're going to do anything more than just probe. So if you put a white space, it will bulk at you. So now, do you watch? It, too, has a mascot. And I'll tell you about it. And I'm not egotistical. It does not solve every single problem. There are some things that D-Watch you don't use it for that you still go to detrace for. And we'll cover that. And then we'll cover probes, actions, and predicates, and profiles, because it does it differently. And profiles is the meat. That's what you want to see. That's why you're here. So this is my mascot for D-Watch. And it's a younger pony corn. And she's got a magnifying glass. And she's looking at detrace. It allows her to see detrace better. And she's got some Sherlock accessories, because she's really into sleuthing out stuff. So today, everything you see me presenting right now, if you have RC1 installed, you have D-Watch. Ready to go. It's out there. And June 22, we're going to have it in 11.2-release. And if you have 12.0 current, that's June 1 or later, you have everything you need to do everything you see in my slides and demos here today. You can even follow along. So what exactly, what precisely is D-Watch? It's a detrace wrapper. It has intelligent probe point selection to make that much easier. You get new globals you can ask for, although most time it just gives it to you. Default action displays are different. It's not just CPU ID function and name. It's much more. And we have profiles for selecting information out of probes to get that specific information that you don't get anywhere else globally. Like, if I'm watching proc, colon, colon, colon, exact, I ought to be able to see specific information about the execution of that process. And of course, I can maybe contentiously integrate pseudo so you don't actually have to use it. And what do we do differently? It's not a single RV for probe, test, and predicate. I separate them. There's a flag for the test, and you can replete it multiple times. There's a flag for the action, and you can have multiple actions. And that is paired up with the probe selector so that you can actually have logic behind the scenes doing much more combined with your custom action. And something that detrays could never, ever think of doing. Dewatch allows you to filter on regex for most everything. And this is a huge advantage. I don't want to see all the events, perhaps. I want to see just the ones matching a particular regex. And the d language is paired down. You can't do regex in d. But if you're smart, you might actually use string char or string string in order to maybe do some of the more basic pattern matching, like fnmatch does. Regex is more powerful than that. So what we do not do well, I don't really do too well. And this is not my fault. It's actually a bug in detrace. It's if detrace is not the foreground running application, a particular feature called aggregations in detrace will not fire when the application exits. So normally a detrace aggregation is to not print information as the probe fires, but to silently collect information in memory. And when I Control-C, dump out either a histogram or a distribution. And that's really, really useful, but it doesn't work unless detrace is the foreground application from my personal testing. Even making it the non-foreground application and emulating a Control-C with a signal 2, it just does not emit the information. So that's one thing I don't do. But I give you a backdoor. There is a backdoor if you really need that. And the value add is that you then see the real time information flowing into the aggregation. And then when you actually exit, you see that information too. So it's not just a black hole sitting there staring you in the face saying nothing. And then Control-C, everything. So that would be an advantage of using D-Watch for an aggregation in this very weird, non-optimal situation. Let's not focus on aggregations then. So probes, notice it's much simpler. I try to make it so that D-Watch, if you don't even want to, I'm sorry, you're going to be forced to learn how detrace works. So if you sit down and spend a day with D-Watch, you're actually 50% of the way to learning detrace. And I make the D-Watch probe type optional. How can I possibly do that? And why would I possibly want to do that? If you sit down and analyze providers, modules, functions and names, and just treat it as a list of words, and then throw away the category, ask yourself how many of those words are unique. 99.95% of all words in detrace as of 11.0-release-p1 were unique. There are only 17 words that overlap to a 0.05%. And I'll show you what they are just for enumeration. There is an overlap between providers and functions. The word FBT is both a provider and a function in the DT malloc provider. The word PROC is both a provider, e.g. PROC colon, colon, colon, colon, or it's a function in DT malloc. I have a very slick algorithm that actually figures out what you most likely meant. And that is to watch the greedy one, watch the one that matches more probes. If you get the wrong one, use the flag to specifically say which one you wanted. So now, DWatch is essentially, I do like, you can give me a four-tuple with three colons or less all day long. I'll take it. But if you give me a single word with no colons, that's the magic. That's only where my algorithm is applied, to intelligently select the PRO for you. There's a little overlap for module and function category. There's only three there, like name I is both a module and the VFS provider and a function in the function boundary tracing provider. And then there's nine in the function name overlap. So the default actions for DWatch are different. You get more info. And talking about that, this is what you get. You get the wall timestamp in four-digit year, three character month, two-digit day, optional leading space, and what is OT? HHMMSS, separated by colons. And that's going to match your date. When you run date, it's going to match exactly. Well, if you were to give it this format. You also get the UID, the GID, the exact name, and the PID, and I plumb curve thread for you. So you don't have to. Oh, that's hundreds of lines of Dtrace to plumb curve thread. It's absolutely disgusting. You want me to do it for you. So now here is an example of a two-word invocation. We saw me using watching VOP create with Dtrace earlier. Now let's watch VOP create with DWatch. That actually is colored green, although that's synthetic, the VFS red and the VOP blue. Yeah, that's synthetic. But yeah, I do have ANSI coloring on my output to separate the date and time from the data. Visual separator. So here we see I'm actually UID 604. That's me. I'm doing the touch. I say touch foo and touch bar. And VOP create catches it. Although we'll see a better invocation that actually tells you what was touched, the full VFS path. And that'll be when we get to profiles. But right now, let's keep looking at the default actions. You've seen the default action with just a probe. Adding dash f, which would normally turn on flow indent and Dtrace, is a simulation that emits the precise probe for tuple that you can copy and paste should you want to zero in and dive deeper and only zero in on that one probe. And that looks like this. The one thing you don't get, though, is you don't actually get space indentation for a stack. It's just going to tell you, oh, I'm entering proc kernel constructor. I'm leaving proc kernel constructor. I'm now in proc kernel none create. I said, and this is cool. A dash capital R will enable a miniature process tree. So here I've said watch exec ve so that I can watch processes being executed in real time. So this SSHD for the first block, there's two blocks on the screen right here. The first block is an SSHD, PID 18434, just exec ve bash, which has actually the parent process of SSHD, which has another parent process of SSHD, which has a parent process of the master SSHD accepting incoming connections on part 22. And then the next block is, of course, me running you name inside that forked bash, that exec bash. I don't print out all the globals that Dtrace has either. You don't get CPU ID, TID, or JID for my default action. But you can ask for it. And now it's actions and predicates for Dwatch. Actions are actually put into dash capital E, and tests are put into dash T. And they can be specified multiple times. So here we're going to say, when I hit kill, I'm going to like before, but using Dwatch this time, print the PID and signal. This is not the final end goal. This gets easier too. Dash T example would be watch exec ve where the caller is bash. Now I'm hinting at the new globals. Yeah, caller exec name is one of those. So now we get to the best part about all of this, profiles. It's a way of having a canned solution in Dtrace. Right at once, never look back. But you can override the action, and you can override the test, and you can override the probe. The profile is the logic for collecting the information. You can ask for what's displayed. There is a default for what's displayed, for each profile. So it's really the automation process. That a profile for Dwatch means you don't have to know the probe, which it can watch a probe profile, and watch multiple probes. You don't have to know how to collect the data into clause, thread, or whatever globals. Clause locals, self locals, or globals. I'm using terminology that Dtrace people will pick up on. But I can educate later. We just don't have the time for that. There are 81 profiles in Dwatch, and I'll show you what those focus on. 11 of those are for PROC. And that's holistic. That's whole. That's everything you need. That's all that the provider gives you. Actually, there's some constructor-destructor ones I haven't done yet. I actually have to be educated on those, because those aren't in the man page. So what I essentially did was I said ls slash user slash share slash man slash man four slash dtrace star. And there are man pages for Dtrace probes. dtrace proc, dtrace underscore proc. If you say man dtrace underscore proc, you'll actually get a description of each probe, what arguments it has, and what you can expect inside those structs that you've passed. I have 18 profiles for watching syscalls. I have 22 for watching networking, which covers IP, UDP, and TCP. I have nine for watching the VFS layer. I have 18 for watching the CPU scheduler. I really wanted to spend a lot of time on those, because people have been saying that FreeBSD's scheduler needs some improvements. I'm like, all right, let me give you some observability. Let's test those theories of yours. There are three profiles for disk.io. And now at 81 profiles, let's get a little unwieldy, so I've given you a way of searching for them. So dash q, r, this can take regex, show me all of the profiles where I can watch a VFS operation. And that previous example, which I promise would get better, has gotten better. dwatch dash x kill to run the kill profile. There's all the information you needed. You do not have to provide an action. You do not have to provide the probe. You do not have to provide anything. Just give me the name of the can solution. Now here we could say, I want the can solution for open, which dwatch, the first three lines you'll see here are informational, tells you I'm sourcing the profile called open. I found it in userlibexecdwatch. The probe that it wants to watch is syscall colon colon open colon entry and syscall colon colon open at colon entry. When either one of those is fired and the program name is not send mail, because I happen to have been getting a lot of noise from send mail when I was watching open at the time when I was making the slide, I said, let's ignore send mail. Show me all the opens that are not send mail. There it is. And we see the path that was opened. So here, let's look at the up lookup. I'm no longer just getting random globals from hitting that probe. The profile actually knows how to extract the path from the V node argument without a transitive pass through name i. If you want a lesson in how to walk a V node, come talk to me after this. Oh, and of course, let's apply some rejects to that. So I only get events where the path had slash through slash in it. And it does actually anti-highlight it for you too on the command line. If you don't want that anti-highlighting, you can always turn it off by piping it into cat or making it look like standard out is not terminal. So let's talk about ports. I have two ports. The first one, I'm not really sure I should have done. The second one is really, really useful for, I think, everybody. You can visualize your process counting. You can visualize system calls. You can visualize the file system access in real time and networking in real time. And installing those ports gives you more profiles. That's why I said 81 plus, because if you install some ports, you've got more than 81, which is the count in base. So I'm going to give you a demo. And this slide is left blank, so I can give you a demo. Gorse is a software that you can install with brew. You execute brew install gorse. Then once that's installed, you have gorse. Gorse itself is not useful unless you feed it. So you can install it with brew. You can install it with brew. And you can install it with brew. And you can install it with brew. Gorse itself is not useful unless you feed it. To feed it, you need to give it either a version control log, which is its modus operandi. That's how it wants to be used. I'm not using it for what it wants to be used for. It usually is used for, like, say, I don't know, the 20-year anniversary video that I made. As a reminder, this video, which we played at the 20th anniversary party in DNALounge in San Francisco, so this is Gorse's normal use case. Take a version control log from Subversion, Git, Mercurial, Perforce, whatever, and render the users committing on the tree. I'm going to use it to render process accounting information. So the first thing you need to do is, well, you've gone to a system and installed the port. So I have all of them installed. That 1.4 dWatch is, ignore that, dWatch is in head now, in base, and 11. So I have additional profiles, but I actually made it super, super easy to do these renderings because I have a hard time getting Gorse to run in X11 on the FreeBSD box. So I actually SSH into the box, remotely start detrace, which funnels all the information back to my Mac into Gorse. I can also just stash the log, copy it over later, and do the rendering that way. But I'm going to show you to you in real time, because that's more effective. There's a tool called GWatch installed by this port. We're going to SCP that back to the Mac. It has a syntax where you can see the code, it has a syntax where it wants to take a host, or dash l if you really do have Gorse installed on your FreeBSD box and want to do a local rendering. Not much, without much more ado. Here we are in real time rendering essentially PS, but it's still going in real time. So as I move this aside, I don't even actually have to SSH into it. We have Chef running in this box. So there will be activity maybe during this conference. I mean during this talk. Now bear with me, I have an insanely intense bash profile. So this will kick off a lot. OK, so here's a sleep 20. Oh, wait. Let me turn off my rainbow colors, because that will convolute the graph. There's a bash and it has a sleep. And I can see that it goes kernel in it SSHD bash sleep. And is it about to die? Still there? Any second now? There it goes. Removed. Gone. Dead. Let's have some fun. There's a bunch of sleeps. And after 10 seconds they will die. We'll have a funeral for them. OK, so this is process accounting. It too has a dash Q. And it's telling me you can say net proc VFS open or syscall. And that's querying the remote machine for which profiles are installed on it. That matched course. This is system calls in real time. So the application, you can see which system calls an application is using. I can filter on this information to see which is on this information to say I only want to see SSHD or I only want to see two system calls, M map and M unmap. The possibilities are limitless. Networking is fun. Isn't it? Isn't that just general statement? Networking is fun. I have three connections. OK, so we have one connection from my laptop on TCP with a client port of 50429. The endpoint of course is 22. This SSHD is firing detrace data at me for the visualization. There was a host. Let me pause it. Let me zoom in. What is that? That's a SSHD host. I can hit tab, NTPD. All right, let me resume. OK, zoom back out. This is interactive. You can do debugging with this. So now, this is when I learned something very scary. I learned that W actually hits my DNS server to look up an address. An address is PTR record. And so I was like, what is W doing here? So I was quite shocked to find out that it was actually doing any UDP traffic at all. So now, this is actually now my favorite tool for testing UDP traffic. All right, there's my mouse. Control C. OK. It'll take a while for them to queues. We're getting to a point, though, where I will visualize every protocol family. And right now, the visualizer actually has UDP and TCP. Ultimately, I would like to also add SETP. And if we invent more protocol families, I'd like to get those in there, too, because I like having multi-family visualizations. You should make something that starts the wire chart XMLs. They've looked at all the protocols predefined. I really like doing it in base, though. Like, write out the box. And be like, OK, even on boot with no packages installed. It'd be cool. Why don't TCP dump it in base, right? Yeah. All right, they're meandering away. And the visualizer will catch up and become performant again. There it goes. Yeah, OK. There it goes. The VFS one is nice. I have some fun things I can do here, too. Like run find. So these are all the files that are being touched just by me logging into the box. That includes libraries, binaries, files that are just straight up opened. Fine. Let's see. Don't kill the system. I created a subdirectory structure in slash temp with a billion subdirectories. Yeah, my rendering was going for a while. It was like hours. So I'm not going to do it on slash temp. So there's everything in var log. Let me just pause that so it stays up there for a while. So like there's lib ruby, which is in user local lib. There's ntdb, which has that path. libmap.d. All these are file systems that were touched in some way. Now I'm watching actually multiple probes. And dwatch tells me what it's watching. Oh, actually, this one's just vlcreate. Is it? No, that's the profile name. What am I? There's the list of probes. I'm watching create, lookup, makedir, makenod, remove, and rmdir, and some link. Let's see. Back to slides. So I've actually got some videos. Yeah, the live demos are fun. But when you can package your demonstration for an audience, that's so much more fun, I think. So this is the one that I want to show you. At the end, you're going to get a link to my slides. You can watch the rest. So I'm going to go ahead and do a quick demo. At the end, you're going to get a link to my slides. You can watch the rest. Let me pause that for a second. What are we looking at here? My visualizer and detrace code is so spot on, I can run it during a build world and capture the entire build world and play it as a movie. And then repeat the same process with the dash j8. And then in iMovie, put the videos together, time sync them so that they start and end at the same amount of time, which is three minutes and 37 seconds. So I've actually radically compressed the video because a build world is ours. Run them side by side to see how they actually compare. Now you'll notice in the top left, we have a key. Let me stop moving the mouse so that those accoutrements go away. Yes, OK. There are 400 C++ invocations. Not concurrently. The visualizer has a three second delta from when a node appears to when it actually kills it. So to its mind, it thinks that there are 400 C++ instances. It's more serial than that. What we find is that the single threaded and the multi threaded build world actually is largely the same for a good chunk of the time. And that's due to cleaning obstacles at the beginning. And so now let me fast forward here. And we're going to see a few more examples. Let's see a huge divergence. The bottom is still ramping up. And here it goes. 10,000, 15,000, 20,000, 29,000 shell instances, incomparably some number of makes and some children. The top one only got up to about 12,000. And it's not on linear scale. You may say dash j8, but you're not going to get an eight times multiplier because there are limits to your CPU setup, your hardware, context switching, and all sorts of complexity. And at the very end, here's the breakdown. The single threaded build world ran in four hours and 40 minutes. The dash j8 multi threaded build finished in one hour and four minutes. It definitely was more intense. There are eight branch points right in here doing the same work you see off here, this node here. Right, so visualizations are very powerful for understanding what your system is doing and what's going on. I'm going to go back to slides. Is it here? Yes. All right. And I have to give a lot of thanks. The mascot was actually written by my spouse, drawn by my spouse by hand. And then I said, hey, let's vectorize that to the Twitter community. And within seconds, somebody was like, hey, let's run this through dimensions or whatever it was, some path tracing program. And we got a really nice vectorized mascot. And then, of course, all this stuff you're seeing here spent 364 days in fabricator. I rewrote it three times. And that 364 days in fabricator was preceded by four years of development. And it was reviewed by George Newell-Neal, Mark J, and B Drury. And I have to thank everybody here, because I know you're going to use it. And I have to thank you all for sitting here. And so we have a questions segment. And while I have this slide up, feel free to take down that URL. The underlined portion is really the better minimum you need to get to the slides. You can navigate the rest of your way. It's just a directory listing. So do I have any questions? I'll take that as a sign. Yes. Yes. So the dash Q is quiet. Capital Q? One of the Qs was to filter out it. Detrace or de-watch? Well, potentially both. But looking at de-watch, can one follow a PXE negotiation filter out the giant turd of payload and actually watch just these important stuff? Absolutely. So if you wanted to watch TFTP from a network point of view, you would do this. It's TCP, right? Yeah. No, wait. Let me just get right. It's both? No. It's all telekinesis. Due to this back, right. Right. My profile for watching UDP traffic stashes all the information that you need into clause local variables, which are accessible to a predicate. So here, if I say, now I'm not going to use TFTP because I have no way of making it fire on this box, I'll watch something I can see. DNS. Right. DNS. OK. So here, we have SSHD port 22. Port 22? Nope. That's a 53. There you go. 53. There's your 53. And 140 bytes. 53 bytes out. 140 bytes back. 53, 53. OK. It would be a really nice fact to actually see more than that. I'm not sure what I would do. Because when I put a clause of showing me DNS, it's just going to show me exactly what we just had. So it should essentially just be a no op. No. R port. 53. Our favorite animal. W. So here we are. That's no other port, but remote port 53. What was the, what was it? Did you expect the PST notation? 69. Yeah, so 69 would be your answer. I'll just leave that up on the screen for a little bit. If anybody wants to take a note for themselves. Any other, more questions? If you don't ask questions, I'm going to assume you're all experts now. So we'll have a hallway track where we're just totally expert talking about detrace, right? Question? No, sorry. It's not you. I knew it. Just felt like so. It's a part of what's going to take a while to do. Yeah, no worries. We're not done yet. So if we don't have enough questions to fill out our time slot, which is still four minutes, I can't believe I did 97. Well, there's a couple more slides. I didn't think I was going to get this far. I get this question a lot. How is detrace doing against its competitors? Completely subjective. My opinion alone, every time something notable has happened in any one of the camps, I'm going to bump that y value up on a graph. Now I'm going to layer them. Let's just see what happens. If we can say this is maturity, then detrace is much more mature than the other technologies. And so I've just made some callouts here. Having a book, being ported to a new OS, having a new tool written against it, which is holistically making its underpinnings easier, like DeWatch. Look at detrace in the back. Ftrace is pretty old in Linux. SystemTap is getting to be kind of old. EBPF didn't make the graph. It's still, I think, kind of nascent for me, because I don't have enough ability to play with it in production. And I'm kind of limited to production. I have Sentos 7.5 at work. We don't take 4As into head or anything like that in Linux LAN. I do that in FreeBSD all the time, though. That's the next talk, isn't it? Yeah. And this is the last slide. I've done many things in FreeBSD. I'm kind of proud of this one. Gandhi.net is who's an internet domain registrar. Made this logo as a mashup. They made many mashups, but they did a FreeBSD mashup. And they mentioned on Twitter that they use FreeBSD a lot. And so I thought I'd return the favor. And so I made them a boot ASCII art. And it's still in use today. And people that work there have no idea I made it. And so that's my talk. Thank you guys so much. Thank you.
 Alright, okay. So today we're going to talk about three things, there's three sections  to my talk. So we're going to talk about detrace. That's kind of important because  my tool, my new tool that I'm going to introduce today which took five years to write, not  just off and on, five years to write, and I actually am building ports off of it now.  So dWatch is going to make your life easier if you want to use detrace. And we have ports  which will give you additional functionality which is just amazing. So let's get into it.  So on the topic of detrace I'm going to, most importantly, it's got a mascot. What  can it do? A brief history and then we're going to get right into the thick of using  detrace. So this is the mascot. It's, detrace solves so many problems, it's like getting  a pony and a unicorn. And well, you can do flame graphs. This is what most people think  of when they think of detrace. But I'm going to show you, you can do more. So we have a  Gorse visualization. Gorse is a visualizer written by Andrew Caldwell. It's open source.  It's a GitHub and it takes version control logs or a custom log format which I'm abusing  in order to do much more than just version control logs. And it's wonderful. You'll get  a live demo. We can trap arguments, syscalls and functions and do so much more with detrace.  And of course we can snoop on all the things, even our slides. For those who don't know,  famous rapper. So, Solaris 10 is when detrace was born. You know, we were not the first  to adopt it. We did not invent it and we will not be the last to adopt it. Right there in  the middle, 2009. FreeBSD 7.1. I think everybody in this room has at least one freeBSD system  that has detrace installed in the base, ready to go. Unless you like running things older  than 7.1. And the co-creator of detrace has these little bullet points to share. It has  its own language. It's a subset of C. And it's kind of Oc-like. It has a micro virtual  machine. Code is actually compiled. The D language is compiled. And it has a conservative  pro point selection. And in the next slide you're going to see what conservative means.  Essentially it means you have to be explicit. You have to tell it what you want. It won't  figure it out for you. So, before you use detrace, you have to know what a probe is.  That's the most important thing about detrace. What is a probe? And this is the simplest  detrace syntax you can possibly use that actually produces meaningful results. Arguably,  meaningful is interpreted differently. It's not until you get into an intermediate, an  advanced, and expert detrace syntax, which still we are in the realm of a one-liner.  We haven't even gone into writing a script yet that I have to kind of break you in. So  a probe is a column separated to string. And it represents a kernel or a userland point  to trace. You can trace one, more, or any number. And so it's separated by the provider,  the module, the function, and the name. Providers are the top level. Providers provide modules.  Modules provide functions and functions provide names. It's not always the case. Sometimes  you have a provider that doesn't actually have any submodules or functions, just names.  But at the top level, it's all providers. There's 26. Get to know them. So now we have  detrace-n of valid probe. This valid probe says, watch all of the VFS create events.  Now, arguably, you don't get much information. This is almost practically worthless, this  very basic syntax. All you get is you get the CPU that the probe fires on, the ID, which  is shorthand. So notice that you only get the function and the name. If you want the  provider and module, you can use the ID. You can say detrace-li, the ID, and it will show  you the exact full probe. And if you break it down, there is actually a couple probes  that you can use to say all probes. And that is colon or colon, colon, colon, colon. Now,  I'm doing something in these slides that you might want to key in on, which is that every  time something is a provider, it's red, every time something is a module, it's blue, and  every time something is a function, it's green, and every time it's a name, it's purple. So  not every output is colorized in the way that you see it on my slides. I'm trying to help  you parse these walls of text. And within a probe, you can actually just omit an entry  between colons to say wildcard. I want all of those things. So this first example would  be I want all of the VFS VUP creates. Well, that's only one. So this is really just like  shorthand because I'm too lazy to type VUP. And you can say star. But you probably don't  want to say star if you are only putting a star because then you have to quote it because  what if your shell finds a file name matching that pattern and expands it? You can also  put the star anywhere in there to mean all attributes, all reads, all writes, whatever.  So here's that in use. Show me all of the functions in the VFS provider as I enter them.  I want to see what functions I'm hitting. Again, this is arguably not really that helpful  because all I'm getting is a CPU that the probe fires on, the ID of the probe, the function  name, and the entry. But we're getting closer to something usable. And now an example on  multiple probes, you just separate them with comma. So not only can you have wildcards,  patterns, you can have multiple probes that select different things separated by commas.  And so the very bottom one there, if I say VFS colon, colon, colon, comma, says colon,  colon, why would I do that? I want to see the VFS and the SysCalls interleaved. That's  2324 probes. So that's what this looks like. So now the first one, I octal, that's a SysCall.  Lookup. That's a VFS. VOPLookup. Lock 1, that's in the VFS provider and I octal, of course,  is a SysCall. So here you can actually see how they fire in order. Which is nice. Although  Pay attention to the CPU.  OK, so the next thing I break you into is there's not just  dash n.  Almost every one liner you find on the internet is going  to have dash n probe.  You don't have to limit yourself to dash n probe and a  four tuple separated by three colons.  You can actually have what it allows is three tuples and  less.  Imagine only specifying two colons.  Imagine not having any colons.  Wouldn't that be nice?  Detrace allows it.  So if you say traditionally dash n name, it will take a  four tuple, but it will also take a name.  Dash n tick is actually equivalent to dash n colon  colon colon tick.  Dash n colon colon colon create comma on CPU.  It knows that the first one is fully qualified.  The last one is not.  And so internally, it will translate this to prop colon  colon colon create comma colon colon colon on CPU.  There's other examples, like if you want to watch the  function named log, dash f log is synonymous with dash n  colon colon log colon that selector.  There's dash m for watching a whole module.  There's dash p for watching a whole provider.  So if I want to watch all of the ZFS functions, just cart  launch, and I don't care what the provider is.  Here it is.  Dash m ZFS.  Synonymous.  CPU ID function and name.  So some good functions here.  Arc available memory, none.  Arc adjust, multi list, get random index, SPA, get random.  Good stuff.  So then you might be interested to then ask detrace to show  you the probes, because maybe you don't want to sit there  and wait for it to fire.  So if you just say dash ln colon, you'll get all the probes,  64,000 plus.  It depends on the OS you're on.  We are always adding new ones.  We have an army of free VC developers  constantly adding new probes.  And also there are some dynamically generated probes  off of unstable providers, like the function boundary tracer,  which we have a function for every function in the kernel.  So if you say dash lp syscall, you'll see all the probes  under the syscall provider.  I've truncated the middle here, but you see it starts off  with syscall frebius d32.  There's actually two modules here.  There's a frebius d32 if you want to watch the 32 bit  entries or the 64.  But if you want to watch both, just put the colons together  and say I want to watch syscall colon colon, whatever it is  you're looking for.  Just if you want to watch both 32 and 64.  Earlier I had mentioned that, for example,  like when you get an output and you're not sure what the provider  in the module was, you can use that ID.  It's not worthless.  Ask dtrace to list that by ID.  Oh, OK.  So that was vfs vop is locked entry.  So now the next thing you learn is actions.  Because isn't it more useful to actually ask dtrace to emit  something more than just that bare bones information?  So this looks like that.  And you have to be careful is that the probe and the action  have to be a single rv element passed to dtrace.  And so here, I'm going to mention to you that earlier we  weren't passing action.  There's a default action.  Much like AUK has a default action of printing the line  if you don't put any curlies.  dtrace, on the other hand, its default action is to print  four globals.  And you do need the curlies all the time if you're going to  what's that statement was actually?  The curlies in AUK, for example, if you're familiar with AUK,  if you put curlies that are empty, there's no action  executed for the line.  This is unlike dtrace where the stuff in the curlies is  actually augmented, not replacing.  So when you ask for additional things in an action  bounded by curlies, give it a probe, or multiple probes,  similarly by commas, you can ask for these default things  plus the things you ask for.  There's a dash q flag, which I'm not even going to cover.  It's not worth it.  It's just 10-second blurb here.  Dash q will not print those four globals.  And then you have full control over what's printed.  But here's all the globals that you don't get that you could  ask for.  There's a little teaser here.  It's like, so yeah, the probe provider, the probe module,  the executable name, the time stamp, the wall time stamp,  the PID, UID, GID, and recently we added JID, the  thread ID, and the best one, per thread, which has  everything you would ever want.  And so here, let's use an action.  So when I hit any sys call, entry or return, print the  executable name.  So here, again, just a reminder, if I'm not really  colored purple and green on your terminal, it's just for  you.  This is all black text.  But here we get detrace, turn server, just co-turn, stuff  like that.  So we're getting closer to something that's usable.  And the previously mentioned dash f, which turns on flow  indent, allows you to see an incrementing and  decrementing stack.  But you only get the function when you turn on dash f.  The default action is to print only two globals, cp  and function.  But here we've given it an action to say, print the  thread name.  All right, so in zio root, we're going to do a trim.  And we're still doing that trim all the way through the  list create.  So now we have to introduce verbose listing, which, yeah,  it's great to be able to ask for some of these globals.  But how about some specific information that's actually  unique to that probe?  How do you know what is available by arguments for  the probe?  Detrace dash lv in the probe, whether it be function vop  is locked, or a full four tuple quad with a dash n.  Of course, I've truncated my get-off, because that's what  I like to do.  And I've given you a little recipe here that, yeah, the  output is longer.  I really only want to zero in on the args, just so I can  fit it all on one side.  So vop is locked.  Entry has a vnode and this opaque args list.  The return, again, has the same vnode, which may have  changed, just a minor note.  And vop is locked args, opaque.  And int, which is probably the return.  So cross-reference with the man page.  So here I'm going to walk you over the next two slides,  actually extracting information from kill to man to kill.  So to put this all together, to bring it home, ask  detrace what the args are.  It tells you that syscall colon freebsd colon kill colon  entry, that approach, until you put it together in your mind,  gives you an integer for arg0 and an integer for arg1.  According to the man page, that's a pit and a signal.  And that's kind of cute, too, is that you are now revealed  that a pint is an int.  And of course an int is an int.  So now with an action, just a probe and action, we're going  to print the pit and the signal.  And so here, I didn't pass dash q, so I get four regular  globals and the information I asked for.  Pit and signal.  Side note, what's a negative pit?  A pit grouping.  So predicates, aka test conditions.  This is your final education on the syntax, which is, it's  probe conditionally slash detrace code slash, which is a  condition that when is true, will execute the actions.  So now the action's only when you want them.  So the next step, let's give us ourselves a very  simple example.  Here, I'm going to watch prop colon colon colon exec, which  fires every time a program is executed, whether  successfully or not.  If the executable name is bash, print the pit that was  forked.  And now this arguably isn't that very useful, because what  am I going to do with a CPU, an ID, a function name, and the  word fork and a pit?  We're going to watch take this and make it much nicer.  So let's review.  In detrace, we have a probe type, most commonly dash n.  Then in a single RV probe, that's non-negotiable.  Optionally test and optionally actions.  You do need the curlies, whether you have an action or  not, if you're going to do anything more than just probe.  So if you put a white space, it will bulk at you.  So now, do you watch?  It, too, has a mascot.  And I'll tell you about it.  And I'm not egotistical.  It does not solve every single problem.  There are some things that D-Watch you don't use it for  that you still go to detrace for.  And we'll cover that.  And then we'll cover probes, actions, and predicates, and  profiles, because it does it differently.  And profiles is the meat.  That's what you want to see.  That's why you're here.  So this is my mascot for D-Watch.  And it's a younger pony corn.  And she's got a magnifying glass.  And she's looking at detrace.  It allows her to see detrace better.  And she's got some Sherlock accessories, because she's  really into sleuthing out stuff.  So today, everything you see me presenting right now, if you  have RC1 installed, you have D-Watch.  Ready to go.  It's out there.  And June 22, we're going to have it in 11.2-release.  And if you have 12.0 current, that's June 1 or later, you  have everything you need to do everything you see in my  slides and demos here today.  You can even follow along.  So what exactly, what precisely is D-Watch?  It's a detrace wrapper.  It has intelligent probe point selection to make that much  easier.  You get new globals you can ask for, although most time it  just gives it to you.  Default action displays are different.  It's not just CPU ID function and name.  It's much more.  And we have profiles for selecting information out of  probes to get that specific information that you don't get  anywhere else globally.  Like, if I'm watching proc, colon, colon, colon, exact, I  ought to be able to see specific information about the  execution of that process.  And of course, I can maybe contentiously integrate  pseudo so you don't actually have to use it.  And what do we do differently?  It's not a single RV for probe, test, and predicate.  I separate them.  There's a flag for the test, and you can  replete it multiple times.  There's a flag for the action, and you can have multiple  actions.  And that is paired up with the probe selector so that you can  actually have logic behind the scenes doing much more  combined with your custom action.  And something that detrays could never, ever think of  doing.  Dewatch allows you to filter on regex for most everything.  And this is a huge advantage.  I don't want to see all the events, perhaps.  I want to see just the ones matching a  particular regex.  And the d language is paired down.  You can't do regex in d.  But if you're smart, you might actually use string char or  string string in order to maybe do some of the more basic  pattern matching, like fnmatch does.  Regex is more powerful than that.  So what we do not do well, I don't really do too well.  And this is not my fault.  It's actually a bug in detrace.  It's if detrace is not the foreground running application,  a particular feature called aggregations in detrace will  not fire when the application exits.  So normally a detrace aggregation is to not print  information as the probe fires, but to silently collect  information in memory.  And when I Control-C, dump out either a histogram or a  distribution.  And that's really, really useful, but it doesn't work  unless detrace is the foreground application from my  personal testing.  Even making it the non-foreground application and  emulating a Control-C with a signal 2, it just does not  emit the information.  So that's one thing I don't do.  But I give you a backdoor.  There is a backdoor if you really need that.  And the value add is that you then see the real time  information flowing into the aggregation.  And then when you actually exit, you see that  information too.  So it's not just a black hole sitting there staring you in  the face saying nothing.  And then Control-C, everything.  So that would be an advantage of using D-Watch for an  aggregation in this very weird, non-optimal situation.  Let's not focus on aggregations then.  So probes, notice it's much simpler.  I try to make it so that D-Watch, if you don't even  want to, I'm sorry, you're going to be forced to learn  how detrace works.  So if you sit down and spend a day with D-Watch, you're  actually 50% of the way to learning detrace.  And I make the D-Watch probe type optional.  How can I possibly do that?  And why would I possibly want to do that?  If you sit down and analyze providers, modules, functions  and names, and just treat it as a list of words, and then  throw away the category, ask yourself how many of those  words are unique.  99.95% of all words in detrace as of 11.0-release-p1  were unique.  There are only 17 words that overlap to a 0.05%.  And I'll show you what they are just for enumeration.  There is an overlap between providers and functions.  The word FBT is both a provider and a function in the  DT malloc provider.  The word PROC is both a provider, e.g. PROC colon,  colon, colon, colon, or it's a function in DT malloc.  I have a very slick algorithm that actually figures out  what you most likely meant.  And that is to watch the greedy one, watch the one that  matches more probes.  If you get the wrong one, use the flag to specifically say  which one you wanted.  So now, DWatch is essentially, I do like, you can give me a  four-tuple with three colons or less all day long.  I'll take it.  But if you give me a single word with no colons, that's the  magic.  That's only where my algorithm is applied, to  intelligently select the PRO for you.  There's a little overlap for module and function category.  There's only three there, like name I is both a module and  the VFS provider and a function in the function boundary  tracing provider.  And then there's nine in the function name overlap.  So the default actions for DWatch are different.  You get more info.  And talking about that, this is what you get.  You get the wall timestamp in four-digit year, three  character month, two-digit day, optional leading space, and  what is OT?  HHMMSS, separated by colons.  And that's going to match your date.  When you run date, it's going to match exactly.  Well, if you were to give it this format.  You also get the UID, the GID, the exact name, and the  PID, and I plumb curve thread for you.  So you don't have to.  Oh, that's hundreds of lines of Dtrace to plumb curve  thread.  It's absolutely disgusting.  You want me to do it for you.  So now here is an example of a two-word invocation.  We saw me using watching VOP create with Dtrace earlier.  Now let's watch VOP create with DWatch.  That actually is colored green, although that's  synthetic, the VFS red and the VOP blue.  Yeah, that's synthetic.  But yeah, I do have ANSI coloring on my output to  separate the date and time from the data.  Visual separator.  So here we see I'm actually UID 604.  That's me.  I'm doing the touch.  I say touch foo and touch bar.  And VOP create catches it.  Although we'll see a better invocation that actually  tells you what was touched, the full VFS path.  And that'll be when we get to profiles.  But right now, let's keep looking at the default actions.  You've seen the default action with just a probe.  Adding dash f, which would normally turn on flow indent  and Dtrace, is a simulation that emits the precise probe  for tuple that you can copy and paste should you want to  zero in and dive deeper and only zero in on that one probe.  And that looks like this.  The one thing you don't get, though, is you don't actually  get space indentation for a stack.  It's just going to tell you, oh, I'm entering  proc kernel constructor.  I'm leaving proc kernel constructor.  I'm now in proc kernel none create.  I said, and this is cool.  A dash capital R will enable a miniature process tree.  So here I've said watch exec ve so that I can watch processes  being executed in real time.  So this SSHD for the first block, there's two blocks on  the screen right here.  The first block is an SSHD, PID 18434, just exec ve bash,  which has actually the parent process of SSHD, which has  another parent process of SSHD, which has a parent process  of the master SSHD accepting incoming connections on part  22.  And then the next block is, of course, me running you name  inside that forked bash, that exec bash.  I don't print out all the globals that Dtrace has either.  You don't get CPU ID, TID, or JID for my default action.  But you can ask for it.  And now it's actions and predicates for Dwatch.  Actions are actually put into dash capital E, and tests are  put into dash T. And they can be specified multiple times.  So here we're going to say, when I hit kill, I'm going to  like before, but using Dwatch this time, print the PID and  signal.  This is not the final end goal.  This gets easier too.  Dash T example would be watch exec ve where the  caller is bash.  Now I'm hinting at the new globals.  Yeah, caller exec name is one of those.  So now we get to the best part about all of this, profiles.  It's a way of having a canned solution in Dtrace.  Right at once, never look back.  But you can override the action, and you can override the  test, and you can override the probe.  The profile is the logic for collecting the information.  You can ask for what's displayed.  There is a default for what's displayed, for each profile.  So it's really the automation process.  That a profile for Dwatch means you don't have to know the  probe, which it can watch a probe profile, and watch  multiple probes.  You don't have to know how to collect the data into  clause, thread, or whatever globals.  Clause locals, self locals, or globals.  I'm using terminology that Dtrace people will pick up on.  But I can educate later.  We just don't have the time for that.  There are 81 profiles in Dwatch, and I'll show you what  those focus on.  11 of those are for PROC.  And that's holistic.  That's whole.  That's everything you need.  That's all that the provider gives you.  Actually, there's some constructor-destructor ones I  haven't done yet.  I actually have to be educated on those, because those aren't  in the man page.  So what I essentially did was I said ls slash user slash  share slash man slash man four slash dtrace star.  And there are man pages for Dtrace probes.  dtrace proc, dtrace underscore proc.  If you say man dtrace underscore proc, you'll  actually get a description of each probe, what arguments it  has, and what you can expect inside those  structs that you've passed.  I have 18 profiles for watching syscalls.  I have 22 for watching networking, which covers  IP, UDP, and TCP.  I have nine for watching the VFS layer.  I have 18 for watching the CPU scheduler.  I really wanted to spend a lot of time on those, because  people have been saying that FreeBSD's scheduler needs  some improvements.  I'm like, all right, let me give you some observability.  Let's test those theories of yours.  There are three profiles for disk.io.  And now at 81 profiles, let's get a little unwieldy, so I've  given you a way of searching for them.  So dash q, r, this can take regex, show me all of the  profiles where I can watch a VFS operation.  And that previous example, which I promise would get  better, has gotten better.  dwatch dash x kill to run the kill profile.  There's all the information you needed.  You do not have to provide an action.  You do not have to provide the probe.  You do not have to provide anything.  Just give me the name of the can solution.  Now here we could say, I want the can solution for open,  which dwatch, the first three lines you'll see here are  informational, tells you I'm sourcing the profile called  open.  I found it in userlibexecdwatch.  The probe that it wants to watch is syscall colon colon  open colon entry and syscall colon colon open at colon  entry.  When either one of those is fired and the program name is  not send mail, because I happen to have been getting a  lot of noise from send mail when I was watching open at the  time when I was making the slide, I said, let's ignore  send mail.  Show me all the opens that are not send mail.  There it is.  And we see the path that was opened.  So here, let's look at the up lookup.  I'm no longer just getting random globals from  hitting that probe.  The profile actually knows how to extract the path from the  V node argument without a transitive pass through name i.  If you want a lesson in how to walk a V node, come talk to  me after this.  Oh, and of course, let's apply some rejects to that.  So I only get events where the path had slash  through slash in it.  And it does actually anti-highlight it for you  too on the command line.  If you don't want that anti-highlighting, you can  always turn it off by piping it into cat or making it look  like standard out is not terminal.  So let's talk about ports.  I have two ports.  The first one, I'm not really sure I should have done.  The second one is really, really useful for, I think,  everybody.  You can visualize your process counting.  You can visualize system calls.  You can visualize the file system access in real time and  networking in real time.  And installing those ports gives you more profiles.  That's why I said 81 plus, because if you install some  ports, you've got more than 81, which is the count in base.  So I'm going to give you a demo.  And this slide is left blank, so I can give you a demo.  Gorse is a software that you can install with brew.  You execute brew install gorse.  Then once that's installed, you have gorse.  Gorse itself is not useful unless you feed it.  So you can install it with brew.  You can install it with brew.  And you can install it with brew.  And you can install it with brew.  Gorse itself is not useful unless you feed it.  To feed it, you need to give it either a version control log,  which is its modus operandi.  That's how it wants to be used.  I'm not using it for what it wants to be used for.  It usually is used for, like, say, I don't know, the 20-year  anniversary video that I made.  As a reminder, this video, which we played at the 20th  anniversary party in DNALounge in San Francisco, so this is  Gorse's normal use case.  Take a version control log from Subversion, Git, Mercurial,  Perforce, whatever, and render the users  committing on the tree.  I'm going to use it to render process accounting  information.  So the first thing you need to do is, well, you've gone to a  system and installed the port.  So I have all of them installed.  That 1.4 dWatch is, ignore that, dWatch is in head now, in  base, and 11.  So I have additional profiles, but I actually made it super,  super easy to do these renderings because I have a  hard time getting Gorse to run in X11 on the FreeBSD box.  So I actually SSH into the box, remotely start detrace, which  funnels all the information back to my Mac into Gorse.  I can also just stash the log, copy it over later, and do the  rendering that way.  But I'm going to show you to you in real time, because  that's more effective.  There's a tool called GWatch installed by this port.  We're going to SCP that back to the Mac.  It has a syntax where you can see the  code, it has a syntax where it wants to take a host, or dash  l if you really do have Gorse installed on your FreeBSD  box and want to do a local rendering.  Not much, without much more ado.  Here we are in real time rendering essentially PS, but  it's still going in real time.  So as I move this aside, I don't even actually have to SSH  into it.  We have Chef running in this box.  So there will be activity maybe during this conference.  I mean during this talk.  Now bear with me, I have an insanely intense bash profile.  So this will kick off a lot.  OK, so here's a sleep 20.  Oh, wait.  Let me turn off my rainbow colors, because that will  convolute the graph.  There's a bash and it has a sleep.  And I can see that it goes kernel in it SSHD bash sleep.  And is it about to die?  Still there?  Any second now?  There it goes.  Removed.  Gone.  Dead.  Let's have some fun.  There's a bunch of sleeps.  And after 10 seconds they will die.  We'll have a funeral for them.  OK, so this is process accounting.  It too has a dash Q. And it's telling me  you can say net proc VFS open or syscall.  And that's querying the remote machine for which profiles  are installed on it.  That matched course.  This is system calls in real time.  So the application, you can see which system calls  an application is using.  I can filter on this information to see which  is on this information to say I only want to see SSHD  or I only want to see two system calls,  M map and M unmap.  The possibilities are limitless.  Networking is fun.  Isn't it?  Isn't that just general statement?  Networking is fun.  I have three connections.  OK, so we have one connection from my laptop on TCP  with a client port of 50429.  The endpoint of course is 22.  This SSHD is firing detrace data at me for the visualization.  There was a host.  Let me pause it.  Let me zoom in.  What is that?  That's a SSHD host.  I can hit tab, NTPD.  All right, let me resume.  OK, zoom back out.  This is interactive.  You can do debugging with this.  So now, this is when I learned something very scary.  I learned that W actually hits my DNS server  to look up an address.  An address is PTR record.  And so I was like, what is W doing here?  So I was quite shocked to find out  that it was actually doing any UDP traffic at all.  So now, this is actually now my favorite tool  for testing UDP traffic.  All right, there's my mouse.  Control C. OK.  It'll take a while for them to queues.  We're getting to a point, though,  where I will visualize every protocol family.  And right now, the visualizer actually has UDP and TCP.  Ultimately, I would like to also add SETP.  And if we invent more protocol families,  I'd like to get those in there, too,  because I like having multi-family visualizations.  You should make something that starts the wire  chart XMLs.  They've looked at all the protocols predefined.  I really like doing it in base, though.  Like, write out the box.  And be like, OK, even on boot with no packages installed.  It'd be cool.  Why don't TCP dump it in base, right?  Yeah.  All right, they're meandering away.  And the visualizer will catch up and become performant again.  There it goes.  Yeah, OK.  There it goes.  The VFS one is nice.  I have some fun things I can do here, too.  Like run find.  So these are all the files that are being touched  just by me logging into the box.  That includes libraries, binaries, files that are just  straight up opened.  Fine.  Let's see.  Don't kill the system.  I created a subdirectory structure in slash temp  with a billion subdirectories.  Yeah, my rendering was going for a while.  It was like hours.  So I'm not going to do it on slash temp.  So there's everything in var log.  Let me just pause that so it stays up there for a while.  So like there's lib ruby, which is in user local lib.  There's ntdb, which has that path.  libmap.d.  All these are file systems that were touched in some way.  Now I'm watching actually multiple probes.  And dwatch tells me what it's watching.  Oh, actually, this one's just vlcreate.  Is it?  No, that's the profile name.  What am I?  There's the list of probes.  I'm watching create, lookup, makedir, makenod, remove,  and rmdir, and some link.  Let's see.  Back to slides.  So I've actually got some videos.  Yeah, the live demos are fun.  But when you can package your demonstration for an audience,  that's so much more fun, I think.  So this is the one that I want to show you.  At the end, you're going to get a link to my slides.  You can watch the rest.  So I'm going to go ahead and do a quick demo.  At the end, you're going to get a link to my slides.  You can watch the rest.  Let me pause that for a second.  What are we looking at here?  My visualizer and detrace code is so spot on,  I can run it during a build world  and capture the entire build world and play it as a movie.  And then repeat the same process with the dash j8.  And then in iMovie, put the videos together, time sync them  so that they start and end at the same amount of time, which  is three minutes and 37 seconds.  So I've actually radically compressed the video  because a build world is ours.  Run them side by side to see how they actually compare.  Now you'll notice in the top left, we have a key.  Let me stop moving the mouse so that those accoutrements go away.  Yes, OK.  There are 400 C++ invocations.  Not concurrently.  The visualizer has a three second delta  from when a node appears to when it actually kills it.  So to its mind, it thinks that there are 400 C++ instances.  It's more serial than that.  What we find is that the single threaded and the multi threaded  build world actually is largely the same for a good chunk  of the time.  And that's due to cleaning obstacles at the beginning.  And so now let me fast forward here.  And we're going to see a few more examples.  Let's see a huge divergence.  The bottom is still ramping up.  And here it goes.  10,000, 15,000, 20,000, 29,000 shell instances,  incomparably some number of makes and some children.  The top one only got up to about 12,000.  And it's not on linear scale.  You may say dash j8, but you're not  going to get an eight times multiplier because there  are limits to your CPU setup, your hardware, context  switching, and all sorts of complexity.  And at the very end, here's the breakdown.  The single threaded build world ran in four hours and 40  minutes.  The dash j8 multi threaded build finished in one hour  and four minutes.  It definitely was more intense.  There are eight branch points right in here doing  the same work you see off here, this node here.  Right, so visualizations are very  powerful for understanding what your system is doing  and what's going on.  I'm going to go back to slides.  Is it here?  Yes.  All right.  And I have to give a lot of thanks.  The mascot was actually written by my spouse,  drawn by my spouse by hand.  And then I said, hey, let's vectorize that to the Twitter  community.  And within seconds, somebody was like, hey, let's run this  through dimensions or whatever it was, some path tracing  program.  And we got a really nice vectorized mascot.  And then, of course, all this stuff you're seeing here  spent 364 days in fabricator.  I rewrote it three times.  And that 364 days in fabricator was preceded by four  years of development.  And it was reviewed by George Newell-Neal, Mark J, and B  Drury.  And I have to thank everybody here, because I know you're  going to use it.  And I have to thank you all for sitting here.  And so we have a questions segment.  And while I have this slide up, feel free to take down that  URL.  The underlined portion is really the better minimum you  need to get to the slides.  You can navigate the rest of your way.  It's just a directory listing.  So do I have any questions?  I'll take that as a sign.  Yes.  Yes.  So the dash Q is quiet.  Capital Q?  One of the Qs was to filter out it.  Detrace or de-watch?  Well, potentially both.  But looking at de-watch, can one follow a PXE negotiation  filter out the giant turd of payload and actually watch just  these important stuff?  Absolutely.  So if you wanted to watch TFTP from a network point of view,  you would do this.  It's TCP, right?  Yeah.  No, wait.  Let me just get right.  It's both?  No.  It's all telekinesis.  Due to this back, right.  Right.  My profile for watching UDP traffic  stashes all the information that you need into clause local  variables, which are accessible to a predicate.  So here, if I say, now I'm not going to use TFTP because I  have no way of making it fire on this box, I'll watch  something I can see.  DNS.  Right.  DNS.  OK.  So here, we have SSHD port 22.  Port 22?  Nope.  That's a 53.  There you go.  53.  There's your 53.  And 140 bytes.  53 bytes out.  140 bytes back.  53, 53.  OK.  It would be a really nice fact to actually see more than  that.  I'm not sure what I would do.  Because when I put a clause of showing me DNS, it's just  going to show me exactly what we just had.  So it should essentially just be a no op.  No.  R port.  53.  Our favorite animal.  W. So here we are.  That's no other port, but remote port 53.  What was the, what was it?  Did you expect the PST notation?  69.  Yeah, so 69 would be your answer.  I'll just leave that up on the screen for a little bit.  If anybody wants to take a note for themselves.  Any other, more questions?  If you don't ask questions, I'm going to assume you're all  experts now.  So we'll have a hallway track where we're just totally  expert talking about detrace, right?  Question?  No, sorry.  It's not you.  I knew it.  Just felt like so.  It's a part of what's going to take a while to do.  Yeah, no worries.  We're not done yet.  So if we don't have enough questions to fill out our time  slot, which is still four minutes, I can't believe I  did 97.  Well, there's a couple more slides.  I didn't think I was going to get this far.  I get this question a lot.  How is detrace doing against its competitors?  Completely subjective.  My opinion alone, every time something notable has happened  in any one of the camps, I'm going to bump that y value up  on a graph.  Now I'm going to layer them.  Let's just see what happens.  If we can say this is maturity, then detrace is much more  mature than the other technologies.  And so I've just made some callouts here.  Having a book, being ported to a new OS, having a new tool  written against it, which is holistically making its  underpinnings easier, like DeWatch.  Look at detrace in the back.  Ftrace is pretty old in Linux.  SystemTap is getting to be kind of old.  EBPF didn't make the graph.  It's still, I think, kind of nascent for me, because I  don't have enough ability to play with it in production.  And I'm kind of limited to production.  I have Sentos 7.5 at work.  We don't take 4As into head or anything like that in Linux  LAN.  I do that in FreeBSD all the time, though.  That's the next talk, isn't it?  Yeah.  And this is the last slide.  I've done many things in FreeBSD.  I'm kind of proud of this one.  Gandhi.net is who's an internet domain registrar.  Made this logo as a mashup.  They made many mashups, but they did a FreeBSD mashup.  And they mentioned on Twitter that they use FreeBSD a lot.  And so I thought I'd return the favor.  And so I made them a boot ASCII art.  And it's still in use today.  And people that work there have no idea I made it.  And so that's my talk.  Thank you guys so much.  Thank you.
Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_0_287.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_288_1595.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_1596_2795.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_2796_2891.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_2892_3503.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_3504_18527.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_18528_24707.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_24708_39755.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_39756_50267.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_50268_51563.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_51564_52799.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_52800_54359.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_54360_54503.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_54504_54803.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_54804_55379.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_55380_55463.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_55464_55655.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_55656_55967.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_55968_59279.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_59280_59459.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_59460_59627.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_59628_60035.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_60036_60131.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_60132_61499.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_61500_62375.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_62376_62471.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_62472_62531.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_62532_62591.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_62592_63875.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_63876_63947.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_63948_64007.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_64008_64151.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_64152_64499.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_64500_65831.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_65832_67583.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_67584_69011.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_69012_69971.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_69972_70115.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_70116_70331.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_70332_70523.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_70524_71219.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_71220_72155.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_72156_72395.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_72396_82307.png Devin_Teske__All_along_the_dwatch_tower_-_BSDCan_2018_xqOl_HY86n8_82308_83501.png