search

vapor / postgres-nio

🐘 Non-blocking, event-driven Swift client for PostgreSQL.
https://api.vapor.codes/postgresnio/documentation/postgresnio/
MIT License
328 stars 76 forks source link

PostgresClient performance decrease when executing the same queries consecutively #511

Open duncangroenewald opened 3 weeks ago

duncangroenewald commented 3 weeks ago

Describe the issue

When running the same fairly complex set of queries (using the same client ) performance in each subsequence execution slows down - e.g first time 5.2 seconds, next time 5.6, next 6.0, etc. and it tends to keep climbing to over 8 seconds and probably more - I stopped testing.

Vapor version

postgres-nio 1.22.1

Operating system and version

macOS 14.6.1

Swift version

5.10.0

Steps to reproduce

A little tricky to reproduce given the number of queries in each execution run.

Restarting the client application seems to always get performance back to 5.2 seconds. Is there some cleanup necessary when using PostgresClient. Note that each execution creates a new PostgresClient but all the queries within the execution run use the same client.

Outcome

I would expect to see identical performance in each subsequent execution run - or at least within 0.1 seconds since the performance on restarting the application is nearly identical the first time the execution is run.

Additional notes

Not running Vapor - just using the PostgresClient from a macOS client application

duncangroenewald commented 3 weeks ago

An additional observation is that is I wait 30 seconds or a minute between running the queries then the performance seems to remain at 5.2 seconds.

This surely is a sign that something is being cleaned up during that time.

Anyone have any suggestions as to how to 'reset' things so that the performance of queries on a new client remain constant.

Perhaps something in the connection pool that needs to be reset so it doesn't get reused ?

MahdiBM commented 3 weeks ago

@duncangroenewald Can we have a reproducible example? Does it need specific queries or does it happen with any simple query?

duncangroenewald commented 3 weeks ago

@MahdiBM - I will try and create an example to reproduce the issue. The queries are all simple single table queries, however there are a lot of them because each execution is fetching a heirarchy that is about 10 levels deep with about 2000 lowest level nodes. There are about 150 top level nodes that need to be retrieved and I was hoping to be able to run multiple concurrent parallel queries but there appears to be a really big performance hit when doing that - everything slows down to the point where it seems like the queries are running in series. Testing on an M3 Max MacBook - which is running at around 120% cpu i.e using just a single core. Client and Postgres db running on the same MacBook.

duncangroenewald commented 3 weeks ago

Here is an example of the performance degradation that we are seeing. I created a test application to do this and see the same issue as with the production application. This is testing against the same database.

The m: value is the number of lowest level nodes fetched for each code. Typically the higher number would mean slightly slower read time. Bearing in mind the m value is 4 levels down in the hierarchy.

However if you take the example of L025 with a fetch time of 0.5 seconds for m:30 nodes and later on M005 m:35 has a fetch time of 3.5 seconds. However run the M005 query standalone and it returns in only 0.6 seconds. In fact just wait a minute or so and then run the M005 query without even restarting the whole application and it returns in the same 0.6s.

