fix(console): fix calculation of busy time during poll

[hds]

The Console API specifies sending task busy duration only for completed
polls, it doesn't include the time spent in the current poll if the task
is active.

Tokio Console then calculates the busy time including the time spent in
the current poll - based on the last poll start and poll end times sent
by the Console Subscriber.

However, there was an error in the logic which determined when a task is
being polled for the purpose of calculating the busy time. The logic
only considered the first poll, when there was no recorded end poll time
at all.

This change adapts the logic so that it also considers the case where
the last recorded poll start is later than the last recorded poll end.
This indicates that the task is being polled.

PR Notes

You can see the current behavior by creating a task which blocks for a
long time (say std::thread::sleep for 5 seconds) in a loop, yielding
in between. Setting the console subscriber interval to 100ms makes
it easier to see.

In console we see the Total Time going up gradually, but the
Busy time stays the same for 5 seconds and then jump up. The
busy percentage jumps up and down as the busy time is incorrect.

Here's a GIF!

After the fix, both times move smoothly and the busy percentage
remains constant as it should.

Another GIF!

[hawkw]

thanks for the fix, good catch!

i left some style suggestions that might be a little clearer, although i'm kind of on the fence about it. let me know if you think my suggestion is easier to understand --- i'm happy to merge the current code, but i thought i'd mention it.

[hawkw]

fwiw, i think we could combine these two match arms, since Option<T> also implements PartialOrd when T: PartialOrd, and None compares less than Some...so we could write

Suggested change

	(Some(started), Some(ended)) if started > ended => busy_time_in_poll(started),
	(Some(started), _) => busy_time_in_poll(started),
	(Some(started), ended) if Some(started) > ended => busy_time_in_poll(started),

but on the other hand, I think having two match arms might be more understandable, so I'm not sure if this change would actually be better...

[hawkw]

actually, thinking about it, this would allow us to get rid of the busy_time_in_poll closure, so this whole function could be

    pub(crate) fn busy(&self, since: SystemTime) -> Duration {
        if self.started > self.ended {
            debug_assert!(
                self.started.is_some(),
                "if `started` is greater than `ended`, it should always be `Some`",
            );
            if let Some(started) = started {
                // the task is currently being polled
                let current_time_in_poll = since.duration_since(started).unwrap_or_default();
                return self.stats.busy + current_time_in_poll;
            }
        }

        self.stats.busy
    }

or something...do you think that's substantially clearer?

[hawkw]

the debug_assert! could also just be an expect:

    pub(crate) fn busy(&self, since: SystemTime) -> Duration {
        if self.started > self.ended {
            // the task is currently being polled
            let started = self.started
                .expect("if `started` is greater than `ended`, it should always be `Some`");
            let current_time_in_poll = since.duration_since(started).unwrap_or_default();
            return self.stats.busy + current_time_in_poll;
        }

        self.stats.busy
    }

[hds]

What about this variant on your second option? It's a little weird to safely unwrap the started time and then use the Option, but it seemed a bit cleaner and doesn't require the .expect or the debug_assert!.

    pub(crate) fn busy(&self, since: SystemTime) -> Duration {
        if let Some(started) = self.stats.last_poll_started {
            if self.stats.last_poll_started > self.stats.last_poll_ended {
                // in this case the task is being polled at the moment
                let current_time_in_poll = since.duration_since(started).unwrap_or_default();
                return self.stats.busy + current_time_in_poll;
            }
        }
        self.stats.busy
    }

[hawkw]

ah, yeah, that's nicer. good call.

[hawkw]

let's remove the commented out code? otherwise, looks great!