httpcore icon indicating copy to clipboard operation
httpcore copied to clipboard
verified publisher icon encode

Add support for connection pool monitoring

Open karpetrosyan opened this issue 2 years ago • 8 comments

closes #508

karpetrosyan avatar May 29 '23 11:05 karpetrosyan

These trace events were added.

  • connection_pool.reuse_connection when our request received the idle connection from the pool
  • connection_pool.set_connection when our request received the connection which was just created
  • connection_pool.unset_connection when the connection pool steals our request's connection

We can use an extension's trace to set a callback for these events because they are traced along with the request argument.

Additionally, some events do not support callbacks.

These are events that are unrelated to requests.

  • connection_pool.remove_idle_connection pool removes the idle connection
  • connection_pool.create_connection pool creates the connection
  • connection_pool.remove_expired_connection pool removes the expired connection

karpetrosyan avatar May 30 '23 08:05 karpetrosyan

Could you demo some log output as part of the description here?

lovelydinosaur avatar May 30 '23 12:05 lovelydinosaur

script

import asyncio
import logging

import httpcore

logging.basicConfig(
    format="%(levelname)s [%(asctime)s] %(name)s - %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
)
logging.getLogger("httpcore.connection_pool").setLevel(logging.DEBUG)

async def main():
    async with httpcore.AsyncConnectionPool() as pool:
        tasks = []
        for i in range(5):
            tasks.append(pool.request('GET', 'http://encode.io'))
        await asyncio.gather(*tasks)

asyncio.run(main())

OUTPUT

DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - create_connection.started origin='http://encode.io:80'
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - create_connection.complete return_value=<AsyncHTTPConnection [CONNECTING]>
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - set_connection.started connection=<AsyncHTTPConnection [CONNECTING]>
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - set_connection.complete
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - Waiting for a connection.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - The ConnectionPool currently has 1 request(s) awaiting connections.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - Connection received.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - The ConnectionPool currently has 0 request(s) awaiting connections.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - create_connection.started origin='http://encode.io:80'
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - create_connection.complete return_value=<AsyncHTTPConnection [CONNECTING]>
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - set_connection.started connection=<AsyncHTTPConnection [CONNECTING]>
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - set_connection.complete
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - Waiting for a connection.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - The ConnectionPool currently has 1 request(s) awaiting connections.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - Connection received.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - The ConnectionPool currently has 0 request(s) awaiting connections.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - create_connection.started origin='http://encode.io:80'
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - create_connection.complete return_value=<AsyncHTTPConnection [CONNECTING]>
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - set_connection.started connection=<AsyncHTTPConnection [CONNECTING]>
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - set_connection.complete
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - Waiting for a connection.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - The ConnectionPool currently has 1 request(s) awaiting connections.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - Connection received.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - The ConnectionPool currently has 0 request(s) awaiting connections.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - create_connection.started origin='http://encode.io:80'
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - create_connection.complete return_value=<AsyncHTTPConnection [CONNECTING]>
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - set_connection.started connection=<AsyncHTTPConnection [CONNECTING]>
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - set_connection.complete
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - Waiting for a connection.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - The ConnectionPool currently has 1 request(s) awaiting connections.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - Connection received.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - The ConnectionPool currently has 0 request(s) awaiting connections.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - create_connection.started origin='http://encode.io:80'
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - create_connection.complete return_value=<AsyncHTTPConnection [CONNECTING]>
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - set_connection.started connection=<AsyncHTTPConnection [CONNECTING]>
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - set_connection.complete
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - Waiting for a connection.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - The ConnectionPool currently has 1 request(s) awaiting connections.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - Connection received.
DEBUG [2023-05-30 16:00:10] httpcore.connection_pool - The ConnectionPool currently has 0 request(s) awaiting connections.
DEBUG [2023-05-30 16:00:11] httpcore.connection_pool - Connection: <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 1]> was returned into the pool
DEBUG [2023-05-30 16:00:11] httpcore.connection_pool - Connection: <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 1]> was returned into the pool
DEBUG [2023-05-30 16:00:11] httpcore.connection_pool - Connection: <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 1]> was returned into the pool
DEBUG [2023-05-30 16:00:11] httpcore.connection_pool - Connection: <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 1]> was returned into the pool
DEBUG [2023-05-30 16:00:11] httpcore.connection_pool - Connection: <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 1]> was returned into the pool

karpetrosyan avatar May 30 '23 13:05 karpetrosyan

With the trace extention enabled

import asyncio
import httpcore
async def log(a, b):
    if a.startswith('connection_pool'):
        print(a, b)
async def main():
    async with httpcore.AsyncConnectionPool(max_connections=1) as pool:
        tasks = []
        for i in range(5):
            tasks.append(pool.request('GET', 'http://encode.io', extensions={'trace': log}))
        await asyncio.gather(*tasks)
asyncio.run(main())

OUTPUT