L002 (m:95) (elapsed: 1.4s, lap: 1.4s seconds) L006 (m:86) (elapsed: 1.3s, lap: 1.3s seconds) L007 (m:96) (elapsed: 1.5s, lap: 1.5s seconds) L011 (m:76) (elapsed: 1.2s, lap: 1.2s seconds) L014 (m:72) (elapsed: 1.1s, lap: 1.1s seconds) L015 (m:71) (elapsed: 1.1s, lap: 1.1s seconds) L016 (m:79) (elapsed: 1.2s, lap: 1.2s seconds) L018 (m:60) (elapsed: 1.0s, lap: 1.0s seconds) L019 (m:70) (elapsed: 1.1s, lap: 1.1s seconds) L021 (m:47) (elapsed: 0.8s, lap: 0.8s seconds) L024 (m:45) (elapsed: 0.7s, lap: 0.7s seconds) L025 (m:30) (elapsed: 0.5s, lap: 0.5s seconds) L027 (m:42) (elapsed: 0.7s, lap: 0.7s seconds) L028 (m:91) (elapsed: 1.5s, lap: 1.5s seconds) L029 (m:73) (elapsed: 1.3s, lap: 1.3s seconds) L033 (m:94) (elapsed: 1.6s, lap: 1.6s seconds) L034 (m:65) (elapsed: 1.2s, lap: 1.2s seconds) L035 (m:64) (elapsed: 1.2s, lap: 1.2s seconds) L038 (m:44) (elapsed: 0.8s, lap: 0.8s seconds) L039 (m:82) (elapsed: 1.5s, lap: 1.5s seconds) L041 (m:95) (elapsed: 1.9s, lap: 1.9s seconds) L042 (m:60) (elapsed: 1.1s, lap: 1.1s seconds) L043 (m:69) (elapsed: 1.4s, lap: 1.4s seconds) L044 (m:71) (elapsed: 1.5s, lap: 1.5s seconds) L045 (m:32) (elapsed: 0.6s, lap: 0.6s seconds) L046 (m:78) (elapsed: 1.6s, lap: 1.6s seconds) L048 (m:54) (elapsed: 1.2s, lap: 1.2s seconds) L050 (m:83) (elapsed: 1.8s, lap: 1.8s seconds) L051 (m:75) (elapsed: 1.6s, lap: 1.6s seconds) L052 (m:79) (elapsed: 1.9s, lap: 1.9s seconds) L053 (m:66) (elapsed: 1.6s, lap: 1.6s seconds) L054 (m:91) (elapsed: 2.3s, lap: 2.3s seconds) L056 (m:68) (elapsed: 1.7s, lap: 1.7s seconds) L057 (m:66) (elapsed: 1.7s, lap: 1.7s seconds) L060 (m:78) (elapsed: 1.9s, lap: 1.9s seconds) L061 (m:75) (elapsed: 1.9s, lap: 1.9s seconds) L062 (m:95) (elapsed: 2.8s, lap: 2.8s seconds) L063 (m:105) (elapsed: 3.5s, lap: 3.5s seconds) L064 (m:110) (elapsed: 3.7s, lap: 3.7s seconds) L065 (m:87) (elapsed: 3.0s, lap: 3.0s seconds) L066 (m:129) (elapsed: 4.4s, lap: 4.4s seconds) L067 (m:65) (elapsed: 2.4s, lap: 2.4s seconds) L068 (m:50) (elapsed: 1.9s, lap: 1.9s seconds) L069 (m:57) (elapsed: 2.0s, lap: 2.0s seconds) L071 (m:36) (elapsed: 1.2s, lap: 1.2s seconds) L072 (m:36) (elapsed: 1.3s, lap: 1.3s seconds) L073 (m:113) (elapsed: 4.2s, lap: 4.2s seconds) L074 (m:111) (elapsed: 4.3s, lap: 4.3s seconds) L075 (m:75) (elapsed: 2.9s, lap: 2.9s seconds) L076 (m:64) (elapsed: 2.5s, lap: 2.5s seconds) L077 (m:81) (elapsed: 3.2s, lap: 3.2s seconds) L078 (m:109) (elapsed: 4.7s, lap: 4.7s seconds) L079 (m:152) (elapsed: 6.7s, lap: 6.7s seconds) L080 (m:75) (elapsed: 3.3s, lap: 3.3s seconds) L081 (m:113) (elapsed: 5.4s, lap: 5.4s seconds) L082 (m:105) (elapsed: 5.2s, lap: 5.2s seconds) L083 (m:0) (elapsed: 0.1s, lap: 0.1s seconds) L085 (m:209) (elapsed: 10.1s, lap: 10.1s seconds) L086 (m:84) (elapsed: 4.3s, lap: 4.3s seconds) L088 (m:0) (elapsed: 0.2s, lap: 0.2s seconds) L089 (m:66) (elapsed: 3.0s, lap: 3.0s seconds) L091 (m:74) (elapsed: 3.5s, lap: 3.5s seconds) L092 (m:106) (elapsed: 5.2s, lap: 5.2s seconds) L093 (m:107) (elapsed: 5.3s, lap: 5.3s seconds) L094 (m:37) (elapsed: 2.0s, lap: 2.0s seconds) L095 (m:67) (elapsed: 3.4s, lap: 3.4s seconds) L096 (m:116) (elapsed: 5.5s, lap: 5.5s seconds) L097 (m:4) (elapsed: 0.4s, lap: 0.4s seconds) L099 (m:71) (elapsed: 3.5s, lap: 3.5s seconds) L104 (m:51) (elapsed: 3.0s, lap: 3.0s seconds) L105 (m:76) (elapsed: 4.2s, lap: 4.2s seconds) L106 (m:123) (elapsed: 8.1s, lap: 8.1s seconds) L108 (m:121) (elapsed: 7.9s, lap: 7.9s seconds) L109 (m:120) (elapsed: 7.8s, lap: 7.8s seconds) L110 (m:67) (elapsed: 4.3s, lap: 4.3s seconds) L111 (m:64) (elapsed: 4.3s, lap: 4.3s seconds) L112 (m:85) (elapsed: 6.0s, lap: 6.0s seconds) L114 (m:87) (elapsed: 6.0s, lap: 6.0s seconds) L116 (m:143) (elapsed: 10.3s, lap: 10.3s seconds) L117 (m:95) (elapsed: 6.4s, lap: 6.4s seconds) L121 (m:0) (elapsed: 0.2s, lap: 0.2s seconds) L201 (m:145) (elapsed: 12.9s, lap: 12.9s seconds) L202 (m:75) (elapsed: 6.0s, lap: 6.0s seconds) L203 (m:68) (elapsed: 4.9s, lap: 4.9s seconds) L204 (m:82) (elapsed: 6.8s, lap: 6.8s seconds) L205 (m:105) (elapsed: 9.1s, lap: 9.1s seconds) L206 (m:83) (elapsed: 7.6s, lap: 7.6s seconds) L207 (m:99) (elapsed: 8.9s, lap: 8.9s seconds) L208 (m:0) (elapsed: 0.3s, lap: 0.3s seconds) L209 (m:93) (elapsed: 8.4s, lap: 8.4s seconds) L210 (m:95) (elapsed: 9.9s, lap: 9.9s seconds) L213 (m:0) (elapsed: 0.3s, lap: 0.3s seconds) L218 (m:86) (elapsed: 8.9s, lap: 8.9s seconds) L224 (m:160) (elapsed: 16.6s, lap: 16.6s seconds) L231 (m:0) (elapsed: 0.3s, lap: 0.3s seconds) L996 (m:0) (elapsed: 0.3s, lap: 0.3s seconds) L997 (m:0) (elapsed: 0.3s, lap: 0.3s seconds) L998 (m:0) (elapsed: 0.3s, lap: 0.3s seconds) L999 (m:0) (elapsed: 0.3s, lap: 0.3s seconds) M001 (m:85) (elapsed: 8.0s, lap: 8.0s seconds) M004 (m:66) (elapsed: 6.4s, lap: 6.4s seconds) M005 (m:35) (elapsed: 3.5s, lap: 3.5s seconds) M008 (m:74) (elapsed: 7.2s, lap: 7.2s seconds) M013 (m:84) (elapsed: 8.2s, lap: 8.2s seconds) M017 (m:48) (elapsed: 4.9s, lap: 4.9s seconds) M018 (m:45) (elapsed: 5.2s, lap: 5.2s seconds) M025 (m:89) (elapsed: 8.8s, lap: 8.8s seconds) M027 (m:57) (elapsed: 6.1s, lap: 6.1s seconds) M029 (m:44) (elapsed: 4.8s, lap: 4.8s seconds) M030 (m:47) (elapsed: 4.5s, lap: 4.5s seconds) M033 (m:42) (elapsed: 4.8s, lap: 4.8s seconds) M034 (m:50) (elapsed: 4.9s, lap: 4.9s seconds) M035 (m:69) (elapsed: 5.4s, lap: 5.4s seconds) M036 (m:54) (elapsed: 4.6s, lap: 4.6s seconds) M038 (m:56) (elapsed: 5.0s, lap: 5.0s seconds) M101 (m:51) (elapsed: 4.9s, lap: 4.9s seconds) M105 (m:55) (elapsed: 4.4s, lap: 4.4s seconds) M310 (m:0) (elapsed: 0.4s, lap: 0.4s seconds) M912 (m:0) (elapsed: 0.4s, lap: 0.4s seconds)

