From d62457837b44bac8d67d0a993e955b086de21c96 Mon Sep 17 00:00:00 2001 From: Bram Veldhoen Date: Tue, 14 Dec 2021 08:39:45 +0100 Subject: [PATCH] Updated usdt_sample for ubuntu 21.10 (and python3) * Updated readme for Ubuntu 21.10 and python3. * Readability improvements. * Using atomic_increment (thus requires bcc 0.21+). * Using/tested probes created using systemtap (dtrace), next to the probes created with macros in the folly header. * Also tested while building usdt_sample with clang. * Some (modern) cmake changes. * Added script to execute build and sample python scripts. --- examples/usdt_sample/.gitignore | 1 + examples/usdt_sample/CMakeLists.txt | 2 +- .../usdt_sample/scripts/bpf_text_shared.c | 26 +- examples/usdt_sample/scripts/lat_avg.py | 52 +- examples/usdt_sample/scripts/lat_dist.py | 23 +- examples/usdt_sample/scripts/latency.py | 19 +- examples/usdt_sample/usdt_sample.md | 595 ++++++++++++++---- examples/usdt_sample/usdt_sample.sh | 95 +++ .../usdt_sample_app1/CMakeLists.txt | 12 +- .../usdt_sample_lib1/CMakeLists.txt | 69 +- .../include/usdt_sample_lib1/lib1_sdt.h | 36 -- .../usdt_sample/usdt_sample_lib1/src/lib1.cpp | 18 +- .../usdt_sample_lib1/src/lib1_sdt.d | 6 +- .../usdt_sample_lib1/src/lib1_sdt.h | 33 + 14 files changed, 738 insertions(+), 249 deletions(-) create mode 100644 examples/usdt_sample/.gitignore create mode 100755 examples/usdt_sample/usdt_sample.sh delete mode 100644 examples/usdt_sample/usdt_sample_lib1/include/usdt_sample_lib1/lib1_sdt.h create mode 100644 examples/usdt_sample/usdt_sample_lib1/src/lib1_sdt.h diff --git a/examples/usdt_sample/.gitignore b/examples/usdt_sample/.gitignore new file mode 100644 index 000000000000..b026c8ffe606 --- /dev/null +++ b/examples/usdt_sample/.gitignore @@ -0,0 +1 @@ +**/build*/ \ No newline at end of file diff --git a/examples/usdt_sample/CMakeLists.txt b/examples/usdt_sample/CMakeLists.txt index 04e50929236f..c8510fcee576 100644 --- a/examples/usdt_sample/CMakeLists.txt +++ b/examples/usdt_sample/CMakeLists.txt @@ -1,4 +1,4 @@ -cmake_minimum_required(VERSION 3.0) +cmake_minimum_required(VERSION 3.12) # This sample requires C++11 enabled. set(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} -std=c++11 -Wall -Weffc++") diff --git a/examples/usdt_sample/scripts/bpf_text_shared.c b/examples/usdt_sample/scripts/bpf_text_shared.c index 41d8c9871a87..6c08b8d5aa7c 100644 --- a/examples/usdt_sample/scripts/bpf_text_shared.c +++ b/examples/usdt_sample/scripts/bpf_text_shared.c @@ -4,15 +4,27 @@ /** * @brief Helper method to filter based on the specified inputString. * @param inputString The operation input string to check against the filter. - * @return True if the specified inputString starts with the hard-coded FILTER_STRING; otherwise, false. + * @return True if the specified inputString starts with the hard-coded filter string; otherwise, false. */ static inline bool filter(char const* inputString) { - char needle[] = "FILTER_STRING"; ///< The FILTER STRING is replaced by python code. - char haystack[sizeof(needle)] = {}; - bpf_probe_read_user(&haystack, sizeof(haystack), (void*)inputString); - for (int i = 0; i < sizeof(needle) - 1; ++i) { - if (needle[i] != haystack[i]) { + static const char* null_ptr = 0x0; + static const char null_terminator = '\0'; + + static const char filter_string[] = "FILTER_STRING"; ///< The filter string is replaced by python code. + if (null_ptr == inputString) { + return false; + } + + // Compare until (not including) the null-terminator for filter_string + for (int i = 0; i < sizeof(filter_string) - 1; ++i) { + char c1 = *inputString++; + if (null_terminator == c1) { + return false; // If the null-terminator for inputString was reached, it can not be equal to filter_string. + } + + char c2 = filter_string[i]; + if (c1 != c2) { return false; } } @@ -45,7 +57,7 @@ int trace_operation_start(struct pt_regs* ctx) struct start_data_t start_data = {}; bpf_usdt_readarg_p(2, ctx, &start_data.input, sizeof(start_data.input)); - FILTER ///< Replaced by python code. + FILTER_STATEMENT ///< Replaced by python code. bpf_usdt_readarg(1, ctx, &start_data.operation_id); diff --git a/examples/usdt_sample/scripts/lat_avg.py b/examples/usdt_sample/scripts/lat_avg.py index 7c72e2110339..6f2ee24d4c47 100755 --- a/examples/usdt_sample/scripts/lat_avg.py +++ b/examples/usdt_sample/scripts/lat_avg.py @@ -12,23 +12,25 @@ formatter_class=argparse.RawDescriptionHelpFormatter) parser.add_argument("-p", "--pid", type=int, help="The id of the process to trace.") parser.add_argument("-i", "--interval", type=int, help="The interval in seconds on which to report the latency distribution.") -parser.add_argument("-c", "--count", type=int, default=16, help="The count of samples over which to calculate the moving average.") +parser.add_argument("-c", "--count", type=int, default=16, help="The maximum number of samples over which to calculate the moving average.") parser.add_argument("-f", "--filterstr", type=str, default="", help="The prefix filter for the operation input. If specified, only operations for which the input string starts with the filterstr are traced.") -parser.add_argument("-v", "--verbose", dest="verbose", action="store_true", help="If true, will output verbose logging information.") +parser.add_argument("-v", "--verbose", dest="verbose", action="store_true", help="If true, will output generated bpf program and verbose logging information.") +parser.add_argument("-s", "--sdt", dest="sdt", action="store_true", help="If true, will use the probes, created by systemtap's dtrace.") + parser.set_defaults(verbose=False) args = parser.parse_args() this_pid = int(args.pid) this_interval = int(args.interval) -this_count = int(args.count) +this_maxsamplesize = int(args.count) this_filter = str(args.filterstr) if this_interval < 1: print("Invalid value for interval, using 1.") this_interval = 1 -if this_count < 1: - print("Invalid value for count, using 1.") - this_count = 1 +if this_maxsamplesize < 1: + print("Invalid value for this_maxsamplesize, using 1.") + this_maxsamplesize = 1 debugLevel=0 if args.verbose: @@ -39,18 +41,18 @@ bpf_text = open(bpf_text_shared, 'r').read() bpf_text += """ -const u32 MAX_SAMPLES = SAMPLE_COUNT; +const u32 max_sample_size = MAX_SAMPLE_SIZE; struct hash_key_t { - char input[64]; + char input[64]; // The operation id is used as key }; struct hash_leaf_t { - u32 count; - u64 total; - u64 average; + u32 sample_size; // Number of operation samples taken + u64 total; // Cumulative duration of the operations + u64 average; // Moving average duration of the operations }; /** @@ -83,31 +85,36 @@ return 0; } - if (hash_leaf->count < MAX_SAMPLES) { - hash_leaf->count++; + if (hash_leaf->sample_size < max_sample_size) { + ++hash_leaf->sample_size; } else { hash_leaf->total -= hash_leaf->average; } hash_leaf->total += duration; - hash_leaf->average = hash_leaf->total / hash_leaf->count; + hash_leaf->average = hash_leaf->total / hash_leaf->sample_size; return 0; } """ -bpf_text = bpf_text.replace("SAMPLE_COUNT", str(this_count)) +bpf_text = bpf_text.replace("MAX_SAMPLE_SIZE", str(this_maxsamplesize)) bpf_text = bpf_text.replace("FILTER_STRING", this_filter) if this_filter: - bpf_text = bpf_text.replace("FILTER", "if (!filter(start_data.input)) { return 0; }") + bpf_text = bpf_text.replace("FILTER_STATEMENT", "if (!filter(start_data.input)) { return 0; }") else: - bpf_text = bpf_text.replace("FILTER", "") + bpf_text = bpf_text.replace("FILTER_STATEMENT", "") # Create USDT context -print("Attaching probes to pid %d" % this_pid) +print("lat_avg.py - Attaching probes to pid: %d; filter: %s" % (this_pid, this_filter)) usdt_ctx = USDT(pid=this_pid) -usdt_ctx.enable_probe(probe="operation_start", fn_name="trace_operation_start") -usdt_ctx.enable_probe(probe="operation_end", fn_name="trace_operation_end") + +if args.sdt: + usdt_ctx.enable_probe(probe="usdt_sample_lib1_sdt:operation_start_sdt", fn_name="trace_operation_start") + usdt_ctx.enable_probe(probe="usdt_sample_lib1_sdt:operation_end_sdt", fn_name="trace_operation_end") +else: + usdt_ctx.enable_probe(probe="usdt_sample_lib1:operation_start", fn_name="trace_operation_start") + usdt_ctx.enable_probe(probe="usdt_sample_lib1:operation_end", fn_name="trace_operation_end") # Create BPF context, load BPF program bpf_ctx = BPF(text=bpf_text, usdt_contexts=[usdt_ctx], debug=debugLevel) @@ -115,13 +122,12 @@ print("Tracing... Hit Ctrl-C to end.") lat_hash = bpf_ctx.get_table("lat_hash") +print("%-12s %-64s %8s %16s" % ("time", "input", "sample_size", "latency (us)")) while (1): try: sleep(this_interval) except KeyboardInterrupt: exit() - print("[%s]" % strftime("%H:%M:%S")) - print("%-64s %8s %16s" % ("input", "count", "latency (us)")) for k, v in lat_hash.items(): - print("%-64s %8d %16d" % (k.input, v.count, v.average / 1000)) + print("%-12s %-64s %8d %16d" % (strftime("%H:%M:%S"), k.input, v.sample_size, v.average / 1000)) diff --git a/examples/usdt_sample/scripts/lat_dist.py b/examples/usdt_sample/scripts/lat_dist.py index 782c960bf1d2..4b4226e99749 100755 --- a/examples/usdt_sample/scripts/lat_dist.py +++ b/examples/usdt_sample/scripts/lat_dist.py @@ -13,7 +13,9 @@ parser.add_argument("-p", "--pid", type=int, help="The id of the process to trace.") parser.add_argument("-i", "--interval", type=int, help="The interval in seconds on which to report the latency distribution.") parser.add_argument("-f", "--filterstr", type=str, default="", help="The prefix filter for the operation input. If specified, only operations for which the input string starts with the filterstr are traced.") -parser.add_argument("-v", "--verbose", dest="verbose", action="store_true", help="If true, will output verbose logging information.") +parser.add_argument("-v", "--verbose", dest="verbose", action="store_true", help="If true, will output generated bpf program and verbose logging information.") +parser.add_argument("-s", "--sdt", dest="sdt", action="store_true", help="If true, will use the probes, created by systemtap's dtrace.") + parser.set_defaults(verbose=False) args = parser.parse_args() this_pid = int(args.pid) @@ -67,26 +69,33 @@ dist_key.slot = bpf_log2l(duration / 1000); start_hash.delete(&operation_id); - dist.increment(dist_key); + dist.atomic_increment(dist_key); return 0; } """ bpf_text = bpf_text.replace("FILTER_STRING", this_filter) if this_filter: - bpf_text = bpf_text.replace("FILTER", "if (!filter(start_data.input)) { return 0; }") + bpf_text = bpf_text.replace("FILTER_STATEMENT", "if (!filter(start_data.input)) { return 0; }") else: - bpf_text = bpf_text.replace("FILTER", "") + bpf_text = bpf_text.replace("FILTER_STATEMENT", "") # Create USDT context -print("Attaching probes to pid %d" % this_pid) +print("lat_dist.py - Attaching probes to pid: %d; filter: %s" % (this_pid, this_filter)) usdt_ctx = USDT(pid=this_pid) -usdt_ctx.enable_probe(probe="operation_start", fn_name="trace_operation_start") -usdt_ctx.enable_probe(probe="operation_end", fn_name="trace_operation_end") + +if args.sdt: + usdt_ctx.enable_probe(probe="usdt_sample_lib1_sdt:operation_start_sdt", fn_name="trace_operation_start") + usdt_ctx.enable_probe(probe="usdt_sample_lib1_sdt:operation_end_sdt", fn_name="trace_operation_end") +else: + usdt_ctx.enable_probe(probe="usdt_sample_lib1:operation_start", fn_name="trace_operation_start") + usdt_ctx.enable_probe(probe="usdt_sample_lib1:operation_end", fn_name="trace_operation_end") # Create BPF context, load BPF program bpf_ctx = BPF(text=bpf_text, usdt_contexts=[usdt_ctx], debug=debugLevel) +print("Tracing... Hit Ctrl-C to end.") + start = 0 dist = bpf_ctx.get_table("dist") while (1): diff --git a/examples/usdt_sample/scripts/latency.py b/examples/usdt_sample/scripts/latency.py index 8a7ec08c8acc..b0079a2baaf4 100755 --- a/examples/usdt_sample/scripts/latency.py +++ b/examples/usdt_sample/scripts/latency.py @@ -12,7 +12,9 @@ formatter_class=argparse.RawDescriptionHelpFormatter) parser.add_argument("-p", "--pid", type=int, help="The id of the process to trace.") parser.add_argument("-f", "--filterstr", type=str, default="", help="The prefix filter for the operation input. If specified, only operations for which the input string starts with the filterstr are traced.") -parser.add_argument("-v", "--verbose", dest="verbose", action="store_true", help="If true, will output verbose logging information.") +parser.add_argument("-v", "--verbose", dest="verbose", action="store_true", help="If true, will output generated bpf program and verbose logging information.") +parser.add_argument("-s", "--sdt", dest="sdt", action="store_true", help="If true, will use the probes, created by systemtap's dtrace.") + parser.set_defaults(verbose=False) args = parser.parse_args() this_pid = int(args.pid) @@ -76,15 +78,20 @@ bpf_text = bpf_text.replace("FILTER_STRING", this_filter) if this_filter: - bpf_text = bpf_text.replace("FILTER", "if (!filter(start_data.input)) { return 0; }") + bpf_text = bpf_text.replace("FILTER_STATEMENT", "if (!filter(start_data.input)) { return 0; }") else: - bpf_text = bpf_text.replace("FILTER", "") + bpf_text = bpf_text.replace("FILTER_STATEMENT", "") # Create USDT context -print("Attaching probes to pid %d" % this_pid) +print("latency.py - Attaching probes to pid: %d; filter: %s" % (this_pid, this_filter)) usdt_ctx = USDT(pid=this_pid) -usdt_ctx.enable_probe(probe="operation_start", fn_name="trace_operation_start") -usdt_ctx.enable_probe(probe="operation_end", fn_name="trace_operation_end") + +if args.sdt: + usdt_ctx.enable_probe(probe="usdt_sample_lib1_sdt:operation_start_sdt", fn_name="trace_operation_start") + usdt_ctx.enable_probe(probe="usdt_sample_lib1_sdt:operation_end_sdt", fn_name="trace_operation_end") +else: + usdt_ctx.enable_probe(probe="usdt_sample_lib1:operation_start", fn_name="trace_operation_start") + usdt_ctx.enable_probe(probe="usdt_sample_lib1:operation_end", fn_name="trace_operation_end") # Create BPF context, load BPF program bpf_ctx = BPF(text=bpf_text, usdt_contexts=[usdt_ctx], debug=debugLevel) diff --git a/examples/usdt_sample/usdt_sample.md b/examples/usdt_sample/usdt_sample.md index fd5b527b3b54..d35613226290 100644 --- a/examples/usdt_sample/usdt_sample.md +++ b/examples/usdt_sample/usdt_sample.md @@ -1,136 +1,159 @@ -Tested on Fedora25 4.11.3-200.fc25.x86_64, gcc (GCC) 6.3.1 20161221 (Red Hat 6.3.1-1) -As an alternative to using ...bcc/tests/python/include/folly/tracing/StaticTracepoint.h, -it's possible to use systemtap-sdt-devel. -However, this is *not* required for this sample. +# Prerequitites + +## Ubuntu 21.10 prerequisites + ```bash -$ sudo dnf install systemtap-sdt-devel # For Fedora25, other distro's might have differently named packages. +$ sudo apt-get install linux-headers-$(uname -r) "llvm-13*" libclang-13-dev luajit luajit-5.1-dev libelf-dev python3-distutils libdebuginfod-dev arping netperf iperf ``` -If using systemtap-sdt-devel, the following commands can be used to generate the corresponding header and object files: -Also see the CMakeLists.txt file for an example how to do this using cmake. +## Building bcc tools + ```bash -$ dtrace -h -s usdt_sample_lib1/src/lib1_sdt.d -o usdt_sample_lib1/include/usdt_sample_lib1/lib1_sdt.h -$ dtrace -G -s usdt_sample_lib1/src/lib1_sdt.d -o lib1_sdt.o +# Make sure you are in the bcc root folder +$ mkdir -p build && cd build +$ cmake .. -DPYTHON_CMD=python3 +$ make -j4 +$ sudo make install ``` -Build the sample: +# Building and executing the usdt_sample (gcc 11.2) + +## Build the sample + +```bash +$ gcc --version +gcc (Ubuntu 11.2.0-7ubuntu2) 11.2.0 +... +# Make sure you are in the bcc root folder +$ mkdir -p examples/usdt_sample/build && cd examples/usdt_sample/build +$ cmake .. +$ make +``` + +## Create probes using StaticTracepoint.h + +bcc comes with a header file, which contains macros to define probes. See tests/python/include/folly/tracing/StaticTracepoint.h + +See the usage of FOLLY_SDT macro in examples/usdt_sample/usdt_sample_lib1/src/lib1.cpp. + +## Create probes using SystemTap dtrace + +As an alternative to using tests/python/include/folly/tracing/StaticTracepoint.h, it's possible to use dtrace, which is installed by systemtap-sdt-dev. ```bash -$ pwd -~/src/bcc -$ mkdir -p examples/usdt_sample/build && pushd examples/usdt_sample/build -$ cmake .. && make -$ popd +$ sudo dnf install systemtap-sdt-dev # For Ubuntu 21.10, other distro's might have differently named packages. ``` -After building, you should see the available probes: +If using systemtap-sdt-dev, the following commands can be used to generate the corresponding header and object files: +See examples/usdt_sample/usdt_sample_lib1/CMakeLists.txt file for an example how to do this using cmake. ```bash -$ python tools/tplist.py -l examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so +$ dtrace -h -s usdt_sample_lib1/src/lib1_sdt.d -o usdt_sample_lib1/include/usdt_sample_lib1/lib1_sdt.h +$ dtrace -G -s usdt_sample_lib1/src/lib1_sdt.d -o lib1_sdt.o +``` + +## Use tplist.py to list the available probes + +Note that the (operation_start, operation_end) probes are created using the macros in the folly headers, the (operation_start_sdt, operation_end_sdt) probes are created using systemtap's dtrace: + +```bash +$ python3 tools/tplist.py -l examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so usdt_sample_lib1:operation_end +examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so usdt_sample_lib1:operation_end_sdt examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so usdt_sample_lib1:operation_start +examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so usdt_sample_lib1:operation_start_sdt $ readelf -n examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so -Displaying notes found at file offset 0x000001c8 with length 0x00000024: - Owner Data size Description - GNU 0x00000014 NT_GNU_BUILD_ID (unique build ID bitstring) - Build ID: 3930c19f654990159563394669f2ed5281513302 +Displaying notes found in: .note.gnu.property + Owner Data size Description + GNU 0x00000010 NT_GNU_PROPERTY_TYPE_0 + Properties: x86 feature: IBT, SHSTK + +Displaying notes found in: .note.gnu.build-id + Owner Data size Description + GNU 0x00000014 NT_GNU_BUILD_ID (unique build ID bitstring) + Build ID: a483dc6ac17d4983ba748cf65ffd0e398639b61a -Displaying notes found at file offset 0x0001b9ec with length 0x000000c0: - Owner Data size Description - stapsdt 0x00000047 NT_STAPSDT (SystemTap probe descriptors) +Displaying notes found in: .note.stapsdt + Owner Data size Description + stapsdt 0x00000047 NT_STAPSDT (SystemTap probe descriptors) Provider: usdt_sample_lib1 Name: operation_end - Location: 0x000000000000ed6d, Base: 0x0000000000000000, Semaphore: 0x0000000000000000 + Location: 0x0000000000011c2f, Base: 0x0000000000000000, Semaphore: 0x0000000000000000 Arguments: -8@%rbx -8@%rax - stapsdt 0x0000004e NT_STAPSDT (SystemTap probe descriptors) + stapsdt 0x0000004f NT_STAPSDT (SystemTap probe descriptors) + Provider: usdt_sample_lib1 + Name: operation_end_sdt + Location: 0x0000000000011c65, Base: 0x000000000001966f, Semaphore: 0x0000000000020a6a + Arguments: 8@%rbx 8@%rax + stapsdt 0x0000004f NT_STAPSDT (SystemTap probe descriptors) Provider: usdt_sample_lib1 Name: operation_start - Location: 0x000000000000ee2c, Base: 0x0000000000000000, Semaphore: 0x0000000000000000 - Arguments: -8@-24(%rbp) -8@%rax + Location: 0x0000000000011d63, Base: 0x0000000000000000, Semaphore: 0x0000000000000000 + Arguments: -8@-104(%rbp) -8@%rax + stapsdt 0x00000057 NT_STAPSDT (SystemTap probe descriptors) + Provider: usdt_sample_lib1 + Name: operation_start_sdt + Location: 0x0000000000011d94, Base: 0x000000000001966f, Semaphore: 0x0000000000020a68 + Arguments: 8@-104(%rbp) 8@%rax ``` -Start the usdt sample application: +## Start the usdt sample application + +The usdt_sample_app1 executes an operation asynchronously on multiple threads, with random (string) parameters, which can be used to filter on. + ```bash -$ examples/usdt_sample/build/usdt_sample_app1/usdt_sample_app1 "pf" 1 30 10 1 50 +$ examples/usdt_sample/build/usdt_sample_app1/usdt_sample_app1 "usdt" 1 30 10 1 50 Applying the following parameters: -Input prefix: pf. +Input prefix: usdt. Input range: [1, 30]. Calls Per Second: 10. Latency range: [1, 50] ms. You can now run the bcc scripts, see usdt_sample.md for examples. -pid: 25433 +pid: 2422725 Press ctrl-c to exit. ``` -Use argdist.py on the individual probes: +## Use argdist.py on the individual probes + ```bash -$ sudo python tools/argdist.py -p 25433 -i 5 -C 'u:usdt_sample_lib1:operation_start():char*:arg2#input' -z 32 -[11:18:29] +# Make sure to replace the pid +$ sudo python3 tools/argdist.py -p 2422725 -i 5 -C "u:$(pwd)/examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so:operation_start():char*:arg2#input" -z 32 +[HH:mm:ss] input - COUNT EVENT - 1 arg2 = pf_10 - 1 arg2 = pf_5 - 1 arg2 = pf_12 - 1 arg2 = pf_1 - 1 arg2 = pf_11 - 1 arg2 = pf_28 - 1 arg2 = pf_16 - 1 arg2 = pf_19 - 1 arg2 = pf_15 - 1 arg2 = pf_2 - 2 arg2 = pf_17 - 2 arg2 = pf_3 - 2 arg2 = pf_25 - 2 arg2 = pf_30 - 2 arg2 = pf_13 - 2 arg2 = pf_18 - 2 arg2 = pf_7 - 2 arg2 = pf_29 - 2 arg2 = pf_26 - 3 arg2 = pf_8 - 3 arg2 = pf_21 - 3 arg2 = pf_14 - 4 arg2 = pf_6 - 4 arg2 = pf_23 - 5 arg2 = pf_24 - -Should that command fail with the error message "HINT: Binary path usdt_sample_lib1 should be absolute", try instead: - -sudo python tools/argdist.py -p 47575 -i 5 -C 'u:ABSOLUTE-PATH-TO-BCC-REPO/bcc/examples/usdt_sample/build/usdt_sample_lib1/libusdt_sample_lib1.so:operation_start():char*:arg2#input' -z 32 - -``` - -Use latency.py to trace the operation latencies: -```bash -$ sudo python examples/usdt_sample/scripts/latency.py -p=25433 -f="pf_2" -Attaching probes to pid 25433 + COUNT EVENT + 1 arg2 = b'usdt_5' + 1 arg2 = b'usdt_30' +... + 3 arg2 = b'usdt_9' + 3 arg2 = b'usdt_17' + 3 arg2 = b'usdt_7' + 5 arg2 = b'usdt_10' +``` + +## Use latency.py to trace the operation latencies + +```bash +# Make sure to replace the pid, the filter value is chosen arbitrarily. +$ sudo python3 examples/usdt_sample/scripts/latency.py -p=2422725 -f="usdt_20" +Attaching probes to pid 2422725 Tracing... Hit Ctrl-C to end. time(s) id input output start (ns) end (ns) duration (us) -0.000000000 7204 pf_28 resp_pf_28 11949439999644 11949489234565 49234 -0.100211886 7205 pf_28 resp_pf_28 11949540211530 11949574403064 34191 -0.300586675 7207 pf_21 resp_pf_21 11949740586319 11949742773571 2187 -0.400774366 7208 pf_28 resp_pf_28 11949840774010 11949859965498 19191 -0.701365719 7211 pf_21 resp_pf_21 11950141365363 11950152551131 11185 -0.901736620 7213 pf_25 resp_pf_25 11950341736264 11950347924333 6188 -1.102162217 7215 pf_21 resp_pf_21 11950542161861 11950567484183 25322 -1.302595998 7217 pf_23 resp_pf_23 11950742595642 11950761841242 19245 -1.503047601 7219 pf_2 resp_pf_2 11950943047245 11950951213474 8166 -1.703371457 7221 pf_27 resp_pf_27 11951143371101 11951176568051 33196 -2.104228899 7225 pf_24 resp_pf_24 11951544228543 11951588432769 44204 -2.304608175 7227 pf_21 resp_pf_21 11951744607819 11951790796068 46188 -2.404796703 7228 pf_21 resp_pf_21 11951844796347 11951877984160 33187 -2.605134923 7230 pf_27 resp_pf_27 11952045134567 11952065327660 20193 -3.206291642 7236 pf_29 resp_pf_29 11952646291286 11952660443343 14152 -3.506887492 7239 pf_21 resp_pf_21 11952946887136 11952995060987 48173 -``` - -Use lat_dist.py to trace the latency distribution: -```bash -$ sudo python examples/usdt_sample/scripts/lat_dist.py -p=25433 -i=30 -f="pf_20" -Attaching probes to pid 25433 -[11:23:47] - -Bucket ptr = 'pf_20' +0.000000000 7754 b'usdt_20' b'resp_usdt_20' 672668584224401 672668625460568 41236 +7.414981834 7828 b'usdt_20' b'resp_usdt_20' 672675999206235 672676011402270 12196 +... +23.948248753 7993 b'usdt_20' b'resp_usdt_20' 672692532473154 672692561680989 29207 +26.352332485 8017 b'usdt_20' b'resp_usdt_20' 672694936556886 672694961690970 25134 +``` + +## Use lat_dist.py to trace the latency distribution + +```bash +# Make sure to replace the pid, the filter value is chosen arbitrarily. +$ sudo python3 examples/usdt_sample/scripts/lat_dist.py -p=2422725 -i=30 -f="usdt_20" +Attaching probes to pid 2422725 +[HH:mm:ss] + +Bucket ptr = b'usdt_20' latency (us) : count distribution 0 -> 1 : 0 | | 2 -> 3 : 0 | | @@ -142,27 +165,367 @@ Bucket ptr = 'pf_20' 128 -> 255 : 0 | | 256 -> 511 : 0 | | 512 -> 1023 : 0 | | - 1024 -> 2047 : 1 |********** | - 2048 -> 4095 : 1 |********** | - 4096 -> 8191 : 0 | | - 8192 -> 16383 : 1 |********** | - 16384 -> 32767 : 4 |****************************************| - 32768 -> 65535 : 3 |****************************** | + 1024 -> 2047 : 1 |***** | + 2048 -> 4095 : 1 |***** | + 4096 -> 8191 : 2 |*********** | + 8192 -> 16383 : 0 | | + 16384 -> 32767 : 3 |***************** | + 32768 -> 65535 : 7 |****************************************| ``` -Use lat_avg.py to trace the moving average of the latencies: +## Use lat_avg.py to trace the moving average of the latencies + +```bash +$ sudo python3 examples/usdt_sample/scripts/lat_avg.py -p=2422725 -i=5 -c=10 -f="usdt_20" +Attaching probes to pid 2422725 +Tracing... Hit Ctrl-C to end. +time input sample_size latency (us) +HH:mm:08 b'usdt_20' 3 29497 +HH:mm:13 b'usdt_20' 3 29497 +HH:mm:18 b'usdt_20' 4 27655 +HH:mm:23 b'usdt_20' 5 28799 +HH:mm:28 b'usdt_20' 7 23644 +``` + +## Attach to the probes, created with SystemTap's dtrace + +-s implies using the systemtap probes, created with dtrace. + ```bash -$ sudo python examples/usdt_sample/scripts/lat_avg.py -p=25433 -i=5 -c=10 -f="pf_2" -Attaching probes to pid 25433 +$ sudo python3 examples/usdt_sample/scripts/lat_avg.py -p=2422725 -i=5 -c=10 -f="usdt_20" -s +Attaching probes to pid 2422725 Tracing... Hit Ctrl-C to end. -[11:28:32] -input count latency (us) -pf_22 3 7807 -pf_23 4 36914 -pf_25 3 31473 -pf_28 2 10627 -pf_27 1 47174 -pf_29 1 8138 -pf_26 1 49121 -pf_20 2 29158 +time input sample_size latency (us) +HH:mm:08 b'usdt_20' 3 29497 +HH:mm:13 b'usdt_20' 3 29497 +HH:mm:18 b'usdt_20' 4 27655 +HH:mm:23 b'usdt_20' 5 28799 +HH:mm:28 b'usdt_20' 7 23644 +``` + +# Building and executing the usdt_sample (clang 13.0.1) + +Build the sample: +```bash +$ clang --version +Ubuntu clang version 13.0.1-++20211124043029+19b8368225dc-1~exp1~20211124043558.23 +... +# Make sure you are in the bcc root folder +$ mkdir -p examples/usdt_sample/build_clang && cd examples/usdt_sample/build_clang +$ cmake .. -DCMAKE_C_COMPILER=clang -DCMAKE_CXX_COMPILER=clang++ +$ make +``` + +## Use tplist.py to list the available probes + +```bash +$ python3 tools/tplist.py -l examples/usdt_sample/build_clang/usdt_sample_lib1/libusdt_sample_lib1.so +examples/usdt_sample/build_clang/usdt_sample_lib1/libusdt_sample_lib1.so usdt_sample_lib1:operation_start +examples/usdt_sample/build_clang/usdt_sample_lib1/libusdt_sample_lib1.so usdt_sample_lib1:operation_start_sdt +examples/usdt_sample/build_clang/usdt_sample_lib1/libusdt_sample_lib1.so usdt_sample_lib1:operation_end +examples/usdt_sample/build_clang/usdt_sample_lib1/libusdt_sample_lib1.so usdt_sample_lib1:operation_end_sdt +$ readelf -n examples/usdt_sample/build_clang/usdt_sample_lib1/libusdt_sample_lib1.so + +Displaying notes found in: .note.gnu.build-id + Owner Data size Description + GNU 0x00000014 NT_GNU_BUILD_ID (unique build ID bitstring) + Build ID: 8814f6c44f9e9df42f29a436af6152d7dcbeb8d9 + +Displaying notes found in: .note.stapsdt + Owner Data size Description + stapsdt 0x00000055 NT_STAPSDT (SystemTap probe descriptors) + Provider: usdt_sample_lib1 + Name: operation_start + Location: 0x000000000000e703, Base: 0x0000000000000000, Semaphore: 0x0000000000000000 + Arguments: -8@-128(%rbp) -8@-136(%rbp) + stapsdt 0x0000005d NT_STAPSDT (SystemTap probe descriptors) + Provider: usdt_sample_lib1 + Name: operation_start_sdt + Location: 0x000000000000e755, Base: 0x0000000000016610, Semaphore: 0x000000000001da48 + Arguments: 8@-144(%rbp) 8@-152(%rbp) + stapsdt 0x00000053 NT_STAPSDT (SystemTap probe descriptors) + Provider: usdt_sample_lib1 + Name: operation_end + Location: 0x00000000000101bc, Base: 0x0000000000000000, Semaphore: 0x0000000000000000 + Arguments: -8@-120(%rbp) -8@-128(%rbp) + stapsdt 0x0000005b NT_STAPSDT (SystemTap probe descriptors) + Provider: usdt_sample_lib1 + Name: operation_end_sdt + Location: 0x0000000000010228, Base: 0x0000000000016610, Semaphore: 0x000000000001da4a + Arguments: 8@-136(%rbp) 8@-144(%rbp) +``` + +## Start the usdt sample application + +```bash +$ examples/usdt_sample/build_clang/usdt_sample_app1/usdt_sample_app1 "usdt" 1 30 10 1 50 +Applying the following parameters: +Input prefix: usdt. +Input range: [1, 30]. +Calls Per Second: 10. +Latency range: [1, 50] ms. +You can now run the bcc scripts, see usdt_sample.md for examples. +pid: 2439214 +Press ctrl-c to exit. +``` + +## Use argdist.py on the individual probes + +```bash +# Make sure to replace the pid +$ sudo python3 tools/argdist.py -p 2439214 -i 5 -C "u:$(pwd)/examples/usdt_sample/build_clang/usdt_sample_lib1/libusdt_sample_lib1.so:operation_start():char*:arg2#input" -z 32 +[HH:mm:ss] +input + COUNT EVENT + 1 arg2 = b'usdt_1' + 1 arg2 = b'usdt_4' +... + 3 arg2 = b'usdt_30' + 3 arg2 = b'usdt_25' + 5 arg2 = b'usdt_18' +``` + +## Use latency.py to trace the operation latencies + +```bash +# Make sure to replace the pid, the filter value is chosen arbitrarily. +$ sudo python3 examples/usdt_sample/scripts/latency.py -p=2439214 -f="usdt_20" +Attaching probes to pid 2439214 +Tracing... Hit Ctrl-C to end. +time(s) id input output start (ns) end (ns) duration (us) +0.000000000 1351 b'usdt_20' b'resp_usdt_20' 673481735317057 673481761592425 26275 +0.400606129 1355 b'usdt_20' b'resp_usdt_20' 673482135923186 673482141074674 5151 +0.600929879 1357 b'usdt_20' b'resp_usdt_20' 673482336246936 673482338400064 2153 +5.610441985 1407 b'usdt_20' b'resp_usdt_20' 673487345759042 673487392977806 47218 +7.213278292 1423 b'usdt_20' b'resp_usdt_20' 673488948595349 673488976845453 28250 +9.016681573 1441 b'usdt_20' b'resp_usdt_20' 673490751998630 673490802198717 50200 +``` + +## Use lat_dist.py to trace the latency distribution + +```bash +# Make sure to replace the pid, the filter value is chosen arbitrarily. +$ sudo python3 examples/usdt_sample/scripts/lat_dist.py -p=2439214 -i=30 -f="usdt_20" +Attaching probes to pid 2439214 +[HH:mm:ss] + +Bucket ptr = b'usdt_20' + latency (us) : count distribution + 0 -> 1 : 0 | | + 2 -> 3 : 0 | | + 4 -> 7 : 0 | | + 8 -> 15 : 0 | | + 16 -> 31 : 0 | | + 32 -> 63 : 0 | | + 64 -> 127 : 0 | | + 128 -> 255 : 0 | | + 256 -> 511 : 0 | | + 512 -> 1023 : 0 | | + 1024 -> 2047 : 0 | | + 2048 -> 4095 : 0 | | + 4096 -> 8191 : 1 |******************** | + 8192 -> 16383 : 2 |****************************************| + 16384 -> 32767 : 1 |******************** | + 32768 -> 65535 : 2 |****************************************| +``` + +## Use lat_avg.py to trace the moving average of the latencies + +```bash +$ sudo python3 examples/usdt_sample/scripts/lat_avg.py -p=2439214 -i=5 -s=10 -f="usdt_20" +Attaching probes to pid 2439214 +Tracing... Hit Ctrl-C to end. +time input sample_size latency (us) +HH:mm:59 b'usdt_20' 1 16226 +HH:mm:04 b'usdt_20' 2 20332 +HH:mm:09 b'usdt_20' 2 20332 +HH:mm:14 b'usdt_20' 5 29657 +HH:mm:19 b'usdt_20' 5 29657 +HH:mm:24 b'usdt_20' 7 33249 +``` + +# Troubleshooting + +## Display the generated BPF program using -v + +```bash +$ sudo python3 examples/usdt_sample/scripts/latency.py -v -p=2439214 -f="usdt_20" +Attaching probes to pid 2439214 +Running from kernel directory at: /lib/modules/5.13.0-22-generic/build +clang -cc1 -triple x86_64-unknown-linux-gnu -emit-llvm-bc -emit-llvm-uselists -disable-free -disable-llvm-verifier -discard-value-names -main-file-name main.c -mrelocation-model static -fno-jump-tables -mframe-pointer=none -fmath-errno -fno-rounding-math -mconstructor-aliases -target-cpu x86-64 -tune-cpu generic -mllvm -treat-scalable-fixed-error-as-warning -debug-info-kind=constructor -dwarf-version=4 -debugger-tuning=gdb -fcoverage-compilation-dir=/usr/src/linux-headers-5.13.0-22-generic -nostdsysteminc -nobuiltininc -resource-dir lib/clang/13.0.1 -isystem /virtual/lib/clang/include -include ./include/linux/kconfig.h -include /virtual/include/bcc/bpf.h -include /virtual/include/bcc/bpf_workaround.h -include /virtual/include/bcc/helpers.h -isystem /virtual/include -I /home/bramv/src/projects/bcc -D __BPF_TRACING__ -I arch/x86/include/ -I arch/x86/include/generated -I include -I arch/x86/include/uapi -I arch/x86/include/generated/uapi -I include/uapi -I include/generated/uapi -D __KERNEL__ -D KBUILD_MODNAME="bcc" -O2 -Wno-deprecated-declarations -Wno-gnu-variable-sized-type-not-at-end -Wno-pragma-once-outside-header -Wno-address-of-packed-member -Wno-unknown-warning-option -Wno-unused-value -Wno-pointer-sign -fdebug-compilation-dir=/usr/src/linux-headers-5.13.0-22-generic -ferror-limit 19 -fgnuc-version=4.2.1 -vectorize-loops -vectorize-slp -faddrsig -D__GCC_HAVE_DWARF2_CFI_ASM=1 -o main.bc -x c /virtual/main.c +#if defined(BPF_LICENSE) +#error BPF_LICENSE cannot be specified through cflags +#endif +#if !defined(CONFIG_CC_STACKPROTECTOR) +#if defined(CONFIG_CC_STACKPROTECTOR_AUTO) \ + || defined(CONFIG_CC_STACKPROTECTOR_REGULAR) \ + || defined(CONFIG_CC_STACKPROTECTOR_STRONG) +#define CONFIG_CC_STACKPROTECTOR +#endif +#endif +#include +__attribute__((always_inline)) +static __always_inline int _bpf_readarg_trace_operation_start_1(struct pt_regs *ctx, void *dest, size_t len) { + if (len != sizeof(int64_t)) return -1; + { u64 __addr = ctx->bp + -128; __asm__ __volatile__("": : :"memory"); int64_t __res = 0x0; bpf_probe_read_user(&__res, sizeof(__res), (void *)__addr); *((int64_t *)dest) = __res; } + return 0; +} +__attribute__((always_inline)) +static __always_inline int _bpf_readarg_trace_operation_start_2(struct pt_regs *ctx, void *dest, size_t len) { + if (len != sizeof(int64_t)) return -1; + { u64 __addr = ctx->bp + -136; __asm__ __volatile__("": : :"memory"); int64_t __res = 0x0; bpf_probe_read_user(&__res, sizeof(__res), (void *)__addr); *((int64_t *)dest) = __res; } + return 0; +} +__attribute__((always_inline)) +static __always_inline int _bpf_readarg_trace_operation_end_1(struct pt_regs *ctx, void *dest, size_t len) { + if (len != sizeof(int64_t)) return -1; + { u64 __addr = ctx->bp + -120; __asm__ __volatile__("": : :"memory"); int64_t __res = 0x0; bpf_probe_read_user(&__res, sizeof(__res), (void *)__addr); *((int64_t *)dest) = __res; } + return 0; +} +__attribute__((always_inline)) +static __always_inline int _bpf_readarg_trace_operation_end_2(struct pt_regs *ctx, void *dest, size_t len) { + if (len != sizeof(int64_t)) return -1; + { u64 __addr = ctx->bp + -128; __asm__ __volatile__("": : :"memory"); int64_t __res = 0x0; bpf_probe_read_user(&__res, sizeof(__res), (void *)__addr); *((int64_t *)dest) = __res; } + return 0; +} +#include +#include + +/** + * @brief Helper method to filter based on the specified inputString. + * @param inputString The operation input string to check against the filter. + * @return True if the specified inputString starts with the hard-coded filter string; otherwise, false. + */ +__attribute__((always_inline)) +static inline bool filter(char const* inputString) +{ + static const char* null_ptr = 0x0; + static const char null_terminator = '\0'; + + static const char filter_string[] = "usdt_20"; ///< The filter string is replaced by python code. + if (null_ptr == inputString) { + return false; + } + // bpf_trace_printk("inputString: '%s'", inputString); + + // Compare until (not including) the null-terminator for filter_string + for (int i = 0; i < sizeof(filter_string) - 1; ++i) { + char c1 = *inputString++; + if (null_terminator == c1) { + return false; // If the null-terminator for inputString was reached, it can not be equal to filter_string. + } + + char c2 = filter_string[i]; + if (c1 != c2) { + return false; + } + } + return true; +} + +/** + * @brief Contains the operation start data to trace. + */ +struct start_data_t +{ + u64 operation_id; ///< The id of the operation. + char input[64]; ///< The input string of the request. + u64 start; ///< Timestamp of the start operation (start timestamp). +}; + +/** + * @brief Contains the operation start data. + * key: the operation id. + * value: The operation start latency data. + */ +BPF_HASH(start_hash, u64, struct start_data_t); + +/** + * @brief Reads the operation request arguments and stores the start data in the hash. + * @param ctx The BPF context. + */ +__attribute__((section(".bpf.fn.trace_operation_start"))) +int trace_operation_start(struct pt_regs* ctx) +{ + + struct start_data_t start_data = {}; + ({ u64 __addr = 0x0; _bpf_readarg_trace_operation_start_2(ctx, &__addr, sizeof(__addr));bpf_probe_read_user(&start_data.input, sizeof(start_data.input), (void *)__addr);}); + + if (!filter(start_data.input)) { return 0; } ///< Replaced by python code. + + _bpf_readarg_trace_operation_start_1(ctx, &start_data.operation_id, sizeof(*(&start_data.operation_id))); + + start_data.start = bpf_ktime_get_ns(); + bpf_map_update_elem((void *)bpf_pseudo_fd(1, -1), &start_data.operation_id, &start_data, BPF_ANY); + return 0; +} + + +/** + * @brief Contains the latency data w.r.t. the complete operation from request to response. + */ +struct end_data_t +{ + u64 operation_id; ///< The id of the operation. + char input[64]; ///< The request (input) string. + char output[64]; ///< The response (output) string. + u64 start; ///< The start timestamp of the operation. + u64 end; ///< The end timestamp of the operation. + u64 duration; ///< The duration of the operation. +}; + +/** + * The output buffer, which will be used to push the latency event data to user space. + */ +BPF_PERF_OUTPUT(operation_event); + +/** + * @brief Reads the operation response arguments, calculates the latency event data, and writes it to the user output buffer. + * @param ctx The BPF context. + */ +__attribute__((section(".bpf.fn.trace_operation_end"))) +int trace_operation_end(struct pt_regs* ctx) +{ + + u64 operation_id; + _bpf_readarg_trace_operation_end_1(ctx, &operation_id, sizeof(*(&operation_id))); + + struct start_data_t* start_data = bpf_map_lookup_elem((void *)bpf_pseudo_fd(1, -1), &operation_id); + if (0 == start_data) { + return 0; + } + + struct end_data_t end_data = {}; + end_data.operation_id = operation_id; + ({ u64 __addr = 0x0; _bpf_readarg_trace_operation_end_2(ctx, &__addr, sizeof(__addr));bpf_probe_read_user(&end_data.output, sizeof(end_data.output), (void *)__addr);}); + end_data.end = bpf_ktime_get_ns(); + end_data.start = start_data->start; + end_data.duration = end_data.end - end_data.start; + __builtin_memcpy(&end_data.input, start_data->input, sizeof(end_data.input)); + + bpf_map_delete_elem((void *)bpf_pseudo_fd(1, -1), &end_data.operation_id); + + bpf_perf_event_output(ctx, bpf_pseudo_fd(1, -2), CUR_CPU_IDENTIFIER, &end_data, sizeof(end_data)); + return 0; +} + +#include +Tracing... Hit Ctrl-C to end. +``` + +## Use bpf_trace_printk + +Add bpf trace statements to the C++ code: + +```C++ +bpf_trace_printk("inputString: '%s'", inputString); +``` + +```bash +$ sudo tail -f /sys/kernel/debug/tracing/trace +... + usdt_sample_app-2439214 [001] d... 635079.194883: bpf_trace_printk: inputString: 'usdt_8' + usdt_sample_app-2439214 [001] d... 635079.295102: bpf_trace_printk: inputString: 'usdt_17' + usdt_sample_app-2439214 [001] d... 635079.395217: bpf_trace_printk: inputString: 'usdt_18' +... ``` diff --git a/examples/usdt_sample/usdt_sample.sh b/examples/usdt_sample/usdt_sample.sh new file mode 100755 index 000000000000..8b1476946ff0 --- /dev/null +++ b/examples/usdt_sample/usdt_sample.sh @@ -0,0 +1,95 @@ +#!/usr/bin/bash + +# sudo apt-get install linux-headers-$(uname -r) "llvm-13*" libclang-13-dev luajit luajit-5.1-dev libelf-dev python3-distutils libdebuginfod-dev arping netperf iperf +# mkdir -p build && cd build +# cmake .. -DPYTHON_CMD=python3 +# make -j4 +# sudo make install + +gcc --version +rm -rf examples/usdt_sample/build_gcc +mkdir -p examples/usdt_sample/build_gcc && pushd examples/usdt_sample/build_gcc +cmake .. +make +popd + +# sudo dnf install systemtap-sdt-dev # For Ubuntu 21.10, other distro's might have differently named packages. +# dtrace -h -s usdt_sample_lib1/src/lib1_sdt.d -o usdt_sample_lib1/include/usdt_sample_lib1/lib1_sdt.h +# dtrace -G -s usdt_sample_lib1/src/lib1_sdt.d -o lib1_sdt.o + +python3 tools/tplist.py -l examples/usdt_sample/build_gcc/usdt_sample_lib1/libusdt_sample_lib1.so +readelf -n examples/usdt_sample/build_gcc/usdt_sample_lib1/libusdt_sample_lib1.so + +examples/usdt_sample/build_gcc/usdt_sample_app1/usdt_sample_app1 "usdt" 1 30 10 1 50 & +pid=$! + +echo "argdist.py - Using non-sdt probes" +sudo python3 tools/argdist.py -p ${pid} -i 5 -C "u:$(pwd)/examples/usdt_sample/build_gcc/usdt_sample_lib1/libusdt_sample_lib1.so:operation_start():char*:arg2#input" -z 32 & +sleep 30 +sudo pkill -f "\\-p.${pid}" +echo "argdist.py - Using sdt probes" +sudo python3 tools/argdist.py -p ${pid} -i 5 -C "u:$(pwd)/examples/usdt_sample/build_gcc/usdt_sample_lib1/libusdt_sample_lib1.so:operation_start_sdt():char*:arg2#input" -z 32 & +sleep 30 +sudo pkill -f "\\-p.${pid}" +sudo python3 examples/usdt_sample/scripts/latency.py -p=${pid} -f="usdt_20" & +sleep 30 +sudo pkill -f "\\-p.${pid}" +sudo python3 examples/usdt_sample/scripts/latency.py -p=${pid} -f="usdt_20" -s & +sleep 30 +sudo pkill -f "\\-p.${pid}" +sudo python3 examples/usdt_sample/scripts/lat_dist.py -p=${pid} -i=5 -f="usdt_20" & +sleep 30 +sudo pkill -f "\\-p.${pid}" +sudo python3 examples/usdt_sample/scripts/lat_dist.py -p=${pid} -i=5 -f="usdt_20" -s & +sleep 30 +sudo pkill -f "\\-p.${pid}" +sudo python3 examples/usdt_sample/scripts/lat_avg.py -p=${pid} -i=5 -c=10 -f="usdt_20" & +sleep 30 +sudo pkill -f "\\-p.${pid}" +sudo python3 examples/usdt_sample/scripts/lat_avg.py -p=${pid} -i=5 -c=10 -f="usdt_20" -s & +sleep 30 +sudo pkill -f "\\-p.${pid}" + +sudo pkill -f "examples/usdt_sample/build_.*/usdt_sample_app1/usdt_sample_app1" + +clang --version +rm -rf examples/usdt_sample/build_clang +mkdir -p examples/usdt_sample/build_clang && pushd examples/usdt_sample/build_clang +cmake .. -DCMAKE_C_COMPILER=clang -DCMAKE_CXX_COMPILER=clang++ +make +popd + +python3 tools/tplist.py -l examples/usdt_sample/build_clang/usdt_sample_lib1/libusdt_sample_lib1.so +readelf -n examples/usdt_sample/build_clang/usdt_sample_lib1/libusdt_sample_lib1.so + +examples/usdt_sample/build_clang/usdt_sample_app1/usdt_sample_app1 "usdt" 1 30 10 1 50 & +pid=$! + +echo "argdist.py - Using non-sdt probes" +sudo python3 tools/argdist.py -p ${pid} -i 5 -C "u:$(pwd)/examples/usdt_sample/build_clang/usdt_sample_lib1/libusdt_sample_lib1.so:operation_start():char*:arg2#input" -z 32 & +sleep 30 +sudo pkill -f "\\-p.${pid}" +echo "argdist.py - Using sdt probes" +sudo python3 tools/argdist.py -p ${pid} -i 5 -C "u:$(pwd)/examples/usdt_sample/build_clang/usdt_sample_lib1/libusdt_sample_lib1.so:operation_start_sdt():char*:arg2#input" -z 32 & +sleep 30 +sudo pkill -f "\\-p.${pid}" +sudo python3 examples/usdt_sample/scripts/latency.py -p=${pid} -f="usdt_20" & +sleep 30 +sudo pkill -f "\\-p.${pid}" +sudo python3 examples/usdt_sample/scripts/latency.py -p=${pid} -f="usdt_20" -s & +sleep 30 +sudo pkill -f "\\-p.${pid}" +sudo python3 examples/usdt_sample/scripts/lat_dist.py -p=${pid} -i=5 -f="usdt_20" & +sleep 30 +sudo pkill -f "\\-p.${pid}" +sudo python3 examples/usdt_sample/scripts/lat_dist.py -p=${pid} -i=5 -f="usdt_20" -s & +sleep 30 +sudo pkill -f "\\-p.${pid}" +sudo python3 examples/usdt_sample/scripts/lat_avg.py -p=${pid} -i=5 -c=10 -f="usdt_20" & +sleep 30 +sudo pkill -f "\\-p.${pid}" +sudo python3 examples/usdt_sample/scripts/lat_avg.py -p=${pid} -i=5 -c=10 -f="usdt_20" -s & +sleep 30 +sudo pkill -f "\\-p.${pid}" + +sudo pkill -f "examples/usdt_sample/build_.*/usdt_sample_app1/usdt_sample_app1" diff --git a/examples/usdt_sample/usdt_sample_app1/CMakeLists.txt b/examples/usdt_sample/usdt_sample_app1/CMakeLists.txt index b447e21049c3..be46c2889c0a 100644 --- a/examples/usdt_sample/usdt_sample_app1/CMakeLists.txt +++ b/examples/usdt_sample/usdt_sample_app1/CMakeLists.txt @@ -1,19 +1,11 @@ -cmake_minimum_required(VERSION 3.0) +cmake_minimum_required(VERSION 3.12) project(usdt_sample_app1) -include_directories( - ${USDT_SAMPLE_LIB1_INCLUDE_DIR} -) - -link_directories( - ${USDT_SAMPLE_LIB1_LINK_DIR} -) - add_executable( ${PROJECT_NAME} ${CMAKE_CURRENT_SOURCE_DIR}/main.cpp ) target_link_libraries( ${PROJECT_NAME} - ${USDT_SAMPLE_LIB1_LIB} + usdt_sample_lib1 pthread ) diff --git a/examples/usdt_sample/usdt_sample_lib1/CMakeLists.txt b/examples/usdt_sample/usdt_sample_lib1/CMakeLists.txt index 3f1c7b242b87..893cebc9989f 100644 --- a/examples/usdt_sample/usdt_sample_lib1/CMakeLists.txt +++ b/examples/usdt_sample/usdt_sample_lib1/CMakeLists.txt @@ -1,4 +1,4 @@ -cmake_minimum_required(VERSION 3.0) +cmake_minimum_required(VERSION 3.12) project(usdt_sample_lib1) # Define variables. @@ -7,39 +7,50 @@ set(USDT_SAMPLE_LIB1_SRC_DIR ${CMAKE_CURRENT_SOURCE_DIR}/src CACHE STRING "USDT_ set(USDT_SAMPLE_LIB1_LINK_DIR ${CMAKE_CURRENT_BINARY_DIR} CACHE STRING "USDT_SAMPLE_LIB1_LINK_DIR" FORCE) set(USDT_SAMPLE_LIB1_LIB ${PROJECT_NAME} CACHE STRING "USDT_SAMPLE_LIB1_LIB" FORCE) set(USDT_SAMPLE_LIB1_GENERATED ${CMAKE_CURRENT_BINARY_DIR}/generated) +set(USDT_SAMPLE_SDT_HEADER ${USDT_SAMPLE_LIB1_SRC_DIR}/lib1_sdt.h) +set(USDT_SAMPLE_SDT_OBJECT ${USDT_SAMPLE_LIB1_GENERATED}/lib1_sdt.o) +set(USDT_SAMPLE_SDT_PROBES ${USDT_SAMPLE_LIB1_SRC_DIR}/lib1_sdt.d) -## Start - N.B. Following section only relevant when using systemtap-sdt-devel. +add_library( ${PROJECT_NAME} SHARED + ${USDT_SAMPLE_LIB1_SRC_DIR}/lib1.cpp +) -# Create usdt header file. -# N.B. ${USDT_SAMPLE_LIB1_INCLUDE_DIR}/usdt_sample_lib1/lib1_sdt.h must be removed manually in order for it to be (re-)created. -# i.e. after making changes to libt_sdt.d -#add_custom_command( -# OUTPUT ${USDT_SAMPLE_LIB1_INCLUDE_DIR}/usdt_sample_lib1/lib1_sdt.h -# PRE_BUILD -# COMMAND dtrace -h -s ${USDT_SAMPLE_LIB1_SRC_DIR}/lib1_sdt.d -o ${USDT_SAMPLE_LIB1_INCLUDE_DIR}/usdt_sample_lib1/lib1_sdt.h -# COMMENT "Create usdt probes header file" -#) +target_include_directories( ${PROJECT_NAME} + PRIVATE + # For folly StaticTracepoint.h: + ${CMAKE_CURRENT_SOURCE_DIR}/../../../tests/python/include + PUBLIC + ${USDT_SAMPLE_LIB1_INCLUDE_DIR} +) -# Create usdt object file. -#file(MAKE_DIRECTORY ${USDT_SAMPLE_LIB1_GENERATED}) -#add_custom_command( -# OUTPUT ${USDT_SAMPLE_LIB1_GENERATED}/lib1_sdt.o -# PRE_BUILD -# COMMAND dtrace -G -s ${USDT_SAMPLE_LIB1_SRC_DIR}/lib1_sdt.d -o ${USDT_SAMPLE_LIB1_GENERATED}/lib1_sdt.o -# COMMENT "Create usdt probes object file" -#) +target_link_libraries( ${PROJECT_NAME} + ${USDT_SAMPLE_SDT_OBJECT} +) -## End +## Start - N.B. Following section is relevant for when using systemtap-sdt-devel to define the probes. -include_directories( - ${USDT_SAMPLE_LIB1_INCLUDE_DIR} - # For folly StaticTracepoint.h: - ${CMAKE_CURRENT_SOURCE_DIR}/../../../tests/python/include +# Create usdt header file. +add_custom_target( ${PROJECT_NAME}_HDR_CLEAN + COMMAND rm -f ${USDT_SAMPLE_SDT_HEADER} + COMMENT "Remove generated header" ) +add_custom_target( ${PROJECT_NAME}_HDR + COMMAND dtrace -h -s ${USDT_SAMPLE_SDT_PROBES} -o ${USDT_SAMPLE_SDT_HEADER} + COMMENT "Create usdt probes header file" +) +add_dependencies(${PROJECT_NAME}_HDR ${PROJECT_NAME}_HDR_CLEAN) -add_library( ${PROJECT_NAME} SHARED -## Only relevant when using systemtap-sdt-devel -# ${USDT_SAMPLE_LIB1_INCLUDE_DIR}/usdt_sample_lib1/lib1_sdt.h -# ${USDT_SAMPLE_LIB1_GENERATED}/lib1_sdt.o - ${USDT_SAMPLE_LIB1_SRC_DIR}/lib1.cpp +# Create usdt object file. +add_custom_target( ${PROJECT_NAME}_CLEAN + COMMAND rm -rf ${USDT_SAMPLE_LIB1_GENERATED} && mkdir -p ${USDT_SAMPLE_LIB1_GENERATED} + COMMENT "Recreate usdt probes generated folder" ) +add_custom_target( ${PROJECT_NAME}_OBJ + COMMAND dtrace -G -s ${USDT_SAMPLE_SDT_PROBES} -o ${USDT_SAMPLE_SDT_OBJECT} + COMMENT "Create usdt probes object file" +) +add_dependencies(${PROJECT_NAME}_OBJ ${PROJECT_NAME}_CLEAN) + +add_dependencies(${PROJECT_NAME} ${PROJECT_NAME}_HDR ${PROJECT_NAME}_OBJ) + +## End diff --git a/examples/usdt_sample/usdt_sample_lib1/include/usdt_sample_lib1/lib1_sdt.h b/examples/usdt_sample/usdt_sample_lib1/include/usdt_sample_lib1/lib1_sdt.h deleted file mode 100644 index 6b8a51a27756..000000000000 --- a/examples/usdt_sample/usdt_sample_lib1/include/usdt_sample_lib1/lib1_sdt.h +++ /dev/null @@ -1,36 +0,0 @@ -// N.B. This file is not used by this usdt_sample. Instead, the StaticTracepoint.h file from folly is used. -// It is here only for demonstration purposes. - -/* Generated by the Systemtap dtrace wrapper */ - - -#define _SDT_HAS_SEMAPHORES 1 - - -#define STAP_HAS_SEMAPHORES 1 /* deprecated */ - - -#include - -/* USDT_SAMPLE_LIB1_OPERATION_START ( uint64_t operation_id, const char * input ) */ -#if defined STAP_SDT_V1 -#define USDT_SAMPLE_LIB1_OPERATION_START_ENABLED() __builtin_expect (operation_start_semaphore, 0) -#define usdt_sample_lib1_operation_start_semaphore operation_start_semaphore -#else -#define USDT_SAMPLE_LIB1_OPERATION_START_ENABLED() __builtin_expect (usdt_sample_lib1_operation_start_semaphore, 0) -#endif -__extension__ extern unsigned short usdt_sample_lib1_operation_start_semaphore __attribute__ ((unused)) __attribute__ ((section (".probes"))); -#define USDT_SAMPLE_LIB1_OPERATION_START(arg1, arg2) \ -DTRACE_PROBE2 (usdt_sample_lib1, operation_start, arg1, arg2) - -/* USDT_SAMPLE_LIB1_OPERATION_END ( uint64_t operation_id, const char * output ) */ -#if defined STAP_SDT_V1 -#define USDT_SAMPLE_LIB1_OPERATION_END_ENABLED() __builtin_expect (operation_end_semaphore, 0) -#define usdt_sample_lib1_operation_end_semaphore operation_end_semaphore -#else -#define USDT_SAMPLE_LIB1_OPERATION_END_ENABLED() __builtin_expect (usdt_sample_lib1_operation_end_semaphore, 0) -#endif -__extension__ extern unsigned short usdt_sample_lib1_operation_end_semaphore __attribute__ ((unused)) __attribute__ ((section (".probes"))); -#define USDT_SAMPLE_LIB1_OPERATION_END(arg1, arg2) \ -DTRACE_PROBE2 (usdt_sample_lib1, operation_end, arg1, arg2) - diff --git a/examples/usdt_sample/usdt_sample_lib1/src/lib1.cpp b/examples/usdt_sample/usdt_sample_lib1/src/lib1.cpp index f19a7eadb5b1..4eb9fcb47bcb 100644 --- a/examples/usdt_sample/usdt_sample_lib1/src/lib1.cpp +++ b/examples/usdt_sample/usdt_sample_lib1/src/lib1.cpp @@ -10,7 +10,7 @@ #include "folly/tracing/StaticTracepoint.h" // When using systemtap-sdt-devel, the following file should be included: -// #include "usdt_sample_lib1/lib1_sdt.h" +#include "lib1_sdt.h" OperationRequest::OperationRequest(const std::string& input_) : _input(input_) @@ -33,14 +33,12 @@ std::shared_future OperationProvider::executeAsync(const Oper static std::atomic operationIdCounter(0); std::uint64_t operationId = operationIdCounter++; + // We create two probes at the same location. One created using the FOLLY_SDT macro, one created using dtrace. FOLLY_SDT(usdt_sample_lib1, operation_start, operationId, request.input().c_str()); - -/* Below an example of how to use this sample with systemtap-sdt-devel: - if (USDT_SAMPLE_LIB1_OPERATION_START_ENABLED()) { + if (USDT_SAMPLE_LIB1_SDT_OPERATION_START_SDT_ENABLED()) { //std::cout << "operation_start probe enabled." << std::endl; - USDT_SAMPLE_LIB1_OPERATION_START(operationId, &inputBuf); + USDT_SAMPLE_LIB1_SDT_OPERATION_START_SDT(operationId, request.input().c_str()); } -*/ auto latencyMs = _dis(_gen); @@ -50,14 +48,12 @@ std::shared_future OperationProvider::executeAsync(const Oper auto output = std::string("resp_") + request.input(); OperationResponse response(output); + // We create two probes at the same location. One created using the FOLLY_SDT macro, one created using dtrace. FOLLY_SDT(usdt_sample_lib1, operation_end, operationId, response.output().c_str()); - -/* Below an example of how to use this sample with systemtap-sdt-devel: - if (USDT_SAMPLE_LIB1_OPERATION_END_ENABLED()) { + if (USDT_SAMPLE_LIB1_SDT_OPERATION_END_SDT_ENABLED()) { //std::cout << "operation_end probe enabled." << std::endl; - USDT_SAMPLE_LIB1_OPERATION_END(operationId, &outputBuf); + USDT_SAMPLE_LIB1_SDT_OPERATION_END_SDT(operationId, response.output().c_str()); } -*/ return response; }); diff --git a/examples/usdt_sample/usdt_sample_lib1/src/lib1_sdt.d b/examples/usdt_sample/usdt_sample_lib1/src/lib1_sdt.d index 4f7129e5edd2..1819ee0c3c30 100644 --- a/examples/usdt_sample/usdt_sample_lib1/src/lib1_sdt.d +++ b/examples/usdt_sample/usdt_sample_lib1/src/lib1_sdt.d @@ -1,7 +1,7 @@ # This file is only relevant when using systemtap-sdt-devel (see usdt_sample.md). # This usdt_sample uses the StaticTracepoint.h header file (from folly) instead. -provider usdt_sample_lib1 +provider usdt_sample_lib1_sdt { - probe operation_start(uint64_t operation_id, const char* input); - probe operation_end(uint64_t operation_id, const char* output); + probe operation_start_sdt(uint64_t operation_id, const char* input); + probe operation_end_sdt(uint64_t operation_id, const char* output); }; diff --git a/examples/usdt_sample/usdt_sample_lib1/src/lib1_sdt.h b/examples/usdt_sample/usdt_sample_lib1/src/lib1_sdt.h new file mode 100644 index 000000000000..de2b76f91653 --- /dev/null +++ b/examples/usdt_sample/usdt_sample_lib1/src/lib1_sdt.h @@ -0,0 +1,33 @@ +/* Generated by the Systemtap dtrace wrapper */ + + +#define _SDT_HAS_SEMAPHORES 1 + + +#define STAP_HAS_SEMAPHORES 1 /* deprecated */ + + +#include + +/* USDT_SAMPLE_LIB1_SDT_OPERATION_START_SDT ( uint64_t operation_id, const char* input ) */ +#if defined STAP_SDT_V1 +#define USDT_SAMPLE_LIB1_SDT_OPERATION_START_SDT_ENABLED() __builtin_expect (operation_start_sdt_semaphore, 0) +#define usdt_sample_lib1_sdt_operation_start_sdt_semaphore operation_start_sdt_semaphore +#else +#define USDT_SAMPLE_LIB1_SDT_OPERATION_START_SDT_ENABLED() __builtin_expect (usdt_sample_lib1_sdt_operation_start_sdt_semaphore, 0) +#endif +__extension__ extern unsigned short usdt_sample_lib1_sdt_operation_start_sdt_semaphore __attribute__ ((unused)) __attribute__ ((section (".probes"))); +#define USDT_SAMPLE_LIB1_SDT_OPERATION_START_SDT(arg1, arg2) \ +DTRACE_PROBE2 (usdt_sample_lib1_sdt, operation_start_sdt, arg1, arg2) + +/* USDT_SAMPLE_LIB1_SDT_OPERATION_END_SDT ( uint64_t operation_id, const char* output ) */ +#if defined STAP_SDT_V1 +#define USDT_SAMPLE_LIB1_SDT_OPERATION_END_SDT_ENABLED() __builtin_expect (operation_end_sdt_semaphore, 0) +#define usdt_sample_lib1_sdt_operation_end_sdt_semaphore operation_end_sdt_semaphore +#else +#define USDT_SAMPLE_LIB1_SDT_OPERATION_END_SDT_ENABLED() __builtin_expect (usdt_sample_lib1_sdt_operation_end_sdt_semaphore, 0) +#endif +__extension__ extern unsigned short usdt_sample_lib1_sdt_operation_end_sdt_semaphore __attribute__ ((unused)) __attribute__ ((section (".probes"))); +#define USDT_SAMPLE_LIB1_SDT_OPERATION_END_SDT(arg1, arg2) \ +DTRACE_PROBE2 (usdt_sample_lib1_sdt, operation_end_sdt, arg1, arg2) +