Add support for connection pool monitoring #702

karpetrosyan · 2023-05-29T11:51:54Z

closes #508

httpcore/_async/connection_pool.py

karpetrosyan · 2023-05-30T08:16:31Z

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

tomchristie · 2023-05-30T12:40:21Z

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

karpetrosyan · 2023-05-30T13:06:13Z

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 · 2023-05-30T13:16:10Z

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}

tomchristie · 2023-06-09T13:15:14Z

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?

karpetrosyan · 2023-06-10T07:23:49Z

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 · 2023-06-10T07:35:47Z

Also timeout event

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

tomchristie

This is looking really promising...
Here's some initial suggestions.

docs/extensions.md

httpcore/_async/connection_pool.py

tests/_async/test_connection_pool.py

Co-authored-by: Tom Christie <tom@tomchristie.com>

…nto add-pool-monitoring

DoryZi · 2024-04-03T13:20:53Z

What's the status of this PR?

karpetrosyan changed the title ~~closes #508~~ Add support for connection pool monitoring May 29, 2023

karpetrosyan added the enhancement New feature or request label May 29, 2023

Pliner reviewed May 29, 2023

View reviewed changes

httpcore/_async/connection_pool.py Outdated Show resolved Hide resolved

karpetrosyan added 2 commits June 10, 2023 10:01

Add trace and atrace functions for single event traces

e5755be

Change trace events

8fa39ed

karpetrosyan force-pushed the add-pool-monitoring branch from 6888dbf to 8fa39ed Compare June 10, 2023 07:03

Add forgotten remove_connection log

ff05c83

karpetrosyan added 2 commits June 10, 2023 11:44

update docs

3f18288

update changelog

a96a826

tomchristie requested changes Jun 12, 2023

View reviewed changes

karpetrosyan and others added 5 commits June 12, 2023 15:45

Update docs/extensions.md

efaaea5

Co-authored-by: Tom Christie <tom@tomchristie.com>

Some refactoring

6c0ce0c

Merge branch 'add-pool-monitoring' of github.com:karosis88/httpcore i…

99634bc

…nto add-pool-monitoring

Change 10 to logging.DEBUG

d47c45d

Merge branch 'master' into add-pool-monitoring

24a7124

karpetrosyan requested a review from tomchristie June 13, 2023 06:20

karpetrosyan and others added 7 commits July 2, 2023 07:12

Merge branch 'master' into add-pool-monitoring

48a0242

Merge branch 'master' into add-pool-monitoring

6fe64e2

Merge branch 'master' into add-pool-monitoring

150b958

Merge branch 'master' into add-pool-monitoring

e98b1c6

Merge branch 'master' into add-pool-monitoring

9493c79

Merge branch 'master' into add-pool-monitoring

1b61766

Merge branch 'master' into add-pool-monitoring

0405a4b

karpetrosyan added 2 commits October 18, 2023 06:28

Merge branch 'master' into add-pool-monitoring

d04eb50

Merge branch 'master' into add-pool-monitoring

fe581d1

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add support for connection pool monitoring #702

Add support for connection pool monitoring #702

karpetrosyan commented May 29, 2023 •

edited

karpetrosyan commented May 30, 2023 •

edited

tomchristie commented May 30, 2023

karpetrosyan commented May 30, 2023

karpetrosyan commented May 30, 2023

tomchristie commented Jun 9, 2023

karpetrosyan commented Jun 10, 2023

karpetrosyan commented Jun 10, 2023

tomchristie left a comment

DoryZi commented Apr 3, 2024

Add support for connection pool monitoring #702

Are you sure you want to change the base?

Add support for connection pool monitoring #702

Conversation

karpetrosyan commented May 29, 2023 • edited

karpetrosyan commented May 30, 2023 • edited

tomchristie commented May 30, 2023

karpetrosyan commented May 30, 2023

karpetrosyan commented May 30, 2023

tomchristie commented Jun 9, 2023

karpetrosyan commented Jun 10, 2023

karpetrosyan commented Jun 10, 2023

tomchristie left a comment

Choose a reason for hiding this comment

DoryZi commented Apr 3, 2024

karpetrosyan commented May 29, 2023 •

edited

karpetrosyan commented May 30, 2023 •

edited