Please help to improve SELECT JOIN performance, EXPLAIN ANALYZE attached

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
11 messages Options
Reply | Threaded
Open this post in threaded view
|

Please help to improve SELECT JOIN performance, EXPLAIN ANALYZE attached

Alexander Farber
Good evening,

I have a word game which uses PostgreSQL 13.2 and 80% of the code is written as stored functions in PL/PgSQL or SQL.

Recently I have purchased some traffic and the number of daily games increased from 100 to 700.

In the PostgreSQL log I have noticed that the duration for 2 particular queries have increased, especially in the evenings:

2021-02-19 17:51:19.104 CET [68932] LOG:  duration: 2356.723 ms  execute <unnamed>: SELECT words_stat_longest($1::int)
2021-02-19 17:55:23.290 CET [68602] LOG:  duration: 2326.507 ms  execute <unnamed>: SELECT words_stat_longest($1::int)
2021-02-19 17:57:57.057 CET [68932] LOG:  duration: 1257.773 ms  execute <unnamed>: SELECT out_uid    AS uid,  out_fcm    AS fcm,    out_apns   AS apns,   out_adm    AS adm,    out_hms    AS hms,    out_social AS social, out_sid    AS sid,    out_body   AS body    FROM words_play_game($1::int, $2::int, $3::jsonb)
2021-02-19 18:02:51.359 CET [68603] LOG:  duration: 2305.950 ms  execute <unnamed>: SELECT words_stat_longest($1::int)
2021-02-19 18:08:26.130 CET [68932] LOG:  duration: 2375.713 ms  execute <unnamed>: SELECT words_stat_longest($1::int)

One of the queries is actually a simple SELECT ... LIMIT 15 to find the 15 longest words played by a user (they are displayed at the player profile page).

I have run the EXPLAIN ANALYZE here: https://explain.depesz.com/s/IcqN

It is difficult for me to understand, what could be missing there, does anybody please have an idea?

Thank you for any input
Alex

P.S. Here are the tables involved in the SELECT query, with the 
        words_moves and words_geoip holding the most records:

# \d words_scores
            Table "public.words_scores"
 Column |  Type   | Collation | Nullable | Default
--------+---------+-----------+----------+---------
 mid    | bigint  |           | not null |
 gid    | integer |           | not null |
 uid    | integer |           | not null |
 word   | text    |           | not null |
 score  | integer |           | not null |
Indexes:
    "words_scores_gid_idx" btree (gid)
    "words_scores_length_mid_idx" btree (length(word) DESC, mid DESC)
    "words_scores_uid_idx" btree (uid)
Check constraints:
    "words_scores_score_check" CHECK (score >= 0)
    "words_scores_word_check" CHECK (word ~ '^[А-Я]{2,}$'::text)
Foreign-key constraints:
    "words_scores_gid_fkey" FOREIGN KEY (gid) REFERENCES words_games(gid) ON DELETE CASCADE
    "words_scores_mid_fkey" FOREIGN KEY (mid) REFERENCES words_moves(mid) ON DELETE CASCADE
    "words_scores_uid_fkey" FOREIGN KEY (uid) REFERENCES words_users(uid) ON DELETE CASCADE

# \d words_moves
                                      Table "public.words_moves"
 Column  |           Type           | Collation | Nullable |                 Default
---------+--------------------------+-----------+----------+------------------------------------------
 mid     | bigint                   |           | not null | nextval('words_moves_mid_seq'::regclass)
 action  | text                     |           | not null |
 gid     | integer                  |           | not null |
 uid     | integer                  |           | not null |
 played  | timestamp with time zone |           | not null |
 tiles   | jsonb                    |           |          |
 score   | integer                  |           |          |
 str     | text                     |           |          |
 hand    | text                     |           |          |
 letters | character(1)[]           |           |          |
 values  | integer[]                |           |          |
Indexes:
    "words_moves_pkey" PRIMARY KEY, btree (mid)
    "words_moves_gid_played_idx" btree (gid, played DESC)
    "words_moves_uid_action_played_idx" btree (uid, action, played)
    "words_moves_uid_idx" btree (uid)
