console icon indicating copy to clipboard operation
console copied to clipboard

Published 20 hours ago • verified publisher icon tokio-rs

Console reporting excessive polling, that isn't there

Open k0nserv opened this issue 2 years ago • 10 comments

What crate(s) in this repo are involved in the problem?

tokio-console, console-subscriber

What is the issue?

I've observed that tokio-console reports excessive polling, to the tune of around 1000 polls per second, for a simple spawned task that is not being woken.

This is the task spawning

https://github.com/webrtc-rs/webrtc/blob/5d05b88de6d3a3eff3cd4e9b57219a25e01d3edc/webrtc/src/peer_connection/operation/mod.rs#L54-L56

and the task itself

https://github.com/webrtc-rs/webrtc/blob/b43e05b574be52b65b648bc367467bb6f14c5e11/webrtc/src/peer_connection/operation/mod.rs#L114-L129

I've observed the task being polled over 1M times over a 24 minute period without having been woken.

How can the bug be reproduced?

I've documented the details and made a small reproducible example in https://github.com/webrtc-rs/webrtc/pull/284

In that PR I've added a printing wrapper around the futures in question as well as introduced more logging. On my machine the excessive polling that tokio-console reports does not line up with the amount of times the futures are actually polled.

Logs, error output, etc

No response

Versions

├── console-subscriber v0.1.7
│   ├── console-api v0.4.0

Possible solution

No response

Additional context

No response

Would you like to work on fixing this bug?

maybe

k0nserv avatar Sep 07 '22 08:09 k0nserv

Interesting, thanks for the report --- this definitely seems like a bug in the console.

