Allow thread name and id to be displayed in traces #818

Pothulapati · 2020-07-14T03:08:22Z

Motivation

Fixes #809

Solution

This PR adds two new methods i.e with_thread_ids and
with_thread_names to the fmt Layer which passed till
the pre-configured Format type, where the check is performed
and these the above values are formatted based on the flags.

The formatting is done by creating to new Types that impl Display
for Id and Name. For Thread Name, we keep track of the max length
of the thread name that occured till now using a thread safe static
type and pad accordingly. For Thread Id, we pad directly with 2
as in most cases we would see a double digit number of threads.

Signed-off-by: Tarun Pothulapati [email protected]

This PR adds two new methods i.e `with_thread_ids` and `with_thread_names` to the fmt Layer which passed till the pre-configured Format type, where the check is performed and these the above values are formatted based on the flags. The formatting is done by creating to new Types that impl Display for Id and Name. For Thread Name, we keep track of the max length of the thread name that occured till now using a thread safe static type and pad accordingly. For Thread Id, we pad directly with 2 as in most cases we would see a double digit number of threads. Signed-off-by: Tarun Pothulapati <[email protected]>

Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw

This definitely looks like the right overall approach. I had some notes on the specifics of the implementation.

Also, I'm ccing @davidbarsky, since I imagine he has formatting opinions...

hawkw · 2020-07-14T17:13:55Z

examples/examples/thread-info.rs

+/// This is a example showing how thread info can be enabled
+/// to be attached with events


How about:

Suggested change

/// This is a example showing how thread info can be enabled

/// to be attached with events

/// This is a example showing how thread info can be displayed when

/// formatting events with `tracing_subscriber::fmt`.

I believe that this may have been incorrectly resolved; I like @hawkw's proposed change.

Ahhh, I had this locally but did not save it. Thank you! :)

tracing-subscriber/src/fmt/fmt_layer.rs

hawkw · 2020-07-14T17:22:46Z

tracing-subscriber/src/fmt/format/json.rs

+                        // fall-back to thread id when name is absent and id's are not enabled
+                        if !self.display_thread_id {
+                            serializer.serialize_entry(
+                                "threadId",


I think that in this case, the key should maybe still be threadName --- if you enable the thread name option, you might reasonably expect all the output JSON to have a field named threadName, and might write parsing code that expects that...

What do you think?

Yep, Makes sense!

hawkw · 2020-07-14T17:28:27Z

tracing-subscriber/src/fmt/format/json.rs

+                        if !self.display_thread_id {
+                            serializer.serialize_entry(
+                                "threadId",
+                                &format!("{:?}", std::thread::current().id()),


Using format! here allocates, since format! constructs a new String. It would be nice if that was not necessary.

After looking at the serde API docs, though, it seems like it might be --- there's no way to serialize something's Debug implementation as a string value except by turning it into a String and borrowing it. That seems like a deficiency in serde (or, I'm missing something in the serde API).

Yeah, I did try searching a way for serde to directly use Debug impl but could not find how. So, had to use format!

hawkw · 2020-07-14T17:36:13Z

tracing-subscriber/src/fmt/format/mod.rs

+                        write!(writer, "{} ", FmtThreadId::new(std::thread::current().id()))?;
+                    }
+                }
+            }
+        }
+
+        if self.display_thread_id {
+            write!(writer, "{} ", FmtThreadId::new(std::thread::current().id()))?;


I don't think the FmtThreadId newtype is really necessary just to add a couple characters of padding...we could just write

Suggested change

write!(writer, "{} ", FmtThreadId::new(std::thread::current().id()))?;

}

}

}

}

if self.display_thread_id {

write!(writer, "{} ", FmtThreadId::new(std::thread::current().id()))?;

write!(writer, "{:>2?} ", std::thread::current().id())?;

}

}

}

}

