Uploaded image for project: 'Python Driver'
  1. Python Driver
  2. PYTHON-5271

Investigate slow task warnings for pymongo_server_monitor_task and pymongo_kill_cursors_thread

XMLWordPrintableJSON

    • Type: Icon: Task Task
    • Resolution: Unresolved
    • Priority: Icon: Unknown Unknown
    • None
    • Affects Version/s: None
    • Component/s: None
    • None
    • Python Drivers
    • Hide

      1. What would you like to communicate to the user about this feature?
      2. Would you like the user to see examples of the syntax and/or executable code and its output?
      3. Which versions of the driver/connector does this apply to?

      Show
      1. What would you like to communicate to the user about this feature? 2. Would you like the user to see examples of the syntax and/or executable code and its output? 3. Which versions of the driver/connector does this apply to?
    • None
    • None
    • None
    • None
    • None
    • None

      When running the following script which creates an async client and waits for 32 pooled connections to be created I noticed multiple suspicious PYTHONASYNCIODEBUG warnings for pymongo_server_monitor_task and pymongo_kill_cursors_thread: debug-slow-tasks.py

      For example:

      $ PYTHONASYNCIODEBUG=1 python debug-slow-tasks.py
...
2025-04-04 15:50:54,456 DEBUG logger {"message": "Server selection started", "selector": "Primary()", "operation": "find", "topologyDescription": "<TopologyDescription id: 67f0624ee2150dc865f9bef6, topology_type: ReplicaSetNoPrimary, servers: [<ServerDescription ('cluster0-shard-00-00-gh2ak.mongodb.net', 27017) server_type: Unknown, rtt: None>, <ServerDescription ('cluster0-shard-00-01-gh2ak.mongodb.net', 27017) server_type: Unknown, rtt: None>, <ServerDescription ('cluster0-shard-00-02-gh2ak.mongodb.net', 27017) server_type: Unknown, rtt: None>]>", "clientId": {"$oid": "67f0624ee2150dc865f9bef6"}}
2025-04-04 15:50:54,456 DEBUG logger {"message": "Waiting for suitable server to become available", "selector": "Primary()", "operation": "find", "topologyDescription": "<TopologyDescription id: 67f0624ee2150dc865f9bef6, topology_type: ReplicaSetNoPrimary, servers: [<ServerDescription ('cluster0-shard-00-00-gh2ak.mongodb.net', 27017) server_type: Unknown, rtt: None>, <ServerDescription ('cluster0-shard-00-01-gh2ak.mongodb.net', 27017) server_type: Unknown, rtt: None>, <ServerDescription ('cluster0-shard-00-02-gh2ak.mongodb.net', 27017) server_type: Unknown, rtt: None>]>", "clientId": {"$oid": "67f0624ee2150dc865f9bef6"}, "remainingTimeMS": 29}
2025-04-04 15:50:54,456 WARNING base_events Executing <Task pending name='Task-1' coro=<main() running at /Users/shane/git/PYTHON-5212/debug-slow-tasks.py:26> wait_for=<Future pending cb=[Task.task_wakeup()] created at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/base_events.py:449> cb=[_run_until_complete_cb() at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/base_events.py:182] created at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/runners.py:100> took 0.446 seconds
2025-04-04 15:50:54,457 DEBUG base_events Get address info cluster0-shard-00-02-gh2ak.mongodb.net:27017, type=<SocketKind.SOCK_STREAM: 1>
2025-04-04 15:50:54,458 DEBUG base_events Get address info cluster0-shard-00-01-gh2ak.mongodb.net:27017, type=<SocketKind.SOCK_STREAM: 1>
2025-04-04 15:50:54,458 DEBUG base_events Get address info cluster0-shard-00-00-gh2ak.mongodb.net:27017, type=<SocketKind.SOCK_STREAM: 1>
2025-04-04 15:50:54,659 INFO base_events Getting address info cluster0-shard-00-01-gh2ak.mongodb.net:27017, type=<SocketKind.SOCK_STREAM: 1> took 200.687ms: [(<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('89.192.235.200', 27017))]
2025-04-04 15:50:54,683 INFO base_events Getting address info cluster0-shard-00-00-gh2ak.mongodb.net:27017, type=<SocketKind.SOCK_STREAM: 1> took 224.747ms: [(<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('89.192.235.196', 27017))]
2025-04-04 15:50:54,698 INFO base_events Getting address info cluster0-shard-00-02-gh2ak.mongodb.net:27017, type=<SocketKind.SOCK_STREAM: 1> took 240.492ms: [(<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('89.192.235.210', 27017))]
2025-04-04 15:50:54,787 WARNING base_events Executing <Task pending name='pymongo_server_monitor_task' coro=<AsyncPeriodicExecutor._run() running at /Users/shane/work/pycharm/PYTHON-5212/lib/python3.12/site-packages/pymongo/periodic_executor.py:98> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/futures.py:387, Task.task_wakeup()] created at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/base_events.py:449> created at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/tasks.py:420> took 0.127 seconds
2025-04-04 15:50:54,911 WARNING base_events Executing <Task pending name='pymongo_server_monitor_task' coro=<AsyncPeriodicExecutor._run() running at /Users/shane/work/pycharm/PYTHON-5212/lib/python3.12/site-packages/pymongo/periodic_executor.py:98> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/futures.py:387, Task.task_wakeup()] created at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/base_events.py:449> created at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/tasks.py:420> took 0.122 seconds
2025-04-04 15:50:55,038 WARNING base_events Executing <Task pending name='pymongo_server_monitor_task' coro=<AsyncPeriodicExecutor._run() running at /Users/shane/work/pycharm/PYTHON-5212/lib/python3.12/site-packages/pymongo/periodic_executor.py:98> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/futures.py:387, Task.task_wakeup()] created at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/base_events.py:449> created at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/tasks.py:420> took 0.127 seconds
...
2025-04-04 15:50:58,816 WARNING base_events Executing <Task pending name='pymongo_kill_cursors_thread' coro=<AsyncPeriodicExecutor._run() running at /Users/shane/work/pycharm/PYTHON-5212/lib/python3.12/site-packages/pymongo/periodic_executor.py:98> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/futures.py:387, Task.task_wakeup()] created at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/base_events.py:449> created at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/tasks.py:420> took 0.126 seconds
2025-04-04 15:50:59,307 DEBUG logger {"clientId": {"$oid": "67f0624ee2150dc865f9bef6"}, "message": "Connection ready", "serverHost": "cluster0-shard-00-02-gh2ak.mongodb.net", "serverPort": 27017, "driverConnectionId": 6, "durationMS": 0.36713241699908394}
2025-04-04 15:50:59,308 DEBUG logger {"clientId": {"$oid": "67f0624ee2150dc865f9bef6"}, "message": "Connection created", "serverHost": "cluster0-shard-00-02-gh2ak.mongodb.net", "serverPort": 27017, "driverConnectionId": 7}
2025-04-04 15:50:59,308 DEBUG base_events Get address info cluster0-shard-00-02-gh2ak.mongodb.net:27017, type=<SocketKind.SOCK_STREAM: 1>
2025-04-04 15:50:59,311 DEBUG base_events Getting address info cluster0-shard-00-02-gh2ak.mongodb.net:27017, type=<SocketKind.SOCK_STREAM: 1> took 2.586ms: [(<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('89.192.235.210', 27017))]
2025-04-04 15:50:59,436 WARNING base_events Executing <Task pending name='pymongo_kill_cursors_thread' coro=<AsyncPeriodicExecutor._run() running at /Users/shane/work/pycharm/PYTHON-5212/lib/python3.12/site-packages/pymongo/periodic_executor.py:98> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/futures.py:387, Task.task_wakeup()] created at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/base_events.py:449> created at /Library/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/tasks.py:420> took 0.124 seconds
...

      I believe the slow DNS resolution is normal asyncio getaaddrinfo behavior: https://github.com/python/cpython/blob/v3.12.4/Lib/asyncio/base_events.py#L870-L903

      But we should investigate the slow task warnings for pymongo_server_monitor_task and pymongo_kill_cursors_thread. I used Python 3.12.4 and connected to M0 free tier.

      Could be related to PYTHON-5212.

        1. debug-slow-tasks.py
          8 kB

            Assignee:
            Unassigned Unassigned
            Reporter:
            shane.harvey@mongodb.com Shane Harvey
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated: