Skip to content

add tracing feature #452

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
guswynn wants to merge 1 commit into
base: master
Choose a base branch
from
Open

add tracing feature #452

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions timely/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,6 +32,7 @@ timely_communication = { path = "../communication", version = "0.12", default-fe
timely_container = { path = "../container", version = "0.12" }
crossbeam-channel = "0.5.0"
futures-util = "0.3"
tracing = { version = "0.1.31", optional = true }

[dev-dependencies]
# timely_sort="0.1.6"
Expand Down
26 changes: 26 additions & 0 deletions timely/src/dataflow/operators/generic/builder_raw.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -161,13 +161,35 @@ impl<G: Scope> OperatorBuilder<G> {
let inputs = self.shape.inputs;
let outputs = self.shape.outputs;

// Generate a tracing span for the function.
#[cfg(feature = "tracing")]
let span = {
let location = std::panic::Location::caller();
// timely.console.span is a marker target allowing us to
// turn these spans on and off specifically
// TODO(guswynn): check with tracing folks if there is a better
// way to do this
tracing::trace_span!(
target: "timely.console.span",
Comment on lines +168 to +173
Copy link

@hawkw hawkw Feb 25, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

in general, tracing targets are Rust module paths when they're not explicitly overrididen; so :: is typically used as a separator rather than . --- the use of . is not forbidden by tracing, but it's not the general convention.

i don't really understand the role of the timely::console::span target --- i would probably just make this

Suggested change
// timely.console.span is a marker target allowing us to
// turn these spans on and off specifically
// TODO(guswynn): check with tracing folks if there is a better
// way to do this
tracing::trace_span!(
target: "timely.console.span",
tracing::trace_span!(
target: "timely::dataflow::operator",

or something if you don't want to use the full module path (the user probably doesn't care about ::generic::builder_raw here?). you'll still be able to filter that target out without having a weird target for it.

Copy link
Author

@guswynn guswynn Feb 25, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I want to have a set target so that if this code ever moves, set filters in our downstream binary don't break, but good point, timely::dataflow::operator is probably better!

"runtime.spawn",
kind = %"timely-operator",
"fn" = %std::any::type_name::<L>(),
task.name = self.shape.name.as_str(),
Comment on lines +175 to +177
Copy link

@hawkw hawkw Feb 25, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i don't know anything about timely dataflow, so...is shape_name something provided by the user that can describe a particular task in the user code, or is it provided by the library? if it's internal to the library and describes a general class of dataflow operator, i would probably use that as the kind field rather than the task.name field --- in Tokio's instrumentation, the kind field will have values like "task", for tasks spawned via tokio::spawn, "local", for tasks spawned via spawn_local, "blocking" for blocking-pool tasks, and "block_on" for tasks created by tokio::runtime::block_on.

if shape_name is something internal to timely dataflow, i would probably use that for the kind field --- the target of the span will still indicate that it's coming from timely. if it's provided by the user, though, this seems correct.

Copy link
Author

@guswynn guswynn Feb 25, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, it is something that people set if using the raw builder api, or wrappers around it like unary_frontier

For other combinators, like flat_map, consolidate, etc., its set to a uppercase version of the function name.
I think it would require more thorough changes throughout timely to distinguish between these, but using kind is a great point for a followup

things like

timely_stream.flat_map(|...| logic)

would end up with

kind = "FlatMap"
name = "FlatMap"
location = hopefully_the_top_level_callsite
target = timely::whatever

(and possible named version of the same functions in the future
and things like

timely_stream.unary_frontier(p_contract, "my_special_name", || logic)

kind = "UnaryFrontier"
name = "my_special_name"
location = hopefully_the_top_level_callsite
target = timely::whatever

I need to go through and add #[track_caller] to all these combinators anyways, so it might be nice to a do extra kind/name refactoring at the same time

loc.file = location.file(),
loc.line = location.line(),
loc.col = location.column(),
)
};

let operator = OperatorCore {
shape: self.shape,
address: self.address,
activations: self.scope.activations(),
logic,
shared_progress: Rc::new(RefCell::new(SharedProgress::new(inputs, outputs))),
summary: self.summary,
#[cfg(feature = "tracing")]
span,
};

self.scope.add_operator_with_indices(Box::new(operator), self.index, self.global);
Expand All @@ -190,6 +212,8 @@ where
shared_progress: Rc<RefCell<SharedProgress<T>>>,
activations: Rc<RefCell<Activations>>,
summary: Vec<Vec<Antichain<T::Summary>>>,
#[cfg(feature = "tracing")]
span: tracing::Span,
}

impl<T, L> Schedule for OperatorCore<T, L>
Expand All @@ -201,6 +225,8 @@ where
fn path(&self) -> &[usize] { &self.address[..] }
fn schedule(&mut self) -> bool {
let shared_progress = &mut *self.shared_progress.borrow_mut();
#[cfg(feature = "tracing")]
let _s = self.span.enter();
(self.logic)(shared_progress)
}
}
Expand Down