Check constraints:
    "words_moves_score_check" CHECK (score >= 0)
Foreign-key constraints:
    "words_moves_gid_fkey" FOREIGN KEY (gid) REFERENCES words_games(gid) ON DELETE CASCADE
    "words_moves_uid_fkey" FOREIGN KEY (uid) REFERENCES words_users(uid) ON DELETE CASCADE
Referenced by:
    TABLE "words_puzzles" CONSTRAINT "words_puzzles_mid_fkey" FOREIGN KEY (mid) REFERENCES words_moves(mid) ON DELETE CASCADE
    TABLE "words_scores" CONSTRAINT "words_scores_mid_fkey" FOREIGN KEY (mid) REFERENCES words_moves(mid) ON DELETE CASCADE

# \d words_geoip
                 Table "public.words_geoip"
 Column |       Type       | Collation | Nullable | Default
--------+------------------+-----------+----------+---------
 block  | inet             |           | not null |
 lat    | double precision |           |          |
 lng    | double precision |           |          |
Indexes:
    "words_geoip_pkey" PRIMARY KEY, btree (block)

# \d words_games
                                      Table "public.words_games"
  Column  |           Type           | Collation | Nullable |                 Default
----------+--------------------------+-----------+----------+------------------------------------------
 gid      | integer                  |           | not null | nextval('words_games_gid_seq'::regclass)
 created  | timestamp with time zone |           | not null |
 finished | timestamp with time zone |           |          |
 player1  | integer                  |           | not null |
 player2  | integer                  |           |          |
 played1  | timestamp with time zone |           |          |
 played2  | timestamp with time zone |           |          |
 state1   | text                     |           |          |
 state2   | text                     |           |          |
 reason   | text                     |           |          |
 hint1    | text                     |           |          |
 hint2    | text                     |           |          |
 score1   | integer                  |           | not null |
 score2   | integer                  |           | not null |
 chat1    | integer                  |           | not null |
 chat2    | integer                  |           | not null |
 hand1    | character(1)[]           |           | not null |
 hand2    | character(1)[]           |           | not null |
 pile     | character(1)[]           |           | not null |
 letters  | character(1)[]           |           | not null |
 values   | integer[]                |           | not null |
 bid      | integer                  |           | not null |
 diff1    | integer                  |           |          |
 diff2    | integer                  |           |          |
 open1    | boolean                  |           | not null | false
 open2    | boolean                  |           | not null | false
Indexes:
    "words_games_pkey" PRIMARY KEY, btree (gid)
    "words_games_player1_coalesce_idx" btree (player1, COALESCE(finished, 'infinity'::timestamp with time zone))
    "words_games_player2_coalesce_idx" btree (player2, COALESCE(finished, 'infinity'::timestamp with time zone))
Check constraints:
    "words_games_chat1_check" CHECK (chat1 >= 0)
    "words_games_chat2_check" CHECK (chat2 >= 0)
    "words_games_check" CHECK (player1 <> player2)
    "words_games_score1_check" CHECK (score1 >= 0)
    "words_games_score2_check" CHECK (score2 >= 0)
Foreign-key constraints:
    "words_games_bid_fkey" FOREIGN KEY (bid) REFERENCES words_boards(bid) ON DELETE CASCADE
    "words_games_player1_fkey" FOREIGN KEY (player1) REFERENCES words_users(uid) ON DELETE CASCADE
    "words_games_player2_fkey" FOREIGN KEY (player2) REFERENCES words_users(uid) ON DELETE CASCADE
Referenced by:
    TABLE "words_chat" CONSTRAINT "words_chat_gid_fkey" FOREIGN KEY (gid) REFERENCES words_games(gid) ON DELETE CASCADE
    TABLE "words_moves" CONSTRAINT "words_moves_gid_fkey" FOREIGN KEY (gid) REFERENCES words_games(gid) ON DELETE CASCADE
    TABLE "words_scores" CONSTRAINT "words_scores_gid_fkey" FOREIGN KEY (gid) REFERENCES words_games(gid) ON DELETE CASCADE