connection_pool.set_connection.started {'connection': <AsyncHTTPConnection [CONNECTING]>}
connection_pool.set_connection.complete {'return_value': None}
connection_pool.reuse_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 1]>}
connection_pool.reuse_connection.complete {'return_value': None}
connection_pool.reuse_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 1]>}
connection_pool.reuse_connection.complete {'return_value': None}
connection_pool.reuse_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 1]>}
connection_pool.reuse_connection.complete {'return_value': None}
connection_pool.reuse_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 1]>}
connection_pool.reuse_connection.complete {'return_value': None}
connection_pool.unset_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, ACTIVE, Request Count: 2]>}
connection_pool.unset_connection.complete {'return_value': None}
connection_pool.unset_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, ACTIVE, Request Count: 2]>}
connection_pool.unset_connection.complete {'return_value': None}
connection_pool.unset_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, ACTIVE, Request Count: 2]>}
connection_pool.unset_connection.complete {'return_value': None}
connection_pool.reuse_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 2]>}
connection_pool.reuse_connection.complete {'return_value': None}
connection_pool.reuse_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 2]>}
connection_pool.reuse_connection.complete {'return_value': None}
connection_pool.reuse_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 2]>}
connection_pool.reuse_connection.complete {'return_value': None}
connection_pool.unset_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, ACTIVE, Request Count: 3]>}
connection_pool.unset_connection.complete {'return_value': None}
connection_pool.unset_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, ACTIVE, Request Count: 3]>}
connection_pool.unset_connection.complete {'return_value': None}
connection_pool.reuse_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 3]>}
connection_pool.reuse_connection.complete {'return_value': None}
connection_pool.reuse_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 3]>}
connection_pool.reuse_connection.complete {'return_value': None}
connection_pool.unset_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, ACTIVE, Request Count: 4]>}
connection_pool.unset_connection.complete {'return_value': None}
connection_pool.reuse_connection.started {'connection': <AsyncHTTPConnection ['http://encode.io:80', HTTP/1.1, IDLE, Request Count: 4]>}
connection_pool.reuse_connection.complete {'return_value': None}

karpetrosyan avatar May 30 '23 13:05 karpetrosyan

Wonderful - thanks for working through this.

We should avoid adding extra state as part of this change, so I'd suggest we avoid the .self._requests_awaiting_connection.

It seems to me that the bits we'd like to trace don't fit in as well with the .started/.complete pairs that we're using elsewhere. Perhaps we want to trace these just as single events instead?

Maybe we'd implement that with a def trace() function for single event cases, instead of the Trace class?

The bits we want to monitor are state changes to ._pool and ._requests.

Suppose we started just with the following trace events/debug lines...

DEBUG [2023-06-09 10:55:09] httpcore.connection_pool - add_connection <HTTPConnection [...]>
DEBUG [2023-06-09 10:55:09] httpcore.connection_pool - add_request <Request [...]>
DEBUG [2023-06-09 10:55:09] httpcore.connection_pool - assign_request_to_connection <Request [...]> <HTTPConnection >
DEBUG [2023-06-09 10:55:09] httpcore.connection_pool - unassign_request_from_connection <Request [...]> <HTTPConnection [...]>
DEBUG [2023-06-09 10:55:09] httpcore.connection_pool - timeout_waiting_for_connection <Request [...]>
DEBUG [2023-06-09 10:55:09] httpcore.connection_pool - remove_request <Request [...]>
DEBUG [2023-06-09 10:55:09] httpcore.connection_pool - remove_connection <HTTPConnection [...]>

Would that be sufficiently comprehensive?

lovelydinosaur avatar Jun 09 '23 13:06 lovelydinosaur

I've added all of the events you mentioned, as well as the "reuse_connection" event.

This is how it looks like now

connection_pool.add_request {'request': <Request [b'GET']>}
connection_pool.add_connection {'connection': <AsyncHTTPConnection [CONNECTING]>}
connection_pool.assign_request_to_connection {'request': <Request [b'GET']>, 'connection': <AsyncHTTPConnection [CONNECTING]>}
connection_pool.remove_request {'request': <Request [b'GET']>}
connection_pool.add_request {'request': <Request [b'GET']>}
connection_pool.reuse_connection {'connection': <AsyncHTTPConnection ['https://www.encode.io:443', HTTP/1.1, IDLE, Request Count: 1]>, 'request': <Request [b'GET']>}
connection_pool.assign_request_to_connection {'request': <Request [b'GET']>, 'connection': <AsyncHTTPConnection ['https://www.encode.io:443', HTTP/1.1, IDLE, Request Count: 1]>}
connection_pool.remove_request {'request': <Request [b'GET']>}
connection_pool.add_request {'request': <Request [b'GET']>}
connection_pool.reuse_connection {'connection': <AsyncHTTPConnection ['https://www.encode.io:443', HTTP/1.1, IDLE, Request Count: 2]>, 'request': <Request [b'GET']>}

karpetrosyan avatar Jun 10 '23 07:06 karpetrosyan

Also timeout event

connection_pool.timeout_waiting_for_connection {'request': <Request [b'GET']>}

karpetrosyan avatar Jun 10 '23 07:06 karpetrosyan

What's the status of this PR?

DoryZi avatar Apr 03 '24 13:04 DoryZi

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] avatar Apr 26 '25 04:04 stale[bot]