1# libatrace_rust benchmarks 2 3Benchmarks to compare the performance of Rust ATrace bindings with directly calling the 4`libcutils` methods from C++. 5 6## Benchmarks 7 8### ATrace wrapper benchmarks 9 10There are two binaries implementing the same benchmarks: 11 12* `libatrace_rust_benchmark` (`atrace_benchmark.rs`) for Rust. 13* `libatrace_rust_benchmark_cc` (`atrace_benchmark.cc`) for C++. 14 15The benchmarks emit ATrace events with tracing off and tracing on. `atrace_begin` is measured 16with short and long event names to check if the string length affects timings. For example, 17`tracing_on_begin/1000` measures `atrace_begin` with a 1000-character name and tracing enabled. 18 19### ATrace tracing subscriber benchmark 20 21There is a benchmark for the tracing crate subscriber - `libatrace_tracing_subscriber_benchmark`. 22We use it to check overhead over the base `libatrace_rust`. 23 24Similarly to the wrapper benchmarks, the subscriber is measured with tracing off and on. There are 25cases with and without extra fields to measure the cost of formatting. Cases that start with 26`filtered_` measure the subscriber in filtering mode with tracing disabled. 27 28## Running the benchmarks 29 30To run the benchmarks, push the binaries to the device with `adb` and launch them via `adb shell`. 31You may need to push dynamic libraries they depend on as well if they're not present on device and 32run with `LD_LIBRARY_PATH`. 33 34Do not enable ATrace collectors. The benchmarks effectively emit events in a loop and will spam 35any trace and distort performance results. 36 37The benchmarks will override system properties to enable or disable events, specifically ATrace App 38event collection in `debug.atrace.app_number` and `debug.atrace.app_0`. After a successful execution 39the events will be disabled. 40 41## Results 42 43The timings are not representative of actual cost of fully enabling tracing, only of emitting 44events via API, since there's nothing receiving the events. 45 46The tests were done on a `aosp_cf_x86_64_phone-userdebug` Cuttlefish VM. Execution times on real 47device may be different but we expect similar relative performance between Rust wrappers and C. 48 49*If you notice that measurements with tracing off and tracing on have similar times, it might mean 50that enabling ATrace events failed and you need to debug the benchmark.* 51 52### ATrace wrapper 53 54Rust results from `libatrace_rust_benchmark 2>&1 | grep time`: 55 56```text 57tracing_off_begin/10 time: [6.0211 ns 6.0382 ns 6.0607 ns] 58tracing_off_begin/1000 time: [6.0119 ns 6.0418 ns 6.0823 ns] 59tracing_off_end time: [6.5417 ns 6.6801 ns 6.8131 ns] 60tracing_on_begin/10 time: [1.2847 µs 1.2929 µs 1.3044 µs] 61tracing_on_begin/1000 time: [1.5395 µs 1.5476 µs 1.5580 µs] 62tracing_on_end time: [1.1153 µs 1.1208 µs 1.1276 µs] 63``` 64 65C++ results from `libatrace_rust_benchmark_cc`: 66 67```text 68------------------------------------------------------------------------ 69Benchmark Time CPU Iterations 70------------------------------------------------------------------------ 71BM_TracingOffAtraceBegin/10 4.00 ns 3.96 ns 175953732 72BM_TracingOffAtraceBegin/1000 4.05 ns 4.02 ns 176298494 73BM_TracingOffAtraceEnd 4.08 ns 4.05 ns 176422059 74BM_TracingOnAtraceBegin/10 1119 ns 1110 ns 640816 75BM_TracingOnAtraceBegin/1000 1151 ns 1142 ns 615781 76BM_TracingOnAtraceEnd 1076 ns 1069 ns 653646 77``` 78 79### ATrace tracing subscriber 80 81The tracing subscriber time consists of the underlying `libatrace_rust` call plus the time spent in 82the subscriber itself. 83 84Results from `libatrace_tracing_subscriber_benchmark 2>&1 | grep time`: 85 86```text 87tracing_off_event time: [47.444 ns 47.945 ns 48.585 ns] 88filtered_event time: [26.852 ns 26.942 ns 27.040 ns] 89tracing_off_event_args time: [80.597 ns 80.997 ns 81.475 ns] 90filtered_event_args time: [26.680 ns 26.782 ns 26.887 ns] 91tracing_off_span time: [316.48 ns 317.72 ns 319.12 ns] 92filtered_span time: [27.900 ns 27.959 ns 28.018 ns] 93tracing_off_span_args time: [364.92 ns 367.57 ns 370.95 ns] 94filtered_span_args time: [27.625 ns 27.919 ns 28.207 ns] 95tracing_on_event time: [1.4639 µs 1.4805 µs 1.4954 µs] 96tracing_on_event_args time: [2.0088 µs 2.0197 µs 2.0314 µs] 97tracing_on_span time: [2.7907 µs 2.7996 µs 2.8103 µs] 98tracing_on_span_args time: [3.6846 µs 3.6992 µs 3.7168 µs] 99``` 100