From 1a4dbd2705c402327ee4b1a6086bbaef9c00f2a7 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Sat, 8 Nov 2025 06:26:18 -0600 Subject: [PATCH 01/23] Add samply-markers crate to workspace This commit adds a new workspace for the `samply-markers` crate starting at version `0.0.0`. Since this is my first PR to this project, introducing a new component, I will bump the version to 0.1.0 once it is fully reviewed, accepted, and ready. --- Cargo.lock | 4 + Cargo.toml | 1 + samply-markers/Cargo.toml | 17 +++ samply-markers/LICENSE-APACHE | 201 ++++++++++++++++++++++++++++++++++ samply-markers/LICENSE-MIT | 25 +++++ samply-markers/src/lib.rs | 15 +++ 6 files changed, 263 insertions(+) create mode 100644 samply-markers/Cargo.toml create mode 100644 samply-markers/LICENSE-APACHE create mode 100644 samply-markers/LICENSE-MIT create mode 100644 samply-markers/src/lib.rs diff --git a/Cargo.lock b/Cargo.lock index 3dbd5df0c..5d34a9d5c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2284,6 +2284,10 @@ dependencies = [ "uuid", ] +[[package]] +name = "samply-markers" +version = "0.1.0" + [[package]] name = "samply-object" version = "0.1.0" diff --git a/Cargo.toml b/Cargo.toml index 5ecdb789a..55b3bee06 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -6,6 +6,7 @@ members = [ "gecko_profile", "samply-api", "samply-debugid", + "samply-markers", "samply-object", "samply-quota-manager", "samply-symbols", diff --git a/samply-markers/Cargo.toml b/samply-markers/Cargo.toml new file mode 100644 index 000000000..9ec19cd7b --- /dev/null +++ b/samply-markers/Cargo.toml @@ -0,0 +1,17 @@ +[package] +name = "samply-markers" +version = "0.1.0" +edition = "2024" +authors = ["Erik Nordin "] +rust-version = "1.85.1" +license = "MIT OR Apache-2.0" +description = "Emit markers for samply profiles." +repository = "https://github.com/mstange/samply/" +readme = "README.md" +keywords = ["profiling", "markers", "instrumentation", "tracing", "performance"] + +[features] +default = [] +enabled = [] + +[dependencies] diff --git a/samply-markers/LICENSE-APACHE b/samply-markers/LICENSE-APACHE new file mode 100644 index 000000000..16fe87b06 --- /dev/null +++ b/samply-markers/LICENSE-APACHE @@ -0,0 +1,201 @@ + Apache License + Version 2.0, January 2004 + http://www.apache.org/licenses/ + +TERMS AND CONDITIONS FOR USE, REPRODUCTION, AND DISTRIBUTION + +1. Definitions. + + "License" shall mean the terms and conditions for use, reproduction, + and distribution as defined by Sections 1 through 9 of this document. + + "Licensor" shall mean the copyright owner or entity authorized by + the copyright owner that is granting the License. + + "Legal Entity" shall mean the union of the acting entity and all + other entities that control, are controlled by, or are under common + control with that entity. For the purposes of this definition, + "control" means (i) the power, direct or indirect, to cause the + direction or management of such entity, whether by contract or + otherwise, or (ii) ownership of fifty percent (50%) or more of the + outstanding shares, or (iii) beneficial ownership of such entity. + + "You" (or "Your") shall mean an individual or Legal Entity + exercising permissions granted by this License. + + "Source" form shall mean the preferred form for making modifications, + including but not limited to software source code, documentation + source, and configuration files. + + "Object" form shall mean any form resulting from mechanical + transformation or translation of a Source form, including but + not limited to compiled object code, generated documentation, + and conversions to other media types. + + "Work" shall mean the work of authorship, whether in Source or + Object form, made available under the License, as indicated by a + copyright notice that is included in or attached to the work + (an example is provided in the Appendix below). + + "Derivative Works" shall mean any work, whether in Source or Object + form, that is based on (or derived from) the Work and for which the + editorial revisions, annotations, elaborations, or other modifications + represent, as a whole, an original work of authorship. For the purposes + of this License, Derivative Works shall not include works that remain + separable from, or merely link (or bind by name) to the interfaces of, + the Work and Derivative Works thereof. + + "Contribution" shall mean any work of authorship, including + the original version of the Work and any modifications or additions + to that Work or Derivative Works thereof, that is intentionally + submitted to Licensor for inclusion in the Work by the copyright owner + or by an individual or Legal Entity authorized to submit on behalf of + the copyright owner. For the purposes of this definition, "submitted" + means any form of electronic, verbal, or written communication sent + to the Licensor or its representatives, including but not limited to + communication on electronic mailing lists, source code control systems, + and issue tracking systems that are managed by, or on behalf of, the + Licensor for the purpose of discussing and improving the Work, but + excluding communication that is conspicuously marked or otherwise + designated in writing by the copyright owner as "Not a Contribution." + + "Contributor" shall mean Licensor and any individual or Legal Entity + on behalf of whom a Contribution has been received by Licensor and + subsequently incorporated within the Work. + +2. Grant of Copyright License. Subject to the terms and conditions of + this License, each Contributor hereby grants to You a perpetual, + worldwide, non-exclusive, no-charge, royalty-free, irrevocable + copyright license to reproduce, prepare Derivative Works of, + publicly display, publicly perform, sublicense, and distribute the + Work and such Derivative Works in Source or Object form. + +3. Grant of Patent License. Subject to the terms and conditions of + this License, each Contributor hereby grants to You a perpetual, + worldwide, non-exclusive, no-charge, royalty-free, irrevocable + (except as stated in this section) patent license to make, have made, + use, offer to sell, sell, import, and otherwise transfer the Work, + where such license applies only to those patent claims licensable + by such Contributor that are necessarily infringed by their + Contribution(s) alone or by combination of their Contribution(s) + with the Work to which such Contribution(s) was submitted. If You + institute patent litigation against any entity (including a + cross-claim or counterclaim in a lawsuit) alleging that the Work + or a Contribution incorporated within the Work constitutes direct + or contributory patent infringement, then any patent licenses + granted to You under this License for that Work shall terminate + as of the date such litigation is filed. + +4. Redistribution. You may reproduce and distribute copies of the + Work or Derivative Works thereof in any medium, with or without + modifications, and in Source or Object form, provided that You + meet the following conditions: + + (a) You must give any other recipients of the Work or + Derivative Works a copy of this License; and + + (b) You must cause any modified files to carry prominent notices + stating that You changed the files; and + + (c) You must retain, in the Source form of any Derivative Works + that You distribute, all copyright, patent, trademark, and + attribution notices from the Source form of the Work, + excluding those notices that do not pertain to any part of + the Derivative Works; and + + (d) If the Work includes a "NOTICE" text file as part of its + distribution, then any Derivative Works that You distribute must + include a readable copy of the attribution notices contained + within such NOTICE file, excluding those notices that do not + pertain to any part of the Derivative Works, in at least one + of the following places: within a NOTICE text file distributed + as part of the Derivative Works; within the Source form or + documentation, if provided along with the Derivative Works; or, + within a display generated by the Derivative Works, if and + wherever such third-party notices normally appear. The contents + of the NOTICE file are for informational purposes only and + do not modify the License. You may add Your own attribution + notices within Derivative Works that You distribute, alongside + or as an addendum to the NOTICE text from the Work, provided + that such additional attribution notices cannot be construed + as modifying the License. + + You may add Your own copyright statement to Your modifications and + may provide additional or different license terms and conditions + for use, reproduction, or distribution of Your modifications, or + for any such Derivative Works as a whole, provided Your use, + reproduction, and distribution of the Work otherwise complies with + the conditions stated in this License. + +5. Submission of Contributions. Unless You explicitly state otherwise, + any Contribution intentionally submitted for inclusion in the Work + by You to the Licensor shall be under the terms and conditions of + this License, without any additional terms or conditions. + Notwithstanding the above, nothing herein shall supersede or modify + the terms of any separate license agreement you may have executed + with Licensor regarding such Contributions. + +6. Trademarks. This License does not grant permission to use the trade + names, trademarks, service marks, or product names of the Licensor, + except as required for reasonable and customary use in describing the + origin of the Work and reproducing the content of the NOTICE file. + +7. Disclaimer of Warranty. Unless required by applicable law or + agreed to in writing, Licensor provides the Work (and each + Contributor provides its Contributions) on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or + implied, including, without limitation, any warranties or conditions + of TITLE, NON-INFRINGEMENT, MERCHANTABILITY, or FITNESS FOR A + PARTICULAR PURPOSE. You are solely responsible for determining the + appropriateness of using or redistributing the Work and assume any + risks associated with Your exercise of permissions under this License. + +8. Limitation of Liability. In no event and under no legal theory, + whether in tort (including negligence), contract, or otherwise, + unless required by applicable law (such as deliberate and grossly + negligent acts) or agreed to in writing, shall any Contributor be + liable to You for damages, including any direct, indirect, special, + incidental, or consequential damages of any character arising as a + result of this License or out of the use or inability to use the + Work (including but not limited to damages for loss of goodwill, + work stoppage, computer failure or malfunction, or any and all + other commercial damages or losses), even if such Contributor + has been advised of the possibility of such damages. + +9. Accepting Warranty or Additional Liability. While redistributing + the Work or Derivative Works thereof, You may choose to offer, + and charge a fee for, acceptance of support, warranty, indemnity, + or other liability obligations and/or rights consistent with this + License. However, in accepting such obligations, You may act only + on Your own behalf and on Your sole responsibility, not on behalf + of any other Contributor, and only if You agree to indemnify, + defend, and hold each Contributor harmless for any liability + incurred by, or claims asserted against, such Contributor by reason + of your accepting any such warranty or additional liability. + +END OF TERMS AND CONDITIONS + +APPENDIX: How to apply the Apache License to your work. + + To apply the Apache License to your work, attach the following + boilerplate notice, with the fields enclosed by brackets "[]" + replaced with your own identifying information. (Don't include + the brackets!) The text should be enclosed in the appropriate + comment syntax for the file format. We also recommend that a + file or class name and description of purpose be included on the + same "printed page" as the copyright notice for easier + identification within third-party archives. + +Copyright [yyyy] [name of copyright owner] + +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. diff --git a/samply-markers/LICENSE-MIT b/samply-markers/LICENSE-MIT new file mode 100644 index 000000000..6a96dd571 --- /dev/null +++ b/samply-markers/LICENSE-MIT @@ -0,0 +1,25 @@ +Copyright (c) 2025 the samply authors + +Permission is hereby granted, free of charge, to any +person obtaining a copy of this software and associated +documentation files (the "Software"), to deal in the +Software without restriction, including without +limitation the rights to use, copy, modify, merge, +publish, distribute, sublicense, and/or sell copies of +the Software, and to permit persons to whom the Software +is furnished to do so, subject to the following +conditions: + +The above copyright notice and this permission notice +shall be included in all copies or substantial portions +of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF +ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED +TO THE WARRANTIES OF MERCHANTABILITY, FITNESS FOR A +PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT +SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY +CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION +OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR +IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER +DEALINGS IN THE SOFTWARE. diff --git a/samply-markers/src/lib.rs b/samply-markers/src/lib.rs new file mode 100644 index 000000000..4930ec8a3 --- /dev/null +++ b/samply-markers/src/lib.rs @@ -0,0 +1,15 @@ +pub fn add(left: u64, right: u64) -> u64 { + left + right +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn it_works() { + let result = add(2, 2); + assert_eq!(result, 4); + } +} + From 18a3dfc0619d96a663e41e6b081458faf5ac8475 Mon Sep 17 00:00:00 2001 From: Ben Pfaff Date: Mon, 18 Aug 2025 16:56:08 -0700 Subject: [PATCH 02/23] Import samply mmap impl from feldera/feldera@1b448b7 Source: https://github.com/feldera/feldera/commit/1b448b757e92c245a02be31932278871cf940a65 Original author: Ben Pfaff File renamed from crates/adapters/src/samply.rs to ./samply-markers/src/unix.rs --- samply-markers/src/lib.rs | 3 +- samply-markers/src/provider/mod.rs | 2 + samply-markers/src/provider/unix.rs | 271 ++++++++++++++++++++++++++++ 3 files changed, 275 insertions(+), 1 deletion(-) create mode 100644 samply-markers/src/provider/mod.rs create mode 100644 samply-markers/src/provider/unix.rs diff --git a/samply-markers/src/lib.rs b/samply-markers/src/lib.rs index 4930ec8a3..3fb40d955 100644 --- a/samply-markers/src/lib.rs +++ b/samply-markers/src/lib.rs @@ -1,3 +1,5 @@ +mod provider; + pub fn add(left: u64, right: u64) -> u64 { left + right } @@ -12,4 +14,3 @@ mod tests { assert_eq!(result, 4); } } - diff --git a/samply-markers/src/provider/mod.rs b/samply-markers/src/provider/mod.rs new file mode 100644 index 000000000..f497353dd --- /dev/null +++ b/samply-markers/src/provider/mod.rs @@ -0,0 +1,2 @@ +#[cfg(all(feature = "enabled", target_family = "unix"))] +pub mod unix; \ No newline at end of file diff --git a/samply-markers/src/provider/unix.rs b/samply-markers/src/provider/unix.rs new file mode 100644 index 000000000..55a4ad839 --- /dev/null +++ b/samply-markers/src/provider/unix.rs @@ -0,0 +1,271 @@ +//! Runtime support for `samply`. +//! +//! The [samply] profiler allows the process that it is profiling to indicate +//! important runtime spans so that they show up in the profile for the thread +//! or the process. The way that the profiled process does this is somewhat +//! arcane, so this module provides support for this on supported systems. +//! +//! Use [SamplySpan] to emit a span. +//! +//! # Viewing in the Firefox Profiler +//! +//! Spans logged by this module show up in the Marker Chart and Marker Table +//! tabs for a given thread. They are linked to particular threads and the +//! profiler will only show them when those threads are selected. Those threads +//! *should* be the ones that emit them, but when `samply` attaches to a process +//! that is already running, it cannot tell which thread emitted them, so it +//! links all of them to the main thread (the one with the process name at the +//! top of the profiler window). For Feldera pipelines, this usually means that +//! all of the spans will be linked to the main thread. +//! +//! See [example] output, which should show spans for `input`, `step`, and +//! `update` in the track for `program_0198a9c5-3b...`. +//! +//! [example]: https://profiler.firefox.com/public/5r65r8dg7estdv9sgd154qf2ta7japgp0hm7r50/marker-chart/?globalTrackOrder=0&hiddenLocalTracksByPid=1305600-0whjowx3x7xawzhznwAb&range=14344m640~14344m184&symbolServer=http%3A%2F%2F127.0.0.1%3A3001%2F3d9s4vp2mr2q30dw5rr3n09f7xgpds0mh8cr5nw&thread=0zjwzn&v=11 +//! +//! # Enabling +//! +//! Logging must be configured to enable emitting spans at runtime: +//! +//! - Debug-level logging must be enabled for this module. +//! +//! - Logging must also be enabled for the particular spans of interest. These +//! are probably also at debug level. +//! +//! For Feldera pipelines, the easiest way to enable logging these spans is +//! probably to enable debug-level logging globally by setting `"logging": +//! "debug"` for the pipeline. +//! +//! # Performance +//! +//! There is some performance cost for emitting a span: +//! +//! - Each thread that emits a span writes a temporary file and retains a file +//! descriptor for it. +//! +//! - Emitting a span takes one system call to write a line to the temporary +//! file. (In theory, this can be avoided using `mmap` to write the file, but +//! writing text files with `mmap` is a nasty business and so far we avoid +//! it.) +//! +//! # Cleanup +//! +//! The process can't delete its temporary files when it exits, because `samply` +//! needs to read them afterward. Pass `--unlink-aux-files` to samply to have +//! it delete them after reading. +//! +//! This implementation writes the temporary files in a temporary directory. +//! Nothing deletes the temporary directory. +//! +//! [samply]: https://github.com/mstange/samply?tab=readme-ov-file#samply +#![warn(missing_docs)] +use std::{ + cell::RefCell, + fmt::{Display, Write as _}, + fs::File, + io::Write, + num::NonZeroUsize, + path::{Path, PathBuf}, + sync::LazyLock, +}; + +use nix::{ + sys::mman::{MapFlags, ProtFlags}, + time::{clock_gettime, ClockId}, +}; +use smallstr::SmallString; +use tempfile::{tempdir, TempDir}; +use tracing::{enabled, error, span::EnteredSpan, Level, Span}; + +#[derive(Copy, Clone, Debug)] +struct Timestamp(i64); + +impl Timestamp { + fn now() -> Self { + let now = clock_gettime(ClockId::CLOCK_MONOTONIC).unwrap(); + Self(now.tv_sec() as i64 * 1_000_000_000 + now.tv_nsec() as i64) + } +} + +impl Display for Timestamp { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "{}", self.0) + } +} + +/// A [Span] that can also be emitted to [samply]. +/// +/// See [module documentation] for more information. +/// +/// [samply]: https://github.com/mstange/samply?tab=readme-ov-file#samply +/// [module documentation]: crate::samply +pub struct SamplySpan { + span: Span, +} + +impl SamplySpan { + /// Constructs a new [SamplySpan] that wraps `span`. + pub fn new(span: Span) -> Self { + Self { span } + } + + /// Returns the inner [Span]. + pub fn into_inner(self) -> Span { + self.span + } + + /// Enters this span, consuming it and returning a + /// [guard](EnteredSamplySpan) that will exit the span when dropped. + /// + /// If the span is enabled for [tracing] purposes, **and** this module is + /// enabled at debug level, then the span will be emitted for consumption by + /// the [samply] profiler. See [module documentation] for more information. + /// + /// [module documentation]: crate::samply + pub fn entered(self) -> EnteredSamplySpan { + EnteredSamplySpan::new(self) + } + + /// Executes the given function in the context of the span. + /// + /// If this span is enabled, then this function enters the span, invokes `f` + /// and then exits the span. If the span is disabled, `f` will still be + /// invoked, but in the context of the currently-executing span (if there is + /// one). + /// + /// Returns the result of evaluating `f`. + /// + /// If the span is enabled for [tracing] purposes, **and** this module is + /// enabled at debug level, then the span will be emitted for consumption by + /// the [samply] profiler. See [module documentation] for more information. + /// + /// [module documentation]: crate::samply + pub fn in_scope(self, f: F) -> T + where + F: FnOnce() -> T, + { + let _entered_span = self.entered(); + f() + } +} + +/// An owned guard representing a span which has been entered and is currently +/// executing. +/// +/// When the guard is dropped, the span will be exited. +/// +/// This is returned by [SamplySpan::entered]. +pub struct EnteredSamplySpan { + span: EnteredSpan, + start: Option, +} + +impl EnteredSamplySpan { + fn new(span: SamplySpan) -> Self { + Self { + start: if span.span.is_disabled() || !enabled!(Level::DEBUG) { + None + } else { + Some(Timestamp::now()) + }, + span: span.span.entered(), + } + } + + /// Exits the span, returning the underlying [SamplySpan]. + #[allow(dead_code)] + pub fn exit(mut self) -> SamplySpan { + self.do_exit(); + SamplySpan { + span: std::mem::replace(&mut self.span, Span::none().entered()).exit(), + } + } + + fn do_exit(&mut self) { + if let Some(start) = self.start.take() { + write_marker( + start, + Timestamp::now(), + self.span.metadata().unwrap().name(), + ); + } + } +} + +impl Drop for EnteredSamplySpan { + fn drop(&mut self) { + self.do_exit(); + } +} + +fn markers_dir() -> Option<&'static Path> { + static MARKERS_DIR: LazyLock> = LazyLock::new(|| { + tempdir() + .map(TempDir::keep) + .inspect_err(|e| error!("Failed to create temporary directory: {e}")) + .ok() + }); + + Some(LazyLock::force(&MARKERS_DIR).as_ref()?) +} + +fn with_marker_file(f: F) -> Option +where + F: FnOnce(&mut File) -> R, +{ + fn create_marker_file() -> Option { + let file_name = markers_dir()?.join(format!( + "marker-{}-{}.txt", + nix::unistd::getpid(), + nix::unistd::gettid() + )); + + // Create the file. + let file = File::options() + .create(true) + .write(true) + .read({ + // We aren't going to read from the file, so we ordinarily + // wouldn't need read permission, but we're about mmap it and + // mmap always requires read permission. + true + }) + .open(&file_name) + .inspect_err(|e| error!("Failed to create marker file {e}: {}", file_name.display())) + .ok()?; + + // Create an mmap for the file. This cannot be skipped because it + // triggers samply to read and interpret the file. We will not use it + // to write to the file (because writing to a text file via mmap is + // painful and we haven't yet proved that it is a performance problem), + // so it is not necessary to map it with any particular protection or + // flags, so we use PROT_READ because that offers the fewest ways to + // screw up. + unsafe { + nix::sys::mman::mmap( + None, + NonZeroUsize::new(4096).unwrap(), + ProtFlags::PROT_READ, + MapFlags::MAP_SHARED, + &file, + 0, + ) + } + .inspect_err(|e| error!("Failed to mmap marker file {e}: {}", file_name.display())) + .ok()?; + + Some(file) + } + + thread_local! { + static MARKER_FILE: RefCell> = RefCell::new(create_marker_file()); + } + + MARKER_FILE.with_borrow_mut(|file| file.as_mut().map(f)) +} + +fn write_marker(start: Timestamp, end: Timestamp, name: &str) { + let mut s = SmallString::<[u8; 64]>::new(); + writeln!(&mut s, "{start} {end} {name}").unwrap(); + let _ = with_marker_file(|f| f.write_all(s.as_bytes())); +} From 79d5392a1bf362a9d92cfeae8bbd0659e37aa9dc Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Sat, 8 Nov 2025 06:31:18 -0600 Subject: [PATCH 03/23] Run cargo-fmt on feldera/feldera@1b448b7 This commit runs cargo-fmt on the ported commit from feldera/feldera@1b448b7 to ensure that the code style is up to date with samply's repository. --- samply-markers/src/provider/unix.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/samply-markers/src/provider/unix.rs b/samply-markers/src/provider/unix.rs index 55a4ad839..f6c91aaa5 100644 --- a/samply-markers/src/provider/unix.rs +++ b/samply-markers/src/provider/unix.rs @@ -71,11 +71,11 @@ use std::{ use nix::{ sys::mman::{MapFlags, ProtFlags}, - time::{clock_gettime, ClockId}, + time::{ClockId, clock_gettime}, }; use smallstr::SmallString; -use tempfile::{tempdir, TempDir}; -use tracing::{enabled, error, span::EnteredSpan, Level, Span}; +use tempfile::{TempDir, tempdir}; +use tracing::{Level, Span, enabled, error, span::EnteredSpan}; #[derive(Copy, Clone, Debug)] struct Timestamp(i64); From eb7a64ee23a21bcdb42116eb3fddf1318d364007 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Sat, 8 Nov 2025 06:35:31 -0600 Subject: [PATCH 04/23] Add required dependencies from feldera/feldera@1b448b7 This commit adds all of the required dependencies in order to get the ported code from feldera/feldera@1b448b7 to build. Some of these dependencies may be removed as I update the API to my vision for the project. --- Cargo.lock | 27 +++++++++++++++++++++++++++ samply-markers/Cargo.toml | 14 ++++++++++++-- 2 files changed, 39 insertions(+), 2 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 5d34a9d5c..fbc9ecdd5 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2287,6 +2287,12 @@ dependencies = [ [[package]] name = "samply-markers" version = "0.1.0" +dependencies = [ + "nix", + "smallstr", + "tempfile", + "tracing", +] [[package]] name = "samply-object" @@ -2452,6 +2458,15 @@ version = "0.4.11" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7a2ae44ef20feb57a68b23d846850f861394c2e02dc425a50098ae8c90267589" +[[package]] +name = "smallstr" +version = "0.3.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "862077b1e764f04c251fe82a2ef562fd78d7cadaeb072ca7c2bcaf7217b1ff3b" +dependencies = [ + "smallvec", +] + [[package]] name = "smallvec" version = "1.15.1" @@ -2786,9 +2801,21 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0" dependencies = [ "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.30" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "81383ab64e72a7a8b8e13130c49e3dab29def6d0c7d76a03087b3cf71c5c6903" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + [[package]] name = "tracing-core" version = "0.1.34" diff --git a/samply-markers/Cargo.toml b/samply-markers/Cargo.toml index 9ec19cd7b..30efcf449 100644 --- a/samply-markers/Cargo.toml +++ b/samply-markers/Cargo.toml @@ -10,8 +10,18 @@ repository = "https://github.com/mstange/samply/" readme = "README.md" keywords = ["profiling", "markers", "instrumentation", "tracing", "performance"] + [features] default = [] -enabled = [] +enabled = [ + "dep:nix", + "dep:smallstr", + "dep:tempfile", +] + +[target.'cfg(unix)'.dependencies] +nix = { version = "0.30.1", features = ["mman", "process", "time"], optional = true } +smallstr = { version = "0.3.1", optional = true } +tempfile = { version = "3.23.0", optional = true } +tracing = "0.1.41" -[dependencies] From 4b7b49cdbdae4d8da722c4581dcdc20e5da40be9 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Sat, 8 Nov 2025 09:59:47 -0600 Subject: [PATCH 05/23] Remove non-unix-specific code from unix.rs This commit removes all of the code from unix.rs that is not specific to actually writing to the `mmap` files on unix systems. This preserves the original author's attributions. --- samply-markers/src/provider/unix.rs | 168 +--------------------------- 1 file changed, 1 insertion(+), 167 deletions(-) diff --git a/samply-markers/src/provider/unix.rs b/samply-markers/src/provider/unix.rs index f6c91aaa5..8bbd475b8 100644 --- a/samply-markers/src/provider/unix.rs +++ b/samply-markers/src/provider/unix.rs @@ -1,64 +1,3 @@ -//! Runtime support for `samply`. -//! -//! The [samply] profiler allows the process that it is profiling to indicate -//! important runtime spans so that they show up in the profile for the thread -//! or the process. The way that the profiled process does this is somewhat -//! arcane, so this module provides support for this on supported systems. -//! -//! Use [SamplySpan] to emit a span. -//! -//! # Viewing in the Firefox Profiler -//! -//! Spans logged by this module show up in the Marker Chart and Marker Table -//! tabs for a given thread. They are linked to particular threads and the -//! profiler will only show them when those threads are selected. Those threads -//! *should* be the ones that emit them, but when `samply` attaches to a process -//! that is already running, it cannot tell which thread emitted them, so it -//! links all of them to the main thread (the one with the process name at the -//! top of the profiler window). For Feldera pipelines, this usually means that -//! all of the spans will be linked to the main thread. -//! -//! See [example] output, which should show spans for `input`, `step`, and -//! `update` in the track for `program_0198a9c5-3b...`. -//! -//! [example]: https://profiler.firefox.com/public/5r65r8dg7estdv9sgd154qf2ta7japgp0hm7r50/marker-chart/?globalTrackOrder=0&hiddenLocalTracksByPid=1305600-0whjowx3x7xawzhznwAb&range=14344m640~14344m184&symbolServer=http%3A%2F%2F127.0.0.1%3A3001%2F3d9s4vp2mr2q30dw5rr3n09f7xgpds0mh8cr5nw&thread=0zjwzn&v=11 -//! -//! # Enabling -//! -//! Logging must be configured to enable emitting spans at runtime: -//! -//! - Debug-level logging must be enabled for this module. -//! -//! - Logging must also be enabled for the particular spans of interest. These -//! are probably also at debug level. -//! -//! For Feldera pipelines, the easiest way to enable logging these spans is -//! probably to enable debug-level logging globally by setting `"logging": -//! "debug"` for the pipeline. -//! -//! # Performance -//! -//! There is some performance cost for emitting a span: -//! -//! - Each thread that emits a span writes a temporary file and retains a file -//! descriptor for it. -//! -//! - Emitting a span takes one system call to write a line to the temporary -//! file. (In theory, this can be avoided using `mmap` to write the file, but -//! writing text files with `mmap` is a nasty business and so far we avoid -//! it.) -//! -//! # Cleanup -//! -//! The process can't delete its temporary files when it exits, because `samply` -//! needs to read them afterward. Pass `--unlink-aux-files` to samply to have -//! it delete them after reading. -//! -//! This implementation writes the temporary files in a temporary directory. -//! Nothing deletes the temporary directory. -//! -//! [samply]: https://github.com/mstange/samply?tab=readme-ov-file#samply -#![warn(missing_docs)] use std::{ cell::RefCell, fmt::{Display, Write as _}, @@ -75,7 +14,7 @@ use nix::{ }; use smallstr::SmallString; use tempfile::{TempDir, tempdir}; -use tracing::{Level, Span, enabled, error, span::EnteredSpan}; +use tracing::error; #[derive(Copy, Clone, Debug)] struct Timestamp(i64); @@ -93,111 +32,6 @@ impl Display for Timestamp { } } -/// A [Span] that can also be emitted to [samply]. -/// -/// See [module documentation] for more information. -/// -/// [samply]: https://github.com/mstange/samply?tab=readme-ov-file#samply -/// [module documentation]: crate::samply -pub struct SamplySpan { - span: Span, -} - -impl SamplySpan { - /// Constructs a new [SamplySpan] that wraps `span`. - pub fn new(span: Span) -> Self { - Self { span } - } - - /// Returns the inner [Span]. - pub fn into_inner(self) -> Span { - self.span - } - - /// Enters this span, consuming it and returning a - /// [guard](EnteredSamplySpan) that will exit the span when dropped. - /// - /// If the span is enabled for [tracing] purposes, **and** this module is - /// enabled at debug level, then the span will be emitted for consumption by - /// the [samply] profiler. See [module documentation] for more information. - /// - /// [module documentation]: crate::samply - pub fn entered(self) -> EnteredSamplySpan { - EnteredSamplySpan::new(self) - } - - /// Executes the given function in the context of the span. - /// - /// If this span is enabled, then this function enters the span, invokes `f` - /// and then exits the span. If the span is disabled, `f` will still be - /// invoked, but in the context of the currently-executing span (if there is - /// one). - /// - /// Returns the result of evaluating `f`. - /// - /// If the span is enabled for [tracing] purposes, **and** this module is - /// enabled at debug level, then the span will be emitted for consumption by - /// the [samply] profiler. See [module documentation] for more information. - /// - /// [module documentation]: crate::samply - pub fn in_scope(self, f: F) -> T - where - F: FnOnce() -> T, - { - let _entered_span = self.entered(); - f() - } -} - -/// An owned guard representing a span which has been entered and is currently -/// executing. -/// -/// When the guard is dropped, the span will be exited. -/// -/// This is returned by [SamplySpan::entered]. -pub struct EnteredSamplySpan { - span: EnteredSpan, - start: Option, -} - -impl EnteredSamplySpan { - fn new(span: SamplySpan) -> Self { - Self { - start: if span.span.is_disabled() || !enabled!(Level::DEBUG) { - None - } else { - Some(Timestamp::now()) - }, - span: span.span.entered(), - } - } - - /// Exits the span, returning the underlying [SamplySpan]. - #[allow(dead_code)] - pub fn exit(mut self) -> SamplySpan { - self.do_exit(); - SamplySpan { - span: std::mem::replace(&mut self.span, Span::none().entered()).exit(), - } - } - - fn do_exit(&mut self) { - if let Some(start) = self.start.take() { - write_marker( - start, - Timestamp::now(), - self.span.metadata().unwrap().name(), - ); - } - } -} - -impl Drop for EnteredSamplySpan { - fn drop(&mut self) { - self.do_exit(); - } -} - fn markers_dir() -> Option<&'static Path> { static MARKERS_DIR: LazyLock> = LazyLock::new(|| { tempdir() From ea591b85f8101ecbcc0c5983dd4cfb9b7292400f Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 08:35:16 -0600 Subject: [PATCH 06/23] Add SamplyTimestamp with default provider This commit adds the `SamplyTimestamp` implementation with a default provider that always returns zero. --- samply-markers/src/lib.rs | 15 +-- samply-markers/src/marker/mod.rs | 5 + samply-markers/src/marker/timestamp.rs | 146 +++++++++++++++++++++++++ samply-markers/src/provider/default.rs | 18 +++ samply-markers/src/provider/mod.rs | 26 ++++- 5 files changed, 194 insertions(+), 16 deletions(-) create mode 100644 samply-markers/src/marker/mod.rs create mode 100644 samply-markers/src/marker/timestamp.rs create mode 100644 samply-markers/src/provider/default.rs diff --git a/samply-markers/src/lib.rs b/samply-markers/src/lib.rs index 3fb40d955..3cbb1b05f 100644 --- a/samply-markers/src/lib.rs +++ b/samply-markers/src/lib.rs @@ -1,16 +1,3 @@ mod provider; -pub fn add(left: u64, right: u64) -> u64 { - left + right -} - -#[cfg(test)] -mod tests { - use super::*; - - #[test] - fn it_works() { - let result = add(2, 2); - assert_eq!(result, 4); - } -} +pub mod marker; diff --git a/samply-markers/src/marker/mod.rs b/samply-markers/src/marker/mod.rs new file mode 100644 index 000000000..86ee9fb4c --- /dev/null +++ b/samply-markers/src/marker/mod.rs @@ -0,0 +1,5 @@ +//! This module contains the core types for instrumenting code with markers. + +mod timestamp; + +pub use timestamp::SamplyTimestamp; diff --git a/samply-markers/src/marker/timestamp.rs b/samply-markers/src/marker/timestamp.rs new file mode 100644 index 000000000..7f52df095 --- /dev/null +++ b/samply-markers/src/marker/timestamp.rs @@ -0,0 +1,146 @@ +//! This module contains the implementation of an opaque monotonic nanosecond timestamp used by [samply-markers](crate). + +use crate::provider::TimestampNowImpl; +use crate::provider::TimestampNowProvider; + +/// A monotonic timestamp expressed in nanoseconds. +/// +/// This type is intentionally opaque to avoid comparison inconsistencies between builds +/// that have [samply-markers](crate) enabled or disabled. +/// +/// # Examples +/// +/// ```rust +/// # use samply_markers::marker::SamplyTimestamp; +/// let start = SamplyTimestamp::now(); +/// ``` +#[derive(Copy, Clone, Debug)] +#[cfg_attr(not(feature = "enabled"), allow(unused))] +pub struct SamplyTimestamp(u64); + +impl SamplyTimestamp { + /// Returns the current monotonic time in nanoseconds. + /// + /// # Examples + /// + /// ```rust + /// # use samply_markers::marker::SamplyTimestamp; + /// let start = SamplyTimestamp::now(); + /// ``` + #[inline] + #[must_use] + pub fn now() -> Self { + ::now() + } + + /// Creates a timestamp from the given nanoseconds of monotonic time. + pub(crate) const fn from_monotonic_nanos(nanos: u64) -> Self { + Self(nanos) + } + + /// Formats a [`SamplyTimestamp`] without implementing [`std::fmt::Display`]. + /// + /// Having a dedicated formatter keeps [`SamplyTimestamp`] opaque, ensuring that it + /// cannot be stringified via [`ToString`] and compared. + #[cfg(feature = "enabled")] + pub(crate) fn fmt(self, writer: &mut W) -> std::fmt::Result + where + W: std::fmt::Write + ?Sized, + { + std::fmt::Write::write_fmt(writer, format_args!("{}", self.0)) + } +} + +/// The following traits are implemented internally for testing only. +/// The [`SamplyTimestamp`] struct should remain opaque to consumers of this crate. +#[cfg(test)] +mod compare { + use super::*; + + impl Eq for SamplyTimestamp {} + impl PartialEq for SamplyTimestamp { + fn eq(&self, other: &Self) -> bool { + self.0 == other.0 + } + } + + impl PartialOrd for SamplyTimestamp { + fn partial_cmp(&self, other: &Self) -> Option { + Some(self.cmp(other)) + } + } + + impl Ord for SamplyTimestamp { + fn cmp(&self, other: &Self) -> std::cmp::Ordering { + self.0.cmp(&other.0) + } + } +} + +#[cfg(test)] +mod test { + use super::*; + + #[test] + #[cfg(feature = "enabled")] + fn fmt_writes_correctly() { + let time = SamplyTimestamp::from_monotonic_nanos(9876543210); + let mut buffer = String::new(); + + let result = time.fmt(&mut buffer); + assert!(result.is_ok(), "Expected the fmt operation to succeed."); + + assert_eq!( + buffer, "9876543210", + "Expected the buffer to contain the formatted timestamp." + ); + } + + #[test] + #[cfg(feature = "enabled")] + fn now_is_monotonic() { + const ITERATIONS: usize = 1000; + let mut timestamps = Vec::with_capacity(ITERATIONS); + + // Collect many timestamps in rapid succession. + for _ in 0..ITERATIONS { + timestamps.push(SamplyTimestamp::now()); + } + + // Verify monotonicity: each timestamp should be >= the previous. + assert!( + timestamps + .iter() + .zip(timestamps.iter().skip(1)) + .all(|(lhs, rhs)| lhs <= rhs), + "Timestamps must be monotonically non-decreasing" + ); + + // At least some timestamps should be strictly increasing. + let strictly_increasing_count = timestamps + .iter() + .zip(timestamps.iter().skip(1)) + .filter(|(lhs, rhs)| lhs < rhs) + .count(); + + assert!( + strictly_increasing_count > 0, + "Expected at least some timestamps to be strictly increasing, but all {} were equal", + ITERATIONS + ); + } + + #[test] + #[cfg(not(feature = "enabled"))] + fn now_returns_zero_when_disabled() { + // When markers are disabled, timestamps should always return zero + for _ in 0..10 { + let now = SamplyTimestamp::now(); + assert_eq!( + now, + SamplyTimestamp::from_monotonic_nanos(0), + "Expected disabled timestamps to always be zero" + ); + } + } +} diff --git a/samply-markers/src/provider/default.rs b/samply-markers/src/provider/default.rs new file mode 100644 index 000000000..97cb8a5a5 --- /dev/null +++ b/samply-markers/src/provider/default.rs @@ -0,0 +1,18 @@ +//! This module contains default internal implementations that no-op when [samply-markers](crate) is not enabled. + +use crate::marker::SamplyTimestamp; +use crate::provider::TimestampNowProvider; + +/// A [`TimestampNowProvider`] that always reports zero when the default provider is active. +pub struct TimestampNowImpl; + +impl TimestampNowProvider for TimestampNowImpl { + /// Returns a zero timestamp. + /// + /// This function is intentionally not `const` because the real provider-specific + /// implementations are not `const`. This keeps the API consistent even when + /// [samply-markers](crate) is disabled. + fn now() -> SamplyTimestamp { + SamplyTimestamp::from_monotonic_nanos(0) + } +} diff --git a/samply-markers/src/provider/mod.rs b/samply-markers/src/provider/mod.rs index f497353dd..2ee4ffca3 100644 --- a/samply-markers/src/provider/mod.rs +++ b/samply-markers/src/provider/mod.rs @@ -1,2 +1,24 @@ -#[cfg(all(feature = "enabled", target_family = "unix"))] -pub mod unix; \ No newline at end of file +//! This module contains context-specific, uniform implementations for the internal APIs used by this crate. +//! +//! The default provider is designed to no-op when the code is not compiled for profiling. +//! +//! When [samply-markers](crate) is enabled, there are platform-specific provider implementations for Unix and Windows systems. +//! +//! * An internal provider must provide a type [`TimestampNowImpl`] that implements the [`TimestampNowProvider`] trait. +//! +//! [`TimestampNowProvider`]: crate::provider::TimestampNowProvider + +use crate::marker::SamplyTimestamp; + +pub use internal_provider::TimestampNowImpl; + +/// A trait implemented by context-specific providers to supply monotonic nanosecond timestamp. +pub trait TimestampNowProvider { + /// Returns a monotonic timestamp in nanoseconds. + fn now() -> SamplyTimestamp; +} + +#[cfg(not(feature = "enabled"))] +pub mod r#default; +#[cfg(not(feature = "enabled"))] +pub use r#default as internal_provider; From 3fb6ccad954a0e829fa2b55683ea312cb858183c Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 10:49:09 -0600 Subject: [PATCH 07/23] Add SamplyMarker with default provider This commit adds the `SamplyMarker` implementation with a default provider that intentionally does not write the markers to a file. --- samply-markers/src/marker/mod.rs | 2 + samply-markers/src/marker/samply_marker.rs | 215 +++++++++++++++++++++ samply-markers/src/provider/default.rs | 12 ++ samply-markers/src/provider/mod.rs | 10 + 4 files changed, 239 insertions(+) create mode 100644 samply-markers/src/marker/samply_marker.rs diff --git a/samply-markers/src/marker/mod.rs b/samply-markers/src/marker/mod.rs index 86ee9fb4c..8ee0e587e 100644 --- a/samply-markers/src/marker/mod.rs +++ b/samply-markers/src/marker/mod.rs @@ -1,5 +1,7 @@ //! This module contains the core types for instrumenting code with markers. +mod samply_marker; mod timestamp; +pub use samply_marker::SamplyMarker; pub use timestamp::SamplyTimestamp; diff --git a/samply-markers/src/marker/samply_marker.rs b/samply-markers/src/marker/samply_marker.rs new file mode 100644 index 000000000..c050626c9 --- /dev/null +++ b/samply-markers/src/marker/samply_marker.rs @@ -0,0 +1,215 @@ +use std::borrow::Cow; +use std::cell::Cell; +use std::marker::PhantomData; + +use crate::marker::SamplyTimestamp; +use crate::provider::WriteMarkerImpl; +use crate::provider::WriteMarkerProvider; + +/// A marker that can emit at the current location in the code's execution. +/// +/// * The marker may emit an instant, which represents a single point in time. +/// * The marker may emit an interval, which represents a span between a start time and end time. +/// +/// # Examples +/// +/// ```rust +/// # use samply_markers::marker::SamplyMarker; +/// # use samply_markers::marker::SamplyTimestamp; +/// # struct Request {} +/// # impl Request { fn id(&self) -> u32 { 0 } } +/// # fn receive_request() -> Request { Request {} } +/// # fn query_database(id: u32) -> Vec { vec![] } +/// # fn serialize_json(data: &[String]) -> String { String::new() } +/// let request = receive_request(); +/// +/// // Emit an instant marker. +/// SamplyMarker::new(format!("received request {}", request.id())).emit_instant(); +/// +/// // Mark the start time for serializing the response. +/// let start = SamplyTimestamp::now(); +/// +/// let data = query_database(request.id()); +/// let json = serialize_json(&data); +/// +/// // Emit an interval marker. +/// SamplyMarker::new("serialize response").emit_interval(start); +/// ``` +#[derive(Debug)] +pub struct SamplyMarker<'data> { + /// The name recorded with every marker emission. + /// + /// Defaults to `"unnamed marker"` if empty. + name: Cow<'data, str>, + + /// This zero-sized member ensures that markers are `!Sync`. + /// + /// Markers are stil `Send`, allowing them to move between threads or be used in async tasks that migrate. + /// When a marker is emitted, it records the TID of the thread that emits it, which accurately represents + /// where the marker event occurred, even if the marker was created on a different thread. + /// + /// However, markers are `!Sync` because I see no valid use case for shared concurrent access to a marker. + /// Markers are meant to be owned and emitted exactly once, not shared and emitted from multiple threads. + /// + /// If we need to remove this restriction in the future, it will be a non-breaking change, but adding this + /// restriction would be a breaking change, so I would prefer to start more restrictively and increase the + /// capabilities if there is an explicit need to do so. + /// + /// This can be removed in favor of `impl !Sync` if negative impls are ever stabilized. + /// * + _no_sync: PhantomData>, +} + +impl<'data> SamplyMarker<'data> { + /// Creates a marker with the given `name`. + /// + /// Accepts [`&str`](str), [`String`], or anything convertible into [`Cow<'data, str>`]. + /// + /// If `name` is an empty string, it will default to `"unnamed marker"`. While every marker _should_ + /// have a descriptive name, providing a default is preferable to panicking, since a third-party crate + /// dependency could emit a marker with an empty name. Panicking in a scenario would mean that the code + /// can no longer be profiled with markers enabled at all. + /// + /// # Examples + /// + /// ```rust + /// # use samply_markers::marker::SamplyMarker; + /// SamplyMarker::new("database query").emit_instant(); + /// + /// let user_id = 123; + /// SamplyMarker::new(format!("fetch user {user_id}")).emit_instant(); + /// ``` + #[inline] + #[must_use] + pub fn new(name: impl Into> + AsRef) -> Self { + if name.as_ref().is_empty() { + Self { + name: Cow::Borrowed("unnamed marker"), + _no_sync: PhantomData, + } + } else { + Self { + name: name.into(), + _no_sync: PhantomData, + } + } + } + + /// Returns the name of this marker. + /// + /// # Examples + /// + /// ```rust + /// # use samply_markers::marker::SamplyMarker; + /// let marker = SamplyMarker::new("database query"); + /// assert_eq!(marker.name(), "database query"); + /// ``` + #[inline] + #[must_use] + pub fn name(&self) -> &str { + &self.name + } + + /// Emits an instant marker at the current time. + /// + /// # Examples + /// + /// ```rust + /// # use samply_markers::marker::SamplyMarker; + /// # fn check_cache() -> Option { None } + /// # fn fetch_from_disk() -> String { String::new() } + /// if let Some(data) = check_cache() { + /// SamplyMarker::new("cache hit").emit_instant(); + /// } else { + /// SamplyMarker::new("cache miss").emit_instant(); + /// fetch_from_disk(); + /// } + /// + /// let request_id = 42; + /// SamplyMarker::new(format!("request {request_id} completed")).emit_instant(); + /// ``` + #[inline] + pub fn emit_instant(self) { + let now = SamplyTimestamp::now(); + ::write_marker(now, now, &self); + } + + /// Emits an interval marker from the given `start_time` to the current time. + /// + /// # Examples + /// + /// ```rust + /// # use samply_markers::marker::SamplyMarker; + /// # use samply_markers::marker::SamplyTimestamp; + /// # fn check_cache() -> Option { None } + /// # fn fetch_from_disk() -> String { String::new() } + /// let start_time = SamplyTimestamp::now(); + /// + /// let data = if let Some(cached_data) = check_cache() { + /// // Emit an interval only for the cache-check portion. + /// SamplyMarker::new("cache check").emit_interval(start_time); + /// cached_data + /// } else { + /// // Emit an interval only for the cache-check portion. + /// SamplyMarker::new("cache check").emit_interval(start_time); + /// + /// let fetch_start = SamplyTimestamp::now(); + /// let fetched_data = fetch_from_disk(); + /// + /// // Emit an interval only for the fetch portion. + /// SamplyMarker::new("fetch from disk").emit_interval(fetch_start); + /// + /// fetched_data + /// }; + /// + /// // Emit an interval for the total time, including cache check and fetch. + /// SamplyMarker::new("total fetch time").emit_interval(start_time); + /// ``` + #[inline] + pub fn emit_interval(self, start_time: SamplyTimestamp) { + let end = SamplyTimestamp::now(); + ::write_marker(start_time, end, &self); + } +} + +#[cfg(test)] +mod test { + use super::*; + + #[test] + fn new_with_str() { + let marker = SamplyMarker::new("test marker"); + assert_eq!(marker.name(), "test marker"); + } + + #[test] + fn new_with_string() { + let name = String::from("dynamic marker"); + let marker = SamplyMarker::new(name); + assert_eq!(marker.name(), "dynamic marker"); + } + + #[test] + fn new_with_format() { + let five = 5; + let high = "high"; + let marker = SamplyMarker::new(format!("{high} {five}!")); + assert_eq!(marker.name(), "high 5!"); + } + + #[test] + fn marker_is_send() { + fn assert_send() {} + assert_send::(); + } + + #[test] + fn new_with_empty_name_defaults_to_unnamed_marker() { + let marker = SamplyMarker::new(""); + assert_eq!( + marker.name(), + "unnamed marker", + "Empty string should default to 'unnamed marker'" + ); + } +} diff --git a/samply-markers/src/provider/default.rs b/samply-markers/src/provider/default.rs index 97cb8a5a5..0f8fb611e 100644 --- a/samply-markers/src/provider/default.rs +++ b/samply-markers/src/provider/default.rs @@ -1,7 +1,9 @@ //! This module contains default internal implementations that no-op when [samply-markers](crate) is not enabled. +use crate::marker::SamplyMarker; use crate::marker::SamplyTimestamp; use crate::provider::TimestampNowProvider; +use crate::provider::WriteMarkerProvider; /// A [`TimestampNowProvider`] that always reports zero when the default provider is active. pub struct TimestampNowImpl; @@ -16,3 +18,13 @@ impl TimestampNowProvider for TimestampNowImpl { SamplyTimestamp::from_monotonic_nanos(0) } } + +/// A [`WriteMarkerProvider`] that does nothing when the default provider is active. +pub struct WriteMarkerImpl; + +impl WriteMarkerProvider for WriteMarkerImpl { + /// Does nothing with the marker data. + fn write_marker(_start: SamplyTimestamp, _end: SamplyTimestamp, _marker: &SamplyMarker) { + // no-op when markers are not enabled. + } +} diff --git a/samply-markers/src/provider/mod.rs b/samply-markers/src/provider/mod.rs index 2ee4ffca3..c6e9ab878 100644 --- a/samply-markers/src/provider/mod.rs +++ b/samply-markers/src/provider/mod.rs @@ -5,12 +5,16 @@ //! When [samply-markers](crate) is enabled, there are platform-specific provider implementations for Unix and Windows systems. //! //! * An internal provider must provide a type [`TimestampNowImpl`] that implements the [`TimestampNowProvider`] trait. +//! * An internal provider must provide a type [`WriteMarkerImpl`] that implements the [`WriteMarkerProvider`] trait. //! //! [`TimestampNowProvider`]: crate::provider::TimestampNowProvider +//! [`WriteMarkerProvider`]: crate::provider::WriteMarkerProvider +use crate::marker::SamplyMarker; use crate::marker::SamplyTimestamp; pub use internal_provider::TimestampNowImpl; +pub use internal_provider::WriteMarkerImpl; /// A trait implemented by context-specific providers to supply monotonic nanosecond timestamp. pub trait TimestampNowProvider { @@ -18,6 +22,12 @@ pub trait TimestampNowProvider { fn now() -> SamplyTimestamp; } +/// A trait implemented by context-specific providers to write markers for ingestion by samply. +pub trait WriteMarkerProvider { + /// Writes a marker span for profiling consumption. + fn write_marker(start: SamplyTimestamp, end: SamplyTimestamp, marker: &SamplyMarker); +} + #[cfg(not(feature = "enabled"))] pub mod r#default; #[cfg(not(feature = "enabled"))] From 8c0c48e4cd2736f87c59e3882074f70f0899c4de Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 10:57:34 -0600 Subject: [PATCH 08/23] Update unix.rs to conform to provider API This commit updates the `unix.rs` implementation to be compatible with the uniform internal provider APIs that markers require in order to function. --- Cargo.lock | 13 -- samply-markers/Cargo.toml | 2 - samply-markers/src/provider/mod.rs | 5 + samply-markers/src/provider/unix.rs | 194 ++++++++++++++++------------ 4 files changed, 117 insertions(+), 97 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index fbc9ecdd5..a079e631d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2291,7 +2291,6 @@ dependencies = [ "nix", "smallstr", "tempfile", - "tracing", ] [[package]] @@ -2801,21 +2800,9 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0" dependencies = [ "pin-project-lite", - "tracing-attributes", "tracing-core", ] -[[package]] -name = "tracing-attributes" -version = "0.1.30" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "81383ab64e72a7a8b8e13130c49e3dab29def6d0c7d76a03087b3cf71c5c6903" -dependencies = [ - "proc-macro2", - "quote", - "syn", -] - [[package]] name = "tracing-core" version = "0.1.34" diff --git a/samply-markers/Cargo.toml b/samply-markers/Cargo.toml index 30efcf449..32b082206 100644 --- a/samply-markers/Cargo.toml +++ b/samply-markers/Cargo.toml @@ -23,5 +23,3 @@ enabled = [ nix = { version = "0.30.1", features = ["mman", "process", "time"], optional = true } smallstr = { version = "0.3.1", optional = true } tempfile = { version = "3.23.0", optional = true } -tracing = "0.1.41" - diff --git a/samply-markers/src/provider/mod.rs b/samply-markers/src/provider/mod.rs index c6e9ab878..6e96cdf10 100644 --- a/samply-markers/src/provider/mod.rs +++ b/samply-markers/src/provider/mod.rs @@ -32,3 +32,8 @@ pub trait WriteMarkerProvider { pub mod r#default; #[cfg(not(feature = "enabled"))] pub use r#default as internal_provider; + +#[cfg(all(feature = "enabled", target_family = "unix"))] +pub mod unix; +#[cfg(all(feature = "enabled", target_family = "unix"))] +pub use unix as internal_provider; diff --git a/samply-markers/src/provider/unix.rs b/samply-markers/src/provider/unix.rs index 8bbd475b8..d0b9d8360 100644 --- a/samply-markers/src/provider/unix.rs +++ b/samply-markers/src/provider/unix.rs @@ -1,105 +1,135 @@ -use std::{ - cell::RefCell, - fmt::{Display, Write as _}, - fs::File, - io::Write, - num::NonZeroUsize, - path::{Path, PathBuf}, - sync::LazyLock, -}; - -use nix::{ - sys::mman::{MapFlags, ProtFlags}, - time::{ClockId, clock_gettime}, -}; +//! This module contains internal provider implementations for compiling [samply-markers](crate) on Unix systems. + +use std::cell::RefCell; +use std::fs::File; +use std::io::Write; +use std::num::NonZeroUsize; +use std::path::Path; +use std::path::PathBuf; +use std::sync::LazyLock; + +use crate::marker::SamplyMarker; +use crate::marker::SamplyTimestamp; +use crate::provider::TimestampNowProvider; +use crate::provider::WriteMarkerProvider; + +use nix::sys::mman::MapFlags; +use nix::sys::mman::ProtFlags; +use nix::time::ClockId; +use nix::time::clock_gettime; + use smallstr::SmallString; -use tempfile::{TempDir, tempdir}; -use tracing::error; +use tempfile::TempDir; +use tempfile::tempdir; -#[derive(Copy, Clone, Debug)] -struct Timestamp(i64); +/// A lazily created directory that holds per-thread mmapped marker files. +static MARKERS_DIR: LazyLock> = LazyLock::new(|| { + tempdir() + .map(TempDir::keep) + .inspect_err(|e| eprintln!("samply-markers: failed to create temporary directory: {e}")) + .ok() +}); -impl Timestamp { - fn now() -> Self { +thread_local! { + /// A thread-local file used to append marker lines that samply will ingest. + static MARKER_FILE: RefCell> = RefCell::new(create_marker_file()); +} + +/// A monotonic nanosecond timestamp backed by [`ClockId::CLOCK_MONOTONIC`]. +pub struct TimestampNowImpl; + +impl TimestampNowProvider for TimestampNowImpl { + /// Queries `clock_gettime` and converts the result to monotonic nanoseconds. + fn now() -> SamplyTimestamp { let now = clock_gettime(ClockId::CLOCK_MONOTONIC).unwrap(); - Self(now.tv_sec() as i64 * 1_000_000_000 + now.tv_nsec() as i64) + SamplyTimestamp::from_monotonic_nanos( + now.tv_sec() as u64 * 1_000_000_000 + now.tv_nsec() as u64, + ) } } -impl Display for Timestamp { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - write!(f, "{}", self.0) +/// A marker writer that appends newline-delimited ranges to the per-thread file. +pub struct WriteMarkerImpl; + +impl WriteMarkerProvider for WriteMarkerImpl { + /// Serializes the marker to the thread-local file, creating it on demand. + fn write_marker(start: SamplyTimestamp, end: SamplyTimestamp, marker: &SamplyMarker) { + let mut s = SmallString::<[u8; 64]>::new(); + start.fmt(&mut s).unwrap(); + s.push(' '); + end.fmt(&mut s).unwrap(); + s.push(' '); + s.push_str(marker.name()); + s.push('\n'); + let _ = with_marker_file(|f| f.write_all(s.as_bytes())); } } +/// Returns the lazily-created temporary markers directory, if available. fn markers_dir() -> Option<&'static Path> { - static MARKERS_DIR: LazyLock> = LazyLock::new(|| { - tempdir() - .map(TempDir::keep) - .inspect_err(|e| error!("Failed to create temporary directory: {e}")) - .ok() - }); - Some(LazyLock::force(&MARKERS_DIR).as_ref()?) } +/// Executes the provided closure with a mutable handle to the thread-local marker file. +/// +/// Returns [`None`] when the file could not be prepared. fn with_marker_file(f: F) -> Option where F: FnOnce(&mut File) -> R, { - fn create_marker_file() -> Option { - let file_name = markers_dir()?.join(format!( - "marker-{}-{}.txt", - nix::unistd::getpid(), - nix::unistd::gettid() - )); - - // Create the file. - let file = File::options() - .create(true) - .write(true) - .read({ - // We aren't going to read from the file, so we ordinarily - // wouldn't need read permission, but we're about mmap it and - // mmap always requires read permission. - true - }) - .open(&file_name) - .inspect_err(|e| error!("Failed to create marker file {e}: {}", file_name.display())) - .ok()?; - - // Create an mmap for the file. This cannot be skipped because it - // triggers samply to read and interpret the file. We will not use it - // to write to the file (because writing to a text file via mmap is - // painful and we haven't yet proved that it is a performance problem), - // so it is not necessary to map it with any particular protection or - // flags, so we use PROT_READ because that offers the fewest ways to - // screw up. - unsafe { - nix::sys::mman::mmap( - None, - NonZeroUsize::new(4096).unwrap(), - ProtFlags::PROT_READ, - MapFlags::MAP_SHARED, - &file, - 0, - ) - } - .inspect_err(|e| error!("Failed to mmap marker file {e}: {}", file_name.display())) - .ok()?; + MARKER_FILE.with_borrow_mut(|file| file.as_mut().map(f)) +} - Some(file) - } +/// Creates a new mmapped marker file for the current thread. +fn create_marker_file() -> Option { + let file_name = markers_dir()?.join(format!( + "marker-{}-{}.txt", + nix::unistd::getpid(), + nix::unistd::gettid() + )); - thread_local! { - static MARKER_FILE: RefCell> = RefCell::new(create_marker_file()); - } + let file = File::options() + .create(true) + .write(true) + .read({ + // We aren't going to read from the file, so we ordinarily + // wouldn't need read permission, but we're about mmap it and + // mmap always requires read permission. + true + }) + .open(&file_name) + .inspect_err(|e| { + eprintln!( + "samply-markers: failed to create marker file {e}: {}", + file_name.display() + ); + }) + .ok()?; - MARKER_FILE.with_borrow_mut(|file| file.as_mut().map(f)) -} + // Create an mmap for the file. This cannot be skipped because it + // triggers samply to read and interpret the file. We will not use it + // to write to the file (because writing to a text file via mmap is + // painful and we haven't yet proved that it is a performance problem), + // so it is not necessary to map it with any particular protection or + // flags, so we use PROT_READ because that offers the fewest ways to + // screw up. + unsafe { + nix::sys::mman::mmap( + None, + NonZeroUsize::new(4096).unwrap_unchecked(), + ProtFlags::PROT_READ, + MapFlags::MAP_SHARED, + &file, + 0, + ) + } + .inspect_err(|e| { + eprintln!( + "samply-markers: failed to mmap marker file {e}: {}", + file_name.display() + ); + }) + .ok()?; -fn write_marker(start: Timestamp, end: Timestamp, name: &str) { - let mut s = SmallString::<[u8; 64]>::new(); - writeln!(&mut s, "{start} {end} {name}").unwrap(); - let _ = with_marker_file(|f| f.write_all(s.as_bytes())); + Some(file) } From fd0d043432c3c19f6fab48367bff68e59c6bdd47 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 11:00:13 -0600 Subject: [PATCH 09/23] Add unimplemented Windows provider This commit adds unimplemented stubs for a Windows provider that would conform to the uniform internal provider APIs. --- samply-markers/src/provider/mod.rs | 5 +++++ samply-markers/src/provider/unix.rs | 3 +++ samply-markers/src/provider/windows.rs | 26 ++++++++++++++++++++++++++ 3 files changed, 34 insertions(+) create mode 100644 samply-markers/src/provider/windows.rs diff --git a/samply-markers/src/provider/mod.rs b/samply-markers/src/provider/mod.rs index 6e96cdf10..229a37708 100644 --- a/samply-markers/src/provider/mod.rs +++ b/samply-markers/src/provider/mod.rs @@ -37,3 +37,8 @@ pub use r#default as internal_provider; pub mod unix; #[cfg(all(feature = "enabled", target_family = "unix"))] pub use unix as internal_provider; + +#[cfg(all(feature = "enabled", target_family = "windows"))] +pub mod windows; +#[cfg(all(feature = "enabled", target_family = "windows"))] +pub use windows as internal_provider; diff --git a/samply-markers/src/provider/unix.rs b/samply-markers/src/provider/unix.rs index d0b9d8360..20fa23fb4 100644 --- a/samply-markers/src/provider/unix.rs +++ b/samply-markers/src/provider/unix.rs @@ -42,6 +42,9 @@ impl TimestampNowProvider for TimestampNowImpl { /// Queries `clock_gettime` and converts the result to monotonic nanoseconds. fn now() -> SamplyTimestamp { let now = clock_gettime(ClockId::CLOCK_MONOTONIC).unwrap(); + + // Monotonic nanoseconds should only ever be positive. + #[allow(clippy::cast_sign_loss)] SamplyTimestamp::from_monotonic_nanos( now.tv_sec() as u64 * 1_000_000_000 + now.tv_nsec() as u64, ) diff --git a/samply-markers/src/provider/windows.rs b/samply-markers/src/provider/windows.rs new file mode 100644 index 000000000..062b4894c --- /dev/null +++ b/samply-markers/src/provider/windows.rs @@ -0,0 +1,26 @@ +//! This module contains internal provider implementations for compiling [samply-markers](crate) on Windows systems. +//! +//! Windows is not yet supported at this time. + +use crate::marker::SamplyMarker; +use crate::marker::SamplyTimestamp; +use crate::provider::TimestampNowProvider; +use crate::provider::WriteMarkerProvider; + +/// A [`TimestampNowProvider`] that always panics because Windows is not supported yet. +pub struct TimestampNowImpl; + +impl TimestampNowProvider for TimestampNowImpl { + fn now() -> SamplyTimestamp { + unimplemented!("samply-markers: this crate is not yet available on Windows"); + } +} + +/// A [`WriteMarkerProvider`] that always panics because Windows is not supported yet. +pub struct WriteMarkerImpl; + +impl WriteMarkerProvider for WriteMarkerImpl { + fn write_marker(_start: SamplyTimestamp, _end: SamplyTimestamp, _marker: &SamplyMarker) { + unimplemented!("samply-markers: this crate is not yet available on Windows"); + } +} From 11191c71fb4848a5bd3d14e1b9ce80c4db7600f8 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 11:04:51 -0600 Subject: [PATCH 10/23] Add SamplyTimer implementation This commit adds a `SamplyTimer` abstraction which is a scoped RAII object that records the start time it was created and emits an interval marker when it goes out of scope. --- samply-markers/src/marker/mod.rs | 2 + samply-markers/src/marker/samply_timer.rs | 197 ++++++++++++++++++++++ 2 files changed, 199 insertions(+) create mode 100644 samply-markers/src/marker/samply_timer.rs diff --git a/samply-markers/src/marker/mod.rs b/samply-markers/src/marker/mod.rs index 8ee0e587e..eca124994 100644 --- a/samply-markers/src/marker/mod.rs +++ b/samply-markers/src/marker/mod.rs @@ -1,7 +1,9 @@ //! This module contains the core types for instrumenting code with markers. mod samply_marker; +mod samply_timer; mod timestamp; pub use samply_marker::SamplyMarker; +pub use samply_timer::SamplyTimer; pub use timestamp::SamplyTimestamp; diff --git a/samply-markers/src/marker/samply_timer.rs b/samply-markers/src/marker/samply_timer.rs new file mode 100644 index 000000000..b577d3fcc --- /dev/null +++ b/samply-markers/src/marker/samply_timer.rs @@ -0,0 +1,197 @@ +use std::borrow::Cow; + +use crate::marker::SamplyMarker; +use crate::marker::SamplyTimestamp; +use crate::provider::WriteMarkerImpl; +use crate::provider::WriteMarkerProvider; + +/// A scoped marker that emits an interval when the current scope ends. +/// +/// * The interval's start time is the moment the marker is created. +/// * The interval's end time is the moment the marker is dropped. +/// +/// The interval can be purposely emitted before the end of the scope by invoking the [`emit()`] function. +/// +/// * If [`emit()`] is called explicitly, it will not be called again when the marker is dropped. +/// +/// # Examples +/// +/// ```rust +/// # use samply_markers::marker::SamplyTimer; +/// # fn update_physics() {} +/// # fn render_scene() {} +/// # fn update_cache() {} +/// fn render_frame() { +/// // Create a timer to represent the entire function. +/// let _timer = SamplyTimer::new("render frame"); +/// +/// // Create a timer only for the physics and scene portion. +/// let render_segment = SamplyTimer::new("render scene"); +/// +/// update_physics(); +/// render_scene(); +/// +/// // Emit here explicitly, instead of at the end of the frame. +/// render_segment.emit(); +/// +/// // Create a timer only for the cache portion. +/// let cache_segment = SamplyTimer::new("update cache"); +/// update_cache(); +/// +/// // The cache_segment marker will be emitted automatically at the end of the frame. +/// // The _timer marker will be emitted automatically at the end of the frame. +/// } +/// +/// render_frame(); +/// ``` +/// +/// [`emit()`]: SamplyTimer::emit +#[derive(Debug)] +pub struct SamplyTimer<'data> { + /// The marker that will be emitted when the timer is dropped. + marker: SamplyMarker<'data>, + /// The timestamp captured from when the timer was created. + start_time: SamplyTimestamp, +} + +impl<'data> SamplyTimer<'data> { + /// Starts a new timer called `name`. + /// + /// # Examples + /// + /// ```rust + /// # use samply_markers::marker::SamplyTimer; + /// # fn compute_result() {} + /// fn expensive_function() { + /// let _timer = SamplyTimer::new("expensive computation"); + /// compute_result(); + /// // _timer emits when it is dropped at the end of scope. + /// } + /// # + /// # expensive_function(); + /// ``` + /// + /// ```rust + /// # use samply_markers::marker::SamplyTimer; + /// # fn process_batch(batch_id: u32) {} + /// fn process_batches() { + /// for batch_id in 0..10 { + /// let _timer = SamplyTimer::new(format!("process batch {batch_id}")); + /// process_batch(batch_id); + /// // 10 intervals are emitted, one for each loop iteration. + /// } + /// } + /// # + /// # process_batches(); + /// ``` + #[inline] + #[must_use] + pub fn new(name: impl Into> + AsRef) -> Self { + Self { + marker: SamplyMarker::new(name), + start_time: SamplyTimestamp::now(), + } + } + + /// Emits the interval immediately, instead of waiting for the end of scope. + /// + /// # Examples + /// + /// ```rust + /// # use samply_markers::marker::SamplyTimer; + /// # fn expensive_computation() {} + /// # fn log_results() {} + /// # fn cleanup_temp_files() {} + /// fn process_data() { + /// let timer = SamplyTimer::new("core computation"); + /// expensive_computation(); + /// + /// // Emit the interval explicitly here. + /// timer.emit(); + /// + /// // These operations are not included in the interval + /// log_results(); + /// cleanup_temp_files(); + /// + /// // The interval is not emitted again at the end of scope. + /// } + /// # + /// # process_data(); + /// ``` + #[inline] + pub fn emit(self) { + drop(self); + } +} + +impl Drop for SamplyTimer<'_> { + /// Emits the interval marker when the timer is dropped. + #[inline] + fn drop(&mut self) { + let end = SamplyTimestamp::now(); + ::write_marker(self.start_time, end, &self.marker); + } +} + +#[cfg(test)] +mod test { + use super::*; + + #[test] + fn new_with_str() { + let timer = SamplyTimer::new("test interval"); + assert_eq!(timer.marker.name(), "test interval"); + } + + #[test] + fn new_with_string() { + let name = String::from("dynamic interval"); + let timer = SamplyTimer::new(name); + assert_eq!(timer.marker.name(), "dynamic interval"); + } + + #[test] + fn new_with_format() { + let five = 5; + let high = "high"; + let timer = SamplyTimer::new(format!("{high} {five}!")); + assert_eq!(timer.marker.name(), "high 5!"); + } + + #[test] + fn new_captures_start_time() { + let before = SamplyTimestamp::now(); + + std::thread::sleep(std::time::Duration::from_micros(10)); + let timer = SamplyTimer::new("timing test"); + std::thread::sleep(std::time::Duration::from_micros(10)); + + let after = SamplyTimestamp::now(); + + #[cfg(feature = "enabled")] + assert!( + timer.start_time > before, + "Expected the start time {:?} to be greater than the before time {before:?}.", + timer.start_time + ); + #[cfg(not(feature = "enabled"))] + assert!( + timer.start_time >= before, + "Expected the start time {:?} to be greater than or equal to the before time {before:?}.", + timer.start_time + ); + + #[cfg(feature = "enabled")] + assert!( + timer.start_time < after, + "Expected the start time {:?} to be less than the after time {after:?}.", + timer.start_time + ); + #[cfg(not(feature = "enabled"))] + assert!( + timer.start_time <= after, + "Expected the start time {:?} to be less than or equal to the after time {after:?}.", + timer.start_time + ); + } +} From 453ff5cc592bc0dc3a1550401bfa23493e23dff2 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 11:08:06 -0600 Subject: [PATCH 11/23] Add samply_marker declarative macro This commit adds a declarative macro wrapper around the `SamplyMarker` implementation with the intent to be the primary way of emitting markers. --- samply-markers/src/lib.rs | 1 + samply-markers/src/macros/mod.rs | 9 ++++ samply-markers/src/macros/samply_marker.rs | 48 ++++++++++++++++++++++ 3 files changed, 58 insertions(+) create mode 100644 samply-markers/src/macros/mod.rs create mode 100644 samply-markers/src/macros/samply_marker.rs diff --git a/samply-markers/src/lib.rs b/samply-markers/src/lib.rs index 3cbb1b05f..371b3fd8f 100644 --- a/samply-markers/src/lib.rs +++ b/samply-markers/src/lib.rs @@ -1,3 +1,4 @@ +mod macros; mod provider; pub mod marker; diff --git a/samply-markers/src/macros/mod.rs b/samply-markers/src/macros/mod.rs new file mode 100644 index 000000000..3cdbcbbda --- /dev/null +++ b/samply-markers/src/macros/mod.rs @@ -0,0 +1,9 @@ +//! This module defines the macros that ship with [samply-markers](crate). +//! +//! While it's possible to use the marker types directly, the macros provide a nicer experience. +//! +//! [samply-markers](crate) provides three primary macros for instrumenting code: +//! +//! * [`samply_marker!`](crate::samply_marker) - Emits an instant or interval marker at the current location. + +mod samply_marker; diff --git a/samply-markers/src/macros/samply_marker.rs b/samply-markers/src/macros/samply_marker.rs new file mode 100644 index 000000000..fa17cf9d2 --- /dev/null +++ b/samply-markers/src/macros/samply_marker.rs @@ -0,0 +1,48 @@ +//! This module defines the [`samply_marker!`](crate::samply_marker) macro for emitting markers directly. + +/// Emits a marker at the current location in the code's execution. +/// +/// * Providing only a `name` will emit an instant marker at the current time. +/// * Providing an optional `start_time` will emit an interval marker from `start_time` to now. +/// +/// # Examples +/// +/// ```rust +/// # use samply_markers::samply_marker; +/// # use samply_markers::marker::SamplyTimestamp; +/// # struct Request {} +/// # impl Request { fn id(&self) -> u32 { 0 } } +/// # fn receive_request() -> Request { Request {} } +/// # fn query_database(id: u32) -> Vec { vec![] } +/// # fn serialize_json(data: &[String]) -> String { String::new() } +/// let request = receive_request(); +/// +/// // Emit an instant marker. +/// samply_marker!({ +/// name: format!("received request {}", request.id()), +/// }); +/// +/// // Mark the start time for serializing the response. +/// let start = SamplyTimestamp::now(); +/// +/// let data = query_database(request.id()); +/// let json = serialize_json(&data); +/// +/// // Emit an interval marker. +/// samply_marker!({ +/// name: "serialize response", +/// start_time: start, +/// }); +/// ``` +#[macro_export] +macro_rules! samply_marker { + // Instant marker with only a name. + {{ name: $name:expr $(,)? }} => {{ + $crate::marker::SamplyMarker::new($name).emit_instant(); + }}; + + // Interval marker with a provided start time. + {{ name: $name:expr, start_time: $start_time:expr $(,)? }} => {{ + $crate::marker::SamplyMarker::new($name).emit_interval($start_time); + }}; +} From 305e59b5fa77a9ced894abc57745f3ef77dd4ca5 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 11:29:08 -0600 Subject: [PATCH 12/23] Add samply_timer declarative macro This commit adds a declarative macro wrapper around the `SamplyTimer` implementation with the intent to be the primary way of constructing timer objects to emit intervals. --- samply-markers/src/macros/mod.rs | 2 + samply-markers/src/macros/samply_timer.rs | 50 +++++++++++++++++++++++ samply-markers/src/marker/samply_timer.rs | 32 +++++++-------- 3 files changed, 68 insertions(+), 16 deletions(-) create mode 100644 samply-markers/src/macros/samply_timer.rs diff --git a/samply-markers/src/macros/mod.rs b/samply-markers/src/macros/mod.rs index 3cdbcbbda..4937c79e9 100644 --- a/samply-markers/src/macros/mod.rs +++ b/samply-markers/src/macros/mod.rs @@ -5,5 +5,7 @@ //! [samply-markers](crate) provides three primary macros for instrumenting code: //! //! * [`samply_marker!`](crate::samply_marker) - Emits an instant or interval marker at the current location. +//! * [`samply_timer!`](crate::samply_timer) - Creates a scoped marker that emits an interval at the end of the frame. mod samply_marker; +mod samply_timer; diff --git a/samply-markers/src/macros/samply_timer.rs b/samply-markers/src/macros/samply_timer.rs new file mode 100644 index 000000000..13509e892 --- /dev/null +++ b/samply-markers/src/macros/samply_timer.rs @@ -0,0 +1,50 @@ +//! This module defines the [`samply_timer!`](crate::samply_timer) macro for scope-based interval timing. + +/// Creates a scoped timer that emits an interval marker when the current scope ends. +/// +/// * The interval marker's start time is the moment the timer is created. +/// * The interval marker's end time is the moment the timer is dropped. +/// +/// The interval marker can be purposely emitted before the end of the scope by invoking the [`emit()`] function. +/// +/// * If [`emit()`] is called explicitly, it will not be called again when the timer is dropped. +/// +/// # Examples +/// +/// ```rust +/// # use samply_markers::samply_timer; +/// # fn update_physics() {} +/// # fn render_scene() {} +/// # fn update_cache() {} +/// fn render_frame() { +/// // Create a timer to represent the entire function. +/// let _timer = samply_timer!({ name: "render frame" }); +/// +/// // Create a timer only for the physics and scene portion. +/// let render_segment = samply_timer!({ name: "render scene" }); +/// +/// update_physics(); +/// render_scene(); +/// +/// // Emit here explicitly, instead of at the end of the frame. +/// render_segment.emit(); +/// +/// // Create a timer only for the cache portion. +/// let cache_segment = samply_timer!({ name: "update cache" }); +/// update_cache(); +/// +/// // The cache_segment timer will be emitted automatically at the end of the frame. +/// // The _timer will be emitted automatically at the end of the frame. +/// } +/// +/// render_frame(); +/// ``` +/// +/// [`emit()`]: crate::marker::SamplyTimer::emit +/// +#[macro_export] +macro_rules! samply_timer { + {{ name: $name:expr $(,)? }} => { + $crate::marker::SamplyTimer::new($name); + }; +} diff --git a/samply-markers/src/marker/samply_timer.rs b/samply-markers/src/marker/samply_timer.rs index b577d3fcc..8ebd730e5 100644 --- a/samply-markers/src/marker/samply_timer.rs +++ b/samply-markers/src/marker/samply_timer.rs @@ -5,14 +5,14 @@ use crate::marker::SamplyTimestamp; use crate::provider::WriteMarkerImpl; use crate::provider::WriteMarkerProvider; -/// A scoped marker that emits an interval when the current scope ends. +/// A scoped timer that emits an interval marker when the current scope ends. /// -/// * The interval's start time is the moment the marker is created. -/// * The interval's end time is the moment the marker is dropped. +/// * The interval marker's start time is the moment the timer is created. +/// * The interval marker's end time is the moment the timer is dropped. /// -/// The interval can be purposely emitted before the end of the scope by invoking the [`emit()`] function. +/// The interval marker can be purposely emitted before the end of the scope by invoking the [`emit()`] function. /// -/// * If [`emit()`] is called explicitly, it will not be called again when the marker is dropped. +/// * If [`emit()`] is called explicitly, it will not be called again when the timer is dropped. /// /// # Examples /// @@ -35,10 +35,10 @@ use crate::provider::WriteMarkerProvider; /// render_segment.emit(); /// /// // Create a timer only for the cache portion. -/// let cache_segment = SamplyTimer::new("update cache"); +/// let _cache_segment = SamplyTimer::new("update cache"); /// update_cache(); /// -/// // The cache_segment marker will be emitted automatically at the end of the frame. +/// // The _cache_segment marker will be emitted automatically at the end of the frame. /// // The _timer marker will be emitted automatically at the end of the frame. /// } /// @@ -78,7 +78,7 @@ impl<'data> SamplyTimer<'data> { /// for batch_id in 0..10 { /// let _timer = SamplyTimer::new(format!("process batch {batch_id}")); /// process_batch(batch_id); - /// // 10 intervals are emitted, one for each loop iteration. + /// // 10 interval markers are emitted, one for each loop iteration. /// } /// } /// # @@ -93,7 +93,7 @@ impl<'data> SamplyTimer<'data> { } } - /// Emits the interval immediately, instead of waiting for the end of scope. + /// Emits the interval marker immediately, instead of waiting for the end of scope. /// /// # Examples /// @@ -106,14 +106,14 @@ impl<'data> SamplyTimer<'data> { /// let timer = SamplyTimer::new("core computation"); /// expensive_computation(); /// - /// // Emit the interval explicitly here. + /// // Emit the interval marker explicitly here. /// timer.emit(); /// - /// // These operations are not included in the interval + /// // These operations are not included in the interval marker /// log_results(); /// cleanup_temp_files(); /// - /// // The interval is not emitted again at the end of scope. + /// // The interval marker is not emitted again at the end of scope. /// } /// # /// # process_data(); @@ -139,15 +139,15 @@ mod test { #[test] fn new_with_str() { - let timer = SamplyTimer::new("test interval"); - assert_eq!(timer.marker.name(), "test interval"); + let timer = SamplyTimer::new("timer from str"); + assert_eq!(timer.marker.name(), "timer from str"); } #[test] fn new_with_string() { - let name = String::from("dynamic interval"); + let name = String::from("timer from String"); let timer = SamplyTimer::new(name); - assert_eq!(timer.marker.name(), "dynamic interval"); + assert_eq!(timer.marker.name(), "timer from String"); } #[test] From 0a3300df495d7881c6eb2dfc37f9f10f32c38533 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 11:31:07 -0600 Subject: [PATCH 13/23] Add samply_measure declarative macro This commit adds a declarative macro wrapper that will automatically measure the runtime of a provided sync or async code block by emitting an intterval marker when the code block has finished running. --- samply-markers/src/macros/mod.rs | 2 + samply-markers/src/macros/samply_measure.rs | 138 ++++++++++++++++++++ 2 files changed, 140 insertions(+) create mode 100644 samply-markers/src/macros/samply_measure.rs diff --git a/samply-markers/src/macros/mod.rs b/samply-markers/src/macros/mod.rs index 4937c79e9..413829112 100644 --- a/samply-markers/src/macros/mod.rs +++ b/samply-markers/src/macros/mod.rs @@ -5,7 +5,9 @@ //! [samply-markers](crate) provides three primary macros for instrumenting code: //! //! * [`samply_marker!`](crate::samply_marker) - Emits an instant or interval marker at the current location. +//! * [`samply_measure!`](crate::samply_measure) - Measures the timing of a code block, emitting an interval automatically. //! * [`samply_timer!`](crate::samply_timer) - Creates a scoped marker that emits an interval at the end of the frame. mod samply_marker; +mod samply_measure; mod samply_timer; diff --git a/samply-markers/src/macros/samply_measure.rs b/samply-markers/src/macros/samply_measure.rs new file mode 100644 index 000000000..fcf504bdb --- /dev/null +++ b/samply-markers/src/macros/samply_measure.rs @@ -0,0 +1,138 @@ +//! This module defines the [`samply_measure!`](crate::samply_measure) macro for measuring code blocks. + +/// Measures the runtime of a block of code by emitting an interval marker. +/// +/// * The interval marker's start time is the beginning of the block. +/// * The interval marker's end time is the end of the block. +/// +/// The block's returned value is preserved by the macro. +/// +/// Supports both synchronous and asynchronous blocks. +/// +/// # Examples +/// +/// #### Synchronous +/// ```rust +/// # use samply_markers::samply_measure; +/// # struct World { entities: Vec } +/// # impl World { +/// # fn new(len: usize) -> Self { Self { entities: vec![1; len] } } +/// # fn simulate_physics(&mut self) {} +/// # fn apply_effects(&mut self) {} +/// # } +/// // Measure the duration of update_world every time it is called. +/// fn update_world(world: &mut World) -> usize { +/// samply_measure!({ +/// world.simulate_physics(); +/// world.apply_effects(); +/// world.entities.len() +/// }, marker: { +/// name: "update world", +/// }) +/// } +/// +/// let mut world = World::new(13); +/// let count = update_world(&mut world); +/// +/// assert_eq!(count, 13); +/// ``` +/// +/// #### Asynchronous +/// +/// ```rust +/// # use samply_markers::samply_measure; +/// # async fn http_get(url: &str) -> Result { Ok(String::from("data")) } +/// # fn parse_response(data: &str) -> Result, ()> { Ok(vec![]) } +/// // Measure the duration of fetch_user_data every time it is called. +/// async fn fetch_user_data(user_id: u64) -> Result, ()> { +/// samply_measure!({ +/// let response = http_get(&format!("/api/users/{user_id}")).await?; +/// parse_response(&response) +/// }, marker: { +/// name: "fetch user data", +/// }) +/// } +/// ``` +/// +/// #### Create a New Async Block +/// +/// Use the `async` keyword to create a new async block, +/// which allows the `?` operator to return from this block instead of the enclosing function. +/// +/// ```rust +/// # use samply_markers::samply_measure; +/// # async fn read_file(path: &str) -> Option { Some(String::from("100,200")) } +/// async fn load_config(path: &str) -> (u32, u32) { +/// let config = samply_measure!(async { +/// let contents = read_file(path).await?; +/// let mut parts = contents.split(','); +/// +/// let x = parts.next()?.parse::().ok()?; +/// let y = parts.next()?.parse::().ok()?; +/// +/// Some((x, y)) +/// }, marker: { +/// name: "load config", +/// }).await; +/// +/// config.unwrap_or((0, 0)) +/// } +/// ``` +/// +/// #### Create a New Async Move Block +/// +/// Use `async move` to transfer ownership of captured variables into the async block. +/// +/// ```rust +/// # use samply_markers::samply_measure; +/// # async fn process_data(data: String) -> usize { data.len() } +/// async fn measure_owned_data() -> usize { +/// let data = String::from("owned data"); +/// samply_measure!(async move { +/// process_data(data).await +/// }, marker: { +/// name: "process owned data", +/// }).await +/// } +/// ``` +#[macro_export] +macro_rules! samply_measure { + // New block scope within the same context + ( + $body:block + $(,)? + marker: { + name: $name:expr $(,)? + } + $(,)? + ) => {{ + let _timer = $crate::marker::SamplyTimer::new($name); + $body + }}; + + // Create a new async block + ( + async $body:block + $(,)? + marker: { + name: $name:expr $(,)? + } + $(,)? + ) => {async { + let _timer = $crate::marker::SamplyTimer::new($name); + (async $body).await + }}; + + // Create a new async move block + ( + async move $body:block + $(,)? + marker: { + name: $name:expr $(,)? + } + $(,)? + ) => {async move { + let _timer = $crate::marker::SamplyTimer::new($name); + (async move $body).await + }}; +} From cc01f01a2cb0691c674ab7ca3aea118cfbcfa153 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 11:33:33 -0600 Subject: [PATCH 14/23] Add prelude module This commit adds a `prelude` module to the `samply-markers` crate so that users have an easy way to glob import everything that they need to instrument their code with markers. --- samply-markers/src/lib.rs | 18 ++++++++++++++++++ samply-markers/src/macros/samply_marker.rs | 3 +-- samply-markers/src/macros/samply_measure.rs | 8 ++++---- samply-markers/src/marker/samply_marker.rs | 12 +++++------- samply-markers/src/marker/samply_timer.rs | 8 ++++---- samply-markers/src/marker/timestamp.rs | 4 ++-- 6 files changed, 34 insertions(+), 19 deletions(-) diff --git a/samply-markers/src/lib.rs b/samply-markers/src/lib.rs index 371b3fd8f..fc26c31ca 100644 --- a/samply-markers/src/lib.rs +++ b/samply-markers/src/lib.rs @@ -2,3 +2,21 @@ mod macros; mod provider; pub mod marker; + +/// This module contains everything needed to add markers within a convenient glob import. +/// +/// ```rust +/// use samply_markers::prelude::*; +/// ``` +pub mod prelude { + pub use crate::marker::SamplyMarker; + pub use crate::marker::SamplyTimer; + pub use crate::marker::SamplyTimestamp; + + #[doc(inline)] + pub use crate::samply_marker; + #[doc(inline)] + pub use crate::samply_measure; + #[doc(inline)] + pub use crate::samply_timer; +} diff --git a/samply-markers/src/macros/samply_marker.rs b/samply-markers/src/macros/samply_marker.rs index fa17cf9d2..a61d39ee2 100644 --- a/samply-markers/src/macros/samply_marker.rs +++ b/samply-markers/src/macros/samply_marker.rs @@ -8,8 +8,7 @@ /// # Examples /// /// ```rust -/// # use samply_markers::samply_marker; -/// # use samply_markers::marker::SamplyTimestamp; +/// # use samply_markers::prelude::*; /// # struct Request {} /// # impl Request { fn id(&self) -> u32 { 0 } } /// # fn receive_request() -> Request { Request {} } diff --git a/samply-markers/src/macros/samply_measure.rs b/samply-markers/src/macros/samply_measure.rs index fcf504bdb..59817cb08 100644 --- a/samply-markers/src/macros/samply_measure.rs +++ b/samply-markers/src/macros/samply_measure.rs @@ -13,7 +13,7 @@ /// /// #### Synchronous /// ```rust -/// # use samply_markers::samply_measure; +/// # use samply_markers::prelude::*; /// # struct World { entities: Vec } /// # impl World { /// # fn new(len: usize) -> Self { Self { entities: vec![1; len] } } @@ -40,7 +40,7 @@ /// #### Asynchronous /// /// ```rust -/// # use samply_markers::samply_measure; +/// # use samply_markers::prelude::*; /// # async fn http_get(url: &str) -> Result { Ok(String::from("data")) } /// # fn parse_response(data: &str) -> Result, ()> { Ok(vec![]) } /// // Measure the duration of fetch_user_data every time it is called. @@ -60,7 +60,7 @@ /// which allows the `?` operator to return from this block instead of the enclosing function. /// /// ```rust -/// # use samply_markers::samply_measure; +/// # use samply_markers::prelude::*; /// # async fn read_file(path: &str) -> Option { Some(String::from("100,200")) } /// async fn load_config(path: &str) -> (u32, u32) { /// let config = samply_measure!(async { @@ -84,7 +84,7 @@ /// Use `async move` to transfer ownership of captured variables into the async block. /// /// ```rust -/// # use samply_markers::samply_measure; +/// # use samply_markers::prelude::*; /// # async fn process_data(data: String) -> usize { data.len() } /// async fn measure_owned_data() -> usize { /// let data = String::from("owned data"); diff --git a/samply-markers/src/marker/samply_marker.rs b/samply-markers/src/marker/samply_marker.rs index c050626c9..fe7fe9bee 100644 --- a/samply-markers/src/marker/samply_marker.rs +++ b/samply-markers/src/marker/samply_marker.rs @@ -14,8 +14,7 @@ use crate::provider::WriteMarkerProvider; /// # Examples /// /// ```rust -/// # use samply_markers::marker::SamplyMarker; -/// # use samply_markers::marker::SamplyTimestamp; +/// # use samply_markers::prelude::*; /// # struct Request {} /// # impl Request { fn id(&self) -> u32 { 0 } } /// # fn receive_request() -> Request { Request {} } @@ -73,7 +72,7 @@ impl<'data> SamplyMarker<'data> { /// # Examples /// /// ```rust - /// # use samply_markers::marker::SamplyMarker; + /// # use samply_markers::prelude::*; /// SamplyMarker::new("database query").emit_instant(); /// /// let user_id = 123; @@ -100,7 +99,7 @@ impl<'data> SamplyMarker<'data> { /// # Examples /// /// ```rust - /// # use samply_markers::marker::SamplyMarker; + /// # use samply_markers::prelude::*; /// let marker = SamplyMarker::new("database query"); /// assert_eq!(marker.name(), "database query"); /// ``` @@ -115,7 +114,7 @@ impl<'data> SamplyMarker<'data> { /// # Examples /// /// ```rust - /// # use samply_markers::marker::SamplyMarker; + /// # use samply_markers::prelude::*; /// # fn check_cache() -> Option { None } /// # fn fetch_from_disk() -> String { String::new() } /// if let Some(data) = check_cache() { @@ -139,8 +138,7 @@ impl<'data> SamplyMarker<'data> { /// # Examples /// /// ```rust - /// # use samply_markers::marker::SamplyMarker; - /// # use samply_markers::marker::SamplyTimestamp; + /// # use samply_markers::prelude::*; /// # fn check_cache() -> Option { None } /// # fn fetch_from_disk() -> String { String::new() } /// let start_time = SamplyTimestamp::now(); diff --git a/samply-markers/src/marker/samply_timer.rs b/samply-markers/src/marker/samply_timer.rs index 8ebd730e5..e7cbd626e 100644 --- a/samply-markers/src/marker/samply_timer.rs +++ b/samply-markers/src/marker/samply_timer.rs @@ -17,7 +17,7 @@ use crate::provider::WriteMarkerProvider; /// # Examples /// /// ```rust -/// # use samply_markers::marker::SamplyTimer; +/// # use samply_markers::prelude::*; /// # fn update_physics() {} /// # fn render_scene() {} /// # fn update_cache() {} @@ -60,7 +60,7 @@ impl<'data> SamplyTimer<'data> { /// # Examples /// /// ```rust - /// # use samply_markers::marker::SamplyTimer; + /// # use samply_markers::prelude::*; /// # fn compute_result() {} /// fn expensive_function() { /// let _timer = SamplyTimer::new("expensive computation"); @@ -72,7 +72,7 @@ impl<'data> SamplyTimer<'data> { /// ``` /// /// ```rust - /// # use samply_markers::marker::SamplyTimer; + /// # use samply_markers::prelude::*; /// # fn process_batch(batch_id: u32) {} /// fn process_batches() { /// for batch_id in 0..10 { @@ -98,7 +98,7 @@ impl<'data> SamplyTimer<'data> { /// # Examples /// /// ```rust - /// # use samply_markers::marker::SamplyTimer; + /// # use samply_markers::prelude::*; /// # fn expensive_computation() {} /// # fn log_results() {} /// # fn cleanup_temp_files() {} diff --git a/samply-markers/src/marker/timestamp.rs b/samply-markers/src/marker/timestamp.rs index 7f52df095..f1efe2590 100644 --- a/samply-markers/src/marker/timestamp.rs +++ b/samply-markers/src/marker/timestamp.rs @@ -11,7 +11,7 @@ use crate::provider::TimestampNowProvider; /// # Examples /// /// ```rust -/// # use samply_markers::marker::SamplyTimestamp; +/// # use samply_markers::prelude::*; /// let start = SamplyTimestamp::now(); /// ``` #[derive(Copy, Clone, Debug)] @@ -24,7 +24,7 @@ impl SamplyTimestamp { /// # Examples /// /// ```rust - /// # use samply_markers::marker::SamplyTimestamp; + /// # use samply_markers::prelude::*; /// let start = SamplyTimestamp::now(); /// ``` #[inline] From 05062faaf7e3520c489ae424d0ead0548621aaab Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 11:34:06 -0600 Subject: [PATCH 15/23] Add top-level doc comment This commit adds a top-level doc comment to the `samply-markers` crate. --- samply-markers/src/lib.rs | 381 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 381 insertions(+) diff --git a/samply-markers/src/lib.rs b/samply-markers/src/lib.rs index fc26c31ca..fd2857c2c 100644 --- a/samply-markers/src/lib.rs +++ b/samply-markers/src/lib.rs @@ -1,3 +1,384 @@ +#![warn(missing_docs)] + +//! # Samply Markers +//! +//! Emit profiler markers that [samply] records and displays in the [Firefox Profiler](https://profiler.firefox.com/) UI. +//! +//!
+//! +//! ## Quick Demo +//! +//!
+//! +//! The following Fibonacci Sequence example demonstrates recursive function call tracking. +//! +//! The [`samply_measure!`](crate::samply_measure) macro emits an interval marker for each recursive call, +//! allowing the profiler to display the complete call tree with timing information for every `fib(n)` invocation. +//! +//! **[macOS](https://share.firefox.dev/4oMKHtT) | +//! [Ubuntu](https://share.firefox.dev/4o3wur4) | +//! Windows (not yet supported)** +//! +//! ```rust,no_run +//! use samply_markers::prelude::*; +//! +//! use std::time::Duration; +//! use std::thread::sleep; +//! +//! fn fib(n: u64) -> u64 { +//! samply_measure!({ +//! match n { +//! 0 | 1 => { +//! sleep(Duration::from_millis(10)); +//! n +//! }, +//! _ => fib(n - 1) + fib(n - 2), +//! } +//! }, marker: { +//! name: format!("fib({n})"), +//! }) +//! } +//! +//! fn main() { +//! let n = 12; +//! let value = fib(n); +//! println!("fib({n}) = {}", value); +//! } +//! ``` +//! +//!
+//! +//! ## Project Configuration +//! +//!
**1)** Add [samply-markers](crate) as a dependency to your project's `Cargo.toml`. +//! +//! ```toml +//! [dependencies] +//! samply-markers = "{version}" +//! ``` +//! +//!
**2)** Add a `samply-markers` feature flag to your project's `Cargo.toml`. +//! +//! > Samply markers are designed to no-op by default, so they must be explicitly enabled in order +//! > to see them in profiles. +//! > +//! > * Using [samply-markers](crate) has effectively zero cost when not enabled. +//! > * Using [samply-markers](crate) does not pull in any additional dependencies when not enabled. +//! +//! ```toml +//! [features] +//! samply-markers = ["samply-markers/enabled"] +//! ``` +//! +//!
**3)** Add a `profiling` profile to your project's `Cargo.toml`. +//! +//! * This step is optional, but highly recommended for profiling with [samply]. +//! +//! ```toml +//! [profile.profiling] +//! inherits = "release" +//! debug = true +//! ``` +//! +//!
**4)** Build your project for profiling, then record the resulting binary with [samply] to process the emitted markers. +//! +//! ```text +//! cargo build --release -p samply +//! cargo build --profile profiling --features samply-markers +//! samply record target/profiling/{binary} +//! ``` +//! +//!
+//! +//! ## Public API +//! +//! +//! #### The [`samply_marker!`](crate::samply_marker) macro +//! +//!
+//! +//! The [`samply_marker!`](crate::samply_marker) macro is the foundational way to emit profiler markers. +//! It creates and emits a [`SamplyMarker`](marker::SamplyMarker) at the current location in your code, +//! supporting both instant markers (a single point in time) and interval markers (a span of time). +//! +//! ##### Instant Marker +//! +//! An instant marker marks a specific point in time: +//! +//! ```rust +//! # use samply_markers::prelude::*; +//! fn process_request(request_id: u32) { +//! // Emit an instant marker at this exact moment +//! samply_marker!({ name: format!("processing request {request_id}") }); +//! +//! // ... process the request. +//! } +//! ``` +//! +//! ##### Interval Marker +//! +//! An interval marker spans from a start time to the current time using [`SamplyTimestamp`](marker::SamplyTimestamp): +//! +//! ```rust +//! # use samply_markers::prelude::*; +//! fn query_database(query: &str) -> Vec { +//! let start = SamplyTimestamp::now(); +//! +//! // ... execute the database query. +//! let results = vec![]; // Placeholder for actual results. +//! +//! // Emit an interval marker from start to now. +//! samply_marker!({ +//! name: format!("database query: {query}"), +//! start_time: start, +//! }); +//! +//! results +//! } +//! ``` +//! +//!
+//! +//! --- +//! +//!
+//! +//! #### The [`samply_timer!`](crate::samply_timer) macro +//! +//!
+//! +//! While [`samply_marker!`](crate::samply_marker) requires manually providing a [`SamplyTimestamp`](marker::SamplyTimestamp) +//! for interval markers, the [`samply_timer!`](crate::samply_timer) macro simplifies this pattern by wrapping the timestamp in a scoped RAII object. +//! It creates a [`SamplyTimer`](marker::SamplyTimer) that registers the time it was created and automatically emits the interval marker when dropped at the end of its scope. +//! +//! ##### Automatic Interval +//! +//! The interval marker emits when the timer is dropped: +//! +//! ```rust +//! # use samply_markers::prelude::*; +//! fn expensive_computation() { +//! let _timer = samply_timer!({ name: "expensive computation" }); +//! +//! // ... perform expensive work. +//! +//! // The interval marker is automatically emitted here when _timer is dropped. +//! } +//! ``` +//! +//! ##### Early Emit +//! +//! You can explicitly emit the interval marker before the end of the scope: +//! +//! ```rust +//! # use samply_markers::prelude::*; +//! fn process_with_cleanup() { +//! let timer = samply_timer!({ name: "core processing" }); +//! +//! // ... perform core processing work. +//! +//! // Emit the interval marker now, excluding cleanup from the measurement. +//! timer.emit(); +//! +//! // ... perform cleanup tasks (not included in the interval marker). +//! +//! // The interval marker will not emit a second time when dropped. +//! } +//! ``` +//! +//!
+//! +//! --- +//! +//!
+//! +//! #### The [`samply_measure!`](crate::samply_measure) macro +//! +//!
+//! +//! Building on the scoped approach of [`samply_timer!`](crate::samply_timer), the [`samply_measure!`](crate::samply_measure) macro further simplifies profiling +//! by eliminating the need to create a scoped timer yourself. Instead, you wrap a code block, then its execution time is automatically measured with an interval marker. +//! +//! ##### Measure Synchronous Code +//! +//! The value of the measured block expression is preserved: +//! +//! ```rust +//! # use samply_markers::prelude::*; +//! fn compute_sum(values: &[i32]) -> i32 { +//! samply_measure!({ +//! values.iter().sum() +//! }, marker: { +//! name: "compute sum", +//! }) +//! } +//! +//! let values = vec![1, 2, 3, 4, 5]; +//! let result = compute_sum(&values); +//! assert_eq!(result, 15); +//! ``` +//! +//! ##### With `?` Operator +//! +//! The block's control flow is preserved, including early returns: +//! +//! ```rust +//! # use samply_markers::prelude::*; +//! fn parse_and_validate(data: &str) -> Result { +//! samply_measure!({ +//! let parsed = data.parse::() +//! .map_err(|e| format!("parse error: {e}"))?; +//! +//! if parsed > 100 { +//! return Err(String::from("value too large")); +//! } +//! +//! Ok(parsed) +//! }, marker: { +//! name: "parse and validate", +//! }) +//! } +//! ``` +//! +//! ##### Measure Asynchronous Code +//! +//! The macro works the same within asynchronous code. However, the clock does not stop between polls. +//! The resulting interval will span the total time to completion, including time spent waiting: +//! +//! ```rust +//! # use samply_markers::prelude::*; +//! # async fn fetch_data() -> String { +//! # String::from("data") +//! # } +//! async fn process_data(data_id: u64) -> String { +//! samply_measure!({ +//! let data = fetch_data().await; +//! format!("Processed: {data} (id: {data_id})") +//! }, marker: { +//! name: format!("process data {data_id}"), +//! }) +//! } +//! ``` +//! +//! ##### Create a New Async Block +//! +//! Use the `async` keyword to create a new async block, which allows the `?` +//! operator to return from the `async` block instead of from the enclosing function: +//! +//! ```rust +//! # use samply_markers::prelude::*; +//! # async fn read_file(path: &str) -> Option { Some(String::from("100,200")) } +//! async fn load_config(path: &str) -> (u32, u32) { +//! let config = samply_measure!(async { +//! let contents = read_file(path).await?; +//! let mut parts = contents.split(','); +//! +//! let x = parts.next()?.parse::().ok()?; +//! let y = parts.next()?.parse::().ok()?; +//! +//! Some((x, y)) +//! }, marker: { +//! name: "load config", +//! }) +//! .await; +//! +//! config.unwrap_or((0, 0)) +//! } +//! ``` +//! +//!
+//! +//! ## Example +//! +//!
+//! +//! Here's a complete example demonstrating everything in context: +//! +//! *See the [examples directory] to build, run, and profile the examples in this README yourself.* +//! +//! **[macOS](https://share.firefox.dev/48eHTj8) | +//! [Ubuntu](https://share.firefox.dev/3LzT6lJ) | +//! Windows (not yet supported)** +//! +//! ```rust,no_run +//! use samply_markers::prelude::*; +//! +//! async fn fetch_url(url: &str) -> (String, Option) { +//! // Emit an interval marker for the time it takes to fetch. +//! let result = samply_measure!(async { +//! let response = reqwest::get(url).await?; +//! response.text().await +//! }, marker: { +//! name: format!("fetch {url}"), +//! }) +//! .await; +//! +//! match result { +//! Ok(content) => { +//! println!(" ✓ Fetched {url} ({} bytes)", content.len()); +//! (String::from(url), Some(content)) +//! } +//! Err(error) => { +//! // Emit an instant marker any time a fetch fails. +//! samply_marker!({ name: format!("fetch failed: {url}") }); +//! println!(" ✗ Failed to fetch {url}: {error}"); +//! (String::from(url), None) +//! } +//! } +//! } +//! +//! #[tokio::main] +//! async fn main() { +//! // Create a timer that will span the entirety of main(). +//! // The timer will emit an interval marker when it is dropped at the end of the scope. +//! let _main_timer = samply_timer!({ name: "main()" }); +//! +//! println!("\nStarting samply-markers demo...\n"); +//! +//! std::thread::sleep(std::time::Duration::from_millis(200)); +//! +//! let urls = &[ +//! "https://example.com", +//! "https://fail.invalid", +//! "https://fail.invalid", +//! "https://en.wikipedia.org/wiki/Firefox", +//! "https://fail.invalid", +//! "https://github.com/nordzilla", +//! ]; +//! +//! println!("\n=== Sequential Fetching ===\n"); +//! +//! // Emit an interval marker for the total time to fetch all URLs sequentially. +//! samply_measure!({ +//! for url in urls { +//! fetch_url(url).await; +//! } +//! }, marker: { +//! name: "fetch all URLs sequentially", +//! }); +//! +//! std::thread::sleep(std::time::Duration::from_millis(200)); +//! +//! println!("\n=== Concurrent Fetching ===\n"); +//! +//! // Emit an interval marker for the total time to fetch all URLs concurrently. +//! samply_measure!({ +//! futures::future::join_all( +//! urls.iter().map(|url| fetch_url(url)) +//! ).await; +//! }, marker: { +//! name: "fetch all URLs concurrently", +//! }); +//! +//! std::thread::sleep(std::time::Duration::from_millis(200)); +//! +//! println!("\nDemo completed!\n"); +//! } +//! ``` +//! +//! [samply]: https://github.com/mstange/samply?tab=readme-ov-file#samply +//! [examples directory]: https://github.com/mstange/samply/tree/main/samply-markers/examples + mod macros; mod provider; From de6fdf93978ed8827ddabf688d0f79046066c5d7 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 11:55:35 -0600 Subject: [PATCH 16/23] Use instant marker timing if span start and end time are the same This commit updates the way Samply adds markers to use instant marker timing, instead of a span marker timing, if the start time and end time of the span are exactly the same. Admittedly, I don't like this change, and I would like to revert it once a different marker file format is potentially supported. I think that a zero-length interval should be possible if that is actually what was measured. But as of right now, I have no way to emit an actual instant marker given the current file-format restrictions. --- samply/src/shared/process_sample_data.rs | 58 +++++++++++++++++++++--- 1 file changed, 52 insertions(+), 6 deletions(-) diff --git a/samply/src/shared/process_sample_data.rs b/samply/src/shared/process_sample_data.rs index 1bdbf31ab..cec9a52bf 100644 --- a/samply/src/shared/process_sample_data.rs +++ b/samply/src/shared/process_sample_data.rs @@ -116,12 +116,26 @@ impl ProcessSampleData { } for marker in marker_spans { - let marker_name_string_index = profile.handle_for_string(&marker.name); - profile.add_marker( - marker.thread_handle, - MarkerTiming::Interval(marker.start_time, marker.end_time), - SimpleMarker(marker_name_string_index), - ); + let MarkerSpanOnThread { + thread_handle, + start_time, + end_time, + name, + } = marker; + + let marker_name_string_index = profile.handle_for_string(&name); + let timing = Self::marker_timing_for_span(start_time, end_time); + let marker = SimpleMarker(marker_name_string_index); + + profile.add_marker(thread_handle, timing, marker); + } + } + + fn marker_timing_for_span(start_time: Timestamp, end_time: Timestamp) -> MarkerTiming { + if start_time == end_time { + MarkerTiming::Instant(start_time) + } else { + MarkerTiming::Interval(start_time, end_time) } } } @@ -285,3 +299,35 @@ impl Marker for SimpleMarker { self.0 } } + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn test_marker_timing_for_span() { + let same_time = Timestamp::from_millis_since_reference(5.0); + let different_start = Timestamp::from_millis_since_reference(10.0); + let different_end = Timestamp::from_millis_since_reference(15.0); + + let zero_duration_timing = ProcessSampleData::marker_timing_for_span(same_time, same_time); + assert!( + matches!(zero_duration_timing, MarkerTiming::Instant(_)), + "Zero duration span should return Instant timing" + ); + if let MarkerTiming::Instant(t) = zero_duration_timing { + assert_eq!(t, same_time); + } + + let non_zero_duration_timing = + ProcessSampleData::marker_timing_for_span(different_start, different_end); + assert!( + matches!(non_zero_duration_timing, MarkerTiming::Interval(_, _)), + "Non-zero duration span should return Interval timing" + ); + if let MarkerTiming::Interval(start, end) = non_zero_duration_timing { + assert_eq!(start, different_start); + assert_eq!(end, different_end); + } + } +} From 2743e38953e4c6da34aa488b38d63e5cbf4e92c5 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 14:34:18 -0600 Subject: [PATCH 17/23] Add integration tests This commit adds integreation tests. The tests for Unix systems are fully fleshed out, ensuring that markers are correctly written to the expected files. The for Windows systems currently expect to panic. --- Cargo.lock | 44 +++ samply-markers/Cargo.toml | 7 + samply-markers/tests/unix.rs | 583 ++++++++++++++++++++++++++++++++ samply-markers/tests/windows.rs | 21 ++ 4 files changed, 655 insertions(+) create mode 100644 samply-markers/tests/unix.rs create mode 100644 samply-markers/tests/windows.rs diff --git a/Cargo.lock b/Cargo.lock index a079e631d..5a4315d03 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2288,9 +2288,13 @@ dependencies = [ name = "samply-markers" version = "0.1.0" dependencies = [ + "futures", "nix", + "regex", + "serial_test", "smallstr", "tempfile", + "tokio", ] [[package]] @@ -2362,6 +2366,15 @@ version = "0.0.6" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0a4416eddc0eaf31e04aa4039bd3db4288ea1ba613955d86cf9c310049c5d1e2" +[[package]] +name = "scc" +version = "2.4.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "46e6f046b7fef48e2660c57ed794263155d713de679057f2d0c169bfc6e756cc" +dependencies = [ + "sdd", +] + [[package]] name = "scopeguard" version = "1.2.0" @@ -2374,6 +2387,12 @@ version = "0.12.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "6ab8598aa408498679922eff7fa985c25d58a90771bd6be794434c5277eab1a6" +[[package]] +name = "sdd" +version = "3.0.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "490dcfcbfef26be6800d11870ff2df8774fa6e86d047e3e8c8a76b25655e41ca" + [[package]] name = "security-framework-sys" version = "2.15.0" @@ -2439,6 +2458,31 @@ dependencies = [ "serde", ] +[[package]] +name = "serial_test" +version = "3.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1b258109f244e1d6891bf1053a55d63a5cd4f8f4c30cf9a1280989f80e7a1fa9" +dependencies = [ + "futures", + "log", + "once_cell", + "parking_lot", + "scc", + "serial_test_derive", +] + +[[package]] +name = "serial_test_derive" +version = "3.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5d69265a08751de7844521fd15003ae0a888e035773ba05695c5c759a6f89eef" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + [[package]] name = "shlex" version = "1.3.0" diff --git a/samply-markers/Cargo.toml b/samply-markers/Cargo.toml index 32b082206..de948adb6 100644 --- a/samply-markers/Cargo.toml +++ b/samply-markers/Cargo.toml @@ -23,3 +23,10 @@ enabled = [ nix = { version = "0.30.1", features = ["mman", "process", "time"], optional = true } smallstr = { version = "0.3.1", optional = true } tempfile = { version = "3.23.0", optional = true } + +[target.'cfg(unix)'.dev-dependencies] +nix = { version = "0.30.1", features = ["process"] } +regex = "1.12.2" +serial_test = "3.2.0" +tokio = { version = "1", features = ["rt", "rt-multi-thread", "macros", "time"] } +futures = "0.3" diff --git a/samply-markers/tests/unix.rs b/samply-markers/tests/unix.rs new file mode 100644 index 000000000..08db101af --- /dev/null +++ b/samply-markers/tests/unix.rs @@ -0,0 +1,583 @@ +//! This module contains integration tests for [`samply-markers`](crate) on Unix systems. + +#![cfg(all(feature = "enabled", target_family = "unix"))] + +use std::env; +use std::fs; +use std::thread; + +use regex::Regex; +use samply_markers::prelude::*; +use serial_test::serial; + +/// Returns a unique thread identifier for the current thread. +#[cfg(target_os = "linux")] +fn get_thread_id() -> u32 { + nix::unistd::gettid().as_raw() as u32 +} + +/// Returns a unique thread identifier for the current thread. +#[cfg(target_os = "macos")] +fn get_thread_id() -> u32 { + // Use pthread_threadid_np() to get the thread ID, same as samply does. + // This returns a u64 but we cast to u32 to match samply's behavior and + // ensure the thread ID fits in the marker filename format. + unsafe { + let mut tid: u64 = 0; + libc::pthread_threadid_np(libc::pthread_self(), &mut tid); + tid as u32 + } +} + +/// Wraps a test body with automatic cleanup of marker files for the current process. +macro_rules! with_marker_file_cleanup { + ($body:block) => {{ + let pid = nix::unistd::getpid().as_raw() as u32; + cleanup_marker_files(pid); + + let result = $body; + + cleanup_marker_files(pid); + result + }}; +} + +/// Asserts that exactly one marker file exists for the given PID, and verifies that it belongs to the given TID. +/// Returns the marker file paths for further inspection. +macro_rules! assert_single_marker_file { + ($pid:expr, $tid:expr) => {{ + let marker_files = find_all_marker_files($pid); + assert_eq!( + marker_files.len(), + 1, + "Expected exactly one marker file for single-threaded test, found {}", + marker_files.len() + ); + + let marker_file = &marker_files[0]; + let expected_pattern = format!("marker-{}-{}", $pid, $tid); + assert!( + marker_file + .file_name() + .unwrap() + .to_string_lossy() + .starts_with(&expected_pattern), + "Expected marker file to be for TID {}, but found {:?}", + $tid, + marker_file + ); + + marker_files + }}; +} + +/// Asserts that the marker file for the given PID/TID matches the expected regex pattern(s). +/// +/// When patterns are provided in the `regex: { ... }` block, the macro will by default +/// verify that the file contains exactly that many lines (one per pattern). +/// This can be disabled by passing `exact_count: false`. +macro_rules! assert_marker_file { + // Regex patterns with exact line count check (default behavior). + ($pid:expr, $tid:expr, regex: { $($pattern:expr),+ $(,)? }) => {{ + assert_marker_file!($pid, $tid, regex: { $($pattern),+ }, exact_count: true) + }}; + + // Regex patterns with optional exact line count check. + ($pid:expr, $tid:expr, regex: { $($pattern:expr),+ $(,)? }, exact_count: $exact:expr) => {{ + let patterns = &[$($pattern),+]; + let combined_pattern = format!("(?m){}", patterns.join("\n")); + assert_marker_file!($pid, $tid, regex: &combined_pattern, pattern_count: patterns.len(), exact_count: $exact) + }}; + + // Internal implementation with pattern count and exact count flag. + ($pid:expr, $tid:expr, regex: $regex:expr, pattern_count: $count:expr, exact_count: $exact:expr) => {{ + let marker_files = find_all_marker_files($pid); + let pattern_prefix = format!("marker-{}-{}", $pid, $tid); + + let marker_file = marker_files + .iter() + .find(|path| { + path.file_name() + .unwrap() + .to_string_lossy() + .starts_with(&pattern_prefix) + }) + .expect(&format!( + "Expected to find marker file for PID {} TID {}.", + $pid, $tid + )); + + let contents = fs::read_to_string(&marker_file).expect("failed to read marker file"); + let regex = Regex::new($regex).expect("invalid regex pattern"); + + assert!( + regex.is_match(&contents), + "Marker file contents did not match expected pattern:\n\ + Expected pattern:\n{}\n\ + Actual contents:\n{}", + $regex, + contents + ); + + if $exact && $count > 0 { + let line_count = contents.lines().count(); + assert_eq!( + line_count, + $count, + "Expected exactly {} lines in marker file, but found {}", + $count, + line_count + ); + } + + for line in contents.lines() { + let parts = line.split_whitespace().collect::>(); + let start: u64 = parts[0].parse().expect("start time should be a valid u64"); + let end: u64 = parts[1].parse().expect("end time should be a valid u64"); + assert!( + end >= start, + "Expected the end time to be greater than or equal to the start time.", + ); + } + + contents + }}; +} + +/// Helper function to find all marker files for a given PID in the system temp directory. +fn find_all_marker_files(pid: u32) -> Vec { + let temp_dir = env::temp_dir(); + let pattern_prefix = format!("marker-{pid}-"); + + fs::read_dir(&temp_dir) + .ok() + .into_iter() + .flatten() + .filter_map(Result::ok) + .filter(|entry| entry.path().is_dir()) + .flat_map(|entry| { + fs::read_dir(entry.path()) + .ok() + .into_iter() + .flatten() + .filter_map(Result::ok) + .filter(|sub_entry| { + sub_entry + .file_name() + .to_string_lossy() + .starts_with(&pattern_prefix) + }) + .map(|sub_entry| sub_entry.path()) + }) + .collect() +} + +/// Helper function to clean up all marker files for a given PID. +fn cleanup_marker_files(pid: u32) { + let marker_files = find_all_marker_files(pid); + for file in marker_files { + let _ = fs::remove_file(file); + } +} + +#[test] +#[serial] +fn instant_writes_marker_to_file() { + with_marker_file_cleanup!({ + samply_marker!({ name: "InstantMarker1" }); + samply_marker!({ name: "InstantMarker2" }); + samply_marker!({ name: "InstantMarker3" }); + + let pid = nix::unistd::getpid().as_raw() as u32; + let tid = get_thread_id(); + + assert_single_marker_file!(pid, tid); + + let contents = assert_marker_file!( + pid, + tid, + regex: { + r"^\d+ \d+ InstantMarker1$", + r"^\d+ \d+ InstantMarker2$", + r"^\d+ \d+ InstantMarker3$", + } + ); + + assert!( + contents.lines().all(|line| { + let parts = line.split_whitespace().collect::>(); + let start: u64 = parts[0].parse().expect("start time should be a valid u64"); + let end: u64 = parts[1].parse().expect("end time should be a valid u64"); + start == end + }), + "Expected all instant markers to have same start and end time." + ); + }); +} + +#[test] +#[serial] +#[should_panic( + expected = "assertion `left == right` failed: Expected exactly 1 lines in marker file, but found 2" +)] +fn assert_marker_file_panics_on_wrong_line_count() { + with_marker_file_cleanup!({ + // Emit exactly 2 markers. + SamplyMarker::new("test marker").emit_instant(); + SamplyMarker::new("test marker").emit_instant(); + + let pid = nix::unistd::getpid().as_raw() as u32; + let tid = get_thread_id(); + + assert_single_marker_file!(pid, tid); + + // Try to assert only 1 pattern when there are 2 lines. + assert_marker_file!( + pid, + tid, + regex: { + r"^\d+ \d+ test marker$", + } + ); + }); +} + +#[test] +#[serial] +fn empty_name_defaults_to_unnamed_marker() { + with_marker_file_cleanup!({ + SamplyMarker::new("").emit_instant(); + SamplyMarker::new(format!("")).emit_instant(); + + let pid = nix::unistd::getpid().as_raw() as u32; + let tid = get_thread_id(); + + assert_single_marker_file!(pid, tid); + + assert_marker_file!( + pid, + tid, + regex: { + r"^\d+ \d+ unnamed marker$", + r"^\d+ \d+ unnamed marker$", + } + ); + }); +} + +#[test] +#[serial] +fn timer_writes_marker_to_file() { + with_marker_file_cleanup!({ + { + let _timer1 = samply_timer!({ name: "TimerMarker1" }); + thread::sleep(std::time::Duration::from_millis(2)); + } + { + let _timer2 = samply_timer!({ name: "TimerMarker2" }); + thread::sleep(std::time::Duration::from_millis(3)); + } + { + let _timer3 = samply_timer!({ name: "TimerMarker3" }); + thread::sleep(std::time::Duration::from_millis(4)); + } + + let pid = nix::unistd::getpid().as_raw() as u32; + let tid = get_thread_id(); + + assert_single_marker_file!(pid, tid); + + assert_marker_file!( + pid, + tid, + regex: { + r"^\d+ \d+ TimerMarker1$", + r"^\d+ \d+ TimerMarker2$", + r"^\d+ \d+ TimerMarker3$", + } + ); + }); +} + +#[test] +#[serial] +fn measure_writes_marker_to_file() { + with_marker_file_cleanup!({ + let result1 = samply_measure!({ + thread::sleep(std::time::Duration::from_millis(2)); + 42 + } marker: { + name: "MeasureMarker1", + }); + + let result2 = samply_measure!({ + thread::sleep(std::time::Duration::from_millis(3)); + "hello" + } marker: { + name: "MeasureMarker2", + }); + + let result3 = samply_measure!({ + thread::sleep(std::time::Duration::from_millis(4)); + vec![1, 2, 3] + } marker: { + name: "MeasureMarker3", + }); + + assert_eq!(result1, 42, "Expected measure to preserve return value."); + assert_eq!( + result2, "hello", + "Expected measure to preserve return value." + ); + assert_eq!( + result3, + vec![1, 2, 3], + "Expected measure to preserve return value." + ); + + let pid = nix::unistd::getpid().as_raw() as u32; + let tid = get_thread_id(); + + assert_single_marker_file!(pid, tid); + + assert_marker_file!( + pid, + tid, + regex: { + r"^\d+ \d+ MeasureMarker1$", + r"^\d+ \d+ MeasureMarker2$", + r"^\d+ \d+ MeasureMarker3$", + } + ); + }); +} + +#[test] +#[serial] +fn multiple_threads_create_separate_files() { + with_marker_file_cleanup!({ + let handles = (0..3) + .map(|i| { + thread::spawn(move || { + samply_marker!({ name: format!("thread {i} marker A") }); + samply_marker!({ name: format!("thread {i} marker B") }); + samply_marker!({ name: format!("thread {i} marker C") }); + thread::sleep(std::time::Duration::from_millis(10)); + + get_thread_id() + }) + }) + .collect::>(); + + let tids = handles + .into_iter() + .map(|h| h.join().expect("thread panicked")) + .collect::>(); + + let pid = nix::unistd::getpid().as_raw() as u32; + + // Multi-threaded test should produce exactly one marker file per thread. + let marker_files = find_all_marker_files(pid); + assert_eq!( + marker_files.len(), + 3, + "Expected exactly 3 marker files (one per thread), found {}", + marker_files.len() + ); + + for tid in tids { + assert_marker_file!( + pid, + tid, + regex: { + r"^\d+ \d+ thread \d marker A$", + r"^\d+ \d+ thread \d marker B$", + r"^\d+ \d+ thread \d marker C$", + } + ); + } + }); +} + +#[serial] +#[tokio::test] +async fn measure_async_writes_marker_to_file() { + use tokio::time::{Duration, sleep}; + + with_marker_file_cleanup!({ + let result = samply_measure!(async { + sleep(Duration::from_millis(5)).await; + 42 + }, marker: { + name: "AsyncMeasure", + }) + .await; + + assert_eq!(result, 42, "Expected measure to preserve return value."); + + let pid = nix::unistd::getpid().as_raw() as u32; + let tid = get_thread_id(); + + assert_single_marker_file!(pid, tid); + + assert_marker_file!( + pid, + tid, + regex: { + r"^\d+ \d+ AsyncMeasure$", + } + ); + }); +} + +#[test] +#[serial] +fn timer_emit_prevents_double_emit_on_drop() { + with_marker_file_cleanup!({ + { + let timer = samply_timer!({ name: "ExplicitEmit" }); + thread::sleep(std::time::Duration::from_millis(2)); + timer.emit(); // Explicitly emit the timer. + // The timer drops here, but should not emit a second time. + } + + let pid = nix::unistd::getpid().as_raw() as u32; + let tid = get_thread_id(); + + assert_single_marker_file!(pid, tid); + + assert_marker_file!( + pid, + tid, + regex: { + r"^\d+ \d+ ExplicitEmit$", + } + ); + }); +} + +#[serial] +#[tokio::test] +async fn measure_async_with_early_return_writes_marker() { + use tokio::time::{Duration, sleep}; + + with_marker_file_cleanup!({ + async fn fallible_operation(should_fail: bool) -> Result { + samply_measure!(async { + sleep(Duration::from_millis(2)).await; + + if should_fail { + return Err("operation failed"); + } + + sleep(Duration::from_millis(2)).await; + Ok(String::from("success")) + }, marker: { + name: "FallibleAsync", + }) + .await + } + + let success_result = fallible_operation(false).await; + assert!(success_result.is_ok()); + + let failure_result = fallible_operation(true).await; + assert!(failure_result.is_err()); + + let pid = nix::unistd::getpid().as_raw() as u32; + let tid = get_thread_id(); + + assert_single_marker_file!(pid, tid); + + assert_marker_file!( + pid, + tid, + regex: { + r"^\d+ \d+ FallibleAsync$", + r"^\d+ \d+ FallibleAsync$", + } + ); + }); +} + +#[serial] +#[tokio::test(flavor = "multi_thread", worker_threads = 3)] +async fn tokio_spawn_writes_markers_across_threads() { + use tokio::time::{Duration, sleep}; + + with_marker_file_cleanup!({ + let handles = (0..3) + .map(|i| { + tokio::spawn(async move { + // Each spawned task may run on different threads. + // Emit multiple markers with awaits in between to allow potential thread migration. + samply_measure!(async { + sleep(Duration::from_millis(2)).await; + }, marker: { + name: format!("async task {i} marker A"), + }) + .await; + + samply_measure!(async { + sleep(Duration::from_millis(3)).await; + }, marker: { + name: format!("async task {i} marker B"), + }) + .await; + + samply_measure!(async { + sleep(Duration::from_millis(4)).await; + }, marker: { + name: format!("async task {i} marker C"), + }) + .await; + + // Return the thread ID where this task's final marker was emitted. + get_thread_id() + }) + }) + .collect::>(); + + let _tids = futures::future::join_all(handles) + .await + .into_iter() + .map(|result| result.expect("task panicked")) + .collect::>(); + + let pid = nix::unistd::getpid().as_raw() as u32; + + // Verify that markers were written. We can't predict which thread each task ran on + // since tokio may schedule tasks on any worker thread, and tasks may migrate between + // threads during execution. We collect all marker files for this PID to ensure we + // find all markers regardless of which thread's file they were written to. + let marker_files = find_all_marker_files(pid); + + // With 3 worker threads, we should have at least 1 file and at most 3 files. + assert!( + !marker_files.is_empty(), + "Expected at least one marker file to exist" + ); + assert!( + marker_files.len() <= 3, + "Expected at most 3 marker files are found {}", + marker_files.len() + ); + + let all_contents = marker_files + .into_iter() + .filter_map(|path| fs::read_to_string(path).ok()) + .collect::>() + .join("\n"); + + // Verify that all 9 markers (3 tasks × 3 markers each) appear somewhere + for n in 0..3 { + for marker in ["marker A", "marker B", "marker C"] { + let expected = format!("async task {n} {marker}"); + assert!( + all_contents.contains(&expected), + "Expected to find '{expected}' in marker files but didn't.\nAll contents:\n{all_contents}" + ); + } + } + }); +} diff --git a/samply-markers/tests/windows.rs b/samply-markers/tests/windows.rs new file mode 100644 index 000000000..272a313d8 --- /dev/null +++ b/samply-markers/tests/windows.rs @@ -0,0 +1,21 @@ +//! This module contains integration tests for [`samply-markers`](crate) on Windows systems. +//! +//! Windows support is not yet implemented, so these tests verify that attempting to use +//! markers on Windows results in a panic. + +#![cfg(all(feature = "enabled", target_family = "windows"))] + +use samply_markers::marker::SamplyMarker; +use samply_markers::marker::SamplyTimestamp; + +#[test] +#[should_panic(expected = "not yet available on Windows")] +fn timestamp_now_panics() { + let _ = SamplyTimestamp::now(); +} + +#[test] +#[should_panic(expected = "not yet available on Windows")] +fn emit_instant_panics() { + SamplyMarker::new("test marker").emit_instant(); +} From 844283bfba50a171e0f9b71f507cdfbbf33d3fba Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Tue, 11 Nov 2025 18:18:21 -0600 Subject: [PATCH 18/23] Add README.md This commit adds a project-level README file to the samply-markers crate. --- samply-markers/README.md | 374 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 374 insertions(+) create mode 100644 samply-markers/README.md diff --git a/samply-markers/README.md b/samply-markers/README.md new file mode 100644 index 000000000..812462522 --- /dev/null +++ b/samply-markers/README.md @@ -0,0 +1,374 @@ +# Samply Markers + +Emit profiler markers that [samply] records and displays in the [Firefox Profiler] UI. + +## Quick Demo + +The following Fibonacci Sequence example demonstrates recursive function call tracking. + +The [`samply_measure!`] macro emits an interval marker +for each recursive call, allowing the profiler to display the complete call tree with timing information for every `fib(n)` invocation. + +**[macOS][fib-profile-macos] | [Ubuntu][fib-profile-ubuntu] | Windows (not yet supported)** + +```rust +use samply_markers::prelude::*; + +use std::thread::sleep; +use std::time::Duration; + +fn fib(n: u64) -> u64 { + samply_measure!({ + match n { + 0 | 1 => { + sleep(Duration::from_millis(10)); + n + }, + _ => fib(n - 1) + fib(n - 2), + } + }, marker: { + name: format!("fib({n})"), + }) +} + +fn main() { + let n = 12; + let value = fib(n); + println!("fib({n}) = {}", value); +} +``` + +## Project Configuration + +
**1)** Add [samply-markers] as a dependency to your project's `Cargo.toml`. + +```toml +[dependencies] +samply-markers = "{version}" +``` + +
**2)** Add a `samply-markers` feature flag to your project's `Cargo.toml`. + +> [!NOTE] +> Samply markers are designed to no-op by default, so they must be explicitly enabled in order +> to see them in profiles. +> +> * Using [samply-markers] has effectively zero cost when not enabled. +> * Using [samply-markers] does not pull in any additional dependencies when not enabled. + +```toml +[features] +samply-markers = ["samply-markers/enabled"] +``` + +
**3)** Add a `profiling` profile to your project's `Cargo.toml`. + +> [!NOTE] +> This step is optional, but highly recommended for profiling with [samply]. + +```toml +[profile.profiling] +inherits = "release" +debug = true +``` + +
**4)** Build your project for profiling, then record the resulting binary with [samply] to process the emitted markers. + +```text +cargo build --profile profiling --features samply-markers +samply record target/profiling/{binary} +``` + +## Public API + +### The [`samply_marker!`] macro + +The [`samply_marker!`] macro is the foundational way to emit profiler markers. +It creates and emits a [`SamplyMarker`] at the current location in your code, +supporting both instant markers (a single point in time) and interval markers (a span of time). + +#### Instant Marker + +An instant marker marks a specific point in time: + +```rust +use samply_markers::prelude::*; + +fn process_request(request_id: u32) { + // Emit an instant marker at this exact moment + samply_marker!({ name: format!("processing request {request_id}") }); + + // ... process the request. +} +``` + +#### Interval Marker + +An interval marker spans from a start time to the current time using [`SamplyTimestamp`]: + +```rust +use samply_markers::prelude::*; + +fn query_database(query: &str) -> Vec { + let start = SamplyTimestamp::now(); + + // ... execute the database query. + let results = vec![]; // Placeholder for actual results. + + // Emit an interval marker from start to now. + samply_marker!({ + name: format!("database query: {query}"), + start_time: start, + }); + + results +} +``` + +--- + +### The [`samply_timer!`] macro + +While [`samply_marker!`] requires manually providing a +[`SamplyTimestamp`] for interval markers, +the [`samply_timer!`] macro simplifies this pattern +by wrapping the timestamp in a scoped RAII object. It creates a [`SamplyTimer`] +that registers the time it was created and automatically emits the interval marker when dropped at the end of its scope. + +#### Automatic Interval + +The interval marker emits when the timer is dropped: + +```rust +use samply_markers::prelude::*; + +fn expensive_computation() { + let _timer = samply_timer!({ name: "expensive computation" }); + + // ... perform expensive work. + + // The interval marker is automatically emitted here when _timer is dropped. +} +``` + +#### Early Emit + +You can explicitly emit the interval marker before the end of the scope: + +```rust +use samply_markers::prelude::*; + +fn process_with_cleanup() { + let timer = samply_timer!({ name: "core processing" }); + + // ... perform core processing work. + + // Emit the interval marker now, excluding cleanup from the measurement. + timer.emit(); + + // ... perform cleanup tasks (not included in the interval marker). + + // The interval marker will not emit a second time when dropped. +} +``` + +--- + +### The [`samply_measure!`] macro + +Building on the scoped approach of [`samply_timer!`], +the [`samply_measure!`] macro further simplifies profiling +by eliminating the need to create a scoped timer yourself. Instead, you wrap a code block, then its execution time is automatically measured with an interval marker. + +#### Measure Synchronous Code + +The value of the measured block expression is preserved: + +```rust +use samply_markers::prelude::*; + +fn compute_sum(values: &[i32]) -> i32 { + samply_measure!({ + values.iter().sum() + }, marker: { + name: "compute sum", + }) +} + +let values = vec![1, 2, 3, 4, 5]; +let result = compute_sum(&values); +assert_eq!(result, 15); +``` + +#### With `?` Operator + +The block's control flow is preserved, including early returns: + +```rust +use samply_markers::prelude::*; + +fn parse_and_validate(data: &str) -> Result { + samply_measure!({ + let parsed = data.parse::() + .map_err(|e| format!("parse error: {e}"))?; + + if parsed > 100 { + return Err(String::from("value too large")); + } + + Ok(parsed) + }, marker: { + name: "parse and validate", + }) +} +``` + +#### Measure Asynchronous Code + +The macro works the same within asynchronous code. However, the clock does not stop between polls. +The resulting interval will span the total time to completion, including time spent waiting: + +```rust +use samply_markers::prelude::*; + +async fn fetch_data() -> String { + String::from("data") +} + +async fn process_data(data_id: u64) -> String { + samply_measure!({ + let data = fetch_data().await; + format!("Processed: {data} (id: {data_id})") + }, marker: { + name: format!("process data {data_id}"), + }) +} +``` + +#### Create a New Async Block + +Use the `async` keyword to create a new async block, which allows the `?` +operator to return from this measured block instead of the enclosing function: + +```rust +use samply_markers::prelude::*; + +async fn read_file(path: &str) -> Option { + Some(String::from("100,200")) +} + +async fn load_config(path: &str) -> (u32, u32) { + let config = samply_measure!(async { + let contents = read_file(path).await?; + let mut parts = contents.split(','); + + let x = parts.next()?.parse::().ok()?; + let y = parts.next()?.parse::().ok()?; + + Some((x, y)) + }, marker: { + name: "load config", + }) + .await; + + config.unwrap_or((0, 0)) +} +``` + +## Example + +Here's a complete example demonstrating everything in context: + + +**[macOS] | [Ubuntu] | Windows (not yet supported)** + +```rust +use samply_markers::prelude::*; + +async fn fetch_url(url: &str) -> (String, Option) { + // Emit an interval marker for the time it takes to fetch. + let result = samply_measure!(async { + let response = reqwest::get(url).await?; + response.text().await + }, marker: { + name: format!("fetch {url}"), + }) + .await; + + match result { + Ok(content) => { + println!(" ✓ Fetched {url} ({} bytes)", content.len()); + (String::from(url), Some(content)) + } + Err(error) => { + // Emit an instant marker any time a fetch fails. + samply_marker!({ name: format!("fetch failed: {url}") }); + println!(" ✗ Failed to fetch {url}: {error}"); + (String::from(url), None) + } + } +} + +#[tokio::main] +async fn main() { + // Create a timer that will span the entirety of main(). + // The timer will emit an interval marker when it is dropped at the end of the scope. + let _main_timer = samply_timer!({ name: "main()" }); + + println!("\nStarting samply-markers demo...\n"); + + std::thread::sleep(std::time::Duration::from_millis(200)); + + let urls = &[ + "https://example.com", + "https://fail.invalid", + "https://fail.invalid", + "https://en.wikipedia.org/wiki/Firefox", + "https://fail.invalid", + "https://github.com/nordzilla", + ]; + + println!("\n=== Sequential Fetching ===\n"); + + // Emit an interval marker for the total time to fetch all URLs sequentially. + samply_measure!({ + for url in urls { + fetch_url(url).await; + } + }, marker: { + name: "fetch all URLs sequentially", + }); + + std::thread::sleep(std::time::Duration::from_millis(200)); + + println!("\n=== Concurrent Fetching ===\n"); + + // Emit an interval marker for the total time to fetch all URLs concurrently. + samply_measure!({ + futures::future::join_all( + urls.iter().map(|url| fetch_url(url)) + ).await; + }, marker: { + name: "fetch all URLs concurrently", + }); + + std::thread::sleep(std::time::Duration::from_millis(200)); + + println!("\nDemo completed!\n"); +} +``` + +[`samply_marker!`]: https://docs.rs/samply-markers/latest/samply_markers/macro.samply_marker.html +[`samply_measure!`]: https://docs.rs/samply-markers/latest/samply_markers/macro.samply_measure.html +[`samply_timer!`]: https://docs.rs/samply-markers/latest/samply_markers/macro.samply_timer.html +[`SamplyMarker`]: https://docs.rs/samply-markers/latest/samply_markers/marker/struct.SamplyMarker.html +[`SamplyTimer`]: https://docs.rs/samply-markers/latest/samply_markers/marker/struct.SamplyTimer.html +[`SamplyTimestamp`]: https://docs.rs/samply-markers/latest/samply_markers/marker/struct.SamplyTimestamp.html +[examples directory]: https://github.com/mstange/samply/tree/main/samply-markers/examples +[fib-profile-macos]: https://share.firefox.dev/4oMKHtT +[fib-profile-ubuntu]: https://share.firefox.dev/4o3wur4 +[Firefox Profiler]: https://profiler.firefox.com/ +[macOS]: https://share.firefox.dev/48eHTj8 +[samply]: https://github.com/mstange/samply?tab=readme-ov-file#samply +[samply-markers]: https://crates.io/crates/samply-markers +[Ubuntu]: https://share.firefox.dev/3LzT6lJ From 69fb5eaa414eeed2d6f0b8e9c3daad48e3a0e6c6 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Wed, 12 Nov 2025 07:45:35 -0600 Subject: [PATCH 19/23] Add truncate behavior to marker file creation This commit ensures that .truncate(true) is set when creating marker files to clarify that existing files should be overwritten. This is unlikely to happen with the temp directory file format containing the PID and TID, but if it were to happen, it's better to be safe than sorry. This also fixes the clippy::suspicious_open_options warning. --- samply-markers/src/provider/unix.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/samply-markers/src/provider/unix.rs b/samply-markers/src/provider/unix.rs index 20fa23fb4..67383a6db 100644 --- a/samply-markers/src/provider/unix.rs +++ b/samply-markers/src/provider/unix.rs @@ -93,6 +93,7 @@ fn create_marker_file() -> Option { let file = File::options() .create(true) + .truncate(true) .write(true) .read({ // We aren't going to read from the file, so we ordinarily From 19a3ea5978edf88bddca8f45577cf71d31147338 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Wed, 12 Nov 2025 07:45:35 -0600 Subject: [PATCH 20/23] Support samply-markers on macOS This commit ensures that the `unix.rs` file correctly handles emitting markers on macOS. I hadn't realized in previous commits that the functionality was only working on Linux. It should work on both systems now. --- Cargo.lock | 49 +++++++++------- samply-markers/Cargo.toml | 4 ++ samply-markers/src/provider/unix.rs | 88 +++++++++++++++++++++++++---- 3 files changed, 111 insertions(+), 30 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 5a4315d03..5b222d5ff 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -74,22 +74,22 @@ dependencies = [ [[package]] name = "anstyle-query" -version = "1.1.4" +version = "1.1.5" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9e231f6134f61b71076a3eab506c379d4f36122f2af15a9ff04415ea4c3339e2" +checksum = "40c48f72fd53cd289104fc64099abca73db4166ad86ea0b4341abe65af83dadc" dependencies = [ - "windows-sys 0.60.2", + "windows-sys 0.61.2", ] [[package]] name = "anstyle-wincon" -version = "3.0.10" +version = "3.0.11" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3e0633414522a32ffaac8ac6cc8f748e090c5717661fddeea04219e2344f5f2a" +checksum = "291e6a250ff86cd4a820112fb8898808a366d8f9f58ce16d1f538353ad55747d" dependencies = [ "anstyle", "once_cell_polyfill", - "windows-sys 0.60.2", + "windows-sys 0.61.2", ] [[package]] @@ -241,9 +241,9 @@ checksum = "1fd0f2584146f6f2ef48085050886acf353beff7305ebd1ae69500e27c67f64b" [[package]] name = "bytes" -version = "1.10.1" +version = "1.11.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d71b6127be86fdcfddb610f7182ac57211d4b18a3e9c82eb2d17662f2227ad6a" +checksum = "b35204fbdc0b3f4446b89fc1ac2cf84a8a68971995d0bf2e925ec7cd960f9cb3" [[package]] name = "bytesize" @@ -274,9 +274,9 @@ dependencies = [ [[package]] name = "cc" -version = "1.2.45" +version = "1.2.46" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "35900b6c8d709fb1d854671ae27aeaa9eec2f8b01b364e1619a40da3e6fe2afe" +checksum = "b97463e1064cb1b1c1384ad0a0b9c8abd0988e2a91f52606c80ef14aadb63e36" dependencies = [ "find-msvc-tools", "shlex", @@ -631,9 +631,9 @@ dependencies = [ [[package]] name = "find-msvc-tools" -version = "0.1.4" +version = "0.1.5" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "52051878f80a721bb68ebfbc930e07b65ba72f2da88968ea5c06fd6ca3d3a127" +checksum = "3a3076410a55c90011c298b04d0cfa770b00fa04e1e3c97d3f6c9de105a03844" [[package]] name = "flate2" @@ -966,9 +966,9 @@ checksum = "135b12329e5e3ce057a9f972339ea52bc954fe1e9358ef27f95e89716fbc5424" [[package]] name = "hyper" -version = "1.8.0" +version = "1.8.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1744436df46f0bde35af3eda22aeaba453aada65d8f1c171cd8a5f59030bd69f" +checksum = "2ab2d4f250c3d7b1c9fcdff1cece94ea4e2dfbec68614f7b87cb205f24ca9d11" dependencies = [ "atomic-waker", "bytes", @@ -1006,9 +1006,9 @@ dependencies = [ [[package]] name = "hyper-util" -version = "0.1.17" +version = "0.1.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3c6995591a8f1380fcb4ba966a252a4b29188d51d2b89e3a252f5305be65aea8" +checksum = "52e9a2a24dc5c6821e71a7030e1e14b7b632acac55c40e9d2e082c621261bb56" dependencies = [ "base64", "bytes", @@ -1359,6 +1359,15 @@ version = "0.2.6" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7b29dffab797218e12e4df08ef5d15ab9efca2504038b1b32b9b32fc844b39c9" +[[package]] +name = "mach2" +version = "0.4.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d640282b302c0bb0a2a8e0233ead9035e3bed871f0b7e81fe4a1ec829765db44" +dependencies = [ + "libc", +] + [[package]] name = "mach2" version = "0.5.0" @@ -1910,9 +1919,9 @@ dependencies = [ [[package]] name = "rangemap" -version = "1.6.0" +version = "1.7.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f93e7e49bb0bf967717f7bd674458b3d6b0c5f48ec7e3038166026a69fc22223" +checksum = "acbbbbea733ec66275512d0b9694f34102e7d5406fdbe2ad8d21b28dce92887c" [[package]] name = "redox_syscall" @@ -2216,7 +2225,7 @@ dependencies = [ "libc", "linux-perf-data", "log", - "mach2", + "mach2 0.5.0", "memchr", "memmap2", "memoffset", @@ -2289,6 +2298,8 @@ name = "samply-markers" version = "0.1.0" dependencies = [ "futures", + "libc", + "mach2 0.4.3", "nix", "regex", "serial_test", diff --git a/samply-markers/Cargo.toml b/samply-markers/Cargo.toml index de948adb6..2728e98dc 100644 --- a/samply-markers/Cargo.toml +++ b/samply-markers/Cargo.toml @@ -24,6 +24,10 @@ nix = { version = "0.30.1", features = ["mman", "process", "time"], optional = t smallstr = { version = "0.3.1", optional = true } tempfile = { version = "3.23.0", optional = true } +[target.'cfg(target_os = "macos")'.dependencies] +libc = "0.2" +mach2 = "0.4" + [target.'cfg(unix)'.dev-dependencies] nix = { version = "0.30.1", features = ["process"] } regex = "1.12.2" diff --git a/samply-markers/src/provider/unix.rs b/samply-markers/src/provider/unix.rs index 67383a6db..5ace6c094 100644 --- a/samply-markers/src/provider/unix.rs +++ b/samply-markers/src/provider/unix.rs @@ -7,6 +7,8 @@ use std::num::NonZeroUsize; use std::path::Path; use std::path::PathBuf; use std::sync::LazyLock; +#[cfg(target_os = "macos")] +use std::sync::OnceLock; use crate::marker::SamplyMarker; use crate::marker::SamplyTimestamp; @@ -15,7 +17,9 @@ use crate::provider::WriteMarkerProvider; use nix::sys::mman::MapFlags; use nix::sys::mman::ProtFlags; +#[cfg(target_os = "linux")] use nix::time::ClockId; +#[cfg(target_os = "linux")] use nix::time::clock_gettime; use smallstr::SmallString; @@ -35,19 +39,47 @@ thread_local! { static MARKER_FILE: RefCell> = RefCell::new(create_marker_file()); } -/// A monotonic nanosecond timestamp backed by [`ClockId::CLOCK_MONOTONIC`]. +#[cfg(target_os = "macos")] +static NANOS_PER_TICK: OnceLock = OnceLock::new(); + +/// A monotonic nanosecond timestamp implementation. pub struct TimestampNowImpl; impl TimestampNowProvider for TimestampNowImpl { - /// Queries `clock_gettime` and converts the result to monotonic nanoseconds. + /// Queries the monotonic clock and converts the result to monotonic nanoseconds. fn now() -> SamplyTimestamp { - let now = clock_gettime(ClockId::CLOCK_MONOTONIC).unwrap(); - - // Monotonic nanoseconds should only ever be positive. - #[allow(clippy::cast_sign_loss)] - SamplyTimestamp::from_monotonic_nanos( - now.tv_sec() as u64 * 1_000_000_000 + now.tv_nsec() as u64, - ) + #[cfg(target_os = "linux")] + { + let now = clock_gettime(ClockId::CLOCK_MONOTONIC).unwrap(); + + // Monotonic nanoseconds should only ever be positive. + #[allow(clippy::cast_sign_loss)] + SamplyTimestamp::from_monotonic_nanos( + now.tv_sec() as u64 * 1_000_000_000 + now.tv_nsec() as u64, + ) + } + + // Use mach_absolute_time() to match samply's clock source on macOS. + // See https://github.com/mstange/samply/blob/2041b956f650bb92d912990052967d03fef66b75/samply/src/mac/time.rs#L8-L20 + #[cfg(target_os = "macos")] + { + use mach2::mach_time; + + let nanos_per_tick = NANOS_PER_TICK.get_or_init(|| { + let mut info = mach_time::mach_timebase_info::default(); + let errno = unsafe { mach_time::mach_timebase_info(&raw mut info) }; + if errno != 0 || info.denom == 0 { + info.numer = 1; + info.denom = 1; + } + info + }); + + let time = unsafe { mach_time::mach_absolute_time() }; + let nanos = time * u64::from(nanos_per_tick.numer) / u64::from(nanos_per_tick.denom); + + SamplyTimestamp::from_monotonic_nanos(nanos) + } } } @@ -83,12 +115,46 @@ where MARKER_FILE.with_borrow_mut(|file| file.as_mut().map(f)) } +/// Returns a unique thread identifier for the current thread. +#[cfg(target_os = "linux")] +fn get_thread_id() -> u32 { + // Thread IDs on Linux are always positive, so the cast from i32 to u32 is safe. + #[allow(clippy::cast_sign_loss)] + let tid = nix::unistd::gettid().as_raw() as u32; + + tid +} + +/// Returns a unique thread identifier for the current thread. +#[cfg(target_os = "macos")] +fn get_thread_id() -> u32 { + // Use pthread_threadid_np() to get the current thread's system thread ID. + // + // This is the simplest way to get our own thread ID. Samply uses thread_info() + // instead because it's extracting thread IDs from other processes via mach ports. + // + // Both approaches return the same underlying system thread ID value. + // + // See https://github.com/mstange/samply/blob/2041b956f650bb92d912990052967d03fef66b75/samply/src/mac/thread_profiler.rs#L209-L229 + let mut tid: u64 = 0; + + unsafe { + libc::pthread_threadid_np(libc::pthread_self(), &raw mut tid); + } + + // Truncate to u32 to match samply's behavior. + #[allow(clippy::cast_possible_truncation)] + let tid = tid as u32; + + tid +} + /// Creates a new mmapped marker file for the current thread. fn create_marker_file() -> Option { let file_name = markers_dir()?.join(format!( "marker-{}-{}.txt", - nix::unistd::getpid(), - nix::unistd::gettid() + nix::unistd::getpid().as_raw(), + get_thread_id() )); let file = File::options() From 47007cedf83665c425cab85e7de9e2e109e125af Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Wed, 12 Nov 2025 09:03:30 -0600 Subject: [PATCH 21/23] Add safety comments to unsafe blocks This commit adds a safety comment to every unsafe block in the `unix.rs` file, explaining why I blieve the call is justified. --- samply-markers/src/provider/unix.rs | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/samply-markers/src/provider/unix.rs b/samply-markers/src/provider/unix.rs index 5ace6c094..742e8a5c6 100644 --- a/samply-markers/src/provider/unix.rs +++ b/samply-markers/src/provider/unix.rs @@ -67,6 +67,9 @@ impl TimestampNowProvider for TimestampNowImpl { let nanos_per_tick = NANOS_PER_TICK.get_or_init(|| { let mut info = mach_time::mach_timebase_info::default(); + // SAFETY: mach_timebase_info is an FFI call on macOS. We pass a valid mutable reference + // to a properly initialized mach_timebase_info struct. + // See https://developer.apple.com/documentation/driverkit/3433733-mach_timebase_info let errno = unsafe { mach_time::mach_timebase_info(&raw mut info) }; if errno != 0 || info.denom == 0 { info.numer = 1; @@ -75,6 +78,9 @@ impl TimestampNowProvider for TimestampNowImpl { info }); + // SAFETY: mach_absolute_time is an FFI call on macOS that returns the current + // absolute time value in tick units. + // See https://developer.apple.com/documentation/kernel/1462446-mach_absolute_time let time = unsafe { mach_time::mach_absolute_time() }; let nanos = time * u64::from(nanos_per_tick.numer) / u64::from(nanos_per_tick.denom); @@ -138,6 +144,9 @@ fn get_thread_id() -> u32 { // See https://github.com/mstange/samply/blob/2041b956f650bb92d912990052967d03fef66b75/samply/src/mac/thread_profiler.rs#L209-L229 let mut tid: u64 = 0; + // SAFETY: pthread_threadid_np is an FFI call. We pass pthread_self() provided by libc, + // along with a valid mutable reference to our tid variable. + // See https://docs.rs/libc/latest/x86_64-apple-darwin/libc/fn.pthread_threadid_np.html unsafe { libc::pthread_threadid_np(libc::pthread_self(), &raw mut tid); } @@ -183,6 +192,12 @@ fn create_marker_file() -> Option { // so it is not necessary to map it with any particular protection or // flags, so we use PROT_READ because that offers the fewest ways to // screw up. + // + // SAFETY: This call to mmap is safe because: + // - We're mapping a valid file descriptor that we just opened + // - The size (4096) is a valid, non-zero size + // - The offset is 0 which is valid for any file + // See https://docs.rs/nix/latest/nix/sys/mman/fn.mmap.html unsafe { nix::sys::mman::mmap( None, From ab391974898d8fd490f44e27c1fbafcd71cec7b3 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Sat, 15 Nov 2025 09:06:38 -0600 Subject: [PATCH 22/23] Add examples directory to samply-markers This commit adds an examples directory with instructions on how to build, run, and profile the examples shown in the main README file. --- Cargo.lock | 254 +++++++++++++++++- Cargo.toml | 5 + samply-markers/Cargo.toml | 6 + samply-markers/README.md | 3 + samply-markers/examples/01_fibonacci.rs | 24 ++ .../examples/02_network_requests.rs | 73 +++++ .../examples/03_tokio_task_migration.rs | 55 ++++ .../examples/04_parallel_computation.rs | 151 +++++++++++ samply-markers/examples/README.md | 111 ++++++++ 9 files changed, 679 insertions(+), 3 deletions(-) create mode 100644 samply-markers/examples/01_fibonacci.rs create mode 100644 samply-markers/examples/02_network_requests.rs create mode 100644 samply-markers/examples/03_tokio_task_migration.rs create mode 100644 samply-markers/examples/04_parallel_computation.rs create mode 100644 samply-markers/examples/README.md diff --git a/Cargo.lock b/Cargo.lock index 5b222d5ff..6c4ffa6b7 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -358,6 +358,16 @@ version = "0.4.30" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3a9b614a5787ef0c8802a55766480563cb3a93b435898c422ed2a359cf811582" +[[package]] +name = "core-foundation" +version = "0.9.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "91e195e091a93c46f7102ec7818a2aa394e1e1771c3ab4825963fa03e45afb8f" +dependencies = [ + "core-foundation-sys", + "libc", +] + [[package]] name = "core-foundation" version = "0.10.1" @@ -416,6 +426,25 @@ dependencies = [ "crossbeam-utils", ] +[[package]] +name = "crossbeam-deque" +version = "0.8.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9dd111b7b7f7d55b72c0a6ae361660ee5853c9af73f70c3c2ef6858b950e2e51" +dependencies = [ + "crossbeam-epoch", + "crossbeam-utils", +] + +[[package]] +name = "crossbeam-epoch" +version = "0.9.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5b82ac4a3c2ca9c3460964f020e1402edd5753411d7737aa39c3714ad1b5420e" +dependencies = [ + "crossbeam-utils", +] + [[package]] name = "crossbeam-utils" version = "0.8.21" @@ -542,6 +571,15 @@ dependencies = [ "stable_deref_trait", ] +[[package]] +name = "encoding_rs" +version = "0.8.35" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "75030f3c4f45dafd7586dd6780965a8c7e8e285a5ecb86713e63a79c5b2766f3" +dependencies = [ + "cfg-if", +] + [[package]] name = "enum-as-inner" version = "0.6.1" @@ -658,6 +696,21 @@ version = "0.1.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d9c4f5dac5e15c24eb999c26181a6ca40b39fe946cbe4c263c7209467bc83af2" +[[package]] +name = "foreign-types" +version = "0.3.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f6f339eb8adc052cd2ca78910fda869aefa38d22d5cb648e6485e4d3fc06f3b1" +dependencies = [ + "foreign-types-shared", +] + +[[package]] +name = "foreign-types-shared" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "00b0228411908ca8685dba7fc2cdd70ec9990a6e753e89b6ac91a84c40fbaf4b" + [[package]] name = "form_urlencoded" version = "1.2.2" @@ -1004,6 +1057,22 @@ dependencies = [ "webpki-roots", ] +[[package]] +name = "hyper-tls" +version = "0.6.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "70206fc6890eaca9fde8a0bf71caa2ddfc9fe045ac9e5c70df101a7dbde866e0" +dependencies = [ + "bytes", + "http-body-util", + "hyper", + "hyper-util", + "native-tls", + "tokio", + "tokio-native-tls", + "tower-service", +] + [[package]] name = "hyper-util" version = "0.1.18" @@ -1023,9 +1092,11 @@ dependencies = [ "percent-encoding", "pin-project-lite", "socket2", + "system-configuration", "tokio", "tower-service", "tracing", + "windows-registry", ] [[package]] @@ -1418,6 +1489,12 @@ dependencies = [ "autocfg", ] +[[package]] +name = "mime" +version = "0.3.17" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6877bb514081ee2a7ff5ef9de3281f14a4dd4bceac4c09388074a6b5df8a139a" + [[package]] name = "minimal-lexical" version = "0.2.1" @@ -1456,6 +1533,23 @@ dependencies = [ "itoa", ] +[[package]] +name = "native-tls" +version = "0.2.14" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "87de3442987e9dbec73158d5c715e7ad9072fda936bb03d19d7fa10e00520f0e" +dependencies = [ + "libc", + "log", + "openssl", + "openssl-probe", + "openssl-sys", + "schannel", + "security-framework", + "security-framework-sys", + "tempfile", +] + [[package]] name = "nix" version = "0.30.1" @@ -1581,6 +1675,50 @@ dependencies = [ "windows-sys 0.60.2", ] +[[package]] +name = "openssl" +version = "0.10.75" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "08838db121398ad17ab8531ce9de97b244589089e290a384c900cb9ff7434328" +dependencies = [ + "bitflags", + "cfg-if", + "foreign-types", + "libc", + "once_cell", + "openssl-macros", + "openssl-sys", +] + +[[package]] +name = "openssl-macros" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a948666b637a0f465e8564c73e89d4dde00d72d4d473cc972f390fc3dcee7d9c" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "openssl-probe" +version = "0.1.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d05e27ee213611ffe7d6348b942e8f942b37114c00cc03cec254295a4a17852e" + +[[package]] +name = "openssl-sys" +version = "0.9.111" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "82cab2d520aa75e3c58898289429321eb788c3106963d0dc886ec7a5f4adc321" +dependencies = [ + "cc", + "libc", + "pkg-config", + "vcpkg", +] + [[package]] name = "option-ext" version = "0.2.0" @@ -1923,6 +2061,26 @@ version = "1.7.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "acbbbbea733ec66275512d0b9694f34102e7d5406fdbe2ad8d21b28dce92887c" +[[package]] +name = "rayon" +version = "1.11.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "368f01d005bf8fd9b1206fb6fa653e6c4a81ceb1466406b81792d87c5677a58f" +dependencies = [ + "either", + "rayon-core", +] + +[[package]] +name = "rayon-core" +version = "1.13.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "22e18b0f0062d30d4230b2e85ff77fdfe4326feb054b9783a3460d8435c8ab91" +dependencies = [ + "crossbeam-deque", + "crossbeam-utils", +] + [[package]] name = "redox_syscall" version = "0.5.18" @@ -2012,17 +2170,22 @@ dependencies = [ "async-compression", "base64", "bytes", + "encoding_rs", "futures-channel", "futures-core", "futures-util", + "h2", "http", "http-body", "http-body-util", "hyper", "hyper-rustls", + "hyper-tls", "hyper-util", "js-sys", "log", + "mime", + "native-tls", "percent-encoding", "pin-project-lite", "quinn", @@ -2033,6 +2196,7 @@ dependencies = [ "serde_urlencoded", "sync_wrapper", "tokio", + "tokio-native-tls", "tokio-rustls", "tokio-util", "tower", @@ -2301,7 +2465,9 @@ dependencies = [ "libc", "mach2 0.4.3", "nix", + "rayon", "regex", + "reqwest", "serial_test", "smallstr", "tempfile", @@ -2386,6 +2552,15 @@ dependencies = [ "sdd", ] +[[package]] +name = "schannel" +version = "0.1.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "891d81b926048e76efe18581bf793546b4c0eaf8448d72be8de2bbee5fd166e1" +dependencies = [ + "windows-sys 0.61.2", +] + [[package]] name = "scopeguard" version = "1.2.0" @@ -2404,6 +2579,19 @@ version = "3.0.10" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "490dcfcbfef26be6800d11870ff2df8774fa6e86d047e3e8c8a76b25655e41ca" +[[package]] +name = "security-framework" +version = "2.11.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "897b2245f0b511c87893af39b033e5ca9cce68824c4d7e7630b5a1d339658d02" +dependencies = [ + "bitflags", + "core-foundation 0.9.4", + "core-foundation-sys", + "libc", + "security-framework-sys", +] + [[package]] name = "security-framework-sys" version = "2.15.0" @@ -2628,6 +2816,27 @@ dependencies = [ "walkdir", ] +[[package]] +name = "system-configuration" +version = "0.6.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3c879d448e9d986b661742763247d3693ed13609438cf3d006f51f5368a5ba6b" +dependencies = [ + "bitflags", + "core-foundation 0.9.4", + "system-configuration-sys", +] + +[[package]] +name = "system-configuration-sys" +version = "0.6.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8e1d1b10ced5ca923a1fcb8d03e96b8d3268065d724548c0211415ff6ac6bac4" +dependencies = [ + "core-foundation-sys", + "libc", +] + [[package]] name = "tap" version = "1.0.1" @@ -2780,6 +2989,16 @@ dependencies = [ "syn", ] +[[package]] +name = "tokio-native-tls" +version = "0.3.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bbae76ab933c85776efabc971569dd6119c580d8f5d448769dec1764bf796ef2" +dependencies = [ + "native-tls", + "tokio", +] + [[package]] name = "tokio-rustls" version = "0.26.4" @@ -3104,7 +3323,7 @@ version = "0.8.1" dependencies = [ "async-compression", "bytes", - "core-foundation", + "core-foundation 0.10.1", "core-foundation-sys", "debugid", "flate2", @@ -3208,8 +3427,8 @@ dependencies = [ "windows-implement", "windows-interface", "windows-link 0.1.3", - "windows-result", - "windows-strings", + "windows-result 0.3.4", + "windows-strings 0.4.2", ] [[package]] @@ -3267,6 +3486,17 @@ dependencies = [ "windows-link 0.1.3", ] +[[package]] +name = "windows-registry" +version = "0.6.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "02752bf7fbdcce7f2a27a742f798510f3e5ad88dbe84871e5168e2120c3d5720" +dependencies = [ + "windows-link 0.2.1", + "windows-result 0.4.1", + "windows-strings 0.5.1", +] + [[package]] name = "windows-result" version = "0.3.4" @@ -3276,6 +3506,15 @@ dependencies = [ "windows-link 0.1.3", ] +[[package]] +name = "windows-result" +version = "0.4.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7781fa89eaf60850ac3d2da7af8e5242a5ea78d1a11c49bf2910bb5a73853eb5" +dependencies = [ + "windows-link 0.2.1", +] + [[package]] name = "windows-strings" version = "0.4.2" @@ -3285,6 +3524,15 @@ dependencies = [ "windows-link 0.1.3", ] +[[package]] +name = "windows-strings" +version = "0.5.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7837d08f69c77cf6b07689544538e017c1bfcf57e34b4c0ff58e6c2cd3b37091" +dependencies = [ + "windows-link 0.2.1", +] + [[package]] name = "windows-sys" version = "0.48.0" diff --git a/Cargo.toml b/Cargo.toml index 55b3bee06..0129eac1e 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -23,3 +23,8 @@ exclude = ["etw-reader"] # Should not be compiled on non-Windows [profile.dist] inherits = "release" lto = "thin" + +# Profile for profiling with samply +[profile.profiling] +inherits = "release" +debug = true diff --git a/samply-markers/Cargo.toml b/samply-markers/Cargo.toml index 2728e98dc..218908266 100644 --- a/samply-markers/Cargo.toml +++ b/samply-markers/Cargo.toml @@ -34,3 +34,9 @@ regex = "1.12.2" serial_test = "3.2.0" tokio = { version = "1", features = ["rt", "rt-multi-thread", "macros", "time"] } futures = "0.3" + +[dev-dependencies] +tokio = { version = "1", features = ["rt", "rt-multi-thread", "macros"] } +reqwest = "0.12" +futures = "0.3" +rayon = "1.10" diff --git a/samply-markers/README.md b/samply-markers/README.md index 812462522..f427c5c79 100644 --- a/samply-markers/README.md +++ b/samply-markers/README.md @@ -279,6 +279,9 @@ async fn load_config(path: &str) -> (u32, u32) { Here's a complete example demonstrating everything in context: +> [!NOTE] +> See the [examples directory] to build, run, and profile the examples in this README yourself. + **[macOS] | [Ubuntu] | Windows (not yet supported)** diff --git a/samply-markers/examples/01_fibonacci.rs b/samply-markers/examples/01_fibonacci.rs new file mode 100644 index 000000000..77f6bbf09 --- /dev/null +++ b/samply-markers/examples/01_fibonacci.rs @@ -0,0 +1,24 @@ +use samply_markers::prelude::*; + +use std::thread::sleep; +use std::time::Duration; + +fn fib(n: u64) -> u64 { + samply_measure!({ + match n { + 0 | 1 => { + sleep(Duration::from_millis(10)); + n + }, + _ => fib(n - 1) + fib(n - 2), + } + }, marker: { + name: format!("fib({n})"), + }) +} + +fn main() { + let n = 12; + let value = fib(n); + println!("fib({n}) = {}", value); +} diff --git a/samply-markers/examples/02_network_requests.rs b/samply-markers/examples/02_network_requests.rs new file mode 100644 index 000000000..cb3466cfd --- /dev/null +++ b/samply-markers/examples/02_network_requests.rs @@ -0,0 +1,73 @@ +use samply_markers::prelude::*; + +async fn fetch_url(url: &str) -> (String, Option) { + // Emit an interval marker for the time it takes to fetch. + let result = samply_measure!(async { + let response = reqwest::get(url).await?; + response.text().await + }, marker: { + name: format!("fetch {url}"), + }) + .await; + + match result { + Ok(content) => { + println!(" ✓ Fetched {url} ({} bytes)", content.len()); + (String::from(url), Some(content)) + } + Err(error) => { + // Emit an instant marker any time a fetch fails. + samply_marker!({ name: format!("fetch failed: {url}") }); + println!(" ✗ Failed to fetch {url}: {error}"); + (String::from(url), None) + } + } +} + +#[tokio::main] +async fn main() { + // Create a timer that will span the entirety of main(). + // The timer will emit an interval marker when it is dropped at the end of the scope. + let _main_timer = samply_timer!({ name: "main()" }); + + println!("\nStarting samply-markers demo...\n"); + + std::thread::sleep(std::time::Duration::from_millis(200)); + + let urls = &[ + "https://example.com", + "https://fail.invalid", + "https://fail.invalid", + "https://en.wikipedia.org/wiki/Firefox", + "https://fail.invalid", + "https://github.com/nordzilla", + ]; + + println!("\n=== Sequential Fetching ===\n"); + + // Emit an interval marker for the total time to fetch all URLs sequentially. + samply_measure!({ + for url in urls { + fetch_url(url).await; + } + }, marker: { + name: "fetch all URLs sequentially", + }); + + std::thread::sleep(std::time::Duration::from_millis(200)); + + println!("\n=== Concurrent Fetching ===\n"); + + // Emit an interval marker for the total time to fetch all URLs concurrently. + samply_measure!({ + futures::future::join_all( + urls.iter().map(|url| fetch_url(url)) + ).await; + }, marker: { + name: "fetch all URLs concurrently", + }); + + std::thread::sleep(std::time::Duration::from_millis(200)); + + println!("\nDemo completed!\n"); +} diff --git a/samply-markers/examples/03_tokio_task_migration.rs b/samply-markers/examples/03_tokio_task_migration.rs new file mode 100644 index 000000000..ef2268294 --- /dev/null +++ b/samply-markers/examples/03_tokio_task_migration.rs @@ -0,0 +1,55 @@ +use samply_markers::prelude::*; +use tokio::time::{Duration, sleep}; + +async fn migrating_task(task_id: usize, iterations: usize) { + for i in 0..iterations { + samply_measure!(async { + samply_marker!({ name: format!("task({task_id}): iteration {i} start") }); + + sleep(Duration::from_micros(100)).await; + + let mut sum = 0u64; + for j in 0..10_000 { + sum = sum.wrapping_add(j); + } + + sleep(Duration::from_micros(100)).await; + }, marker: { + name: format!("task {task_id} iter {i}"), + }) + .await; + + // Yield to encourage task migration. + tokio::task::yield_now().await; + } +} + +#[tokio::main(flavor = "multi_thread", worker_threads = 10)] +async fn main() { + let _main_timer = samply_timer!({ name: "main()" }); + + println!("\n=== Tokio Task Migration Demo ===\n"); + println!("This example spawns async tasks on a multi-threaded runtime."); + println!("Tasks will migrate between worker threads during execution."); + + let num_tasks = 8; + let iterations_per_task = 20; + + samply_marker!({ name: "spawning tasks" }); + + let handles = (0..num_tasks) + .map(|task_id| { + tokio::spawn(async move { migrating_task(task_id, iterations_per_task).await }) + }) + .collect::>(); + + samply_marker!({ name: "all tasks spawned" }); + + samply_measure!({ + futures::future::join_all(handles).await + }, marker: { + name: "waiting for all tasks", + }); + + println!("\nAll tasks completed!"); +} diff --git a/samply-markers/examples/04_parallel_computation.rs b/samply-markers/examples/04_parallel_computation.rs new file mode 100644 index 000000000..ba2df24c1 --- /dev/null +++ b/samply-markers/examples/04_parallel_computation.rs @@ -0,0 +1,151 @@ +use rayon::{ThreadPoolBuilder, prelude::*}; +use samply_markers::prelude::*; +use std::{collections::HashSet, time::Duration}; + +fn contains_digit(mut value: u32, digit: u32) -> bool { + if value == 0 { + return digit == 0; + } + + while value > 0 { + if value % 10 == digit { + return true; + } + value /= 10; + } + + false +} + +fn filter_numbers_with_digit( + chunk_id: usize, + numbers: &[u32], + digit: u32, + parallel_filters: bool, +) -> Vec { + let mode = if parallel_filters { + "parallel" + } else { + "sequential" + }; + + samply_measure!({ + if parallel_filters { + numbers + .par_iter() + .filter(|&&n| contains_digit(n, digit)) + .cloned() + .collect() + } else { + numbers + .iter() + .filter(|&&n| contains_digit(n, digit)) + .cloned() + .collect() + } + }, marker: { + name: format!("chunk {chunk_id} filter digit {digit} ({mode})"), + }) +} + +fn symmetric_difference_sum(chunk_id: usize, twos: &[u32], fives: &[u32]) -> u64 { + samply_measure!({ + let two_set: HashSet = twos.iter().copied().collect(); + let five_set: HashSet = fives.iter().copied().collect(); + + let only_twos: u64 = two_set + .difference(&five_set) + .map(|&value| value as u64) + .sum(); + let only_fives: u64 = five_set + .difference(&two_set) + .map(|&value| value as u64) + .sum(); + + only_twos + only_fives + }, marker: { + name: format!("chunk {chunk_id} symmetric diff"), + }) +} + +fn process_chunk_pipeline(chunk_id: usize, numbers: &[u32], parallel_filters: bool) -> u64 { + let _chunk_timer = samply_timer!({ name: format!("chunk {chunk_id} pipeline") }); + + let twos = filter_numbers_with_digit(chunk_id, numbers, 2, parallel_filters); + let fives = filter_numbers_with_digit(chunk_id, numbers, 5, parallel_filters); + + symmetric_difference_sum(chunk_id, &twos, &fives) +} + +fn generate_chunks(chunk_count: usize, chunk_len: usize) -> Vec> { + let mut seed = 0u64; + + (0..chunk_count) + .map(|_| { + let mut values = Vec::with_capacity(chunk_len); + for _ in 0..chunk_len { + seed = seed.wrapping_mul(1_664_525).wrapping_add(1_013_904_223); + values.push((seed % 1_000_000) as u32); + } + values + }) + .collect() +} + +fn main() { + let _main_timer = samply_timer!({ name: "main()" }); + + ThreadPoolBuilder::new() + .num_threads(8) + .build_global() + .expect("Failed to configure Rayon thread pool"); + + println!("\n=== Digit Symmetric Difference Demo ===\n"); + + let chunk_count = 32; + let chunk_len = 131072; + let chunks = generate_chunks(chunk_count, chunk_len); + + println!( + "Generated {} chunks with {} numbers each ({} total)\n", + chunk_count, + chunk_len, + chunk_count * chunk_len + ); + + println!("=== Sequential Processing ==="); + let sequential_results: Vec<_> = samply_measure!({ + chunks + .iter() + .enumerate() + .map(|(i, chunk)| process_chunk_pipeline(i, chunk, false)) + .collect() + }, marker: { + name: "sequential pass", + }); + let sequential_total: u64 = sequential_results.iter().sum(); + println!( + "Sequential: {} chunks processed | total symmetric diff sum {}\n", + sequential_results.len(), + sequential_total + ); + + std::thread::sleep(Duration::from_millis(20)); + + println!("=== Parallel Processing (Rayon) ==="); + let parallel_results: Vec<_> = samply_measure!({ + chunks + .par_iter() + .enumerate() + .map(|(i, chunk)| process_chunk_pipeline(i + chunk_count, chunk, true)) + .collect() + }, marker: { + name: "parallel pass", + }); + let parallel_total: u64 = parallel_results.iter().sum(); + println!( + "Parallel: {} chunks processed | total symmetric diff sum {}\n", + parallel_results.len(), + parallel_total + ); +} diff --git a/samply-markers/examples/README.md b/samply-markers/examples/README.md new file mode 100644 index 000000000..be1fb0edb --- /dev/null +++ b/samply-markers/examples/README.md @@ -0,0 +1,111 @@ +# Samply Markers Examples + +This directory contains runnable examples demonstrating the `samply-markers` crate. + +> [!NOTE] +> These commands work from any directory in the workspace. The `target` directory is always at the workspace root. + +## Examples + +### 01) Fibonacci + +Demonstrates recursive function-call tracing of the [Fibonacci Sequence]. + +**[macOS][01-fib-example-macos] | [Ubuntu][01-fib-example-ubuntu] | Windows (not yet supported)** + +```bash +# Build samply +cargo build --release -p samply + +# Build the example +cargo build -p samply-markers --example 01_fibonacci --profile profiling --features enabled + +# Profile +TARGET=$(cargo metadata --format-version 1 | jq -r '.target_directory') +$TARGET/release/samply record $TARGET/profiling/examples/01_fibonacci +``` + +--- + +### 02) Network Requests + +Demonstrates sequential vs. parallel async network requests with [reqwest]. + +**[macOS][02-network-example-macos] | [Ubuntu][02-network-example-ubuntu] | Windows (not yet supported)** + +```bash +# Build samply +cargo build --release -p samply + +# Build the example +cargo build -p samply-markers --example 02_network_requests --profile profiling --features enabled + +# Profile +TARGET=$(cargo metadata --format-version 1 | jq -r '.target_directory') +$TARGET/release/samply record $TARGET/profiling/examples/02_network_requests +``` + +--- + +### 03) Tokio Task Migration + +Demonstrates async task migration across worker threads in a multi-threaded [tokio] runtime. + +**[macOS][03-tokio-example-macos] | [Ubuntu][03-tokio-example-ubuntu] | Windows (not yet supported)** + +```bash +# Build samply +cargo build --release -p samply + +# Build the example +cargo build -p samply-markers --example 03_tokio_task_migration --profile profiling --features enabled + +# Profile +TARGET=$(cargo metadata --format-version 1 | jq -r '.target_directory') +$TARGET/release/samply record $TARGET/profiling/examples/03_tokio_task_migration +``` + +--- + +### 04) Parallel Computation + +Demonstrates sequential vs. parallel computation using [rayon]. + +**[macOS][04-parallel-example-macos] | [Ubuntu][04-parallel-example-ubuntu] | Windows (not yet supported)** + +> [!IMPORTANT] +> This example isn't working correctly with the current FlushOnDrop implemenation. +> Rayon's threads live forever, so the per-thread buffers never flush to their files. +> +> This example works fine if you force a flush on write, but that is quite slow. +> +> I'm going to have to revisit the per-thread writing strategy to cover this case. + + +```bash +# Build samply +cargo build --release -p samply + +# Build the example +cargo build -p samply-markers --example 04_parallel_computation --profile profiling --features enabled + +# Profile +TARGET=$(cargo metadata --format-version 1 | jq -r '.target_directory') +$TARGET/release/samply record $TARGET/profiling/examples/04_parallel_computation +``` + +[01-fib-example-macos]: https://share.firefox.dev/4oMKHtT +[01-fib-example-ubuntu]: https://share.firefox.dev/4o3wur4 +[02-network-example-macos]: https://share.firefox.dev/48eHTj8 +[02-network-example-ubuntu]: https://share.firefox.dev/3LzT6lJ +[03-tokio-example-macos]: https://share.firefox.dev/3X3Wl7k +[03-tokio-example-ubuntu]: https://share.firefox.dev/43vXgB9 +[04-parallel-example-macos]: https://share.firefox.dev/4iabqhw +[04-parallel-example-ubuntu]: https://share.firefox.dev/4oSvBDe +[jq]: https://jqlang.github.io/jq/ +[cargo metadata]: https://doc.rust-lang.org/cargo/commands/cargo-metadata.html +[Fibonacci Sequence]: https://en.wikipedia.org/wiki/Fibonacci_sequence +[rayon]: https://crates.io/crates/rayon +[reqwest]: https://crates.io/crates/reqwest +[samply]: https://github.com/mstange/samply?tab=readme-ov-file#samply +[tokio]: https://crates.io/crates/tokio From 8a5e0327a79134ed697457548e798f8e8f2e4701 Mon Sep 17 00:00:00 2001 From: Erik Nordin Date: Sat, 15 Nov 2025 14:01:55 -0600 Subject: [PATCH 23/23] Improve performance of writing markers MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This commit improves the performance of samply-markers when enabled, based on benchmarks of the Fibonacci example increased to n = 30 and measured with hyperfine. The Fibonacci example at n = 30 makes 2,692,536 recursive calls, emitting the same number of markers. This provides a great stress test for marker emission overhead. The configurations are as follows: - disabled: samply-markers disabled - enabled-baseline: samply-markers enabled before any performance improvements - buffered-writes: adds the buffered writes improvement - itoa-buffers: adds the itoa improvement on top of buffered writes Linux results: Benchmark 1: ./fib30-disabled Time (mean ± σ): 128.2 ms ± 0.6 ms [User: 127.2 ms, System: 0.9 ms] Range (min … max): 127.1 ms … 129.6 ms 23 runs Benchmark 2: ./fib30-enabled-baseline Time (mean ± σ): 3.144 s ± 0.009 s [User: 0.924 s, System: 2.220 s] Range (min … max): 3.134 s … 3.161 s 10 runs Benchmark 3: ./fib30-enabled-buffered-writes Time (mean ± σ): 522.9 ms ± 1.1 ms [User: 478.9 ms, System: 43.7 ms] Range (min … max): 520.2 ms … 524.1 ms 10 runs Benchmark 4: ./fib30-enabled-itoa-buffers Time (mean ± σ): 423.1 ms ± 1.8 ms [User: 377.8 ms, System: 45.1 ms] Range (min … max): 419.6 ms … 426.3 ms 10 runs Summary ./fib30-disabled ran 3.30 ± 0.02 times faster than ./fib30-enabled-itoa-buffers 4.08 ± 0.02 times faster than ./fib30-enabled-buffered-writes 24.53 ± 0.14 times faster than ./fib30-enabled-baseline macOS results: Benchmark 1: ./fib30-disabled Time (mean ± σ): 90.7 ms ± 0.4 ms [User: 89.4 ms, System: 0.9 ms] Range (min … max): 90.0 ms … 91.6 ms 31 runs Benchmark 2: ./fib30-enabled-baseline Time (mean ± σ): 4.384 s ± 0.053 s [User: 0.578 s, System: 3.783 s] Range (min … max): 4.295 s … 4.495 s 10 runs Benchmark 3: ./fib30-enabled-buffered-writes Time (mean ± σ): 257.4 ms ± 1.8 ms [User: 237.6 ms, System: 16.9 ms] Range (min … max): 255.1 ms … 261.8 ms 11 runs Benchmark 4: ./fib30-enabled-itoa-buffers Time (mean ± σ): 187.6 ms ± 1.1 ms [User: 169.9 ms, System: 16.1 ms] Range (min … max): 186.3 ms … 190.1 ms 15 runs Summary ./fib30-disabled ran 2.07 ± 0.01 times faster than ./fib30-enabled-itoa-buffers 2.84 ± 0.02 times faster than ./fib30-enabled-buffered-writes 48.32 ± 0.62 times faster than ./fib30-enabled-baseline Profiles: Ubuntu: * fib30-disabled: https://share.firefox.dev/48id64U * fib30-enabled-baseline: https://share.firefox.dev/47K8Taf * fib30-enabled-buffered-writes: https://share.firefox.dev/4oK5Uog * fib30-enabled-itoa-buffers: https://share.firefox.dev/47ZtGVQ macOS: * fib30-disabled: https://share.firefox.dev/3LMmaX2 * fib30-enabled-baseline: https://share.firefox.dev/49TPODF * fib30-enabled-buffered-writes: https://share.firefox.dev/4oFo1LP * fib30-enabled-itoa-buffers: https://share.firefox.dev/3K6rLqG Overall: - Using buffered writes dramatically reduces overhead. - Using itoa provides an additional ~19% improvement on Linux and ~27% on macOS. --- Cargo.lock | 11 +- samply-markers/Cargo.toml | 4 +- samply-markers/src/marker/timestamp.rs | 26 +- samply-markers/src/provider/unix.rs | 106 ++++-- samply-markers/tests/unix.rs | 465 +++++++++++++++++-------- 5 files changed, 421 insertions(+), 191 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 6c4ffa6b7..36717ba3f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2462,6 +2462,7 @@ name = "samply-markers" version = "0.1.0" dependencies = [ "futures", + "itoa", "libc", "mach2 0.4.3", "nix", @@ -2469,7 +2470,6 @@ dependencies = [ "regex", "reqwest", "serial_test", - "smallstr", "tempfile", "tokio", ] @@ -2700,15 +2700,6 @@ version = "0.4.11" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7a2ae44ef20feb57a68b23d846850f861394c2e02dc425a50098ae8c90267589" -[[package]] -name = "smallstr" -version = "0.3.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "862077b1e764f04c251fe82a2ef562fd78d7cadaeb072ca7c2bcaf7217b1ff3b" -dependencies = [ - "smallvec", -] - [[package]] name = "smallvec" version = "1.15.1" diff --git a/samply-markers/Cargo.toml b/samply-markers/Cargo.toml index 218908266..f9aa73ecf 100644 --- a/samply-markers/Cargo.toml +++ b/samply-markers/Cargo.toml @@ -14,14 +14,14 @@ keywords = ["profiling", "markers", "instrumentation", "tracing", "performance"] [features] default = [] enabled = [ + "dep:itoa", "dep:nix", - "dep:smallstr", "dep:tempfile", ] [target.'cfg(unix)'.dependencies] +itoa = { version = "1.0.15", optional = true } nix = { version = "0.30.1", features = ["mman", "process", "time"], optional = true } -smallstr = { version = "0.3.1", optional = true } tempfile = { version = "3.23.0", optional = true } [target.'cfg(target_os = "macos")'.dependencies] diff --git a/samply-markers/src/marker/timestamp.rs b/samply-markers/src/marker/timestamp.rs index f1efe2590..9282bc2b4 100644 --- a/samply-markers/src/marker/timestamp.rs +++ b/samply-markers/src/marker/timestamp.rs @@ -38,16 +38,14 @@ impl SamplyTimestamp { Self(nanos) } - /// Formats a [`SamplyTimestamp`] without implementing [`std::fmt::Display`]. + /// Returns the inner nanosecond value. /// - /// Having a dedicated formatter keeps [`SamplyTimestamp`] opaque, ensuring that it - /// cannot be stringified via [`ToString`] and compared. + /// This is only exposed within the crate for formatting and testing purposes, + /// keeping [`SamplyTimestamp`] opaque to external consumers. + #[inline] #[cfg(feature = "enabled")] - pub(crate) fn fmt(self, writer: &mut W) -> std::fmt::Result - where - W: std::fmt::Write + ?Sized, - { - std::fmt::Write::write_fmt(writer, format_args!("{}", self.0)) + pub(crate) const fn as_nanos(self) -> u64 { + self.0 } } @@ -83,16 +81,12 @@ mod test { #[test] #[cfg(feature = "enabled")] - fn fmt_writes_correctly() { + fn as_nanos_returns_correct_value() { let time = SamplyTimestamp::from_monotonic_nanos(9876543210); - let mut buffer = String::new(); - - let result = time.fmt(&mut buffer); - assert!(result.is_ok(), "Expected the fmt operation to succeed."); - assert_eq!( - buffer, "9876543210", - "Expected the buffer to contain the formatted timestamp." + time.as_nanos(), + 9876543210, + "Expected as_nanos to return the underlying nanosecond value." ); } diff --git a/samply-markers/src/provider/unix.rs b/samply-markers/src/provider/unix.rs index 742e8a5c6..1cf10b5f1 100644 --- a/samply-markers/src/provider/unix.rs +++ b/samply-markers/src/provider/unix.rs @@ -2,6 +2,7 @@ use std::cell::RefCell; use std::fs::File; +use std::io::BufWriter; use std::io::Write; use std::num::NonZeroUsize; use std::path::Path; @@ -22,10 +23,36 @@ use nix::time::ClockId; #[cfg(target_os = "linux")] use nix::time::clock_gettime; -use smallstr::SmallString; use tempfile::TempDir; use tempfile::tempdir; +/// A wrapper around [`std::io::BufWriter`] that flushes on drop to ensure data is written. +/// +/// This is used in conjunction with [`std::thread_local!`] to ensure that buffers are +/// flushed when the thread exits. +struct FlushOnDrop(BufWriter); + +impl Drop for FlushOnDrop { + fn drop(&mut self) { + if let Err(e) = self.0.flush() { + eprintln!("samply-markers: failed to flush marker-file buffer: {e}"); + } + } +} + +impl std::ops::Deref for FlushOnDrop { + type Target = BufWriter; + fn deref(&self) -> &Self::Target { + &self.0 + } +} + +impl std::ops::DerefMut for FlushOnDrop { + fn deref_mut(&mut self) -> &mut Self::Target { + &mut self.0 + } +} + /// A lazily created directory that holds per-thread mmapped marker files. static MARKERS_DIR: LazyLock> = LazyLock::new(|| { tempdir() @@ -35,8 +62,8 @@ static MARKERS_DIR: LazyLock> = LazyLock::new(|| { }); thread_local! { - /// A thread-local file used to append marker lines that samply will ingest. - static MARKER_FILE: RefCell> = RefCell::new(create_marker_file()); + /// A thread-local buffered writer used to append marker lines that samply will ingest. + static MARKER_FILE: RefCell> = RefCell::new(create_marker_file()); } #[cfg(target_os = "macos")] @@ -47,10 +74,12 @@ pub struct TimestampNowImpl; impl TimestampNowProvider for TimestampNowImpl { /// Queries the monotonic clock and converts the result to monotonic nanoseconds. + #[inline] fn now() -> SamplyTimestamp { #[cfg(target_os = "linux")] { - let now = clock_gettime(ClockId::CLOCK_MONOTONIC).unwrap(); + let now = clock_gettime(ClockId::CLOCK_MONOTONIC) + .expect("samply-markers: unable to get time from CLOCK_MONOTONIC"); // Monotonic nanoseconds should only ever be positive. #[allow(clippy::cast_sign_loss)] @@ -94,15 +123,23 @@ pub struct WriteMarkerImpl; impl WriteMarkerProvider for WriteMarkerImpl { /// Serializes the marker to the thread-local file, creating it on demand. + #[inline] fn write_marker(start: SamplyTimestamp, end: SamplyTimestamp, marker: &SamplyMarker) { - let mut s = SmallString::<[u8; 64]>::new(); - start.fmt(&mut s).unwrap(); - s.push(' '); - end.fmt(&mut s).unwrap(); - s.push(' '); - s.push_str(marker.name()); - s.push('\n'); - let _ = with_marker_file(|f| f.write_all(s.as_bytes())); + let () = MARKER_FILE.with_borrow_mut(|file| { + if let Some(f) = file.as_mut() { + // Use stack-allocated itoa buffers to format timestamps without heap allocation. + // Format: "{start_ns} {end_ns} {marker_name}\n" + let mut start_buf = itoa::Buffer::new(); + let mut end_buf = itoa::Buffer::new(); + + let _ = f.write_all(start_buf.format(start.as_nanos()).as_bytes()); + let _ = f.write_all(b" "); + let _ = f.write_all(end_buf.format(end.as_nanos()).as_bytes()); + let _ = f.write_all(b" "); + let _ = f.write_all(marker.name().as_bytes()); + let _ = f.write_all(b"\n"); + } + }); } } @@ -111,16 +148,6 @@ fn markers_dir() -> Option<&'static Path> { Some(LazyLock::force(&MARKERS_DIR).as_ref()?) } -/// Executes the provided closure with a mutable handle to the thread-local marker file. -/// -/// Returns [`None`] when the file could not be prepared. -fn with_marker_file(f: F) -> Option -where - F: FnOnce(&mut File) -> R, -{ - MARKER_FILE.with_borrow_mut(|file| file.as_mut().map(f)) -} - /// Returns a unique thread identifier for the current thread. #[cfg(target_os = "linux")] fn get_thread_id() -> u32 { @@ -159,7 +186,7 @@ fn get_thread_id() -> u32 { } /// Creates a new mmapped marker file for the current thread. -fn create_marker_file() -> Option { +fn create_marker_file() -> Option { let file_name = markers_dir()?.join(format!( "marker-{}-{}.txt", nix::unistd::getpid().as_raw(), @@ -216,5 +243,36 @@ fn create_marker_file() -> Option { }) .ok()?; - Some(file) + // I benchmarked the buffer size with hyperfine, using the Fibonacci example + // given n = 30, which generates about 2.7 million markers per run. + // + // Ubuntu results: + // ------------------------------------------ + // 4 KiB: 470.9 ms ± 1.2 ms (5.3% slower) + // 8 KiB: 457.4 ms ± 2.1 ms (2.2% slower) + // 16 KiB: 451.0 ms ± 1.3 ms (0.8% slower) + // 32 KiB: 447.6 ms ± 1.5 ms (0.1% slower) + // 64 KiB: 447.4 ms ± 2.9 ms (optimal speed) + // 128 KiB: 448.6 ms ± 1.1 ms (0.3% slower) + // 256 KiB: 450.5 ms ± 1.4 ms (0.7% slower) + // 512 KiB: 450.1 ms ± 1.1 ms (0.6% slower) + // 1024 KiB: 449.9 ms ± 2.6 ms (0.6% slower) + // + // macOS results: + // ------------------------------------------ + // 4 KiB: 303.0 ms ± 2.5 ms (43.9% slower) + // 8 KiB: 258.3 ms ± 1.2 ms (22.6% slower) + // 16 KiB: 236.4 ms ± 1.2 ms (12.2% slower) + // 32 KiB: 223.4 ms ± 0.7 ms (06.0% slower) + // 64 KiB: 217.2 ms ± 1.2 ms (03.1% slower) + // 128 KiB: 213.3 ms ± 0.7 ms (01.3% slower) + // 256 KiB: 211.9 ms ± 1.3 ms (00.6% slower) + // 512 KiB: 210.6 ms ± 0.7 ms (optimal speed) + // 1024 KiB: 210.7 ms ± 0.7 ms (00.0% slower) + // + // Even though macOS benefitted from a larger buffer size, + // I feel like a 512 KiB buffer per thread feels like overkill. + // + // 64 KiB feels like a good balance based on this benchmark. + Some(FlushOnDrop(BufWriter::with_capacity(64 * 1024, file))) } diff --git a/samply-markers/tests/unix.rs b/samply-markers/tests/unix.rs index 08db101af..f7a08771a 100644 --- a/samply-markers/tests/unix.rs +++ b/samply-markers/tests/unix.rs @@ -1,4 +1,41 @@ //! This module contains integration tests for [`samply-markers`](crate) on Unix systems. +//! +//! # Test Design: +//! +//! These tests verify that markers are correctly written to files by inspecting the marker file +//! contents after emission. To ensure deterministic testing, most tests wrap marker emission in +//! `thread::spawn` and join the thread before reading marker files. +//! +//! ## The FlushOnDrop Mechanism +//! +//! Marker files use buffered writes for performance. The buffer is wrapped in a `FlushOnDrop` +//! type that lives in thread-local storage. When a thread exits, the thread-local storage is +//! dropped, triggering an automatic flush of the buffer to disk. +//! +//! ## Why Thread Spawning is Required +//! +//! Without spawning a new thread, markers emitted in the test would be buffered in the main test +//! thread's thread-local storage. The buffer would only flush when the test thread exits, which +//! may happen after the test's assertions run. This creates a race condition where the test might +//! read the marker file before the buffer is flushed, causing spurious failures. +//! +//! ## When Writing New Tests +//! +//! If your test needs to verify marker file contents after emission, wrap the marker-emitting +//! code in `thread::spawn` and join the thread before reading the marker file. +//! +//! Example pattern: +//! ```rust +//! let tid = thread::spawn(move || { +//! samply_marker!({ name: "MyMarker" }); +//! get_thread_id() +//! }) +//! .join() +//! .expect("thread panicked"); +//! +//! // Now it's safe to read and verify the marker file +//! assert_marker_file!(pid, tid, regex: { r"^\d+ \d+ MyMarker$" }); +//! ``` #![cfg(all(feature = "enabled", target_family = "unix"))] @@ -184,12 +221,17 @@ fn cleanup_marker_files(pid: u32) { #[serial] fn instant_writes_marker_to_file() { with_marker_file_cleanup!({ - samply_marker!({ name: "InstantMarker1" }); - samply_marker!({ name: "InstantMarker2" }); - samply_marker!({ name: "InstantMarker3" }); - let pid = nix::unistd::getpid().as_raw() as u32; - let tid = get_thread_id(); + + let tid = thread::spawn(move || { + samply_marker!({ name: "InstantMarker1" }); + samply_marker!({ name: "InstantMarker2" }); + samply_marker!({ name: "InstantMarker3" }); + + get_thread_id() + }) + .join() + .expect("thread panicked"); assert_single_marker_file!(pid, tid); @@ -222,12 +264,17 @@ fn instant_writes_marker_to_file() { )] fn assert_marker_file_panics_on_wrong_line_count() { with_marker_file_cleanup!({ - // Emit exactly 2 markers. - SamplyMarker::new("test marker").emit_instant(); - SamplyMarker::new("test marker").emit_instant(); - let pid = nix::unistd::getpid().as_raw() as u32; - let tid = get_thread_id(); + + let tid = thread::spawn(move || { + // Emit exactly 2 markers. + SamplyMarker::new("test marker").emit_instant(); + SamplyMarker::new("test marker").emit_instant(); + + get_thread_id() + }) + .join() + .expect("thread panicked"); assert_single_marker_file!(pid, tid); @@ -246,11 +293,16 @@ fn assert_marker_file_panics_on_wrong_line_count() { #[serial] fn empty_name_defaults_to_unnamed_marker() { with_marker_file_cleanup!({ - SamplyMarker::new("").emit_instant(); - SamplyMarker::new(format!("")).emit_instant(); - let pid = nix::unistd::getpid().as_raw() as u32; - let tid = get_thread_id(); + + let tid = thread::spawn(move || { + SamplyMarker::new("").emit_instant(); + SamplyMarker::new(format!("")).emit_instant(); + + get_thread_id() + }) + .join() + .expect("thread panicked"); assert_single_marker_file!(pid, tid); @@ -269,21 +321,26 @@ fn empty_name_defaults_to_unnamed_marker() { #[serial] fn timer_writes_marker_to_file() { with_marker_file_cleanup!({ - { - let _timer1 = samply_timer!({ name: "TimerMarker1" }); - thread::sleep(std::time::Duration::from_millis(2)); - } - { - let _timer2 = samply_timer!({ name: "TimerMarker2" }); - thread::sleep(std::time::Duration::from_millis(3)); - } - { - let _timer3 = samply_timer!({ name: "TimerMarker3" }); - thread::sleep(std::time::Duration::from_millis(4)); - } - let pid = nix::unistd::getpid().as_raw() as u32; - let tid = get_thread_id(); + + let tid = thread::spawn(move || { + { + let _timer1 = samply_timer!({ name: "TimerMarker1" }); + thread::sleep(std::time::Duration::from_millis(2)); + } + { + let _timer2 = samply_timer!({ name: "TimerMarker2" }); + thread::sleep(std::time::Duration::from_millis(3)); + } + { + let _timer3 = samply_timer!({ name: "TimerMarker3" }); + thread::sleep(std::time::Duration::from_millis(4)); + } + + get_thread_id() + }) + .join() + .expect("thread panicked"); assert_single_marker_file!(pid, tid); @@ -303,40 +360,45 @@ fn timer_writes_marker_to_file() { #[serial] fn measure_writes_marker_to_file() { with_marker_file_cleanup!({ - let result1 = samply_measure!({ - thread::sleep(std::time::Duration::from_millis(2)); - 42 - } marker: { - name: "MeasureMarker1", - }); - - let result2 = samply_measure!({ - thread::sleep(std::time::Duration::from_millis(3)); - "hello" - } marker: { - name: "MeasureMarker2", - }); - - let result3 = samply_measure!({ - thread::sleep(std::time::Duration::from_millis(4)); - vec![1, 2, 3] - } marker: { - name: "MeasureMarker3", - }); + let pid = nix::unistd::getpid().as_raw() as u32; - assert_eq!(result1, 42, "Expected measure to preserve return value."); - assert_eq!( - result2, "hello", - "Expected measure to preserve return value." - ); - assert_eq!( - result3, - vec![1, 2, 3], - "Expected measure to preserve return value." - ); + let tid = thread::spawn(move || { + let result1 = samply_measure!({ + thread::sleep(std::time::Duration::from_millis(2)); + 42 + } marker: { + name: "MeasureMarker1", + }); + + let result2 = samply_measure!({ + thread::sleep(std::time::Duration::from_millis(3)); + "hello" + } marker: { + name: "MeasureMarker2", + }); + + let result3 = samply_measure!({ + thread::sleep(std::time::Duration::from_millis(4)); + vec![1, 2, 3] + } marker: { + name: "MeasureMarker3", + }); + + assert_eq!(result1, 42, "Expected measure to preserve return value."); + assert_eq!( + result2, "hello", + "Expected measure to preserve return value." + ); + assert_eq!( + result3, + vec![1, 2, 3], + "Expected measure to preserve return value." + ); - let pid = nix::unistd::getpid().as_raw() as u32; - let tid = get_thread_id(); + get_thread_id() + }) + .join() + .expect("thread panicked"); assert_single_marker_file!(pid, tid); @@ -405,18 +467,27 @@ async fn measure_async_writes_marker_to_file() { use tokio::time::{Duration, sleep}; with_marker_file_cleanup!({ - let result = samply_measure!(async { - sleep(Duration::from_millis(5)).await; - 42 - }, marker: { - name: "AsyncMeasure", - }) - .await; + let pid = nix::unistd::getpid().as_raw() as u32; - assert_eq!(result, 42, "Expected measure to preserve return value."); + let tid = thread::spawn(move || { + let runtime = tokio::runtime::Runtime::new().unwrap(); - let pid = nix::unistd::getpid().as_raw() as u32; - let tid = get_thread_id(); + runtime.block_on(async { + let result = samply_measure!(async { + sleep(Duration::from_millis(5)).await; + 42 + }, marker: { + name: "AsyncMeasure", + }) + .await; + + assert_eq!(result, 42, "Expected measure to preserve return value."); + }); + + get_thread_id() + }) + .join() + .expect("thread panicked"); assert_single_marker_file!(pid, tid); @@ -434,15 +505,20 @@ async fn measure_async_writes_marker_to_file() { #[serial] fn timer_emit_prevents_double_emit_on_drop() { with_marker_file_cleanup!({ - { - let timer = samply_timer!({ name: "ExplicitEmit" }); - thread::sleep(std::time::Duration::from_millis(2)); - timer.emit(); // Explicitly emit the timer. - // The timer drops here, but should not emit a second time. - } - let pid = nix::unistd::getpid().as_raw() as u32; - let tid = get_thread_id(); + + let tid = thread::spawn(move || { + { + let timer = samply_timer!({ name: "ExplicitEmit" }); + thread::sleep(std::time::Duration::from_millis(2)); + timer.emit(); // Explicitly emit the timer. + // The timer drops here, but should not emit a second time. + } + + get_thread_id() + }) + .join() + .expect("thread panicked"); assert_single_marker_file!(pid, tid); @@ -462,30 +538,39 @@ async fn measure_async_with_early_return_writes_marker() { use tokio::time::{Duration, sleep}; with_marker_file_cleanup!({ - async fn fallible_operation(should_fail: bool) -> Result { - samply_measure!(async { - sleep(Duration::from_millis(2)).await; + let pid = nix::unistd::getpid().as_raw() as u32; - if should_fail { - return Err("operation failed"); - } + let tid = thread::spawn(move || { + let runtime = tokio::runtime::Runtime::new().unwrap(); - sleep(Duration::from_millis(2)).await; - Ok(String::from("success")) - }, marker: { - name: "FallibleAsync", - }) - .await - } + runtime.block_on(async { + async fn fallible_operation(should_fail: bool) -> Result { + samply_measure!(async { + sleep(Duration::from_millis(2)).await; - let success_result = fallible_operation(false).await; - assert!(success_result.is_ok()); + if should_fail { + return Err("operation failed"); + } - let failure_result = fallible_operation(true).await; - assert!(failure_result.is_err()); + sleep(Duration::from_millis(2)).await; + Ok(String::from("success")) + }, marker: { + name: "FallibleAsync", + }) + .await + } - let pid = nix::unistd::getpid().as_raw() as u32; - let tid = get_thread_id(); + let success_result = fallible_operation(false).await; + assert!(success_result.is_ok()); + + let failure_result = fallible_operation(true).await; + assert!(failure_result.is_err()); + }); + + get_thread_id() + }) + .join() + .expect("thread panicked"); assert_single_marker_file!(pid, tid); @@ -500,66 +585,65 @@ async fn measure_async_with_early_return_writes_marker() { }); } +#[test] #[serial] -#[tokio::test(flavor = "multi_thread", worker_threads = 3)] -async fn tokio_spawn_writes_markers_across_threads() { +fn tokio_spawn_writes_markers_across_threads() { use tokio::time::{Duration, sleep}; with_marker_file_cleanup!({ let handles = (0..3) .map(|i| { - tokio::spawn(async move { - // Each spawned task may run on different threads. - // Emit multiple markers with awaits in between to allow potential thread migration. - samply_measure!(async { - sleep(Duration::from_millis(2)).await; - }, marker: { - name: format!("async task {i} marker A"), - }) - .await; - - samply_measure!(async { - sleep(Duration::from_millis(3)).await; - }, marker: { - name: format!("async task {i} marker B"), - }) - .await; - - samply_measure!(async { - sleep(Duration::from_millis(4)).await; - }, marker: { - name: format!("async task {i} marker C"), - }) - .await; - - // Return the thread ID where this task's final marker was emitted. + thread::spawn(move || { + // Create a tokio runtime on this thread to test async markers + let runtime = tokio::runtime::Runtime::new().unwrap(); + + runtime.block_on(async move { + // Emit async markers with awaits + samply_measure!(async { + sleep(Duration::from_millis(2)).await; + }, marker: { + name: format!("async task {i} marker A"), + }) + .await; + + samply_measure!(async { + sleep(Duration::from_millis(3)).await; + }, marker: { + name: format!("async task {i} marker B"), + }) + .await; + + samply_measure!(async { + sleep(Duration::from_millis(4)).await; + }, marker: { + name: format!("async task {i} marker C"), + }) + .await; + }); + + // Return the thread ID where markers were emitted. + // Buffer will auto-flush when this thread exits (FlushOnDrop) get_thread_id() }) }) .collect::>(); - let _tids = futures::future::join_all(handles) - .await + let _tids = handles .into_iter() - .map(|result| result.expect("task panicked")) + .map(|h| h.join().expect("thread panicked")) .collect::>(); let pid = nix::unistd::getpid().as_raw() as u32; - // Verify that markers were written. We can't predict which thread each task ran on - // since tokio may schedule tasks on any worker thread, and tasks may migrate between - // threads during execution. We collect all marker files for this PID to ensure we - // find all markers regardless of which thread's file they were written to. + // Verify that markers were written across multiple threads. + // Each thread gets its own marker file. let marker_files = find_all_marker_files(pid); - // With 3 worker threads, we should have at least 1 file and at most 3 files. - assert!( - !marker_files.is_empty(), - "Expected at least one marker file to exist" - ); - assert!( - marker_files.len() <= 3, - "Expected at most 3 marker files are found {}", + // With 3 threads, we should have exactly 3 marker files. + assert_eq!( + marker_files.len(), + 3, + "Expected exactly 3 marker files (one per thread), found {}", marker_files.len() ); @@ -581,3 +665,106 @@ async fn tokio_spawn_writes_markers_across_threads() { } }); } + +#[test] +#[serial] +fn tokio_task_migration_writes_markers_correctly() { + use tokio::time::{Duration, sleep}; + + with_marker_file_cleanup!({ + // Create a shared multi-threaded runtime that allows task migration between threads. + let runtime = tokio::runtime::Builder::new_multi_thread() + .worker_threads(8) + .enable_time() + .build() + .unwrap(); + + runtime.block_on(async { + // Spawn tasks using tokio::spawn, which allows migration between worker threads. + let handles = (0..8) + .map(|i| { + tokio::spawn(async move { + for marker_num in 0..10 { + samply_measure!(async { + sleep(Duration::from_millis(2)).await; + }, marker: { + name: format!("migrating task {i} marker {marker_num}"), + }) + .await; + + // Yield to encourage task migration. + tokio::task::yield_now().await; + } + + get_thread_id() + }) + }) + .collect::>(); + + // Wait for all tasks to complete. + let _tids = futures::future::join_all(handles) + .await + .into_iter() + .map(|result| result.expect("task panicked")) + .collect::>(); + }); + + // Drop the runtime, which causes worker threads to exit and flush their buffers. + drop(runtime); + + let pid = nix::unistd::getpid().as_raw() as u32; + let marker_files = find_all_marker_files(pid); + + // With 8 worker threads, we should have 1-8 marker files depending on task migration. + // The total number of markers across the 1-8 files should always be exactly 80. + // + // Run the following command to see this output: + // ❯ cargo test -p samply-markers --features enabled tokio_task_migration_writes_markers_correctly -- --nocapture + println!("\n=== Marker File Distribution ===\n"); + println!("Total marker files created: {}\n", marker_files.len()); + + assert!( + !marker_files.is_empty() && marker_files.len() <= 8, + "Expected 1-8 marker files, found {}", + marker_files.len() + ); + + let all_contents = marker_files + .iter() + .filter_map(|path| { + fs::read_to_string(path).ok().map(|contents| { + let line_count = contents.lines().count(); + println!( + " - {} has {} markers", + path.file_name().unwrap().to_string_lossy(), + line_count + ); + contents + }) + }) + .collect::>() + .join(""); + + let total_marker_count = all_contents.lines().count(); + println!("\nTotal markers across all files: {}\n", total_marker_count); + + assert_eq!( + total_marker_count, 80, + "Expected exactly 80 markers (8 tasks x 10 markers each), but found {}", + total_marker_count + ); + + // Verify all 80 markers appear with the correct names. + for task_num in 0..8 { + for marker_num in 0..10 { + let expected = format!("migrating task {task_num} marker {marker_num}"); + assert!( + all_contents.contains(&expected), + "Expected to find '{expected}' in marker files but didn't.\n\ + This proves FlushOnDrop successfully flushed when tokio runtime shut down.\n\ + All contents:\n{all_contents}" + ); + } + } + }); +}