Looking at your reproduction (https://github.com/webrtc-rs/webrtc/pull/284), I see you've included a screenshot of the task details view, where a very large number of polls is visible in the poll duration histogram. Is this same poll count shown in the task list view (the main view that's shown when launching the console)? It would be useful to determine whether this is caused by a bug in how the console tracks polls overall, or if it's specific to how we record the poll duration histogram. Thanks!

hawkw avatar Sep 07 '22 21:09 hawkw

The poll count is the same in the task view, I only took the screenshot in the details view to show that the task hasn't been woken. I'm gonna try and debug print the join handle to see if the ID matches that of the task reported in console.

k0nserv avatar Sep 07 '22 21:09 k0nserv

Hmm, this was quite interesting. Task as reported by

let handle = tokio::spawn(trace_future(
    Operations::start(l, ops_tx, ops_rx, close_rx),
    "Operations::start",
));
log::info!("Started operations task {:?}", handle);

is

webrtc/src/peer_connection/operation/mod.rs:95 [INFO] 22:41:23.828372 - Started operations task JoinHandle { id: Id(14) }

Console shows two ids:

  • The ID column in the task list/ID within the task pane inside the details view(this changed when I restarted console, was 5 then 38)
  • The task.id field reported in the details view(this matches the logged message and is 14)
image

k0nserv avatar Sep 07 '22 21:09 k0nserv

  • The ID column in the task list/ID within the task pane inside the details view(this changed when I restarted console, was 5 then 38)

  • The task.id field reported in the details view(this matches the logged message and is 14)

This is expected behavior: these are different task IDs assigned by different sources. The one reported in the task list/task pane in the details view is assigned by the console, while the one in the fields list and in the JoinHandle fmt::Debug output is assigned by Tokio.

The console doesn't currently know about the runtime-assigned task IDs generated by Tokio, as these were added quite recently. Although it would be nice to make it aware of them and have the console map its internal IDs to Tokio-assigned task IDs when available, this isn't a bug, as the console will always identify the task by its console-assigned ID.

hawkw avatar Sep 07 '22 22:09 hawkw

Thanks for the explanation. It sounds like that my theory that the data was being reported for the wrong task in console is disproven then.

I'm happy to take any pointers on how to continue investigating this further

k0nserv avatar Sep 07 '22 22:09 k0nserv

The logic for tracking polls is in the console_subscriber::ConsoleLayer type's on_enter and on_exit callbacks, here: https://github.com/tokio-rs/console/blob/da0e9724fa132595e2085cfb08ac7bfbf10542ba/console-subscriber/src/lib.rs#L767-L850 That's probably a good place to start adding some dbg!s or something, if you're interested in continuing to investigate this.

Alternatively, it could be really useful to see if it's possible to reproduce this behavior outside of webrtc, by writing a simple program that just spawns a single similarly-shaped task with a select! in it, and eliminating as many other variables as possible.

Either of those avenues are probably worth pursuing. Thanks for your interest in helping to debug this issue, it's very appreciated!

hawkw avatar Sep 07 '22 22:09 hawkw

Aight, here's what I did:

I applied the following patch to 3bf60bce

diff --git a/console-subscriber/src/aggregator/mod.rs b/console-subscriber/src/aggregator/mod.rs
index cf126b1..ede09a7 100644
--- a/console-subscriber/src/aggregator/mod.rs
+++ b/console-subscriber/src/aggregator/mod.rs
@@ -399,6 +399,13 @@ impl Aggregator {
                 fields,
                 location,
             } => {
+                println!(
+                    "Spawned task with ID: {}, location: {:?}, fields: {:?}",
+                    id.into_u64(),
+                    location,
+                    fields
+                );
+
                 self.tasks.insert(
                     id.clone(),
                     Task {
@@ -449,6 +456,8 @@ impl Aggregator {
                 task_id,
                 is_ready,
             } => {
+                println!("Polled future with task ID: {}", task_id.into_u64());
+
                 let poll_op = proto::resources::PollOp {
                     metadata: Some(metadata.into()),
                     resource_id: Some(resource_id.into()),

Then I ran the reproduction example from https://github.com/webrtc-rs/webrtc/pull/284 for about three minutes.

I wrote a small Python script to analyse the resulting logs and spit out the most spawned tasks by joining up the task_id from the poll event with those form the spawned event.

find-tasks.py 
from collections import Counter
import sys
import re

TASK_ID_REGEX = re.compile("Spawned.+ID:\s*(\d+).*")

# Polled future with task ID: 9008298766368777
def extract_id(line):
    if line.startswith("Polled future"):
        parts = line.split(":")
        return int(parts[1])
    
    return None


def extract_task_id(line):
    mat = TASK_ID_REGEX.match(line)

    if mat is not None:
        return int(mat.group(1))

    return None


def main():
    ids = Counter()
    known_tasks = {}

    for line in sys.stdin.readlines():
        task_id = extract_id(line)

        if task_id is not None:
            ids[task_id] += 1
            continue

        spawned_task_id = extract_task_id(line)

        if spawned_task_id is not None:
            known_tasks[spawned_task_id] = line


    most_common = ids.most_common(50)
    for (task_id, count, spawn_line) in ((i, c, known_tasks[i]) for (i, c) in most_common):
        print(f"{task_id} polled {count} times. Spawned as {spawn_line}")



if __name__ == '__main__':
    main()

Findings

Comparing this output to tokio-console shows that console is mixing up the attribution between polls and task somehow.

Here's the log from the above python script

Log 
139612413082206237 polled 141325 times. Spawned as Spawned task with ID: 139612413082206237, location: Some(Location { file: Some("examples/examples/reflect/reflect.rs"), module_path: None, line: Some(246), column: Some(21) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(63)) }]

47289445354831901 polled 54036 times. Spawned as Spawned task with ID: 47289445354831901, location: Some(Location { file: Some("webrtc/src/mux/mod.rs"), module_path: None, line: Some(53), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(51)) }]

72058143793741859 polled 40692 times. Spawned as Spawned task with ID: 72058143793741859, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/srtp/src/session/mod.rs"), module_path: None, line: Some(84), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(54)) }]

18014398509482143 polled 37795 times. Spawned as Spawned task with ID: 18014398509482143, location: Some(Location { file: Some("interceptor/src/twcc/receiver/mod.rs"), module_path: None, line: Some(174), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(20)) }]

9007749010554899 polled 28298 times. Spawned as Spawned task with ID: 9007749010554899, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/agent_internal.rs"), module_path: None, line: Some(1044), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(46)) }]

53 polled 20117 times. Spawned as Spawned task with ID: 53, location: Some(Location { file: Some("interceptor/src/stats/interceptor.rs"), module_path: None, line: Some(93), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(15)) }]

18014398509482107 polled 16120 times. Spawned as Spawned task with ID: 18014398509482107, location: Some(Location { file: Some("examples/examples/reflect/reflect.rs"), module_path: None, line: Some(180), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(21)) }]

11259548824240171 polled 13733 times. Spawned as Spawned task with ID: 11259548824240171, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/srtp/src/session/mod.rs"), module_path: None, line: Some(84), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(55)) }]

29274222211629071 polled 6406 times. Spawned as Spawned task with ID: 29274222211629071, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/agent_internal.rs"), module_path: None, line: Some(258), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(37)) }]

9007199254741154 polled 5971 times. Spawned as Spawned task with ID: 9007199254741154, location: Some(Location { file: Some("interceptor/src/nack/generator/mod.rs"), module_path: None, line: Some(191), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(17)) }]

