Add a benchmark for the tracing subscriber

Measure the times so that we can optimize them.

Bug: 293435349
Test: Run benchmarks on aosp_cf_x86_64_phone
Change-Id: I2f5c23254533a92d122fab35f18bdbf4cafb19b2

5 files changed, 232 insertions, 31 deletions

diff --git a/libatrace_rust/benchmark/Android.bp b/libatrace_rust/benchmark/Android.bp
index 7f219921..9ab9070b 100644
--- a/libatrace_rust/benchmark/Android.bp
+++ b/libatrace_rust/benchmark/Android.bp
@@ -7,8 +7,34 @@ rust_binary {
     srcs: ["src/atrace_benchmark.rs"],
     rustlibs: [
         "libatrace_rust",
+        "libatrace_rust_benchmark_common",
         "libcriterion",
     ],
+}
+
+rust_binary {
+    name: "libatrace_tracing_subscriber_benchmark",
+    srcs: ["src/tracing_subscriber_benchmark.rs"],
+    rustlibs: [
+        "libatrace_rust_benchmark_common",
+        "libatrace_tracing_subscriber",
+        "libcriterion",
+        "libtracing",
+        "libtracing_subscriber",
+    ],
+}
+
+rust_library {
+    name: "libatrace_rust_benchmark_common",
+    crate_name: "atrace_rust_benchmark_common",
+    srcs: ["src/atrace_benchmark_common.rs"],
+    rustlibs: [
+        "libcriterion",
+    ],
+    shared_libs: [
+        "libcutils",
+        "liblog",
+    ],
     static_libs: [
         "libatrace_benchmark_trace_enabler",
     ],
diff --git a/libatrace_rust/benchmark/README.md b/libatrace_rust/benchmark/README.md
index 27af5176..b80d1627 100644
--- a/libatrace_rust/benchmark/README.md
+++ b/libatrace_rust/benchmark/README.md
@@ -3,6 +3,10 @@
 Benchmarks to compare the performance of Rust ATrace bindings with directly calling the
 `libcutils` methods from C++.
 
+## Benchmarks
+
+### ATrace wrapper benchmarks
+
 There are two binaries implementing the same benchmarks:
 
 * `libatrace_rust_benchmark` (`atrace_benchmark.rs`) for Rust.
@@ -12,6 +16,14 @@ The benchmarks emit ATrace events with tracing off and tracing on. `atrace_begin
 with short and long event names to check if the string length affects timings. For example,
 `tracing_on_begin/1000` measures `atrace_begin` with a 1000-character name and tracing enabled.
 
+### ATrace tracing subscriber benchmark
+
+There is a benchmark for the tracing crate subscriber - `libatrace_tracing_subscriber_benchmark`.
+We use it to check overhead over the base `libatrace_rust`.
+
+Similarly to the wrapper benchmarks, the subscriber is measured with tracing off and on. There are
+cases with and without extra fields to measure the cost of formatting.
+
 ## Running the benchmarks
 
 To run the benchmarks, push the binaries to the device with `adb` and launch them via `adb shell`.
@@ -33,6 +45,11 @@ events via API, since there's nothing receiving the events.
 The tests were done on a `aosp_cf_x86_64_phone-userdebug` Cuttlefish VM. Execution times on real
 device may be different but we expect similar relative performance between Rust wrappers and C.
 
+*If you notice that measurements with tracing off and tracing on have similar times, it might mean
+that enabling ATrace events failed and you need to debug the benchmark.*
+
+### ATrace wrapper benchmark results
+
 Rust results from `libatrace_rust_benchmark 2>&1 | grep time`:
 
 ```text
@@ -58,5 +75,20 @@ BM_TracingOnAtraceBegin/1000        1151 ns         1142 ns       615781
 BM_TracingOnAtraceEnd               1076 ns         1069 ns       653646
 ```
 
-*If you notice that measurements with tracing off and tracing on have similar times, it might mean
-that enabling ATrace events failed and you need to debug the benchmark.*
+### ATrace tracing subscriber benchmark results
+
+The tracing subscriber time consists of the underlying `libatrace_rust` call plus the time spent in
+the subscriber itself.
+
+Results from `libatrace_tracing_subscriber_benchmark 2>&1 | grep time`:
+
+```text
+tracing_off_event       time:   [312.28 ns 314.32 ns 316.71 ns]
+tracing_off_event_args  time:   [2.1963 µs 2.2101 µs 2.2257 µs]
+tracing_off_span        time:   [686.20 ns 707.75 ns 727.21 ns]
+tracing_off_span_args   time:   [2.8813 µs 2.8928 µs 2.9044 µs]
+tracing_on_event        time:   [1.6981 µs 1.7117 µs 1.7264 µs]
+tracing_on_event_args   time:   [3.6242 µs 3.6466 µs 3.6718 µs]
+tracing_on_span         time:   [3.1288 µs 3.1446 µs 3.1612 µs]
+tracing_on_span_args    time:   [5.3117 µs 5.3344 µs 5.3598 µs]
+```
diff --git a/libatrace_rust/benchmark/src/atrace_benchmark.rs b/libatrace_rust/benchmark/src/atrace_benchmark.rs
index da9d0a49..3614569a 100644
--- a/libatrace_rust/benchmark/src/atrace_benchmark.rs
+++ b/libatrace_rust/benchmark/src/atrace_benchmark.rs
@@ -15,37 +15,9 @@
 //! Benchmark for ATrace bindings.
 
 use atrace::AtraceTag;
+use atrace_rust_benchmark_common::{new_criterion, turn_tracing_off, turn_tracing_on};
 use criterion::{BenchmarkId, Criterion};
 
-extern "C" {
-    fn disable_app_atrace();
-    fn enable_atrace_for_single_app(name: *const std::os::raw::c_char);
-}
-
-fn turn_tracing_off() {
-    // SAFETY: This call is always safe.
-    unsafe {
-        disable_app_atrace();
-    }
-}
-
-fn turn_tracing_on() {
-    let procname = std::ffi::CString::new(std::env::args().next().unwrap()).unwrap();
-    // SAFETY: `procname` is a valid C string and the function doesn't store it after it returns.
-    unsafe {
-        enable_atrace_for_single_app(procname.as_ptr());
-    }
-}
-
-fn new_criterion() -> Criterion {
-    let path = "/data/local/tmp/criterion/benchmarks";
-    std::fs::create_dir_all(path).unwrap_or_else(|e| {
-        panic!("The criterion folder should be possible to create at {}: {}", path, e)
-    });
-    std::env::set_var("CRITERION_HOME", path);
-    Criterion::default()
-}
-
 fn bench_tracing_off_begin(c: &mut Criterion, name_len: usize) {
     turn_tracing_off();
     let name = "0".repeat(name_len);
diff --git a/libatrace_rust/benchmark/src/atrace_benchmark_common.rs b/libatrace_rust/benchmark/src/atrace_benchmark_common.rs
new file mode 100644
index 00000000..6078d164
--- /dev/null
+++ b/libatrace_rust/benchmark/src/atrace_benchmark_common.rs
@@ -0,0 +1,53 @@
+// Copyright (C) 2023 The Android Open Source Project
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+//! Utilities to benchmark ATrace in Rust.
+
+use criterion::Criterion;
+
+// We could use bindgen to generate these bindings automatically but the signatures are simple and
+// we don't expect them to change much (if at all). So we specify them manually and skip having an
+// intermediate target.
+extern "C" {
+    fn disable_app_atrace();
+    fn enable_atrace_for_single_app(name: *const std::os::raw::c_char);
+}
+
+/// Disables ATrace for all apps (ATRACE_TAG_APP).
+pub fn turn_tracing_off() {
+    // SAFETY: This call is always safe.
+    unsafe {
+        disable_app_atrace();
+    }
+}
+
+/// Enables ATrace for this app.
+pub fn turn_tracing_on() {
+    // ATrace uses command line for per-process tracing control, so env::current_exe won't work.
+    let procname = std::ffi::CString::new(std::env::args().next().unwrap()).unwrap();
+    // SAFETY: `procname` is a valid C string and the function doesn't store it after it returns.
+    unsafe {
+        enable_atrace_for_single_app(procname.as_ptr());
+    }
+}
+
+/// Creates a new configured instance of Criterion for benchmarking.
+pub fn new_criterion() -> Criterion {
+    let path = "/data/local/tmp/criterion/benchmarks";
+    std::fs::create_dir_all(path).unwrap_or_else(|e| {
+        panic!("The criterion folder should be possible to create at {}: {}", path, e)
+    });
+    std::env::set_var("CRITERION_HOME", path);
+    Criterion::default()
+}
diff --git a/libatrace_rust/benchmark/src/tracing_subscriber_benchmark.rs b/libatrace_rust/benchmark/src/tracing_subscriber_benchmark.rs
new file mode 100644
index 00000000..07899496
--- /dev/null
+++ b/libatrace_rust/benchmark/src/tracing_subscriber_benchmark.rs
@@ -0,0 +1,118 @@
+// Copyright (C) 2023 The Android Open Source Project
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+//! Benchmark for ATrace tracing subscriber.
+
+use atrace_rust_benchmark_common::{new_criterion, turn_tracing_off, turn_tracing_on};
+use atrace_tracing_subscriber::AtraceSubscriber;
+use criterion::Criterion;
+use tracing_subscriber::prelude::__tracing_subscriber_SubscriberExt;
+
+fn bench_with_subscriber<F>(c: &mut Criterion, name: &str, mut f: F)
+where
+    F: FnMut(),
+{
+    let subscriber = tracing_subscriber::registry().with(AtraceSubscriber::default());
+    tracing::subscriber::with_default(subscriber, || {
+        c.bench_function(name, |b| b.iter(&mut f));
+    });
+}
+
+fn bench_tracing_off_event(c: &mut Criterion) {
+    turn_tracing_off();
+    bench_with_subscriber(c, "tracing_off_event", || tracing::info!("bench info event"));
+}
+
+fn bench_tracing_off_event_args(c: &mut Criterion) {
+    turn_tracing_off();
+    bench_with_subscriber(c, "tracing_off_event_args", || {
+        tracing::info!(debug_arg1 = 123,
+            debug_arg2 = "argument",
+            debug_arg3 = ?Vec::from([1, 2, 3, 4]),
+            debug_arg4 = "last",
+            "bench info event")
+    });
+}
+
+fn bench_tracing_off_span(c: &mut Criterion) {
+    turn_tracing_off();
+    bench_with_subscriber(c, "tracing_off_span", || {
+        let _entered = tracing::info_span!("bench info span").entered();
+    });
+}
+
+fn bench_tracing_off_span_args(c: &mut Criterion) {
+    turn_tracing_off();
+    bench_with_subscriber(c, "tracing_off_span_args", || {
+        let _entered = tracing::info_span!("bench info span", debug_arg1 = 123,
+            debug_arg2 = "argument",
+            debug_arg3 = ?Vec::from([1, 2, 3, 4]),
+            debug_arg4 = "last")
+        .entered();
+    });
+}
+
+fn bench_tracing_on_event(c: &mut Criterion) {
+    turn_tracing_on();
+    bench_with_subscriber(c, "tracing_on_event", || tracing::info!("bench info event"));
+    turn_tracing_off();
+}
+
+fn bench_tracing_on_event_args(c: &mut Criterion) {
+    turn_tracing_on();
+    bench_with_subscriber(c, "tracing_on_event_args", || {
+        tracing::info!(debug_arg1 = 123,
+            debug_arg2 = "argument",
+            debug_arg3 = ?Vec::from([1, 2, 3, 4]),
+            debug_arg4 = "last",
+            "bench info event")
+    });
+    turn_tracing_off();
+}
+
+fn bench_tracing_on_span(c: &mut Criterion) {
+    turn_tracing_on();
+    bench_with_subscriber(c, "tracing_on_span", || {
+        let _entered = tracing::info_span!("bench info span").entered();
+    });
+    turn_tracing_off();
+}
+
+fn bench_tracing_on_span_args(c: &mut Criterion) {
+    turn_tracing_on();
+    bench_with_subscriber(c, "tracing_on_span_args", || {
+        let _entered = tracing::info_span!("bench info span", debug_arg1 = 123,
+            debug_arg2 = "argument",
+            debug_arg3 = ?Vec::from([1, 2, 3, 4]),
+            debug_arg4 = "last")
+        .entered();
+    });
+    turn_tracing_off();
+}
+
+fn main() -> Result<(), Box<dyn std::error::Error>> {
+    let mut criterion = new_criterion();
+
+    bench_tracing_off_event(&mut criterion);
+    bench_tracing_off_event_args(&mut criterion);
+    bench_tracing_off_span(&mut criterion);
+    bench_tracing_off_span_args(&mut criterion);
+
+    bench_tracing_on_event(&mut criterion);
+    bench_tracing_on_event_args(&mut criterion);
+    bench_tracing_on_span(&mut criterion);
+    bench_tracing_on_span_args(&mut criterion);
+
+    Ok(())
+}