Skip to content

internal: add some tracing to {Request, Notification}Dispatch #16394

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

Jump to bottom
Merged
merged 1 commit into from
Jan 30, 2024
Merged

internal: add some tracing to {Request, Notification}Dispatch #16394

merged 1 commit into from
Jan 30, 2024

Conversation

davidbarsky
Copy link
Contributor

Some of the tracing config would need to be changed in order to benefit more from this (especially .with_span_events(FmtSpan::CLOSE)), which provides span events like the following:

2024-01-18T02:41:06.675779Z  INFO request{method="textDocument/codeLens" request_id=RequestId(I32(17))}: rust_analyzer::dispatch: close time.busy=61.8µs time.idle=5.29µs

I dunno if y'all need LoggerFormatter in here, but if you don't, I'd be happy to yeet it out of rust-analyzer. In any case, this provided a pretty decent amount of information in the logs, and I can expand this as needed or we can land this PR and expand later.

@rustbot rustbot added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Jan 18, 2024
@davidbarsky davidbarsky marked this pull request as ready for review January 18, 2024 02:46
@Veykril
Copy link
Member

Veykril commented Jan 18, 2024

LoggerFormatter I think we only have because of salsa using log (we can replace this with tracing since we forked it), and https://github.com/matklad/always-assert. I'd love to get rid of the LoggerFormatter.

@Veykril
Copy link
Member

Veykril commented Jan 18, 2024 •
edited
Loading

On a related note, would be nice if we could replace our hprof thing with tracing / just use tracing for that kind of stuff. cc #3794

@matklad
Copy link
Member

matklad commented Jan 18, 2024

Yeah, I'd personally feel pretty strongly about not building two profiling infras. At this point, going all-in on tracing makes sense.

I used tracing with https://github.com/matklad/tracing-span-tree/ at NEAR, and the end-result was pretty similar to hprof.

If someone is looking into this seriously, I'd also recommend taking a closer look tracing-tracy:

https://github.com/nagisa/rust_tracy_client

@davidbarsky
Copy link
Contributor Author

I'll swap the hprof infrastructure over to tracing. I don't have a strong preference between tracing-tree and tracing-span-tree since both seem to do the job and they're pretty easy to swap out as needed.

As for the LoggerFormatter, I'll send PRs for both those crates to use tracing, forking as necessary.

@davidbarsky
Copy link
Contributor Author

Oh, rust-analyzer is already using tracing-tree. I'll see if I can make it more hprof-like.

@Veykril
Copy link
Member

Veykril commented Jan 19, 2024

Note our salsa fork is at https://github.com/rust-analyzer/salsa

This was referenced Jan 22, 2024
Merged
Merged
@davidbarsky
Copy link
Contributor Author

Quick update:

@Veykril
Copy link
Member

Veykril commented Jan 23, 2024

Let me know if this looks reasonable at a glance before I continue on and rewrite the profiling infrastructure in terms of tracing

👍

@davidbarsky
Copy link
Contributor Author

Few updates: I've swapped the hprof infrastructure over to a vendored version of tracing-span-tree, which is currently set to be equivalent to RAPROFILE=*>2. It works nicely I think, but I'll port the the existing parsing/filtering infrastructure over to tracing in a second.

Veykril
Veykril reviewed Jan 26, 2024
View reviewed changes
@Veykril
Copy link
Member

Veykril commented Jan 29, 2024 •
edited
Loading

@bors delegate+
r=me with CI green, thanks a lot for this I've wanted this changed for ages :)

@bors
Copy link
Contributor

bors commented Jan 29, 2024

✌️ @davidbarsky, you can now approve this pull request!

If @Veykril told you to "r=me" after making some further change, please make that change, then do @bors r=@Veykril

@Veykril Veykril added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Jan 29, 2024
@davidbarsky davidbarsky force-pushed the david/add-more-tracing-spans branch from c87fdd3 to 1f0209f Compare January 29, 2024 23:11
@davidbarsky
Copy link
Contributor Author