13510798882111651 polled 5712 times. Spawned as Spawned task with ID: 13510798882111651, location: Some(Location { file: Some("interceptor/src/report/receiver/mod.rs"), module_path: None, line: Some(157), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(18)) }]

18014398509482144 polled 3120 times. Spawned as Spawned task with ID: 18014398509482144, location: Some(Location { file: Some("interceptor/src/report/sender/mod.rs"), module_path: None, line: Some(115), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(19)) }]

63 polled 391 times. Spawned as Spawned task with ID: 63, location: Some(Location { file: Some("webrtc/src/peer_connection/operation/mod.rs"), module_path: None, line: Some(91), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(16)) }]

11259823702147091 polled 164 times. Spawned as Spawned task with ID: 11259823702147091, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/agent_gather.rs"), module_path: None, line: Some(101), column: Some(21) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(39)) }]

267965002462265366 polled 142 times. Spawned as Spawned task with ID: 267965002462265366, location: Some(Location { file: Some("examples/examples/reflect/reflect.rs"), module_path: None, line: Some(211), column: Some(25) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(62)) }]

9007749010554904 polled 78 times. Spawned as Spawned task with ID: 9007749010554904, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/agent_internal.rs"), module_path: None, line: Some(1044), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(47)) }]

54044295040073741 polled 66 times. Spawned as Spawned task with ID: 54044295040073741, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/agent_internal.rs"), module_path: None, line: Some(1044), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(50)) }]

284 polled 63 times. Spawned as Spawned task with ID: 284, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/agent_internal.rs"), module_path: None, line: Some(1083), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(24)) }]

9007749010554914 polled 60 times. Spawned as Spawned task with ID: 9007749010554914, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/agent_internal.rs"), module_path: None, line: Some(1044), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(49)) }]

1649267441702 polled 52 times. Spawned as Spawned task with ID: 1649267441702, location: Some(Location { file: Some("dtls/src/conn/mod.rs"), module_path: None, line: Some(293), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(52)) }]

1374389534721 polled 49 times. Spawned as Spawned task with ID: 1374389534721, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/agent_gather.rs"), module_path: None, line: Some(603), column: Some(17) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(42)) }]

1649267441703 polled 46 times. Spawned as Spawned task with ID: 1649267441703, location: Some(Location { file: Some("dtls/src/conn/mod.rs"), module_path: None, line: Some(324), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(53)) }]

13511348637925465 polled 37 times. Spawned as Spawned task with ID: 13511348637925465, location: Some(Location { file: Some("webrtc/src/peer_connection/peer_connection_internal.rs"), module_path: None, line: Some(1248), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(60)) }]