# \d words_users
                                        Table "public.words_users"
   Column    |           Type           | Collation | Nullable |                 Default
-------------+--------------------------+-----------+----------+------------------------------------------
 uid         | integer                  |           | not null | nextval('words_users_uid_seq'::regclass)
 created     | timestamp with time zone |           | not null |
 visited     | timestamp with time zone |           | not null |
 ip          | inet                     |           | not null |
 fcm         | text                     |           |          |
 apns        | text                     |           |          |
 adm         | text                     |           |          |
 motto       | text                     |           |          |
 vip_until   | timestamp with time zone |           |          |
 grand_until | timestamp with time zone |           |          |
 elo         | integer                  |           | not null |
 medals      | integer                  |           | not null |
 coins       | integer                  |           | not null |
 avg_score   | double precision         |           |          |
 avg_time    | interval                 |           |          |
 hms         | text                     |           |          |
 removed     | boolean                  |           | not null | false
 muted       | boolean                  |           | not null | false
Indexes:
    "words_users_pkey" PRIMARY KEY, btree (uid)
Check constraints:
    "words_users_elo_check" CHECK (elo >= 0)
    "words_users_medals_check" CHECK (medals >= 0)
Referenced by:
    TABLE "words_chat" CONSTRAINT "words_chat_uid_fkey" FOREIGN KEY (uid) REFERENCES words_users(uid) ON DELETE CASCADE
    TABLE "words_games" CONSTRAINT "words_games_player1_fkey" FOREIGN KEY (player1) REFERENCES words_users(uid) ON DELETE CASCADE
    TABLE "words_games" CONSTRAINT "words_games_player2_fkey" FOREIGN KEY (player2) REFERENCES words_users(uid) ON DELETE CASCADE
    TABLE "words_moves" CONSTRAINT "words_moves_uid_fkey" FOREIGN KEY (uid) REFERENCES words_users(uid) ON DELETE CASCADE
    TABLE "words_puzzles" CONSTRAINT "words_puzzles_uid_fkey" FOREIGN KEY (uid) REFERENCES words_users(uid) ON DELETE CASCADE
    TABLE "words_reviews" CONSTRAINT "words_reviews_author_fkey" FOREIGN KEY (author) REFERENCES words_users(uid) ON DELETE CASCADE
    TABLE "words_reviews" CONSTRAINT "words_reviews_uid_fkey" FOREIGN KEY (uid) REFERENCES words_users(uid) ON DELETE CASCADE
    TABLE "words_scores" CONSTRAINT "words_scores_uid_fkey" FOREIGN KEY (uid) REFERENCES words_users(uid) ON DELETE CASCADE
    TABLE "words_social" CONSTRAINT "words_social_uid_fkey" FOREIGN KEY (uid) REFERENCES words_users(uid) ON DELETE CASCADE
    TABLE "words_stats" CONSTRAINT "words_stats_uid_fkey" FOREIGN KEY (uid) REFERENCES words_users(uid) ON DELETE CASCADE

# \d words_social
                Table "public.words_social"
 Column |       Type       | Collation | Nullable | Default
--------+------------------+-----------+----------+---------
 sid    | text             |           | not null |
 social | integer          |           | not null |
 given  | text             |           | not null |
 family | text             |           |          |
 photo  | text             |           |          |
 lat    | double precision |           |          |
 lng    | double precision |           |          |
 stamp  | integer          |           | not null |
 uid    | integer          |           | not null |
Indexes:
    "words_social_pkey" PRIMARY KEY, btree (sid, social)
    "words_social_uid_stamp_idx" btree (uid, stamp DESC)
Check constraints:
    "words_social_given_check" CHECK (given ~ '\S'::text)
    "words_social_photo_check" CHECK (photo ~* '^https?://...'::text)
    "words_social_sid_check" CHECK (sid ~ '\S'::text)
    "words_social_social_check" CHECK (0 < social AND social <= 128)
Foreign-key constraints:
    "words_social_uid_fkey" FOREIGN KEY (uid) REFERENCES words_users(uid) ON DELETE CASCADE
