Different administrative profiling results under `uvloop`
- Dominant language
- Python
- Stars
- 1.7k
- Forks
- 778
- Avg merge
- 2h 50m
- Merged PRs (30d)
- 3
Description
The "Scheduler (Administrative)" or "Worker (Administrative)" profiles from a `performance_report` appear very different depending on whether you're using `uvloop` or not. With `uvloop`, it shows a lot more total time, and a lot less of it seems to be spent doing "actual work":
Using Tornado: [`report-tornado.html`](https://gistcdn.githack.com/gjoseph92/27a44c2f88d54ebed81fc00664a95976/raw/a3ef3b46fc3d60a97c8816d06d74910677f90f13/report-tornado.html)

Using uvloop: [`report-uvloop.html`](https://gistcdn.githack.com/gjoseph92/27a44c2f88d54ebed81fc00664a95976/raw/a3ef3b46fc3d60a97c8816d06d74910677f90f13/report-uvloop.html)

These are for the same no-op workload:
```python
import time
import dask
import distributed
if __name__ == "__main__":
event_loop = dask.config.get("distributed.admin.event-loop", None)
client = distributed.Client(n_workers=0)
with distributed.performance_report(filename=f"report-{event_loop}.html"):
# don't even need to do work or have workers to see the difference
time.sleep(5)
```
```shell
$ python profiling-basic.py
$ DASK_DISTRIBUTED__ADMIN__EVENT_LOOP=uvloop python profiling-basic.py
```
It seems the difference is caused by:
https://github.com/dask/distributed/blob/bf9ddab3fd67c33b0d87da4f18bcdc7e47262393/distributed/core.py#L186
Basically, having `"selectors.py"` in there causes us to ignore frames where an [asyncio.SelectorEventLoop](https://docs.python.org/3/library/asyncio-eventloop.html#asyncio.SelectorEventLoop) is `await`ing some IO event. I assume the intent here is to not show idle time spent waiting for IO, since that's not interesting from a profiling perspective.
However, uvloop bypasses the [selectors](https://docs.python.org/3/library/selectors.html) module entirely, since libuv handles the polling internally. So we don't drop those frames where the loop is waiting on IO, which makes it look like we're spending nearly all of our time doing nothing... because, well, we are.
(FWIW I suspect you'll see the same issue profiling on Windows even with the default asyncio event loop, since it'll use a [`ProactorEventLoop`](https://docs.python.org/3/library/asyncio-eventloop.html#asyncio.ProactorEventLoop) which doesn't use `selectors` at all. Really, with any event loop besides `SelectorEventLoop`.)
To figure out a solution for this, I removed `"selectors.py"` from the `omit` list and then looked at the most common frames/callstacks we saw while profiling:
Code:
```python
# NOTE: requires `"selectors.py"` to be removed from the `omit` list here:
# https://github.com/dask/distributed/blob/bf9ddab3fd67c33b0d87da4f18bcdc7e47262393/distributed/core.py#L186
import time
import collections
import dask
import distributed
def callstack_id(state):
id = state["identifier"]
children = state["children"]
assert len(children) <= 1, "Run with `distributed.worker.profile.cycle` = 0"
if not children:
return (id,)
return callstack_id(next(iter(children.values()))) + (id,)
# ^ NOTE: we put `id` last in order to print the callstack from newset frame -> oldest frame.
if __name__ == "__main__":
# Force every profile state logged to represent exactly 1 frame (don't merge frames every 10ms)
dask.config.set({"distributed.worker.profile.cycle": 0})
for config in [
"distributed.admin.event-loop",
"distributed.worker.profile.interval",
"distributed.worker.profile.cycle",
]:
print(f"{config}: {dask.config.get(config, None)}")
event_loop = dask.config.get("distributed.admin.event-loop", None)
client = distributed.Client(n_workers=0)
time.sleep(5)
states = client.cluster.scheduler.io_loop.profile.copy()
client.shutdown()
client.close()
callstacks = [callstack_id(state[1]) for state in states]
counts = collections.Counter(callstacks)
print("Most common callstacks:")
for (callstack, count) in counts.most_common():
print(count)
print(callstack)
print()
```
Most commonly-sampled callstack under default asyncio event loop:
```shell
(distributed-dev) Gabes-MacBook-Pro dev/distributed ‹uvloop-profile*› » python profiling-basic.py
distributed.admin.event-loop: tornado
distributed.worker.profile.interval: 10ms
distributed.worker.profile.cycle: 0
Most common callstacks:
419
select;/Users/gabe/miniconda3/envs/distributed-dev/lib/python3.9/selectors.py;554
_run_once;/Users/gabe/miniconda3/envs/distributed-dev/lib/python3.9/asyncio/base_events.py;1815
run_forever;/Users/gabe/miniconda3/envs/distributed-dev/lib/python3.9/asyncio/base_events.py;583
start;/Users/gabe/miniconda3/envs/distributed-dev/lib/python3.9/site-packages/tornado/platform/asyncio.py;191
run_loop;/Users/gabe/dev/distributed/distributed/utils.py;427
run;/Users/gabe/miniconda3/envs/distributed-dev/lib/python3.9/threading.py;881
_bootstrap_inner;/Users/gabe/miniconda3/envs/distributed-dev/lib/python3.9/threading.py;937
_bootstrap;/Users/gabe/miniconda3/envs/distributed-dev/lib/python3.9/threading.py;898
root
1
root
...
```
Most commonly-sampled callstack under uvloop:
```shell
(distributed-dev) Gabes-MacBook-Pro dev/distributed ‹uvloop-profile*› » DASK_DISTRIBUTED__ADMIN__EVENT_LOOP=uvloop python profiling-basic.py
distributed.admin.event-loop: uvloop
distributed.worker.profile.interval: 10ms
distributed.worker.profile.cycle: 0
Most common callstacks:
418
start;/Users/gabe/miniconda3/envs/distributed-dev/lib/python3.9/site-packages/tornado/platform/asyncio.py;191
run_loop;/Users/gabe/dev/distributed/distributed/utils.py;427
run;/Users/gabe/miniconda3/envs/distributed-dev/lib/python3.9/threading.py;881
_bootstrap_inner;/Users/gabe/miniconda3/envs/distributed-dev/lib/python3.9/threading.py;937
_bootstrap;/Users/gabe/miniconda3/envs/distributed-dev/lib/python3.9/threading.py;898
root
1
root
...
```
Looking at that, there isn't one obvious file we should just add to `omit` (`tornado/platform/asyncio.py` doesn't seem like a good idea).
We could try targeting our own `LoopRunner` as the thing to omit (since that should apply to any event loop). We'd just move `LoopRunner` out of `distributed/utils.py` and into its own file. However, that probably won't work for `asynchronous=True` schedulers, since the LoopRunner becomes a pass-through.
**Environment**:
- Dask version: bf9ddab3fd67c33b0d87da4f18bcdc7e47262393
- Python version: 3.9.2
- Operating System: macOS
- Install method (conda, pip, source): source
Contributor guide
Assessment
This issue has not been assessed yet.