63050394783187176 polled 24 times. Spawned as Spawned task with ID: 63050394783187176, location: Some(Location { file: Some("mdns/src/conn/mod.rs"), module_path: None, line: Some(126), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(22)) }]

754353487340372055 polled 18 times. Spawned as Spawned task with ID: 754353487340372055, location: Some(Location { file: Some("interceptor/src/nack/responder/mod.rs"), module_path: None, line: Some(109), column: Some(17) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(64)) }]

13511348637925441 polled 12 times. Spawned as Spawned task with ID: 13511348637925441, location: Some(Location { file: Some("webrtc/src/peer_connection/peer_connection_internal.rs"), module_path: None, line: Some(1248), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(58)) }]

283 polled 9 times. Spawned as Spawned task with ID: 283, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/agent_internal.rs"), module_path: None, line: Some(1061), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(23)) }]

2251799813685538 polled 6 times. Spawned as Spawned task with ID: 2251799813685538, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(302), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(25)) }]

2251799813685543 polled 6 times. Spawned as Spawned task with ID: 2251799813685543, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(302), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(26)) }]

6755399441056042 polled 6 times. Spawned as Spawned task with ID: 6755399441056042, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(302), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(27)) }]

6755399441056047 polled 6 times. Spawned as Spawned task with ID: 6755399441056047, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(302), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(28)) }]

2251799813685558 polled 6 times. Spawned as Spawned task with ID: 2251799813685558, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(302), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(29)) }]

2251799813685563 polled 6 times. Spawned as Spawned task with ID: 2251799813685563, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(302), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(30)) }]

2251799813685568 polled 6 times. Spawned as Spawned task with ID: 2251799813685568, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(302), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(31)) }]

2251799813685573 polled 6 times. Spawned as Spawned task with ID: 2251799813685573, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(302), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(32)) }]

6755399441056072 polled 6 times. Spawned as Spawned task with ID: 6755399441056072, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(302), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(33)) }]

6755399441056077 polled 6 times. Spawned as Spawned task with ID: 6755399441056077, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(302), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(34)) }]

40532946402148365 polled 6 times. Spawned as Spawned task with ID: 40532946402148365, location: Some(Location { file: Some("webrtc/src/peer_connection/peer_connection_internal.rs"), module_path: None, line: Some(239), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(56)) }]

47288345843204107 polled 6 times. Spawned as Spawned task with ID: 47288345843204107, location: Some(Location { file: Some("webrtc/src/peer_connection/peer_connection_internal.rs"), module_path: None, line: Some(297), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(57)) }]

27021597764223331 polled 5 times. Spawned as Spawned task with ID: 27021597764223331, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(470), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(38)) }]

2251799813685588 polled 3 times. Spawned as Spawned task with ID: 2251799813685588, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(302), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(35)) }]

2251799813685593 polled 3 times. Spawned as Spawned task with ID: 2251799813685593, location: Some(Location { file: Some("/Users/hugotunius/Code/Work/webrtc/webrtc/ice/src/agent/mod.rs"), module_path: None, line: Some(302), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(36)) }]

13511348637925462 polled 3 times. Spawned as Spawned task with ID: 13511348637925462, location: Some(Location { file: Some("webrtc/src/rtp_transceiver/rtp_receiver/mod.rs"), module_path: None, line: Some(785), column: Some(17) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(59)) }]

119346214759039007 polled 3 times. Spawned as Spawned task with ID: 119346214759039007, location: Some(Location { file: Some("webrtc/src/peer_connection/mod.rs"), module_path: None, line: Some(599), column: Some(13) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(61)) }]

and a correspodning screenshot of tokio-console

Screenshot 2022-09-08 at 12 02 49

As you can see here the task that's actually spawned for webrtc/src/peer_connection/operation/mod.rs:91 has the tokio task id 16 and from the log there were 391 polls in the task that matches said id:

63 polled 391 times. Spawned as Spawned task with ID: 63, location: Some(Location { file: Some("webrtc/src/peer_connection/operation/mod.rs"), module_path: None, line: Some(91), column: Some(9) }), fields: [Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("kind")), value: Some(DebugVal("task")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.name")), value: Some(DebugVal("")) }, Field { metadata_id: Some(MetaId { id: 4397460048 }), name: Some(StrName("task.id")), value: Some(U64Val(16)) }].

tokio-console seems to be reporting the poll count for examples/examples/reflect/reflect.rs:246:21(id 63) for the task webrtc/src/peer_connection/operation/mod.rs:91 in the UI.

When looking at what's reported on the tokio-console side it seems the confusion happens in the subscriber sometimes between the logs I added and sending the data to the console i.e. the issue is in console-subscriber somehwere.

k0nserv avatar Sep 08 '22 11:09 k0nserv

I've got it!

The "problem", not really sure if it's a problem, is that the operations inside webrtc/src/peer_connection/operation/mod.rs:91 themselves spawn tasks. When this happens the polls of those spawned tasks are attributed to the webrtc/src/peer_connection/operation/mod.rs:91 task, not the task that's actually being polled.

k0nserv avatar Sep 08 '22 12:09 k0nserv

Hmm, that definitely seems wrong --- we shouldn't be counting polls of a child task as polls of the task that spawned it.

hawkw avatar Sep 08 '22 23:09 hawkw

Here's how I figured this out:

Using the following diff:

diff.patch 
diff --git a/console-subscriber/src/aggregator/mod.rs b/console-subscriber/src/aggregator/mod.rs
index cf126b1..ede09a7 100644
--- a/console-subscriber/src/aggregator/mod.rs
+++ b/console-subscriber/src/aggregator/mod.rs
@@ -399,6 +399,13 @@ impl Aggregator {
                 fields,
                 location,
             } => {
+                println!(
+                    "Spawned task with ID: {}, location: {:?}, fields: {:?}",
+                    id.into_u64(),
+                    location,
+                    fields
+                );
+
                 self.tasks.insert(
                     id.clone(),
                     Task {
@@ -449,6 +456,8 @@ impl Aggregator {
                 task_id,
                 is_ready,
             } => {
+                println!("Polled future with task ID: {}", task_id.into_u64());
+
                 let poll_op = proto::resources::PollOp {
                     metadata: Some(metadata.into()),
                     resource_id: Some(resource_id.into()),
diff --git a/console-subscriber/src/lib.rs b/console-subscriber/src/lib.rs
index 748b045..303b8ab 100644
--- a/console-subscriber/src/lib.rs
+++ b/console-subscriber/src/lib.rs
@@ -573,6 +573,11 @@ where
                 };
                 (event, stats)
             }) {
+                println!(
+                    "Attached {:?} to span with id {}, reason: spawn",
+                    Arc::as_ptr(&stats),
+                    id.into_u64()
+                );
                 ctx.span(id).expect("if `on_new_span` was called, the span must exist; this is a `tracing` bug!").extensions_mut().insert(stats);
             }
             return;
@@ -611,6 +616,11 @@ where
                     };
                     (event, stats)
                 }) {
+                    println!(
+                        "Attached {:?} to span with id {}, reason: resource",
+                        Arc::as_ptr(&stats),
+                        id.into_u64()
+                    );
                     ctx.span(id).expect("if `on_new_span` was called, the span must exist; this is a `tracing` bug!").extensions_mut().insert(stats);
                 }
             }
@@ -649,6 +659,11 @@ where
                             (event, stats)
                         })
                     {
+                        println!(
+                            "Attached {:?} to span with id {}, reason: async op",
+                            Arc::as_ptr(&stats),
+                            id.into_u64()
+                        );
                         ctx.span(id).expect("if `on_new_span` was called, the span must exist; this is a `tracing` bug!").extensions_mut().insert(stats);
                     }
                 }