Referenced by:
    TABLE "words_payments" CONSTRAINT "words_payments_sid_fkey" FOREIGN KEY (sid, social) REFERENCES words_social(sid, social) ON DELETE CASCADE

    "words_geoip_block_idx" spgist (block)




Reply | Threaded
Open this post in threaded view
|

Re: Please help to improve SELECT JOIN performance, EXPLAIN ANALYZE attached

Michael Lewis
Your explain analyze is showing an example that runs in less than 15ms, and your logs indicate queries taking 2-3 seconds. I am missing part of the picture here. Can you clarify?
Reply | Threaded
Open this post in threaded view
|

Re: Please help to improve SELECT JOIN performance, EXPLAIN ANALYZE attached

Alexander Farber
Yes, Michael, that I have noticed too, but should have written more in my original mail.

The query when I try it does run in 15ms, but evening logs show the query (I think only small percentage of it) running 1-3s.

At the same time my CentOS 8 server with 64 GB RAM is never loaded, the load average show by top is 0.35-0.45.

What could be the reason, does PostgreSQL 13.2 has some scheduled task maybe?

I have only changed few lines in the postgresql.conf:

# diff postgresql.conf.OLD postgresql.conf
64c64
< max_connections = 100                 # (change requires restart)
---
> max_connections = 120                 # (change requires restart)
130c130
< #work_mem = 4MB                               # min 64kB
---
> work_mem = 8MB                                # min 64kB
132c132
< #maintenance_work_mem = 64MB          # min 1MB
---
> maintenance_work_mem = 128MB          # min 1MB
393c393
< #effective_cache_size = 4GB
---
> effective_cache_size = 8GB
410,411c410,411
< #from_collapse_limit = 8
< #join_collapse_limit = 8              # 1 disables collapsing of explicit
---
> from_collapse_limit = 24
> join_collapse_limit = 24              # 1 disables collapsing of explicit
469c469
< #log_min_messages = warning           # values in order of decreasing detail:
---
> log_min_messages = notice             # values in order of decreasing detail:
497c497
< #log_min_duration_statement = -1      # -1 is disabled, 0 logs all statements
---
> log_min_duration_statement = 1000     # -1 is disabled, 0 logs all statements

And I have pgbouncer in front of the PostgreSQL:

 diff pgbouncer.ini.OLD pgbouncer.ini
12a13,15
> words_de = host=/tmp user=xxx password=xxx dbname=words_de
> words_en = host=/tmp user=xxx  password=xxx dbname=words_en
> words_ru = host=/tmp user=xxx password=xxx dbname=words_ru
115a119
> ;; auth_type = md5
148c152
< ;server_reset_query = DISCARD ALL
---
> server_reset_query = DISCARD ALL
156c160
< ;ignore_startup_parameters = extra_float_digits
---
> ignore_startup_parameters = extra_float_digits
180c184
< ;max_client_conn = 100
---
> max_client_conn = 1000
185c189
< ;default_pool_size = 20
---
> default_pool_size = 100

Or is maybe everything ok...? The daily gzipped dump grows big:

939343358 Dec 31 01:33 words_ru-Dec.sql.gz
1221682336 Jan 31 01:33 words_ru-Jan.sql.gz
1423324283 Feb 20 01:34 words_ru-Feb.sql.gz

and being an inexperienced pg admin I am a bit worried.

Thank you
Alex
Reply | Threaded
Open this post in threaded view
|

Re: Please help to improve SELECT JOIN performance, EXPLAIN ANALYZE attached

Peter J. Holzer
On 2021-02-20 10:24:36 +0100, Alexander Farber wrote:
> The query when I try it does run in 15ms, but evening logs show the query (I
> think only small percentage of it) running 1-3s.
>
> At the same time my CentOS 8 server with 64 GB RAM is never loaded, the load
> average show by top is 0.35-0.45.
>
> What could be the reason, does PostgreSQL 13.2 has some scheduled task maybe?

One very common reason for wildly different execution times is where the
data is: Accessing data in RAM is a lot faster than accessing it on disk
(even for SSDs, but especially for rotating disks).

