Re: Sudden insert performance degradation - Mailing list pgsql-performance

Hello again list,

Turns out that the good performance didn't last long. After processing about
300 CSV files with 1 million records each (inserting between 200k and 300k new
records per file into the DB), performance went downhill again :(



Table `users_basic_profile_no_dups_partitioned` stats:
- 1530 partitions (based on user_id)
- 473,316,776 rows
- Unlogged
- Stored in an 8TB 7200 RPM HDD

Table `users_basic_profile` stats:
- Unlogged
- 1 million rows
- Stored in memory (using tmpfs)

Configuration file has the following custom configurations for the tests
executed below:

```
ssl = off
shared_buffers = 160GB                  # min 128kB
work_mem = 96GB                         # min 64kB
maintenance_work_mem = 12GB             # min 1MB
max_stack_depth = 4MB                   # min 100kB
dynamic_shared_memory_type = posix      # the default is the first option
synchronous_commit = off                # synchronization level;
commit_delay = 100000                   # range 0-100000, in microseconds
max_wal_size = 3GB
min_wal_size = 1GB
min_parallel_index_scan_size = 64kB
effective_cache_size = 96GB
log_min_messages = debug1 # values in order of decreasing detail:
log_checkpoints = on
log_error_verbosity = verbose # terse, default, or verbose messages
log_line_prefix = '%m [%p] %q%u@%d '            # special values:
log_lock_waits = on                     # log lock waits >= deadlock_timeout
log_timezone = 'America/New_York'
log_executor_stats = on
datestyle = 'iso, mdy'
```

(max_wal_size was 80GB before and min_wal_size was 80MB; I changed the max
because the first restart I did to the service took a long time since it had
to sync 80+GB of data to the disk)

I restarted the postgres service and ran this query:

```
select user_id from users_basic_profile_no_dups_partitioned
where
    user_id in (
        select user_id from users_basic_profile order by user_id
    );
```

The above query took 659 seconds to run and read 73.64 GB of data from the
disk. From observing the `top` output I assume that all this data was loaded
into RAM and kept there.

I then ran the same query again and it ran in 195 seconds. This second time,
no data was read from the disk and CPU usage stayed at 100% the whole time.
I am not sure why it took so long since it seems the whole data was in memory.

I then ran the following query 6 times while increasing the limit as shown in
the table below:

```
select user_id from users_basic_profile_no_dups_partitioned
where
    user_id in (
        select user_id from users_basic_profile order by user_id
        limit 10
    );
```

  Limit  |  Time (seconds)
---------|------------------
10       | 0.6
100      | 0.6
1000     | 1.3
10000    | 116.9
100000   | 134.8
1000000  | 193.2

Notice the jump in time execution from a 1k limit to a 10k limit. Amount of
data raised 10x and execution time raised 100x.

It seems to me that inserting the data in this case is slow because the time
it takes to identify the duplicate records (which I assume would be done in a
fashion similiar to the queries above) is taking a long time.

I have attached the `explain analyze` output for the 1k and 10k queries to
this email (they are 4k+ lines each, didn't want to make this messager bigger
than it already is).

* exp1k.txt
* exp10k.txt

One thing to keep in mind is: all the data in the `users_basic_profile` table
already exists in the `users_basic_profile_no_dups_partitioned` table. So if I
try to insert the data now again, it goes SUPER fast:

```

insert into users_basic_profile_no_dups_partitioned(
                       created_ts,
                       user_id,
                       name,
                       profile_picture
                   ) (
                   select
                       created_ts,
                       user_id,
                       name,
                       profile_picture
                   from
                        users_basic_profile
                    order by
                        user_id limit 10000
                   ) on conflict do nothing;
INSERT 0 0
Time: 276.905 ms
```

I droped the `users_basic_profile` table, recreated it and then and loaded a
new file into it that has not been previously loaded:

```
drop table users_basic_profile;

create unlogged table users_basic_profile (
   created_ts timestamp without time zone default current_timestamp,
   user_id bigint,
   name text,
   profile_picture text
)
with (autovacuum_enabled = false, toast.autovacuum_enabled = false)
tablespace ramdisk;

copy users_basic_profile(user_id, name, profile_picture)
from '/tmp/myfile.csv' with (
    format csv,
    header true,
    delimiter ',',
    quote '"',
    escape '\'
);
```

The `COPY` command took 3 seconds.

I then ran the `SELECT` queries above again:


  Limit  |  Time (seconds)
---------|------------------
10       | 0.7
100      | 0.6
1000     | 1
10000    | 5.3
100000   | 68.8
1000000  | Did not complete

The 1 million query ran for 54 minutes when I finally decided to cancel it.
Disk reads at this point were at 1.4MB per second by the process performing
the `SELECT`. No other process was using the disk.

This execution was not fair, since the new data was probably not cached in RAM
yet. So I re-ran all the queries again:


  Limit  |  Time (seconds)
---------|------------------
10       | 0.7
100      | 0.7
1000     | 0.8
10000    | 1.9
100000   | 11.2
1000000  | Did not complete

The 1 million query didn't complete again. The disk read speed was again at
1.4MB/s and if it didn't complete in 10 minutes it wasn't gonna complete any
time soon.

While these numbers look better, I find the 5x increase from the 10k to
100k a bit suspicious.

The `explain analyze` plans for the 1k, 10k and 100k queries are attached:

* exp1k-secondtime.txt
* exp10k-secondtime.txt
* exp100k-secondtime.txt

The `explain` for the 1million query is also attached:
* exp1million.txt

I then tried to insert the data into the table with this query:

```
begin;
explain analyze insert into users_basic_profile_no_dups_partitioned(created_ts,
   user_id,
   name,
   profile_picture
) (
select
   created_ts,
   user_id,
   name,
   profile_picture
from
    users_basic_profile
order by
    user_id
) on conflict do nothing;
```

Disk read speed during this query was around 9MB/s with writes around 500KB/s.

The result of the explain analyze is as follows:

```
                                                                        QUERY PLAN                                              
----------------------------------------------------------------------------------------------------------------------------------------------------------
 Insert on users_basic_profile_no_dups_partitioned  (cost=386110.19..423009.25 rows=2951925 width=80) (actual time=156773.296..156773.296 rows=0 loops=1)
   Conflict Resolution: NOTHING
   Tuples Inserted: 293182
   Conflicting Tuples: 706818
   ->  Sort  (cost=386110.19..393490.00 rows=2951925 width=80) (actual time=777.295..1423.577 rows=1000000 loops=1)
         Sort Key: users_basic_profile.user_id
         Sort Method: quicksort  Memory: 540206kB
         ->  Seq Scan on users_basic_profile  (cost=0.00..68878.25 rows=2951925 width=80) (actual time=0.019..173.278 rows=1000000 loops=1)
 Planning Time: 0.139 ms
 Execution Time: 156820.603 ms
(10 rows)
```

This query took 156 seconds to complete. 156 seconds is not too bad, but I was
getting between 8 seconds and 20 seconds this morning as I mentioned before.
So still something seems off. I was able to process 300 files this morning,
each one containing 1 million records inserting anything between 200k and 300k
new records into the table per file. This means that while runing these tests,
I have about 70 million more rows in the table than I did this morning.

After completing the `INSERT` I executed a `COMMIT` that took 0.03 seconds.

I decided to run the `SELECT` queries one last time:

  Limit  |  Time (seconds)
---------|------------------
10       | 0.6
100      | 0.6
1000     | 0.7
10000    | 1.6
100000   | 10.7
1000000  | 110.7

This time the 1 million query completed. Most likely due to some caching
mechanism I'd guess. Still 110 seconds seems somewhat slow.

So, does anyone have any suggestions on what could be wrong? The questions
that come to mind are:

* Why are these execution times so crazy?
* Why is the read speed from the disk so low?
* What is causing the sudden drop in performance?
* Any idea how to fix any of this?

* Any suggestions on what I should do/test/look for?

= Extra Information =

Before starting all these tests, I had executed the following
`REINDEX` command on all partitions of
`users_basic_profile_no_dups_partitioned`:


```
DO $$DECLARE r record;
BEGIN
    FOR r IN select indexname from pg_indexes where tablename like 'ubp_%'
    LOOP
        raise notice 'Processing index [%]', r.indexname;
        EXECUTE 'alter index ' || r.indexname || ' set (fillfactor=50)';
        EXECUTE 'reindex index ' || r.indexname;
    END LOOP;
END$$;
```

Before setting the `fillfactor` to 50, I tried just a regular `REINDEX`
keeping the original `fillfactor` but the results were still the same.

Structure of table `users_basic_profile_no_dups_partitioned`:

```

# \d users_basic_profile_no_dups_partitioned

        Unlogged table "public.users_basic_profile_no_dups_partitioned"
     Column      |            Type             | Collation | Nullable | Default
-----------------+-----------------------------+-----------+----------+---------
 created_ts      | timestamp without time zone |           | not null |
 user_id         | bigint                      |           | not null |
 name            | text                        |           |          |
 profile_picture | text                        |           |          |
Partition key: RANGE (user_id)
Indexes:
    "users_basic_profile_no_dups_partitioned_pkey" PRIMARY KEY, btree (user_id)
Number of partitions: 1530 (Use \d+ to list them.)
```

The `profile_picture` column stores a `URL` to the picture, not a blob of the
picture.