While CI is passing, I'd like to hold on merging to squash this history and ensure that unreported profiles are, well, actually reported as they were before this change.

@bors
Copy link
Contributor

bors commented Jan 30, 2024

☔ The latest upstream changes (presumably #16439) made this pull request unmergeable. Please resolve the merge conflicts.

@davidbarsky davidbarsky force-pushed the david/add-more-tracing-spans branch 2 times, most recently from a27c7c9 to 5972410 Compare January 30, 2024 17:09
@davidbarsky
internal: switch to tracing from log
e1ea7c8 
This commit also adds `tracing` to NotificationDispatcher/RequestDispatcher,
bumps `rust-analyzer-salsa` to 0.17.0-pre.6, `always-assert` to 0.2, and
removes the homegrown `hprof` implementation in favor of a vendored
tracing-span-tree.
@davidbarsky davidbarsky force-pushed the david/add-more-tracing-spans branch from 5972410 to e1ea7c8 Compare January 30, 2024 17:27
@davidbarsky
Copy link
Contributor Author

I've squashed the history, but opted to avoid reporting on unreported spans because my naive implementation of unreported profiles was really noisy. My feeling is that I'd rather land this PR and re-implement that later, need be. Anyways, here's a screenshot of the output:

Collapsed Screenshot A screenshot of VS Code on macOS. It contains a file explorer, a open Rust file (`hprof.rs`), and the `RA_PROFILE` output from `tracing` in the output pane.

@davidbarsky
Copy link
Contributor Author

@bors r=@Veykril

@bors
Copy link
Contributor

bors commented Jan 30, 2024

📌 Commit e1ea7c8 has been approved by Veykril

It is now in the queue for this repository.

@bors
Copy link
Contributor

bors commented Jan 30, 2024

⌛ Testing commit e1ea7c8 with merge d923d62...

@bors
Copy link
Contributor

bors commented Jan 30, 2024

☀️ Test successful - checks-actions
Approved by: Veykril
Pushing d923d62 to master...

@bors bors merged commit d923d62 into rust-lang:master Jan 30, 2024
This was referenced Jan 30, 2024
Closed
Merged
@davidbarsky davidbarsky deleted the david/add-more-tracing-spans branch January 30, 2024 22:15
@davidbarsky davidbarsky mentioned this pull request Jan 30, 2024
Merged
bors added a commit that referenced this pull request Jan 31, 2024
@bors
Auto merge of #16456 - davidbarsky:david/tracing-followups, r=Veykril
0396811 
internal: `tracing` improvements and followups

Hi folks! Building on #16394, I've got a few small tweaks:
- Removed the accidental `mod.rs` usage that I introduced.
- Removed a panic in `pat_analysis.rs`.
- Recorded the event kind in `handle_event` to better distinguish what _kind_ of event is being handled.
- Did a small refactor of `hprof` to have somewhat more linear control flow, and more importantly, write the recorded fields to the output.

The end result is the following:
<img width="1530" alt="A screenshot of Visual Studio Code on a Mac. `hprof.rs` is open, with " src="https://github.com/rust-lang/rust-analyzer/assets/2067774/bd11dde5-b2da-4774-bc38-bcb4772d1192">
This was referenced May 9, 2024
Closed
Closed
Closed
Closed
Merged
This was referenced May 28, 2024
Merged
Closed
Closed
Closed
Merged
@philips-software-forest-releaser philips-software-forest-releaser bot mentioned this pull request Jun 4, 2024
Merged
This was referenced Jun 11, 2024
Merged
Merged
@philips-software-forest-releaser philips-software-forest-releaser bot mentioned this pull request Jun 18, 2024
Merged
@philips-software-forest-releaser philips-software-forest-releaser bot mentioned this pull request Jun 25, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@Veykril Veykril Veykril left review comments

Assignees
No one assigned
Labels
S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author.
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
5 participants
@davidbarsky @Veykril @matklad @bors @rustbot