So it might be that when you executed the EXPLAIN the data just happened
to be in RAM (that's almost certainly the case if you executed the same
query without EXPLAIN before that) while in those cases where it was
slow, the data (or a large part of it) had to be loaded from disk first.

Data might not be in RAM because it wasn't needed for some time, because
some other query or process which needed lots of RAM displaced it, or
because the server was just rebootet.


> I have only changed few lines in the postgresql.conf:

I don't see shared_buffers here. That's quite small by default so you
might want to increase it. The usual recommendation is to start with 25%
of the memory (that would be 16 GB in your case) and then see if it gets
better if decrease or increase it.

        hp

--
   _  | Peter J. Holzer    | Story must make more sense than reality.
|_|_) |                    |
| |   | [hidden email]         |    -- Charles Stross, "Creative writing
__/   | http://www.hjp.at/ |       challenge!"

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Please help to improve SELECT JOIN performance, EXPLAIN ANALYZE attached

Peter J. Holzer
In reply to this post by Alexander Farber
On 2021-02-19 21:25:36 +0100, Alexander Farber wrote:
> In the PostgreSQL log I have noticed that the duration for 2 particular queries
> have increased, especially in the evenings:
[...]
> One of the queries is actually a simple SELECT ... LIMIT 15 to find the 15
> longest words played by a user (they are displayed at the player profile page).
>
> I have run the EXPLAIN ANALYZE here: https://explain.depesz.com/s/IcqN

Well, I wouldn't call a query with 8 joins "simple".

I notice two things:

1) It does a lot more than the description ("Select 15 longest words
   played by the user id 5") suggests. It not only selects those words, but
   also the games in which they were played and some information about both
   players.

2) The query seems to spend most of the time in
    https://explain.depesz.com/s/IcqN#l11, retrieving all the words ever
    played by that user via a parallel bitmap heap scan, only to sort
    them and discard all but the 15 longest. I think using an index
    should make that much more efficient.

Therefore, three suggestions:

1) Add an index on words_scores(uid, length(word) desc).

2) If postgresql still isn't using that, isolate the core query by
   putting it into a CTE:
    with s as (select * from words_scores where uid = 5 order by length(word))
    select ...
    from s
    join words_moves m ...

3) If that shifts the bottleneck towards that extra per-user info
    (location, photo, ...) try to cache that in the application. That
    probably doesn't change very often and doesn't have to be retrieved
    from the database every time.

        hp

--
   _  | Peter J. Holzer    | Story must make more sense than reality.
|_|_) |                    |
| |   | [hidden email]         |    -- Charles Stross, "Creative writing
__/   | http://www.hjp.at/ |       challenge!"

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Please help to improve SELECT JOIN performance, EXPLAIN ANALYZE attached

Michael Lewis
In reply to this post by Alexander Farber
Using auto_explain may be needed to catch the plan when it is slow, if the other suggestions don't resolve things for you.
Reply | Threaded
Open this post in threaded view
|

Re: Please help to improve SELECT JOIN performance, EXPLAIN ANALYZE attached

Peter J. Holzer
On 2021-02-20 06:43:28 -0700, Michael Lewis wrote:
> Using auto_explain may be needed to catch the plan when it is slow, if the
> other suggestions don't resolve things for you.

Yes, auto_explain is very helpful. Unfortunately, by default it only
does an explain, not the equivalent of an explain analyze. So you know
what the plan was and what the total time was, but you still don't know
where it spent that time.

You can set auto_explain.log_analyze = on, but the documentation warns
that "this can have an extremely negative impact on performance". Does
anybody have experience with trying this in a real-world workload? (I
was never brave enough)

        hp

--
   _  | Peter J. Holzer    | Story must make more sense than reality.
|_|_) |                    |
| |   | [hidden email]         |    -- Charles Stross, "Creative writing
__/   | http://www.hjp.at/ |       challenge!"

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Please help to improve SELECT JOIN performance, EXPLAIN ANALYZE attached

Alexander Farber
Thank you all, I will try at first

shared_buffers = 16GB        and

index on words_scores(uid, length(word) desc)


Reply | Threaded
Open this post in threaded view
|

Re: Please help to improve SELECT JOIN performance, EXPLAIN ANALYZE attached