@@ -773,7 +788,13 @@ where
             // if the span we are entering is a task or async op, record the
             // poll stats.
             if let Some(stats) = exts.get::<Arc<stats::TaskStats>>() {
+                let is_parent = at.is_some();
                 let at = at.unwrap_or_else(Instant::now);
+                println!(
+                    "Entered with stats: {:?}, is_parent: {}",
+                    Arc::as_ptr(&stats),
+                    is_parent
+                );
                 stats.start_poll(at);
                 Some(at)
             } else if let Some(stats) = exts.get::<Arc<stats::AsyncOpStats>>() {
diff --git a/tokio-console/src/state/tasks.rs b/tokio-console/src/state/tasks.rs
index 8be120d..cc7305e 100644
--- a/tokio-console/src/state/tasks.rs
+++ b/tokio-console/src/state/tasks.rs
@@ -186,6 +186,7 @@ impl TasksState {
                     warnings: Vec::new(),
                     location,
                 };
+                tracing::debug!(?task, "Created new task");
                 task.lint(linters);
                 Some((id, task))
             });

I again ran the reproduction example for several minutes. Then I figured out the address of the stats::TaskStats that was created when webrtc/src/peer_connection/operation/mod.rs:91 was spawned.

Grepping for that address resulted in by far the most frequent entries and almost all report is_parent: true.

$ cat run_9.txt| grep 0x13b60e730 | wc -l
  154924
$ cat run_9.txt| grep 0x13b60e730 | grep "is_parent: true" | wc -l
  154915
$ cat run_9.txt| grep 0x13b60e730 | grep "is_parent: false" | wc -l
  8

Honestly, I'm a bit confused about how this all fits together but it seems like things are getting attributed incorrectly at least

k0nserv avatar Sep 09 '22 14:09 k0nserv

Here is a simpler program to reproduce the issue. We have two loops "outer loop 5s" and "inner loop 5ms", which just print to stdout and sleep.

use std::time::Duration;

use tokio::time::sleep;

#[tokio::main]
async fn main() {
    console_subscriber::init();
    tokio::task::Builder::new()
        .name("outer loop 5s")
        .spawn(async move {
            tokio::task::Builder::new()
                .name("inner loop 5ms")
                .spawn(async move {
                    // inner loop 5ms
                    loop {
                        sleep(Duration::from_millis(5)).await;
                        print!(".");
                    }
                })
                .unwrap();

            // outer loop 5s
            loop {
                sleep(Duration::from_secs(5)).await;
                println!(".");
            }
        })
        .unwrap();
    sleep(Duration::from_secs(120)).await;
}

Screenshot from 2023-05-23 16-10-56 Screenshot from 2023-05-23 16-11-17

Notice how the outer loop task is reported as being polled every 5ms instead of every 5s. Also, it's reported to spend a lot of time in the scheduled state. This happens only for nested tasks: spawning the two tasks as child of the main task will report the correct results.

MatteoNardi avatar May 24 '23 08:05 MatteoNardi

I've been doing some debugging. I think the issue is indeed inside on_enter and on_exit.

if let Some(now) = update(&span, None) {
    if let Some(parent) = span.parent() {
        update(&parent, Some(now));
    }
   ...

The second call to update will increase the polling stats of the parent task, even if it's not the one being polled. Removing those lines fixes both the wrong poll stats issue and the wrong scheduled time issue.

The real question is if I'm breaking something by removing it :) @hawkw, do you remember the reason of that code? It was introduced in #238, I haven't checked yet if the bug was already present before. I don't fully grasp yet the console-subscriber design, so any hint would be appreciated.

I'd be happy to open a PR once I'm sure I'm not breaking everything.

MatteoNardi avatar Jun 01 '23 09:06 MatteoNardi

Thanks for looking into this issue @MatteoNardi!

I originally suspected that updating the parent span was to do with a task -> resouce hierarchy. But I can't find anything that supports this in the code. We'll wait for Eliza's answer to confirm, but your proposal to remove the parent update makes sense from what I can see.

hds avatar Jun 02 '23 09:06 hds