Asyncpg pool waits for all results

1.3k views Asked by At

I use asyncpg to make a heavy query that often takes around 15-20 seconds to compute. I was experimenting with a min and max sizes of a pool and noticed a strange behaviour. When I try to make multiple requests, they are executed simultaneously, but results return in a batch. The batch is always the same size as a pool. This behaviour leads to a long time of the first response, like 50 seconds or so. After a first batch, I need to wait for another 50 seconds, to get other results. It seems like asyncpg waits to collect all results from the pool and return them, rather than returning results as soon as they are ready.

Is there a way to get a result of a single request as soon as it executed? Maybe some setting that I'm missing?

For some time I could keep 25 connections, but it seems like a hack, which I really don't like.

I use DSN to create a pool if that's important.

db_pool = await asyncpg.create_pool(loop=self._loop, **params)

Here is the code, that I use to make a request to DB:

    async def first(self, query: str, values: List, db_name: str = 'default'):
        pool = self.get_pool(db_name)

        async with pool.acquire() as conn:
            return await conn.fetchrow(query, *values)

Right now I'm testing the default pool sizes (10 max, 10 min) and send 25 requests simultaneously.

result for 336997:  45.43796348571777 s
result for 368406:  45.43796348571777 s
result for 288307:  45.81912803649902 s
result for 283236:  46.499717235565186 s
result for 296000:  49.140310764312744 s
result for 304671:  49.20531177520752 s
result for 283685:  49.26837992668152 s
result for 283772:  49.3363881111145 s
result for 283720:  49.3753764629364 s
result for 294811:  49.39737892150879 s
result for 325604:  112.60201215744019 s
result for 336997:  112.60101222991943 s
result for 283028:  112.62509346008301 s
result for 291122:  113.41229104995728 s
result for 281105:  115.48561716079712 s
result for 304874:  115.59060764312744 s
result for 281875:  115.73372554779053 s
result for 283219:  115.73472547531128 s
result for 312094:  116.00303101539612 s
result for 312094:  116.0290174484253 s
result for 368406:  157.77449679374695 s
result for 325604:  157.77449679374695 s
result for 281932:  157.79654741287231 s
result for 290687:  157.79554748535156 s
result for 304874:  158.38678884506226 s

If I set max and min to 25, when I get these results:

result for 368406:  96.23042106628418 s
result for 368406:  96.22842144966125 s
result for 283236:  97.59920930862427 s
result for 304671:  99.69211030006409 s
result for 281932:  107.54676508903503 s
result for 283685:  107.95523738861084 s
result for 281875:  108.28549408912659 s
result for 283720:  108.39060115814209 s
result for 283028:  108.388601064682 s
result for 296000:  108.44459056854248 s
result for 283772:  108.55759739875793 s
result for 291122:  108.59360837936401 s
result for 294811:  108.90663266181946 s
result for 336997:  109.07162356376648 s
result for 325604:  109.07562470436096 s
result for 325604:  109.17762279510498 s
result for 336997:  109.30463767051697 s
result for 312094:  109.40563464164734 s
result for 312094:  109.40663456916809 s
result for 281105:  109.63970899581909 s
result for 290687:  109.66070008277893 s
result for 304874:  109.66170001029968 s
result for 288307:  109.68773555755615 s
result for 304874:  109.68273568153381 s
result for 283219:  109.68573522567749 s

5/5 connections bring terrible results

result for 288307:  38.87580060958862 s
result for 325604:  38.87280225753784 s
result for 283219:  38.87380290031433 s
result for 283772:  38.98385691642761 s
result for 304671:  39.80011057853699 s
result for 368406:  94.94180464744568 s
result for 283720:  94.94180464744568 s
result for 296000:  94.98080492019653 s
result for 294811:  95.45388603210449 s
result for 283685:  95.85135459899902 s
result for 291122:  156.6862394809723 s
result for 325604:  156.68523907661438 s
result for 336997:  156.68724012374878 s
result for 304874:  156.8772156238556 s
result for 283236:  157.72206735610962 s
result for 336997:  219.94082736968994 s
result for 368406:  219.96384191513062 s
result for 312094:  220.39882922172546 s
result for 281105:  220.8170771598816 s
result for 283028:  221.18352794647217 s
result for 290687:  283.105571269989 s
result for 281932:  283.10657024383545 s
result for 304874:  283.105571269989 s
result for 281875:  283.21556425094604 s
result for 312094:  283.7060844898224 s
2

There are 2 answers

0
Aleks Kuznetsov On BEST ANSWER

It was an issue on the DB side, we had to increase resources to fix this problem.

0
jjanes On

Each query is only waiting for its own results. If all the queries take about the same amount of work, then they all (of those that are actually running) finish after about the same amount of time. And is not all that similar anyway, the spread from 45.4 to 49.4 is not trivial. If it were somehow intentionally synchronizing them, you would think it would do a better job of it.

For some time I could keep 25 connections, but it seems like a hack, which I really don't like.

What would you rather do instead? Use a lower number? A higher one? A random number that changes from minute to minute? You should put a limit on connection pool. Why would 25 be a hack but some other number would not be?