Alexander Farber
With shared_buffers=16GB, pg_top shows:


last pid:  2613;  load avg:  0.49,  0.45,  0.37;       up 0+00:19:21   16:41:16
16 processes: 16 sleeping
CPU states:  9.2% user,  0.0% nice,  0.2% system, 90.4% idle,  0.1% iowait
Memory: 21G used, 42G free, 29M buffers, 18G cached
DB activity:  39 tps,  0 rollbs/s,   0 buffer r/s, 100 hit%,   3625 row r/s,   11 row w/s
DB I/O:     0 reads/s,     0 KB/s,     0 writes/s,     0 KB/s
DB disk: 0.0 GB total, 0.0 GB free (100% used)
Swap: 32G free

  PID USERNAME PRI NICE  SIZE   RES STATE   TIME   WCPU    CPU COMMAND
 2114 postgres  20    0   17G 6378M sleep   2:11  0.77% 44.80% postgres: words words_ru [local] idle
 2012 postgres  20    0   17G 6005M sleep   0:55  0.45% 26.30% postgres: words words_ru [local] idle
 2107 postgres  20    0   17G 6175M sleep   1:16  0.02%  0.97% postgres: words words_ru [local] idle
 1184 postgres  20    0   17G   22M sleep   0:00  0.02%  0.97% postgres: walwriter
 2030 postgres  20    0   17G 5948M sleep   1:18  0.00%  0.00% postgres: words words_ru [local] idle
 2013 postgres  20    0   17G 5724M sleep   0:57  0.00%  0.00% postgres: words words_ru [local] idle
 2103 postgres  20    0   17G 5823M sleep   0:52  0.00%  0.00% postgres: words words_ru [local] idle
 2031 postgres  20    0   17G 5619M sleep   0:41  0.00%  0.00% postgres: words words_ru [local] idle
 2029 postgres  20    0   17G 1128M sleep   0:00  0.00%  0.00% postgres: words words_ru [local] idle
 2104 postgres  20    0   17G  948M sleep   0:00  0.00%  0.00% postgres: words words_ru [local] idle
 2106 postgres  20    0   17G 1257M sleep   0:00  0.00%  0.00% postgres: words words_ru [local] idle
 1182 postgres  20    0   17G  231M sleep   0:00  0.00%  0.00% postgres: checkpointer
 1183 postgres  20    0   17G  135M sleep   0:00  0.00%  0.00% postgres: background writer
 1185 postgres  20    0   17G 8696K sleep   0:00  0.00%  0.00% postgres: autovacuum launcher
 2614 postgres  20    0   17G   22M sleep   0:00  0.00%  0.00% postgres: words words_ru [local] idle
 1187 postgres  20    0   17G 6764K sleep   0:00  0.00%  0.00% postgres: logical replication launcher


On Sat, Feb 20, 2021 at 4:15 PM Alexander Farber <[hidden email]> wrote:
Thank you all, I will try at first

shared_buffers = 16GB        and

index on words_scores(uid, length(word) desc)


Reply | Threaded
Open this post in threaded view
|

Re: Please help to improve SELECT JOIN performance, EXPLAIN ANALYZE attached

Michael Lewis
In reply to this post by Peter J. Holzer
No issues for us. We have used a low sample rate of 1% or so and gotten some very useful data. Particularly with logging nested statements so we can profile stored procs more easily than adding a large number of raise notice statements.
Reply | Threaded
Open this post in threaded view
|

Re: Please help to improve SELECT JOIN performance, EXPLAIN ANALYZE attached

Peter J. Holzer
On 2021-02-21 10:14:04 -0700, Michael Lewis wrote:
> No issues for us. We have used a low sample rate of 1% or so and gotten some
> very useful data.

Oh, somehow I never noticed the auto_explain.sample_rate parameter in
the docs. Good to know.

        hp

--
   _  | Peter J. Holzer    | Story must make more sense than reality.
|_|_) |                    |
| |   | [hidden email]         |    -- Charles Stross, "Creative writing
__/   | http://www.hjp.at/ |       challenge!"

signature.asc (849 bytes) Download Attachment