duncangroenewald commented 3 weeks ago

After some more testing I find I can get a dramatic improvement in performance consistency by setting the following:

    config.options.minimumConnections = 10
    config.options.keepAliveBehavior = nil

The default keepAliceBehavior seems to have a significant negative impact on performance.

L002 (m:95) (elapsed: 1.2s, lap: 1.2s seconds) L006 (m:86) (elapsed: 1.1s, lap: 1.1s seconds) L007 (m:96) (elapsed: 1.2s, lap: 1.2s seconds) L011 (m:77) (elapsed: 1.0s, lap: 1.0s seconds) L014 (m:72) (elapsed: 0.9s, lap: 0.9s seconds) L015 (m:71) (elapsed: 0.9s, lap: 0.9s seconds) L016 (m:79) (elapsed: 1.0s, lap: 1.0s seconds) L018 (m:60) (elapsed: 0.8s, lap: 0.8s seconds) L019 (m:70) (elapsed: 0.8s, lap: 0.8s seconds) L021 (m:47) (elapsed: 0.5s, lap: 0.5s seconds) L024 (m:45) (elapsed: 0.7s, lap: 0.7s seconds) L025 (m:30) (elapsed: 0.5s, lap: 0.5s seconds) L027 (m:42) (elapsed: 0.7s, lap: 0.7s seconds) L028 (m:91) (elapsed: 1.0s, lap: 1.0s seconds) L029 (m:73) (elapsed: 0.7s, lap: 0.7s seconds) L033 (m:94) (elapsed: 1.0s, lap: 1.0s seconds) L034 (m:65) (elapsed: 0.7s, lap: 0.7s seconds) L035 (m:64) (elapsed: 0.8s, lap: 0.8s seconds) L038 (m:44) (elapsed: 0.6s, lap: 0.6s seconds) L039 (m:82) (elapsed: 0.9s, lap: 0.9s seconds) L041 (m:95) (elapsed: 1.0s, lap: 1.0s seconds) L042 (m:60) (elapsed: 0.6s, lap: 0.6s seconds) L043 (m:69) (elapsed: 0.7s, lap: 0.7s seconds) L044 (m:71) (elapsed: 0.8s, lap: 0.8s seconds) L045 (m:32) (elapsed: 0.5s, lap: 0.5s seconds) L046 (m:78) (elapsed: 0.9s, lap: 0.9s seconds) L048 (m:54) (elapsed: 0.6s, lap: 0.6s seconds) L050 (m:83) (elapsed: 0.9s, lap: 0.9s seconds) L051 (m:75) (elapsed: 0.8s, lap: 0.8s seconds) L052 (m:79) (elapsed: 0.9s, lap: 0.9s seconds) L053 (m:66) (elapsed: 0.8s, lap: 0.8s seconds) L054 (m:91) (elapsed: 1.1s, lap: 1.1s seconds) L056 (m:68) (elapsed: 0.7s, lap: 0.7s seconds) L057 (m:66) (elapsed: 0.6s, lap: 0.6s seconds) L060 (m:78) (elapsed: 0.9s, lap: 0.9s seconds) L061 (m:75) (elapsed: 0.9s, lap: 0.9s seconds) L062 (m:95) (elapsed: 1.0s, lap: 1.0s seconds) L063 (m:105) (elapsed: 1.1s, lap: 1.1s seconds) L064 (m:110) (elapsed: 1.2s, lap: 1.2s seconds) L065 (m:87) (elapsed: 0.9s, lap: 0.9s seconds) L066 (m:129) (elapsed: 1.4s, lap: 1.4s seconds) L067 (m:65) (elapsed: 0.8s, lap: 0.8s seconds) L068 (m:50) (elapsed: 0.5s, lap: 0.5s seconds) L069 (m:57) (elapsed: 0.8s, lap: 0.8s seconds) L071 (m:36) (elapsed: 0.4s, lap: 0.4s seconds) L072 (m:36) (elapsed: 0.6s, lap: 0.6s seconds) L073 (m:113) (elapsed: 1.2s, lap: 1.2s seconds) L074 (m:111) (elapsed: 1.2s, lap: 1.2s seconds) L075 (m:75) (elapsed: 0.7s, lap: 0.7s seconds) L076 (m:64) (elapsed: 0.6s, lap: 0.6s seconds) L077 (m:81) (elapsed: 0.9s, lap: 0.9s seconds) L078 (m:109) (elapsed: 1.2s, lap: 1.2s seconds) L079 (m:152) (elapsed: 1.7s, lap: 1.7s seconds) L080 (m:75) (elapsed: 0.7s, lap: 0.7s seconds) L081 (m:113) (elapsed: 1.2s, lap: 1.2s seconds) L082 (m:105) (elapsed: 1.1s, lap: 1.1s seconds) L083 (m:0) (elapsed: 0.1s, lap: 0.1s seconds) L085 (m:209) (elapsed: 2.2s, lap: 2.2s seconds) L086 (m:84) (elapsed: 0.9s, lap: 0.9s seconds) L088 (m:0) (elapsed: 0.1s, lap: 0.1s seconds) L089 (m:66) (elapsed: 0.7s, lap: 0.7s seconds) L091 (m:74) (elapsed: 0.8s, lap: 0.8s seconds) L092 (m:106) (elapsed: 1.0s, lap: 1.0s seconds) L093 (m:107) (elapsed: 1.1s, lap: 1.1s seconds) L094 (m:37) (elapsed: 0.4s, lap: 0.4s seconds) L095 (m:67) (elapsed: 0.7s, lap: 0.7s seconds) L096 (m:116) (elapsed: 1.2s, lap: 1.2s seconds) L097 (m:4) (elapsed: 0.1s, lap: 0.1s seconds) L099 (m:71) (elapsed: 0.7s, lap: 0.7s seconds) L104 (m:51) (elapsed: 0.6s, lap: 0.6s seconds) L105 (m:76) (elapsed: 0.8s, lap: 0.8s seconds) L106 (m:123) (elapsed: 1.2s, lap: 1.2s seconds) L108 (m:121) (elapsed: 1.2s, lap: 1.2s seconds) L109 (m:120) (elapsed: 1.2s, lap: 1.2s seconds) L110 (m:67) (elapsed: 0.7s, lap: 0.7s seconds) L111 (m:64) (elapsed: 0.6s, lap: 0.6s seconds) L112 (m:85) (elapsed: 0.9s, lap: 0.9s seconds) L114 (m:87) (elapsed: 0.9s, lap: 0.9s seconds) L116 (m:143) (elapsed: 1.4s, lap: 1.4s seconds) L117 (m:95) (elapsed: 1.0s, lap: 1.0s seconds) L121 (m:0) (elapsed: 0.1s, lap: 0.1s seconds) L201 (m:145) (elapsed: 1.5s, lap: 1.5s seconds) L202 (m:75) (elapsed: 0.7s, lap: 0.7s seconds) L203 (m:68) (elapsed: 0.8s, lap: 0.8s seconds) L204 (m:82) (elapsed: 0.9s, lap: 0.9s seconds) L205 (m:105) (elapsed: 1.1s, lap: 1.1s seconds) L206 (m:83) (elapsed: 0.9s, lap: 0.9s seconds) L207 (m:99) (elapsed: 1.1s, lap: 1.1s seconds) L208 (m:0) (elapsed: 0.1s, lap: 0.1s seconds) L209 (m:93) (elapsed: 1.0s, lap: 1.0s seconds) L210 (m:95) (elapsed: 1.3s, lap: 1.3s seconds) L213 (m:0) (elapsed: 0.1s, lap: 0.1s seconds) L218 (m:86) (elapsed: 1.2s, lap: 1.2s seconds) L224 (m:160) (elapsed: 1.8s, lap: 1.8s seconds) L231 (m:0) (elapsed: 0.1s, lap: 0.1s seconds) L996 (m:0) (elapsed: 0.1s, lap: 0.1s seconds) L997 (m:0) (elapsed: 0.1s, lap: 0.1s seconds) L998 (m:0) (elapsed: 0.1s, lap: 0.1s seconds) L999 (m:0) (elapsed: 0.2s, lap: 0.2s seconds) M001 (m:85) (elapsed: 0.9s, lap: 0.9s seconds) M004 (m:66) (elapsed: 0.7s, lap: 0.7s seconds) M005 (m:35) (elapsed: 0.4s, lap: 0.4s seconds) M008 (m:74) (elapsed: 1.0s, lap: 1.0s seconds) M013 (m:84) (elapsed: 1.0s, lap: 1.0s seconds) M017 (m:48) (elapsed: 0.5s, lap: 0.5s seconds) M018 (m:45) (elapsed: 0.5s, lap: 0.5s seconds) M025 (m:89) (elapsed: 1.1s, lap: 1.1s seconds) M027 (m:57) (elapsed: 0.7s, lap: 0.7s seconds) M029 (m:44) (elapsed: 0.5s, lap: 0.5s seconds) M030 (m:47) (elapsed: 0.5s, lap: 0.5s seconds) M033 (m:42) (elapsed: 0.5s, lap: 0.5s seconds) M034 (m:50) (elapsed: 0.6s, lap: 0.6s seconds) M035 (m:69) (elapsed: 0.9s, lap: 0.9s seconds) M036 (m:54) (elapsed: 0.6s, lap: 0.6s seconds) M038 (m:56) (elapsed: 0.7s, lap: 0.7s seconds) M101 (m:51) (elapsed: 0.6s, lap: 0.6s seconds) M105 (m:55) (elapsed: 0.6s, lap: 0.6s seconds) M310 (m:0) (elapsed: 0.1s, lap: 0.1s seconds) M912 (m:0) (elapsed: 0.1s, lap: 0.1s seconds)

fabianfett commented 3 weeks ago

How many concurrent requests do you run, with how many connections?