if self.display_thread_id {

write!(writer, "{:>2?} ", std::thread::current().id())?;

instead, which is a bit simpler...

Yep, That makes sense! Just thought it would be better to have a single place which knows how to format threadId's 👍

tracing-subscriber/src/fmt/format/mod.rs

tracing-subscriber/src/fmt/mod.rs

hawkw · 2020-07-14T17:39:10Z

tracing-subscriber/src/fmt/format/mod.rs

+        if self.display_thread_name {
+            match std::thread::current().name() {
+                Some(name) => {
+                    write!(writer, "{} ", FmtThreadName::new(name))?;
+                }
+                None => {
+                    // fall-back to thread id when name is absent and id's are not enabled
+                    if !self.display_thread_id {
+                        write!(writer, "{} ", FmtThreadId::new(std::thread::current().id()))?;
+                    }
+                }
+            }
+        }
+
+        if self.display_thread_id {
+            write!(writer, "{} ", FmtThreadId::new(std::thread::current().id()))?;
+        }


same suggestions as the FullCtx suggestions above.

tracing-subscriber/src/fmt/format/json.rs

Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw

A couple additional suggestions, but overall, this looks great.

I'd still love to hear @davidbarsky's thoughts on the formatting.

tracing-subscriber/src/fmt/format/mod.rs

hawkw · 2020-07-16T17:45:57Z

examples/examples/thread-info.rs

+        .with_thread_ids(true)
+        .with_thread_names(true)


It could be good to add comments on these lines explaining what they're doing, since it's the main thing the example is intended to demonstrate.

Also, take it or leave it: might be nice if the example had CLI arguments to control thread IDs and thread names separately, so that users can demo all the possible combinations? But, adding argument-parsing would add a bunch of code not directly related to the things we're trying to show in this example, so I am not sure whether or not this is a good idea. What do you think?

tracing-subscriber/src/fmt/format/json.rs

davidbarsky

This does look very good, thank you! Just a few notes on documentation.

davidbarsky · 2020-07-16T18:07:18Z

examples/examples/thread-info.rs

+/// This is a example showing how thread info can be enabled
+/// to be attached with events


I believe that this may have been incorrectly resolved; I like @hawkw's proposed change.

davidbarsky · 2020-07-16T18:16:51Z

tracing-subscriber/src/fmt/format/mod.rs

+
+        static MAX_LEN: AtomicUsize = AtomicUsize::new(0);


Nit: can you add a comment explaining why this is necessary? If I'm following along correctly, this sets the maximum length a thread name can be, to ensure better formatted logs? If so, can you add a comment saying that?

Also, what is the scope of MAX_LEN? It doesn't get dropped once this fmt call ends, does it?

Also, what is the scope of MAX_LEN? It doesn't get dropped once this fmt call ends, does it?

Statics don't get dropped. The only difference between a static inside a function and a static outside of a function is visibility; the function-local static is only visible to that function.

re:

Nit: can you add a comment explaining why this is necessary?

@Pothulapati, IIRC, when I suggested we do this, I think I sent a version of this code with comments explaining what it was doing; if you like, please feel free to reuse that.

Signed-off-by: Tarun Pothulapati <[email protected]>

Pothulapati · 2020-07-16T19:40:25Z

tracing-subscriber/src/fmt/format/mod.rs

+    /// when formatting events
+    ///
+    /// [thread ID]: https://doc.rust-lang.org/stable/std/thread/struct.ThreadId.html
+    pub fn with_thread_id(self, display_thread_id: bool) -> Format<F, T> {


Should these fn names also be plural here? My reason for keeping them singular is that they deal with a single event being part of Format. WDYT?

IMO, I think it's better for them to be consistent --- it's annoying to call a method on one type, and then try to call it on a different type, and get an error because the name is slightly different. Also, the formatter will almost certainly be used to format more than one event, too.

But, I could definitely be convinced otherwise!

Signed-off-by: Tarun Pothulapati <[email protected]>

tracing-subscriber/src/fmt/format/mod.rs

Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw · 2020-07-17T17:09:18Z

Okay, this looks great to me! I'm going to go ahead and merge it.

Thanks again for working on this!

@mockersf

Changed - **fmt**: When the `chrono` dependency is enabled, the `SystemTime` timestamp now emits human-readable timestamps rather than using `SystemTime`'s fmt::Debug`implementation (`chrono` is still required for customized timestamp formatting) (#807) - **ansi**: Updated `ansi_term` dependency to 0.12 (#816) Added - **json**: `with_span_list` method to configure the JSON formatter to include a list of all spans in the current trace in formatting events (similarly to the text formatter) (#741) - **json**: `with_current_span` method to configure the JSON formatter to include a field for the _current_ span (the leaf of the trace) in formatted events (#741) - **fmt**: `with_thread_names` and `with_thread_ids` methods to configure `fmt::Subscriber`s and `fmt::Layer`s to include the thread name and/or thread ID of the current thread when formatting events (#818) Thanks to new contributors @mockersf, @keetonian, and @Pothulapati for contributing to this release!

@mockersf

### Changed - **fmt**: When the `chrono` dependency is enabled, the `SystemTime` timestamp now emits human-readable timestamps rather than using `SystemTime`'s fmt::Debug`implementation (`chrono` is still required for customized timestamp formatting) (#807) - **ansi**: Updated `ansi_term` dependency to 0.12 (#816) ### Added - **json**: `with_span_list` method to configure the JSON formatter to include a list of all spans in the current trace in formatting events (similarly to the text formatter) (#741) - **json**: `with_current_span` method to configure the JSON formatter to include a field for the _current_ span (the leaf of the trace) in formatted events (#741) - **fmt**: `with_thread_names` and `with_thread_ids` methods to configure `fmt::Subscriber`s and `fmt::Layer`s to include the thread name and/or thread ID of the current thread when formatting events (#818) Thanks to new contributors @mockersf, @keetonian, and @Pothulapati for contributing to this release!

Pothulapati requested review from hawkw and a team as code owners July 14, 2020 03:08

Pothulapati added 5 commits July 14, 2020 09:12

add a thread_info example dealing wide cases

dc5c790

Signed-off-by: Tarun Pothulapati <[email protected]>

update example file name

8ab8e8e

Signed-off-by: Tarun Pothulapati <[email protected]>

idiomatic tracing example

93565da

Signed-off-by: Tarun Pothulapati <[email protected]>

styling fix

a29aaaf

Signed-off-by: Tarun Pothulapati <[email protected]>

allow thread info to be written in json Format

5e036c1

Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw requested a review from davidbarsky July 14, 2020 17:13

hawkw reviewed Jul 14, 2020

View reviewed changes

Pothulapati added 4 commits July 15, 2020 08:08

incorporate feedback on comments and idiomatic rust

c0a6db4

Signed-off-by: Tarun Pothulapati <[email protected]>

use the same field name i.e threadName even during fall back to id

a4eb444

Signed-off-by: Tarun Pothulapati <[email protected]>

remove FmtThreadId type and do formatting directly

79e5a98

Signed-off-by: Tarun Pothulapati <[email protected]>

styling fix

a94b75e

Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw approved these changes Jul 16, 2020

View reviewed changes

davidbarsky reviewed Jul 16, 2020

View reviewed changes

Pothulapati added 5 commits July 17, 2020 00:39

update comments along with a example

033131f

Signed-off-by: Tarun Pothulapati <[email protected]>

use consistent comments for with_thread_* fns

9174313

Signed-off-by: Tarun Pothulapati <[email protected]>

add more comments to the thread-info example

934687a

Signed-off-by: Tarun Pothulapati <[email protected]>

get thread only once when display_thread_name is enabled

df7babf

Signed-off-by: Tarun Pothulapati <[email protected]>

add a comment regarding MAX_LEN

fdb9e13

Signed-off-by: Tarun Pothulapati <[email protected]>

Pothulapati commented Jul 16, 2020

View reviewed changes

Pothulapati added 2 commits July 17, 2020 01:30

add better docs for max_len

75b0f93

Signed-off-by: Tarun Pothulapati <[email protected]>

use consistent with_thread_* method names

db1a716

Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw reviewed Jul 17, 2020

View reviewed changes

tracing-subscriber/src/fmt/format/mod.rs Outdated Show resolved Hide resolved

use 0 padding for thread ids instead of space

2149d51

Signed-off-by: Tarun Pothulapati <[email protected]>

hawkw merged commit c109197 into tokio-rs:master Jul 17, 2020

hawkw mentioned this pull request Jul 17, 2020

subscriber: prepare to release 0.2.8 #823

Merged

		/// This is a example showing how thread info can be enabled
		/// to be attached with events

Allow thread name and id to be displayed in traces #818

Allow thread name and id to be displayed in traces #818

Uh oh!

Conversation

Pothulapati commented Jul 14, 2020

Motivation

Solution

Uh oh!

hawkw left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

hawkw left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

davidbarsky left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

hawkw commented Jul 17, 2020

Uh oh!

Uh oh!