![\"\"](\"http:\/\/dlang.org\/blog\/wp-content\/uploads\/2018\/02\/bug.jpg\")
At one time or another during application development you need to make a decision: does your application work like it should and, if not, what is wrong with it? There are different techniques to help you decide, some of which are logging, tracing, and profiling. How are they different? One way to look at it is like this:<\/p>\n
In this article, we focus on tracing.<\/p>\n
When developing an application, you can use tracing to monitor its characteristics at run time to, for example, estimate its performance or memory consumption. There are several options to do so, and some of them are:<\/p>\n
writef<\/code>, a.k.a. printf<\/code> debugging)<\/li>\n- debuggers (using scripts or remote tracing)<\/li>\n
- OS-specific tracing frameworks (linux {k|u}probes and usdt probes, linux kernel event, performance events in windows etc)<\/li>\n<\/ul>\n
In this article, the following contrived D example is used to help illustrate all three cases. We\u2019ll be focusing on Linux. All example code in this article can be found in the GitHub repository at https:\/\/github.com\/drug007\/tracing_post<\/a>.<\/p>\nforeach(counter; 0..total_cycles)\r\n{\r\n \/\/ randomly generate one of three kinds of event\r\n Event event = cast(Event) uniform(0, 3);\r\n\r\n \/\/ \"perform\" the job and benchmark its CPU execution time\r\n switch (event)\r\n {\r\n case Event.One:\r\n\r\n doSomeWork;\r\n\r\n break;\r\n case Event.Two:\r\n\r\n doSomeWork;\r\n\r\n break;\r\n case Event.Three:\r\n\r\n doSomeWork;\r\n\r\n break;\r\n default:\r\n assert(0);\r\n }\r\n}<\/pre>\ndoSomeWork<\/code> simulates a CPU-intensive job by using DRuntime\u2019s Thread.sleep<\/code> method. This is a very common pattern where an application runs in cycles and, on every iteration, performs a job depending on the application state. Here we can see that the application has three code paths (CaseOne<\/code>, CaseTwo<\/code>, and CaseThree<\/code>). We need to trace the application at run time and collect information about its timings.<\/p>\nThe writef<\/code>-Based Approach<\/h2>\nUsing writef\/ln<\/code> from Phobos, D\u2019s standard library<\/a>, to trace the application is naive, but can be very useful nevertheless. The code from tracing_writef.d<\/a>:<\/p>\n case Event.One:\r\n auto sw = StopWatch(AutoStart.no);\r\n sw.start();\r\n\r\n doSomeWork;\r\n\r\n sw.stop();\r\n writefln(\"%d:\\tEvent %s took: %s\", counter, event, sw.peek);\r\n break;\r\n<\/pre>\nWith this trivial approach, StopWatch<\/code> from the standard library is used to measure the execution time of the code block of interest. Compile and run the application with the command dub tracing_writef.d<\/code> and look at its output:<\/p>\nRunning .\/example-writef\r\n0: Event One took: 584 ms, 53 \u03bcs, and 5 hnsecs\r\n1: Event One took: 922 ms, 72 \u03bcs, and 6 hnsecs\r\n2: Event Two took: 1 sec, 191 ms, 73 \u03bcs, and 8 hnsecs\r\n3: Event Two took: 974 ms, 73 \u03bcs, and 7 hnsecs\r\n...<\/pre>\nThere is a price for this\u2014we need to compile tracing code into our binary, we need to manually implement the collection of tracing output, disable it when we need to, and so on\u2014and this means the size of the binary increases. To summarize:<\/p>\n
Pros<\/strong><\/p>\n\n- all the might of Phobos is available to employ (except when in BetterC mode<\/a>)<\/li>\n
- tracing output can be displayed in a human readable format (look at the nice output of
Duration<\/code> above; thanks to Jonathan M. Davis for the std.datetime<\/code> package<\/a>)<\/li>\n- source code is portable<\/li>\n
- easy to use<\/li>\n
- no third-party tools required<\/li>\n<\/ul>\n
Cons<\/strong><\/p>\n\n- the application must be rebuilt and restarted in order to make any changes, which is inappropriate for some applications (such as servers)<\/li>\n
- no low-level access to the application state<\/li>\n
- noise in the code due to the addition of tracing code<\/li>\n
- can be unusable due to a lot of debug output<\/li>\n
- overhead can be large<\/li>\n
- can be hard to use in production<\/li>\n<\/ul>\n
This approach is very suitable in the early stages of development and less useful in the final product. Although, if the tracing logic is fixed and well defined, this approach can be used in production-ready applications\/libraries. For example, this approach was suggest by Stefan Koch for tracing the DMD frontend to profile performance and memory consumption<\/a>.<\/p>\nDebugger-Based Approach<\/h2>\n
The debugger, in this case GDB, is a more advanced means to trace applications. There is no need to modify the application to change the tracing methodology, making it very useful in production. Instead of compiling tracing logic into the application, breakpoints are set. When the debugger stops execution on a breakpoint, the developer can use the large arsenal of GDB functionality to inspect the internal state of the inferior<\/em> (which, in GDB terms, usually refers to the process being debugged<\/a>). It is not possible in this case to use Phobos directly, but helpers are available and, moreover, you have access to registers and the stack\u2014options which are unavailable in the case of writef<\/code> debugging.<\/p>\nLet\u2019s take a look the code from tracing_gdb.d<\/a> for the first event:<\/p>\n case Case.One:\r\n\r\n doSomeWork;\r\n\r\n break;<\/pre>\nAs you can see, now there is no tracing code and it is much cleaner. The tracing logic is placed in a separate file called trace.gdb<\/a>. It consists of a series of command blocks configured to execute on specific breakpoints, like this:<\/p>\nset pagination off\r\nset print address off\r\n\r\nbreak app.d:53\r\ncommands\r\nset $EventOne = currClock()\r\ncontinue\r\nend\r\n\r\nbreak app.d:54\r\ncommands\r\nset $EventOne = currClock() - $EventOne\r\nprintf \"%d:\\tEvent One took: %s\\n\", counter, printClock($EventOne)\r\ncontinue\r\nend\r\n\r\n...\r\n\r\nrun\r\nquit<\/pre>\nIn the first line, pagination is switched off. This enables scrolling so that there is no need to press \u201cEnter\u201d or \u201cQ\u201d to continue script execution when the current console fills up. The second line disables showing the address of the current breakpoint in order to make the output less verbose. Then breakpoints are set on lines 53 and 54, each followed by a list of commands (between the commands<\/code> and end<\/code> labels) that will be executed when GDB stops on these breakpoints. The breakpoint on line 53 is configured to fetch the current timestamp (using a helper) before doSomeWork<\/code> is called, and the one on line 54 to get the current timestamp after doSomeWork<\/code> has been executed. In fact, line 54 is an empty line in the source code, but GDB is smart enough to set the breakpoint on the next available line. $EventOne<\/code> is a convenience variable<\/a> where we store the timestamps to calculate code execution time. currClock()<\/code> and printClock(long)<\/code> are helpers to let us prettify the formatting by means of Phobos. The last two commands in the script initiate the debugging and quit the debugger when it\u2019s finished.<\/p>\nTo build and run this tracing session, use the following commands:<\/p>\n
dub build tracing_gdb.d --single\r\ngdb --command=trace.gdb .\/tracing-gdb | grep Event<\/pre>\ntrace.gdb<\/code> is the name of the GDB script and tracing-gdb<\/code> is the name of the binary. We use grep<\/code> to make the GDB output look like writefln<\/code> output for easier comparison.<\/p>\nPros<\/strong><\/p>\n\n- the code is clean and contains no tracing code<\/li>\n
- there is no need to recompile the application to change the tracing methodology\u2014in many cases, it\u2019s enough to simply change the GDB script<\/li>\n
- there is no need to restart the application<\/li>\n
- it can be used in production (sort of)<\/li>\n
- there is no overhead if\/when not tracing and little when tracing<\/li>\n
- watchpoints<\/a> and catchpoints<\/a> can be used instead of breakpoints<\/li>\n<\/ul>\n
Cons<\/strong><\/p>\n\n- using breakpoints in some cases may be inconvenient, annoying, or impossible.<\/li>\n
- GDB\u2019s pretty-printing provides \u201cless pretty\u201d output because of the lack of full Phobos support compared to the
writef<\/code> approach<\/li>\n- sometimes GDB is not available in production<\/li>\n<\/ul>\n
The point about setting breakpoints in GDB being inconvenient is based on the fact that you can use only an address, a line number, or a function name (see the gdb manual<\/a>). Using an address is too low level and inconvenient. Line numbers are ephemeral and can easily change when the source file is edited, so the scripts will be broken (this is annoying). Using function names is convenient and stable, but is useless if you need to place a tracing probe inside a function.<\/p>\nA good example of using GDB for tracing is Vladimir Panteleev\u2019s dmdprof<\/a>.<\/p>\nThe USDT-Based Approach<\/h2>\n
So far we have two ways to trace our application that are complimentary, but is there a way to unify all the advantages of these two approaches and avoid their drawbacks? Of course, the answer is yes. In fact there are several ways to achieve this, but hereafter only one will be discussed: USDT (Userland Statically Defined Tracing).<\/p>\n
Unfortunately, due to historical reasons, the Linux tracing ecosystem is fragmented and rather confusing. There is no plain and simple introduction. Get ready to invest much more time if you want to understand this domain. The first well-known, full-fledged tracing framework was DTrace, developed by Sun Microsystems (now it is open source and licensed under the GPL<\/a>). Yes, strace and ltrace have been around for a long time, but they are limited, e.g., they do not let you trace what happens inside a function call. Today, DTrace is available on Solaris, FreeBSD, macOS, and Oracle Linux. DTrace is not available in other Linux distributions because it was initially licensed under the CDDL. In 2018, it was relicensed under the GPL, but by then Linux had its own tracing ecosystem. As with everything, Open Source has disadvantages. In this case, it resulted in fragmentation. There are now several tools\/frameworks\/etc. that are able to solve the same problems in different ways but somehow and sometimes can interoperate with each other.<\/p>\nWe will be using bpftrace<\/a>, a high level tracing language for Linux eBPF<\/a>. In D, USDT probes are provided by the usdt library<\/a>. Let\u2019s start from the code in tracing_usdt.d<\/a>:<\/p>\n\tcase Case.One:\r\n\t\tmixin(USDT_PROBE!(\"dlang\", \"CaseOne\", kind));\r\n\r\n\t\tdoSomeWork;\r\n\r\n\t\tmixin(USDT_PROBE!(\"dlang\", \"CaseOne_return\", kind));\r\n\tbreak;<\/pre>\nHere we mixed in<\/a> two probes at the start and the end of the code of interest. It looks similar to the first example using writef<\/code>, but a huge difference is that there is no logic here. We only defined two probes that are NOP instructions. That means that these probes have almost zero overhead and we can use them in production. The second great advantage is that we can change the logic while the application is running. That is just impossible when using the writef<\/code> approach. Since we are using bpftrace, we need to write a script, called bpftrace.bt<\/a>, to define actions that should be performed on the probes:<\/p>\nusdt:.\/tracing-usdt:dlang:CaseOne\r\n{\r\n\t@last[\"CaseOne\"] = nsecs;\r\n}\r\n\r\nusdt:.\/tracing-usdt:dlang:CaseOne_return\r\n{\r\n\tif (@last[\"CaseOne\"] != 0)\r\n\t{\r\n\t\t$tmp = nsecs;\r\n\t\t$period = ($tmp - @last[\"CaseOne\"]) \/ 1000000;\r\n\t\tprintf(\"%d:\\tEvent CaseOne took: %d ms\\n\", @counter++, $period);\r\n\t\t@last[\"CaseOne\"] = $tmp;\r\n\t\t@timing = hist($period);\r\n\t}\r\n}\r\n...<\/pre>\nThe first statement is the action block. It triggers on the USDT probe that is compiled in the .\/tracing-usdt<\/code> executable (it includes the path to the executable) with the dlang<\/code> provider name and the CaseOne<\/code> probe name. When this probe is hit, then the global (indicated by the @<\/code> sign) associative array last<\/code> updates the current timestamp for its element CaseOne<\/code>. This stores the time of the moment the code starts running. The second action block defines actions performed when the CaseOne_return<\/code> probe is hit. It first checks if corresponding element in the @last<\/code> associative array is already initialized. This is needed because the application may already be running when the script is executed, in which case the CaseOne_return<\/code> probe can be fired before CaseOne<\/code>. Then we calculate how much time code execution took, output it, and store it in a histogram called timing<\/code>.<\/p>\nThe BEGIN and END blocks at the top of bpftrace.bt<\/code> define actions that should be performed at the beginning and the end of script execution. This is nothing more than initialization and finalization. Build and run the example with:<\/p>\ndub build tracing_usdt.d --single --compiler=ldmd2 # or gdc\r\n.\/tracing-usdt & # run the example in background\r\nsudo bpftrace bpftrace.bt # start tracing session<\/pre>\nOutput:<\/p>\n
Attaching 8 probes...\r\n0:\tEvent CaseThree took: 552 ms\r\n1:\tEvent CaseThree took: 779 ms\r\n2:\tEvent CaseTwo took: 958 ms\r\n3:\tEvent CaseOne took: 1174 ms\r\n4:\tEvent CaseOne took: 1059 ms\r\n5:\tEvent CaseThree took: 481 ms\r\n6:\tEvent CaseTwo took: 1044 ms\r\n7:\tEvent CaseThree took: 611 ms\r\n8:\tEvent CaseOne took: 545 ms\r\n9:\tEvent CaseTwo took: 1038 ms\r\n10:\tEvent CaseOne took: 913 ms\r\n11:\tEvent CaseThree took: 989 ms\r\n12:\tEvent CaseOne took: 1149 ms\r\n13:\tEvent CaseThree took: 541 ms\r\n14:\tEvent CaseTwo took: 1072 ms\r\n15:\tEvent CaseOne took: 633 ms\r\n16:\tEvent CaseTwo took: 832 ms\r\n17:\tEvent CaseTwo took: 1120 ms\r\n^C\r\n\r\n\r\n\r\n@timing:\r\n[256, 512) 1 |@@@@@ |\r\n[512, 1K) 10 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|\r\n[1K, 2K) 7 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |<\/pre>\nIn the session output above there are only 18 lines instead of 20; it\u2019s because tracing-usdt<\/code> was started before the bpftrace<\/code> script so the first two events were lost. Also, it’s necessary to kill the example by typing Ctrl-C<\/code> after tracing-usdt<\/code> completes. After the bpftrace<\/code> script stops execution, it ouputs the contents of the timing<\/code> map as a histogram. The histogram says that one-time code execution takes between 256 and 512 ms, ten times between 512 and 1024 ms, and seven times more between 1024 and 2048 ms. These builtin statistics make using bpftrace<\/code> easy.<\/p>\nPros<\/strong><\/p>\n\n- provides low-level access to the code (registers, memory, etc.)<\/li>\n
- minimal noise in the code<\/li>\n
- no need to recompile or restart when changing the tracing logic<\/li>\n
- almost zero overhead<\/li>\n
- can be effectively used in production<\/li>\n<\/ul>\n
Cons<\/strong><\/p>\n\n- learning USDT can be hard, particularly considering the state of the Linux tracing ecosystem<\/li>\n
- requires external tools (frontends)<\/li>\n
- OS specific<\/li>\n<\/ul>\n
Note: GDB has had support for USDT probes since version 7.5. To use it, modify the trace.gdb<\/code> script to set breakpoints using USDT probes instead of line numbers. That eases development because it eliminates the need to synchronize line numbers during source code modification.<\/p>\nFuther reading:<\/p>\n
\n- Profiling D\u2019s Garbage Collection with Bpftrace<\/a><\/li>\n
- Systemtap Probes and Gdb<\/a><\/li>\n<\/ul>\n
Conclusion<\/h2>\n
\n\n \n\nFeature<\/th>\n writef<\/th>\n gdb<\/th>\n usdt<\/th>\n<\/tr>\n<\/thead>\n \n\npretty
\nprinting<\/td>\n by means of Phobos
\nand other libs<\/td>\n by means of
\npretty-printing<\/a><\/td>\n limited builtins<\/td>\n<\/tr>\n \nlow-level<\/td>\n no<\/td>\n yes<\/td>\n yes<\/td>\n<\/tr>\n \nclean code<\/td>\n no<\/td>\n yes<\/td>\n sort of<\/td>\n<\/tr>\n \nrecompilation<\/td>\n yes<\/td>\n no<\/td>\n no<\/td>\n<\/tr>\n \nrestart<\/td>\n yes<\/td>\n no<\/td>\n no<\/td>\n<\/tr>\n \nusage
\ncomplexity<\/td>\n easy<\/td>\n easy+<\/td>\n advanced<\/td>\n<\/tr>\n \nthird-party
\ntools<\/td>\n no<\/td>\n only debugger<\/td>\n tracing system front end<\/td>\n<\/tr>\n \ncross platform<\/td>\n yes<\/td>\n sorta of<\/td>\n OS specific<\/td>\n<\/tr>\n \noverhead<\/td>\n can be large<\/td>\n none<\/td>\n can be ignored
\neven in production<\/td>\n<\/tr>\n \nproduction ready<\/td>\n sometimes possible<\/td>\n sometimes impossible<\/td>\n yes<\/td>\n<\/tr>\n \n<\/td>\n <\/td>\n<\/tr>\n<\/tbody>\n<\/table>\nFeature<\/strong> descriptions:<\/p>\n\n- pretty printing<\/strong> is important if the tracing output should be read by humans (and can be ignored in the case of inter-machine data exchange)<\/li>\n
- low-level<\/strong> means access to low-level details of the traced binary, e.g., registers or memory<\/li>\n
- clean code<\/strong> characterizes whether additional tracing code which is unrelated to the applications\u2019s business logic would be required.<\/li>\n
- recompilation<\/strong> determines if it is necessary to recompile when changing the tracing methodology<\/li>\n
- restart<\/strong> determines if it is necessary to restart the application when changing the tracing methodology<\/li>\n
- usage complexity<\/strong> indicates the level of development experience that may be required to utilize this technology<\/li>\n
- third-party tools<\/strong> describes tools not provided by standard D language distributions are required to use this technology<\/li>\n
- cross platform<\/strong> indicates if this technology can be used on different platforms without changes<\/li>\n
- overhead<\/strong> – the cost of using this technology<\/li>\n
- production ready<\/strong> – indicates if this technology may be used in a production system without consequences<\/li>\n<\/ul>\n","protected":false},"excerpt":{"rendered":"
At one time or another during application development you need to make a decision: does your application work like it should and, if not, what is wrong with it? There are different techniques to help you decide, some of which are logging, tracing, and profiling. How are they different? One way to look at it […]<\/p>\n","protected":false},"author":39,"featured_media":0,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":[],"categories":[26,9,30],"tags":[],"_links":{"self":[{"href":"https:\/\/dlang.org\/blog\/wp-json\/wp\/v2\/posts\/2325"}],"collection":[{"href":"https:\/\/dlang.org\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/dlang.org\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/dlang.org\/blog\/wp-json\/wp\/v2\/users\/39"}],"replies":[{"embeddable":true,"href":"https:\/\/dlang.org\/blog\/wp-json\/wp\/v2\/comments?post=2325"}],"version-history":[{"count":6,"href":"https:\/\/dlang.org\/blog\/wp-json\/wp\/v2\/posts\/2325\/revisions"}],"predecessor-version":[{"id":2351,"href":"https:\/\/dlang.org\/blog\/wp-json\/wp\/v2\/posts\/2325\/revisions\/2351"}],"wp:attachment":[{"href":"https:\/\/dlang.org\/blog\/wp-json\/wp\/v2\/media?parent=2325"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/dlang.org\/blog\/wp-json\/wp\/v2\/categories?post=2325"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/dlang.org\/blog\/wp-json\/wp\/v2\/tags?post=2325"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}