Reproduction of excessive tokio polling

[k0nserv]

⚠️ Don't merge, only intended for reproduction ⚠️

This change reproduces something weird that I ran across in tokio-console. For some reason the task

webrtc/webrtc/src/peer_connection/operation/mod.rs

Lines 54 to 56 in 5d05b88

	tokio::spawn(async move {
	Operations::start(l, ops_tx, ops_rx, close_rx).await;
	});

seems to be polled extremely excessively by the Tokio runtime, despite it's waker not being woken.

Example screenshot after running for only a few minutes

Generally, the task only gets woken when an operation is queued, as one would expect.

To reproduce

1. Build with RUSTFLAGS="--cfg tokio_unstable" cargo build --example reflect from the root
2. Follow the instructions in the reflect README.md, but add the --debug argument when starting the example.
3. Start tokio console with tokio-console

Environment

OS: macOS 12.5
Machine: Apple M1 Max Macbook Pro

[codecov]

Codecov Report

Merging #284 (4c5bbc3) into master (b43e05b) will decrease coverage by 0.06%.
The diff coverage is 0.00%.

@@            Coverage Diff             @@
##           master     #284      +/-   ##
==========================================
- Coverage   56.44%   56.38%   -0.07%     
==========================================
  Files         500      500              
  Lines       47316    47317       +1     
  Branches    12811    12804       -7     
==========================================
- Hits        26708    26679      -29     
- Misses       9992    10002      +10     
- Partials    10616    10636      +20     

Impacted Files	Coverage Δ
examples/examples/reflect/reflect.rs	0.00% <0.00%> (ø)
data/src/message/message_type.rs	75.00% <0.00%> (-5.00%)	⬇️
data/src/message/message_channel_open.rs	79.51% <0.00%> (-4.82%)	⬇️
rtcp/src/header.rs	63.93% <0.00%> (-3.28%)	⬇️
interceptor/src/stats/mod.rs	72.61% <0.00%> (-3.18%)	⬇️
rtp/src/header.rs	63.91% <0.00%> (-2.58%)	⬇️
media/src/track/constraint/non_numeric.rs	75.47% <0.00%> (-1.89%)	⬇️
rtcp/src/extended_report/dlrr.rs	55.88% <0.00%> (-1.48%)	⬇️
webrtc/src/peer_connection/peer_connection_test.rs	55.33% <0.00%> (-0.80%)	⬇️
sdp/src/description/session.rs	62.88% <0.00%> (-0.62%)	⬇️
... and 2 more

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

[k0nserv]

Added tracing of the futures involved in 4c5bbc3

As expected there's some polling at first, but then there's no more:

webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.573234 - Polled future Operations::start
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.573257 - Polled future Operation("_", "set_remote_description")
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.579477 - Polled future Operations::start
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.579533 - Polled future Operation("_", "set_remote_description")
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.583075 - Polled future Operations::start
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.583123 - Polled future Operation("_", "set_remote_description")
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.594881 - Polled future Operations::start
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.594937 - Polled future Operation("_", "set_remote_description")
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.598352 - Polled future Operations::start
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.598423 - Polled future Operation("_", "set_remote_description")
webrtc/src/peer_connection/mod.rs:936 [INFO] 17:28:15.608205 - peer connection state changed: connected
Peer Connection State has changed: connected
webrtc/src/peer_connection/operation/mod.rs:166 [INFO] 17:28:15.608504 - Done with operation Operation("_", "set_remote_description")
webrtc/src/peer_connection/operation/mod.rs:169 [INFO] 17:28:15.608569 - Operation loop spun
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.608584 - Polled future ops_rx.recv()
webrtc/src/peer_connection/operation/mod.rs:160 [INFO] 17:28:15.608602 - Started operation Operation("_", "set_local_description")
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.608615 - Polled future Operation("_", "set_local_description")
webrtc/src/peer_connection/operation/mod.rs:166 [INFO] 17:28:15.622875 - Done with operation Operation("_", "set_local_description")
webrtc/src/peer_connection/operation/mod.rs:169 [INFO] 17:28:15.622956 - Operation loop spun
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.622970 - Polled future ops_rx.recv()
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.622992 - Polled future close_rx.recv()

[k0nserv]

Closing as there's no intent to merge this