feat(console): add scheduled time per task #406

hds · 2023-04-03T20:45:51Z

Each task displays the sum of the time it has been idle and busy, as
well as the total. The idle time includes the time between when a task
is woken, and when the runtime actually polls that task.

There are cases where a task may be scheduled for a long time after
being woken, before it is polled. Especially if many tasks are woken at
the same time and don't yield back to the runtime quickly.

To add visibility to this, the total time that a task is scheduled
before being polled has been added. Additionally, a new task state
Scheduled has been added. This is displayed in both the tasks table
and in the task detail view.

In the console-api, the last_wake time has been moved from
tasks::Stats to common::PollStats, where the total scheduled_time
for the task has also been added.

This is the first of two parts. In the second part (#409), a histogram for
scheduled time will be added, the equivalent of the poll time histogram
which is already available on the task detail screen.

To show a pathological case which may lead to needing to see the
scheduled time, a new example has been added to the console-subscriber
examples.

Breaking wire format change

Just to be super clear, by moving last_wake from tasks::Stats to
common::PollStats, this is a breaking change to the wire format (at least
functionally). It's not stricly necessary, but leaving it as it is will make some
other things messier.

Of course, mess can be cleaned up later if we want a more polished upgrade
path than requiring that console-subscriber and tokio-console are
updated at the same time.

PR Notes

This PR does something adjacent to what is described in #50, but not quite.

The unicode character used for a SCHED task is ⏫.

The second PR (#409) will record a scheduled time histogram the same as it
recorded for poll times. These two changes should go in together (and certainly
shouldn't be released separately). However, this PR is already quite big, so they'll
be separated out.

The idea is that this PR isn't merged until the next one has also been reviewed
and approved. It would be good to get some feedback at this stage though.

The task list view with the new column for Sched time:

The Task block in the task detail view showing the new Scheduled time entry.

Each task displays the sum of the time it has been idle and busy, as well as the total. The idle time includes the time between when a task is woken, and when the runtime actually polls that task. There are cases where a task may be scheduled for a long time after being woken, before it is polled. Especially if many tasks are woken at the same time and don't yield back to the runtime quickly. To add visibility to this, the total time that a task is scheduled before being polled has been added. Additionally, a new task state `Scheduled` has been added. This is displayed in both the tasks table and in the task detail view. In the `console-api`, the `last_wake` time has been moved from `tasks::Stats` to `common::PollStats`, where the total `scheduled_time` for the task has also been added. This is the first of two parts. In the second part (#409), a histogram for scheduled time will be added, the equivalent of the poll time histogram which is already available on the task detail screen. To show a pathological case which may lead to needing to see the scheduled time, a new example has been added to the `console-subscriber` examples.

hawkw · 2023-04-18T17:28:25Z

Just to be super clear, by moving last_wake from tasks::Stats to
common::PollStats, this is a breaking change to the wire format (at least
functionally). It's not stricly necessary, but leaving it as it is will make some
other things messier.

I'm not totally sure if I understand the motivation for this change. Only tasks can be woken, so why do we now include a wake timestamp on non-task objects?

console-subscriber/src/stats.rs

console-subscriber/examples/long_scheduled.rs

tokio-console/src/state/tasks.rs

Co-authored-by: Eliza Weisman <eliza@buoyant.io>

console-subscriber/src/stats.rs

Co-authored-by: Eliza Weisman <eliza@buoyant.io>

hds · 2023-04-19T11:35:16Z

Just to be super clear, by moving last_wake from tasks::Stats to
common::PollStats, this is a breaking change to the wire format (at least
functionally). It's not stricly necessary, but leaving it as it is will make some
other things messier.

I'm not totally sure if I understand the motivation for this change. Only tasks can be woken, so why do we now include a wake timestamp on non-task objects?

I think that here I was basically commiting the sin of exposing implementation details in the API. I needed to move the last_wake time in the console-subscriber in order to calculate the scheduled time, and so I moved it in the API too.

You're right, it doesn't make sense. And I think that by the same reasoning, it also doesn't make sense to put the scheduled_time inside common::PollStats either is it isn't used by async ops. I'm going to move it into tasks::Stats.

PollStats is used by both tasks and async ops, but scheduled time and the last wake timestamp are specific to tasks. The new `scheduled_time` has been moved to `tasks::Stats` and `last_wake` has been moved back there.

hawkw

some tiny docs nits, but beyond that, looks good to me!

console-api/proto/common.proto

hawkw · 2023-04-19T16:14:14Z

console-api/proto/tasks.proto

+    // The total duration this task was scheduled prior to being polled, summed
+    // across all poll cycles. Note that this includes only polls that have
+    // started and is not reflecting any scheduled state where the task hasn't
+    // yet been polled. Subtracting both `busy_time` and `scheduled_time` from the


should this maybe note that busy_time is defined on PollStats?

console-api/proto/tasks.proto

Co-authored-by: Eliza Weisman <eliza@buoyant.io>

hawkw · 2023-04-19T16:30:14Z

Agh, sorry, we raced --- I also pushed some docs fixes because I was about to merge this.

hds · 2023-04-19T16:32:38Z

No worries, I just added what I think was a missing backtick too.

hds · 2023-04-19T17:05:25Z

@hawkw I think I disabled your auto merge with that last commit.

Display the scheduled time percentiles and sparklines for the histogram of scheduled times. The schduled time is the time between when a task is woken and when it is next polled. The scheduled time, which was already calculated, is now stored in a histogram and sent over the wire in together with the task details. This is used to draw percentiles and sparklines on the task details view, in the same way that is done for the poll times histogram. The refactoring done in #408 has been used to more easily display two sets of durations (percentiles and histogram where possible). ## PR Notes The PR depends on both #406, which adds initial support for recording the scheduled (wake-to-poll) time, and #408, which refactors the percentile and histogram widgets to make them easier to reuse. It shouldn't really be reviewed in depth until those two have been merged as it contains a lot of duplication and will need to be rebased. Here are some examples of the scheduled times durations on the task detail view: <img width="1037" alt="task detail view for the sender task in the long-scheduled example" src="https://user-images.githubusercontent.com/89589/232608774-d8ac48a7-3fe7-4742-a75b-e11bdb23abaa.png"> <img width="1043" alt="task detail view for the burn task in the app example" src="https://user-images.githubusercontent.com/89589/232608864-637f4f52-d4a6-468d-88fc-8fe1d53fdff9.png">

Each task displays the sum of the time it has been idle and busy, as well as the total. The idle time includes the time between when a task is woken, and when the runtime actually polls that task. There are cases where a task may be scheduled for a long time after being woken, before it is polled. Especially if many tasks are woken at the same time and don't yield back to the runtime quickly. To add visibility to this, the total time that a task is scheduled before being polled has been added. Additionally, a new task state `Scheduled` has been added. This is displayed in both the tasks table and in the task detail view. In the `console-api`, the total `scheduled_time` for the task has been added to the `TaskStats` message in `tasks.proto`. This is the first of two parts. In the second part (#409), a histogram for scheduled time will be added, the equivalent of the poll time histogram which is already available on the task detail screen. To show a pathological case which may lead to needing to see the scheduled time, a new example has been added to the `console-subscriber` ## PR Notes This PR does something adjacent to what is described in #50, but not quite. The unicode character used for a `SCHED` task is ⏫. The second PR (#409) will record a scheduled time histogram the same as it recorded for poll times. These two changes should go in together (and certainly shouldn't be released separately). However, this PR is already quite big, so they'll be separated out. The idea is that this PR isn't merged until the next one has also been reviewed and approved. It would be good to get some feedback at this stage though. The task list view with the new column for `Sched` time: <img width="1032" alt="a tasks table view for the long-scheduled example" src="https://user-images.githubusercontent.com/89589/232456977-2921f884-4673-420f-ba4f-3646627d44db.png"> The `Task` block in the task detail view showing the new `Scheduled` time entry. <img width="510" alt="The task block on the task detail view for the rx task in the long-scheduled example" src="https://user-images.githubusercontent.com/89589/232457332-e455e086-9468-42c9-8fda-7965d8d1e6f8.png">

Display the scheduled time percentiles and sparklines for the histogram of scheduled times. The schduled time is the time between when a task is woken and when it is next polled. The scheduled time, which was already calculated, is now stored in a histogram and sent over the wire in together with the task details. This is used to draw percentiles and sparklines on the task details view, in the same way that is done for the poll times histogram. The refactoring done in #408 has been used to more easily display two sets of durations (percentiles and histogram where possible). ## PR Notes The PR depends on both #406, which adds initial support for recording the scheduled (wake-to-poll) time, and #408, which refactors the percentile and histogram widgets to make them easier to reuse. It shouldn't really be reviewed in depth until those two have been merged as it contains a lot of duplication and will need to be rebased. Here are some examples of the scheduled times durations on the task detail view: <img width="1037" alt="task detail view for the sender task in the long-scheduled example" src="https://user-images.githubusercontent.com/89589/232608774-d8ac48a7-3fe7-4742-a75b-e11bdb23abaa.png"> <img width="1043" alt="task detail view for the burn task in the app example" src="https://user-images.githubusercontent.com/89589/232608864-637f4f52-d4a6-468d-88fc-8fe1d53fdff9.png">

# Changelog All notable changes to this project will be documented in this file. This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ## console-subscriber-v0.2.0 - (2023-09-29) [0b0c1af](https://github.com/tokio-rs/console/commit/0b0c1aff18c3260d3a45a78f6c0d6f4206af1cbb)...[0b0c1af](https://github.com/tokio-rs/console/commit/0b0c1aff18c3260d3a45a78f6c0d6f4206af1cbb) ### <a id = "console-subscriber-v0.2.0-breaking"></a>Breaking Changes - **Update Tonic and Prost dependencies ([#364](#364 ([f9b8e03](https://github.com/tokio-rs/console/commit/f9b8e03bd7ee1d0edb441c94a93a350d5b06ed3b))<br />This commit updates the public dependencies `prost` and `tonic` to semver-incompatible versions (v0.11.0 and v0.8.0, respectively). This is a breaking change for users who are integrating the `console-api` protos with their own `tonic` servers or clients. - **Update `tonic` to v0.10 and increase MSRV to 1.64 ([#464](#464 ([96e62c8](https://github.com/tokio-rs/console/commit/96e62c83ef959569bb062dc8fee98fa2b2461e8d))<br />This is a breaking change for users of `console-api` and `console-subscriber`, as it changes the public `tonic` dependency to a semver-incompatible version. This breaks compatibility with `tonic` 0.9.x and `prost` 0.11.x. ### Added - [**breaking**](#console-subscriber-v0.2.0-breaking) Update Tonic and Prost dependencies ([#364](#364)) ([f9b8e03](f9b8e03)) - Add support for Unix domain sockets ([#388](#388)) ([a944dbc](a944dbc), closes [#296](#296)) - Add scheduled time per task ([#406](#406)) ([f280df9](f280df9)) - Add task scheduled times histogram ([#409](#409)) ([d92a399](d92a399)) - Update `tonic` to 0.9 ([#420](#420)) ([48af1ee](48af1ee)) - Update MSRV to Rust 1.60.0 ([b18ee47](b18ee47)) - Expose server parts ([#451](#451)) ([e51ac5a](e51ac5a)) - Add cfg `console_without_tokio_unstable` ([#446](#446)) ([7ed6673](7ed6673)) - Add warning for tasks that never yield ([#439](#439)) ([d05fa9e](d05fa9e)) - [**breaking**](#console-subscriber-v0.2.0-breaking) Update `tonic` to v0.10 and increase MSRV to 1.64 ([#464](#464)) ([96e62c8](96e62c8)) ### Documented - Fix unclosed code block ([#463](#463)) ([362bdbe](362bdbe)) - Update MSRV version docs to 1.64 ([#467](#467)) ([94a5a51](94a5a51)) ### Fixed - Fix build on tokio 1.21.0 ([#374](#374)) ([c34ac2d](c34ac2d)) - Fix off-by-one indexing for `callsites` ([#391](#391)) ([43891ab](43891ab)) - Bump minimum Tokio version ([#397](#397)) ([bbb8f25](bbb8f25), fixes [#386](#386)) - Fix self wakes count ([#430](#430)) ([d308935](d308935)) - Remove clock skew warning in `start_poll` ([#434](#434)) ([4a88b28](4a88b28)) - Do not report excessive polling ([#378](#378)) ([#440](#440)) ([8b483bf](8b483bf), closes [#378](#378)) - Correct retain logic ([#447](#447)) ([36ffc51](36ffc51)) Signed-off-by: Eliza Weisman <eliza@buoyant.io>

# Changelog All notable changes to this project will be documented in this file. This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ## tokio-console-v0.1.10 - (2023-09-29) [7d009f8](https://github.com/tokio-rs/console/commit/7d009f87120ce0c89f5f9c5311f05b6756ca770f)...[7d009f8](https://github.com/tokio-rs/console/commit/7d009f87120ce0c89f5f9c5311f05b6756ca770f) ### <a id = "tokio-console-v0.1.10-breaking"></a>Breaking Changes - **Update Tonic and Prost dependencies ([#364](#364 ([f9b8e03](https://github.com/tokio-rs/console/commit/f9b8e03bd7ee1d0edb441c94a93a350d5b06ed3b))<br />This commit updates the public dependencies `prost` and `tonic` to semver-incompatible versions (v0.11.0 and v0.8.0, respectively). This is a breaking change for users who are integrating the `console-api` protos with their own `tonic` servers or clients. - **Update `tonic` to v0.10 and increase MSRV to 1.64 ([#464](#464 ([96e62c8](https://github.com/tokio-rs/console/commit/96e62c83ef959569bb062dc8fee98fa2b2461e8d))<br />This is a breaking change for users of `console-api` and `console-subscriber`, as it changes the public `tonic` dependency to a semver-incompatible version. This breaks compatibility with `tonic` 0.9.x and `prost` 0.11.x. ### Added - [**breaking**](#tokio-console-v0.1.10-breaking) Update Tonic and Prost dependencies ([#364](#364)) ([f9b8e03](f9b8e03)) - Only suggest opening issues for panics ([#365](#365)) ([da2a89c](da2a89c)) - Init error handling before subcmds ([#365](#365)) ([ec66eda](ec66eda)) - Filter out boring frames in backtraces ([#365](#365)) ([95a5e54](95a5e54)) - Include config options in autogenerated issues ([#365](#365)) ([3244a1f](3244a1f)) - Reduce decimal digits in UI ([#402](#402)) ([c13085e](c13085e)) - Use tokio task ids in task views ([#403](#403)) ([f5b06d2](f5b06d2)) - Add support for Unix domain sockets ([#388](#388)) ([a944dbc](a944dbc), closes [#296](#296)) - Add scheduled time per task ([#406](#406)) ([f280df9](f280df9)) - Add task scheduled times histogram ([#409](#409)) ([d92a399](d92a399)) - Update `tonic` to 0.9 ([#420](#420)) ([48af1ee](48af1ee)) - Update MSRV to Rust 1.60.0 ([b18ee47](b18ee47)) - Migrate to `ratatui` and update `crossterm` ([#425](#425)) ([b209dd6](b209dd6)) - Help view modal ([#432](#432)) ([359a4e7](359a4e7)) - Add way to inspect details of task from resource view ([#449](#449)) ([132ed4e](132ed4e), closes [#448](#448)) - Add warning for tasks that never yield ([#439](#439)) ([d05fa9e](d05fa9e)) - [**breaking**](#tokio-console-v0.1.10-breaking) Update `tonic` to v0.10 and increase MSRV to 1.64 ([#464](#464)) ([96e62c8](96e62c8)) ### Documented - Update screenshots in README ([#419](#419)) ([e9bcd67](e9bcd67)) - Revert "update screenshots in README ([#419](#419))" ([993a3d9](993a3d9)) - Update screenshots in README ([#421](#421)) ([8a27f96](8a27f96)) - Add column descriptions for all tables ([#431](#431)) ([e3cf82b](e3cf82b)) - Update MSRV version docs to 1.64 ([#467](#467)) ([94a5a51](94a5a51)) ### Fixed - Fix ascii-only flipped input ([#377](#377)) ([652ac34](652ac34)) - Declare `tokio-console` bin as `default-run` ([#379](#379)) ([9ce60ec](9ce60ec)) - Make `retain_for` default to 6s if not specfied ([#383](#383)) ([0a6012b](0a6012b), fixes [#382](#382)) - Enable view-switching keystrokes on details views ([#387](#387)) ([f417d7a](f417d7a)) - Fix `ViewOptions` default lang' ([#394](#394)) ([a1cf1b8](a1cf1b8), fixes [#393](#393)) - Remove `tracing-subscriber` 0.2 from dependencies ([#404](#404)) ([768534a](768534a)) - Fix calculation of busy time during poll ([#405](#405)) ([e2c536a](e2c536a)) - Remove histogram minimum count ([#424](#424)) ([02cf8a6](02cf8a6)) - Remove trailing space from task/resource location ([#443](#443)) ([90e5918](90e5918)) - Make long locations readable ([#441](#441)) ([9428d7f](9428d7f), closes [#411](#411)) - Fix task detail view Id to display remote tokio::task::Id ([#455](#455)) ([70c3952](70c3952)) Signed-off-by: Eliza Weisman <eliza@buoyant.io>

hds requested a review from a team as a code owner April 3, 2023 20:45

hds mentioned this pull request Apr 11, 2023

feat(console): add task scheduled times histogram #409

Merged

hds force-pushed the woken branch from a4c9cf3 to e3bc9ce Compare April 17, 2023 10:11

hds changed the title ~~feat(console): add woken time per task~~ feat(console): add scheduled time per task Apr 17, 2023

hds force-pushed the woken branch from e3bc9ce to bfaa90e Compare April 17, 2023 10:24

hawkw reviewed Apr 18, 2023

View reviewed changes

console-subscriber/src/stats.rs Outdated Show resolved Hide resolved

console-subscriber/examples/long_scheduled.rs Show resolved Hide resolved

tokio-console/src/state/tasks.rs Show resolved Hide resolved

Update console-subscriber/src/stats.rs

2d2e03a

Co-authored-by: Eliza Weisman <eliza@buoyant.io>

hawkw reviewed Apr 18, 2023

View reviewed changes

console-subscriber/src/stats.rs Outdated Show resolved Hide resolved

Update console-subscriber/src/stats.rs

5821a07

Co-authored-by: Eliza Weisman <eliza@buoyant.io>

Move task specific items out of PollStats

4dba62b

PollStats is used by both tasks and async ops, but scheduled time and the last wake timestamp are specific to tasks. The new `scheduled_time` has been moved to `tasks::Stats` and `last_wake` has been moved back there.

hawkw approved these changes Apr 19, 2023

View reviewed changes

hds and others added 5 commits April 19, 2023 18:19

Update console-api/proto/common.proto

2be24f1

Co-authored-by: Eliza Weisman <eliza@buoyant.io>

Update console-api/proto/tasks.proto

6fdb1c7

Co-authored-by: Eliza Weisman <eliza@buoyant.io>

document where busy_time is located in API

e0d7a8c

commit the compiled protobuf files (-;

396da0e

minor docs fixups

869c0ee

regen protos

5522930

hawkw enabled auto-merge (squash) April 19, 2023 16:31

add missing backtick

b1454ce

auto-merge was automatically disabled April 19, 2023 16:32
Head branch was pushed to by a user without write access

hawkw merged commit ac20daa into tokio-rs:main Apr 19, 2023
12 checks passed

hds mentioned this pull request Feb 14, 2024

subscriber: record a histogram of wake-to-poll times #50

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(console): add scheduled time per task #406

feat(console): add scheduled time per task #406

hds commented Apr 3, 2023 •

edited

hawkw commented Apr 18, 2023

hds commented Apr 19, 2023

hawkw left a comment

hawkw Apr 19, 2023

hawkw commented Apr 19, 2023

hds commented Apr 19, 2023

hds commented Apr 19, 2023

feat(console): add scheduled time per task #406

feat(console): add scheduled time per task #406

Conversation

hds commented Apr 3, 2023 • edited

Breaking wire format change

PR Notes

hawkw commented Apr 18, 2023

hds commented Apr 19, 2023

hawkw left a comment

Choose a reason for hiding this comment

hawkw Apr 19, 2023

Choose a reason for hiding this comment

hawkw commented Apr 19, 2023

hds commented Apr 19, 2023

hds commented Apr 19, 2023

hds commented Apr 3, 2023 •

edited