Improvement: better concurrency support of interleaved futures #64

ten3roberts · 2023-07-04T15:49:00Z

See: #60

ten3roberts · 2023-07-25T10:37:03Z

src/lib.rs

+        let bufs = &mut *self.bufs.lock().unwrap();
+
+        // Store the most recently entered span
+        let _ = self.current_span.compare_exchange(


I am not entirely sure what the new value should be here.

Closing a span won't necessarily mean that the parent span is the new active one, as any span could be printed next on a different thread. I think for non-concurrent usage the parent of a span will most often be the currently active span, or it will be closed immediately afterwards (SeqCst).

What are you thoughts @davidbarsky?

Sorry, I had missed this mention. I'm not sure why the notification didn't go through as it normally does—I blame my impulse self for running an iOS beta.

I think for non-concurrent usage the parent of a span will most often be the currently active span, or it will be closed immediately afterwards (SeqCst).

That's correct, yes. Spans are open so long their child spans are open, which necessitates closing spans from child to parent.

ten3roberts · 2023-07-25T10:40:26Z

src/lib.rs

+}
+
+/// Runs `A` and `B` side by side and only yields items present in `B`
+struct DifferenceIter<L, R, F> {


This is used for only printing the relevant new spans.

Solving the Lowest Common Ancestor problem for the span tree

ten3roberts · 2023-08-02T09:10:29Z

Added a debugging for span modes, to see why a branch was printed, to be able to debug if it is a retrace, pre-open or open event

Retracing may print parent spans leading up to the current span. The indent was always formatted as the depth of the subscribers *current_span* which is not connect for spans in the middle of the tree. This fixes this issue

ten3roberts · 2023-08-09T15:48:57Z

When working on this I've managed to implement two other things using the same bit of code that was required for retracing two work.

The changes include:

Span retracing Improvement: better concurrency support of interleaved futures #60
Fix broken lines when only one of verbose_open/exit are enabled Using verbose_entry without verbose_exit leads and vice-versa leads to incorrect indent lines #66
Defer span opening until an event is generated inside (and skipping the span altogether if not)

Additionally, there is a small with_span_modes that prints the kind of the span event such as open/pre_open/close etc, which aids when debugging this crate and figuring out what a line. If you don't want it to remain I'll happily remove it

I've added examples and tests for each.

Here is how retracing looks:

Please do let me know what you think of this @oli-obk

davidbarsky · 2023-08-09T16:37:19Z

I really like the overall outcome of this in the screenshot! I'll need to dig into the specifics, though.

ten3roberts · 2023-08-09T20:34:32Z

Good to hear.

Interestingly the deferred/lazy spans didn't require any extensive rewrite, but rather didn't need more than simply doing nothing in on_new_span and having the existing span retracing print the span when encountered in an event.

Another thing that changed is having the Buffers locked and passed to write_span_info rather than locking inside of it (inside the retrace loop etc), to avoid interleaving multithreaded calls as that would muddle the current_span temporal context.

The default behavior is unchanged, and the retracing is opt-in. I am consider if it may be a good idea for discoverability and autoimprovement if retracing could be enabled by default, as having it off just makes events seem to appear in the wrong span. The retracing feature essential connects each "timeline" or branch of events with a line branching off the right vertical line, which can be seen in the screenshot above when interleaving spans of different depths and parents.

ten3roberts · 2023-08-12T14:41:35Z

Another thing that I've been wondering about is the standard or suggested style for writing tracing events.

It seems as if both you and hyperium use the lowercase terse/machine like format, while some others use a more sentence or subject-verb-object style f writing them

For example

trace!("ignore unknown frame type {:#x}", ty);

While others have used

trace!("Ignoring unknown frame type {:#x}", ty)

I've awkardly found both in this PR 😅, just wanting to keep consistency of this while I am at it.

Anyways, hoping you find this PR useful and in good quality. Let me know if you have any changes you request and I'll be happy to fix them up

davidbarsky · 2023-08-14T19:20:57Z

The default behavior is unchanged, and the retracing is opt-in. I am consider if it may be a good idea for discoverability and autoimprovement if retracing could be enabled by default, as having it off just makes events seem to appear in the wrong span. The retracing feature essential connects each "timeline" or branch of events with a line branching off the right vertical line, which can be seen in the screenshot above when interleaving spans of different depths and parents.

I think for those that need it, they really need. We can always call it out on the main documentation page.

It seems as if both you and hyperium use the lowercase terse/machine like format, while some others use a more sentence or subject-verb-object style f writing them

Yeah, my feeling is the value—pardon the pun—are the key/values on spans and events. The sentence is really more to provide a hint of context on what is happening, so a full sentence isn't as valuable.

I've awkardly found both in this PR 😅, just wanting to keep consistency of this while I am at it.

I think this occurred because the original example was lifted from slog, which preferred more of the sentence-style to logging.

ten3roberts · 2023-08-14T21:51:44Z

Alright thanks, that really explains it.

I'll fix those sentences up to be consistent, and I suppose the current doc comments on the builder are enough, as there doesn't seem to be any "overview" in lib.rs to consider.

May I re-add you as a reviewer when done with that? Is there anything more I should add or fix up?

ten3roberts · 2023-08-29T21:16:36Z

Hi @oli-obk do you think we could get this PR reviewed?

I'd love to hear what you think about this feature and its implementation

oli-obk · 2023-09-04T10:33:53Z

Sorry I'm still completely swamped with rustc reviews since I returned from vacation last week. The rendered version lgtm, but I won't get to reviewing the code in depth in the next week

output.log

ten3roberts · 2023-09-21T09:12:34Z

Sorry I'm still completely swamped with rustc reviews since I returned from vacation last week. The rendered version lgtm, but I won't get to reviewing the code in depth in the next week

No worries at all, this is the nature of asynchronous work, so don't stress yourself over it. Just wanted to know all was ok and that this wasn't forgotten 😊

Do you think a new crates.io version could be published with this, or are there more things that are in planning before that?

oli-obk · 2023-09-21T10:21:49Z

I'm looking at #68, too, so we could publish with both changes. If it looks like it needs more time, we'll publish a new version with just everything up to this PR

chore: reproduce example for davidbarsky#60

61069e5

ten3roberts mentioned this pull request Jul 6, 2023

Improvement: better concurrency support of interleaved futures #60

Closed

ten3roberts added 4 commits July 11, 2023 17:35

feat: detect concurrent span switching

8ccafe8

feat: initial span retracing

e67c3b0

fix: don't interleave mutex locking between write_span_infos

1b94d2d

wip(retracing): handle span closing

4642c04

ten3roberts commented Jul 25, 2023

View reviewed changes

ten3roberts added 2 commits July 31, 2023 13:48

chore: better defined exit strategies

0c2ee82

wip: lazy spans

07f51e6

ten3roberts mentioned this pull request Aug 2, 2023

Using verbose_entry without verbose_exit leads and vice-versa leads to incorrect indent lines #66

Open

ten3roberts added 8 commits August 2, 2023 17:54

feat: show the span/event kind

a245dc9

fix: verbose_exit should instead be verbose_entry davidbarsky#66

d551f42

chore: lazy_entry => deferred_spans

cc504ce

fix: print any span outside the context of current span

c80a6b8

Retracing may print parent spans leading up to the current span. The indent was always formatted as the depth of the subscribers *current_span* which is not connect for spans in the middle of the tree. This fixes this issue

chore: with_verbose_retrace => with_span_retrace

234285a

fix: deferred span event generation

2326701

chore: bless and minor cleanup

f523ad5

fix: ensure open and close lines are connected

2065d20

ten3roberts force-pushed the main branch from 005a45e to 2065d20 Compare August 9, 2023 15:37

ten3roberts added 2 commits August 9, 2023 17:39

chore: bless tests

5eec932

chore: add tests for davidbarsky#66

8e273a2

ten3roberts marked this pull request as ready for review August 9, 2023 15:50

fix: warnings and unused code

982bc1a

chore: distinguish raw println! for side effect timing

1c9197f

ten3roberts requested a review from davidbarsky August 15, 2023 11:49

oli-obk approved these changes Sep 21, 2023

View reviewed changes

output.log Outdated Show resolved Hide resolved

fix: remove accidental log file

ebfd6bf

oli-obk merged commit 8aa51bc into davidbarsky:main Sep 21, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improvement: better concurrency support of interleaved futures #64

Improvement: better concurrency support of interleaved futures #64

ten3roberts commented Jul 4, 2023

ten3roberts Jul 25, 2023

davidbarsky Aug 9, 2023 •

edited

Loading

ten3roberts Jul 25, 2023

ten3roberts commented Aug 2, 2023

ten3roberts commented Aug 9, 2023

davidbarsky commented Aug 9, 2023

ten3roberts commented Aug 9, 2023 •

edited

Loading

ten3roberts commented Aug 12, 2023 •

edited

Loading

davidbarsky commented Aug 14, 2023

ten3roberts commented Aug 14, 2023

ten3roberts commented Aug 29, 2023

oli-obk commented Sep 4, 2023

ten3roberts commented Sep 21, 2023

oli-obk commented Sep 21, 2023

Improvement: better concurrency support of interleaved futures #64

Improvement: better concurrency support of interleaved futures #64

Conversation

ten3roberts commented Jul 4, 2023

ten3roberts Jul 25, 2023

Choose a reason for hiding this comment

davidbarsky Aug 9, 2023 • edited Loading

Choose a reason for hiding this comment

ten3roberts Jul 25, 2023

Choose a reason for hiding this comment

ten3roberts commented Aug 2, 2023

ten3roberts commented Aug 9, 2023

davidbarsky commented Aug 9, 2023

ten3roberts commented Aug 9, 2023 • edited Loading

ten3roberts commented Aug 12, 2023 • edited Loading

davidbarsky commented Aug 14, 2023

ten3roberts commented Aug 14, 2023

ten3roberts commented Aug 29, 2023

oli-obk commented Sep 4, 2023

ten3roberts commented Sep 21, 2023

oli-obk commented Sep 21, 2023

davidbarsky Aug 9, 2023 •

edited

Loading

ten3roberts commented Aug 9, 2023 •

edited

Loading

ten3roberts commented Aug 12, 2023 •

edited

Loading