Thread: Why could different data in a table be processed with different performance?

On Thu, Sep 20, 2018 at 05:07:21PM -0700, Vladimir Ryabtsev wrote:
> I am experiencing a strange performance problem when accessing JSONB
> content by primary key.

> I noticed that with some IDs it works pretty fast while with other it is
> 4-5 times slower. It is suitable to note, there are two main 'categories'
> of IDs in this table: first is range 270000000-500000000, and second is
> range 10000000000-100030000000. For the first range it is 'fast' and for
> the second it is 'slow'.

Was the data populated differently, too ?
Has the table been reindexed (or pg_repack'ed) since loading (or vacuumed for
that matter) ?
Were the tests run when the DB was otherwise idle?

You can see the index scan itself takes an additional 11sec, the "heap" portion
takes the remaining, additional 14sec (33s-12s-7s).

So it seems to me like the index itself is slow to scan.  *And*, the heap
referenced by the index is slow to scan, probably due to being referenced by
the index less consecutively.

> "Small' range: disk read rate is around 10-11 MB/s uniformly across the
> test. Output rate was 1300-1700 rows/s. Read ratio is around 13% (why?
> Shouldn't it be ~ 100% after drop_caches?).

I guess you mean buffers cache hit ratio: read/hit, which I think should
actually be read/(hit+read).

It's because a given buffer can be requested multiple times.  For example, if
an index page is read which references multiple items on the same heap page,
each heap access is counted separately.  If the index is freshly built, that'd
happen nearly every item.

Justin

> Aggregate  (cost=8635.91..8635.92 rows=1 width=16) (actual time=6625.993..6625.995 rows=1 loops=1)
>   Buffers: shared hit=26847 read=3914
>   ->  Index Scan using articles_pkey on articles  (cost=0.57..8573.35 rows=5005 width=107) (actual
time=21.649..1128.004rows=5000 loops=1)
 
>         Index Cond: ((article_id >= 438000000) AND (article_id <= 438005000))
>         Buffers: shared hit=4342 read=671

> Aggregate  (cost=5533.02..5533.03 rows=1 width=16) (actual time=33219.100..33219.102 rows=1 loops=1)
>   Buffers: shared hit=6568 read=7104
>   ->  Index Scan using articles_pkey on articles  (cost=0.57..5492.96 rows=3205 width=107) (actual
time=22.167..12082.624rows=2416 loops=1)
 
>         Index Cond: ((article_id >= '100021000000'::bigint) AND (article_id <= '100021010000'::bigint))
>         Buffers: shared hit=50 read=2378

Sorry, dropped -performance.

>>>> Has the table been reindexed (or pg_repack'ed) since loading (or vacuumed
>>>> for that matter) ?
>>> Not sure what you mean... We created indexes on some fields (on
>> I mean REINDEX INDEX articles_pkey;
>> Or (from "contrib"): /usr/pgsql-10/bin/pg_repack -i articles_pkey
>I never did it... Do you recommend to try it? Which variant is preferable?

REINDEX is likely to block access to the table [0], and pg_repack is "online"
(except for briefly acquiring an exclusive lock).

[0] https://www.postgresql.org/docs/10/static/sql-reindex.html

>>>> You can see the index scan itself takes an additional 11sec, the "heap"
>>>> portion takes the remaining, additional 14sec (33s-12s-7s).
>>> Sorry, I see 33 s total and 12 s for index, where do you see 7 s?
>> 6625 ms (for short query).
>> So the heap component of the long query is 14512 ms slower.
> Yes, I see, thanks.
> So reindex can help only with index component? What should I do for heap?
> May be reindex the corresponding toast table?

I think reindex will improve the heap access..and maybe the index access too.
I don't see why it would be bloated without UPDATE/DELETE, but you could check
to see if its size changes significantly after reindex.

Justin

Vladimir Ryabtsev wrote:
> explain (analyze, buffers)
> select count(*), sum(length(content::text)) from articles where article_id between %s and %s
> 
> Sample output:
> 
> Aggregate  (cost=8635.91..8635.92 rows=1 width=16) (actual time=6625.993..6625.995 rows=1 loops=1)
>   Buffers: shared hit=26847 read=3914
>   ->  Index Scan using articles_pkey on articles  (cost=0.57..8573.35 rows=5005 width=107) (actual
time=21.649..1128.004rows=5000 loops=1)
 
>         Index Cond: ((article_id >= 438000000) AND (article_id <= 438005000))
>         Buffers: shared hit=4342 read=671
> Planning time: 0.393 ms
> Execution time: 6626.136 ms
> 
> Aggregate  (cost=5533.02..5533.03 rows=1 width=16) (actual time=33219.100..33219.102 rows=1 loops=1)
>   Buffers: shared hit=6568 read=7104
>   ->  Index Scan using articles_pkey on articles  (cost=0.57..5492.96 rows=3205 width=107) (actual
time=22.167..12082.624rows=2416 loops=1)
 
>         Index Cond: ((article_id >= '100021000000'::bigint) AND (article_id <= '100021010000'::bigint))
>         Buffers: shared hit=50 read=2378
> Planning time: 0.517 ms
> Execution time: 33219.218 ms
> 
> During iteration, I parse the result of EXPLAIN and collect series of following metrics:
> 
> - buffer hits/reads for the table,
> - buffer hits/reads for the index,
> - number of rows (from "Index Scan..."),
> - duration of execution.
> 
> Based on metrics above I calculate inherited metrics:
> 
> - disk read rate: (index reads + table reads) * 8192 / duration,
> - reads ratio: (index reads + table reads) / (index reads + table reads + index hits + table hits),
> - data rate: (index reads + table reads + index hits + table hits) * 8192 / duration,
> - rows rate: number of rows / duration.
> 
> Since "density" of IDs is different in "small" and "big" ranges, I adjusted
> size of chunks in order to get around 5000 rows on each iteration in both cases,
> though my experiments show that chunk size does not really matter a lot.
> 
> The issue posted at the very beginning of my message was confirmed for the
> *whole* first and second ranges (so it was not just caused by randomly cached data).
> 
> To eliminate cache influence, I restarted Postgres server with flushing buffers:
> 
> /$ postgresql stop; sync; echo 3 > /proc/sys/vm/drop_caches; postgresql start
> 
> After this I repeated the test and got next-to-same picture.
> 
> "Small' range: disk read rate is around 10-11 MB/s uniformly across the test.
> Output rate was 1300-1700 rows/s. Read ratio is around 13% (why? Shouldn't it be
> ~ 100% after drop_caches?).
> "Big" range: In most of time disk read speed was about 2 MB/s but sometimes
> it jumped to 26-30 MB/s. Output rate was 70-80 rows/s (but varied a lot and
> reached 8000 rows/s). Read ratio also varied a lot.
> 
> I rendered series from the last test into charts:
> "Small" range: https://i.stack.imgur.com/3Zfml.png
> "Big" range (insane): https://i.stack.imgur.com/VXdID.png
> 
> During the tests I verified disk read speed with iotop and found its indications
> very close to ones calculated by me based on EXPLAIN BUFFERS. I cannot say I was
> monitoring it all the time, but I confirmed it when it was 2 MB/s and 22 MB/s on
> the second range and 10 MB/s on the first range. I also checked with htop that
> CPU was not a bottleneck and was around 3% during the tests.
> 
> The issue is reproducible on both master and slave servers. My tests were conducted
> on slave, while there were no any other load on DBMS, or disk activity on the
> host unrelated to DBMS.
> 
> My only assumption is that different fragments of data are being read with different
> speed due to virtualization or something, but... why is it so strictly bound
> to these ranges? Why is it the same on two different machines?

What is the storage system?

Setting "track_io_timing = on" should measure the time spent doing I/O
more accurately.

One problem with measuring read speed that way is that "buffers read" can
mean "buffers read from storage" or "buffers read from the file system cache",
but you say you observe a difference even after dropping the cache.

To verify if the difference comes from the physical placement, you could
run VACUUM (FULL) which rewrites the table and see if that changes the behavior.

Another idea is that the operating system rearranges I/O in a way that
is not ideal for your storage.

Try a different I/O scheduler by running

echo deadline > /sys/block/sda/queue/scheduler

(replace "sda" with the disk where your database resides)

See if that changes the observed I/O speed.

Yours,
Laurenz Albe
-- 
Cybertec | https://www.cybertec-postgresql.com

Hi Vladimir,



On 09/21/2018 02:07 AM, Vladimir Ryabtsev wrote:

> 
> I have such a table:
> 
> CREATE TABLE articles
> (
>     article_id bigint NOT NULL,
>     content jsonb NOT NULL,
>     published_at timestamp without time zone NOT NULL,
>     appended_at timestamp without time zone NOT NULL,
>     source_id integer NOT NULL,
>     language character varying(2) NOT NULL,
>     title text NOT NULL,
>     topicstopic[] NOT NULL,
>     objects object[] NOT NULL,
>     cluster_id bigint NOT NULL,
>     CONSTRAINT articles_pkey PRIMARY KEY (article_id)
> )
> 
> select content from articles where id between $1 and $2
> 
> I noticed that with some IDs it works pretty fast while with other it is
> 4-5 times slower. It is suitable to note, there are two main
> 'categories' of IDs in this table: first is range 270000000-500000000,
> and second is range 10000000000-100030000000. For the first range it is
> 'fast' and for the second it is 'slow'. Besides larger absolute numbers
> withdrawing them from int to bigint, values in the second range are more
> 'sparse', which means in the first range values are almost consequent
> (with very few 'holes' of missing values) while in the second range
> there are much more 'holes' (average filling is 35%). Total number of
> rows in the first range: ~62M, in the second range: ~10M.
> 
> 
> explain (analyze, buffers)
> select count(*), sum(length(content::text)) from articles where
> article_id between %s and %s
> 

is the length of the text equally distributed over the 2 partitions?

> Sample output:
> 
> Aggregate  (cost=8635.91..8635.92 rows=1 width=16) (actual
> time=6625.993..6625.995 rows=1 loops=1)
>   Buffers: shared hit=26847 read=3914
>   ->  Index Scan using articles_pkey on articles  (cost=0.57..8573.35
> rows=5005 width=107) (actual time=21.649..1128.004 rows=5000 loops=1)
>         Index Cond: ((article_id >= 438000000) AND (article_id <=
> 438005000))
>         Buffers: shared hit=4342 read=671
> Planning time: 0.393 ms
> Execution time: 6626.136 ms
> 
> Aggregate  (cost=5533.02..5533.03 rows=1 width=16) (actual
> time=33219.100..33219.102 rows=1 loops=1)
>   Buffers: shared hit=6568 read=7104
>   ->  Index Scan using articles_pkey on articles  (cost=0.57..5492.96
> rows=3205 width=107) (actual time=22.167..12082.624 rows=2416 loops=1)
>         Index Cond: ((article_id >= '100021000000'::bigint) AND
> (article_id <= '100021010000'::bigint))
>         Buffers: shared hit=50 read=2378
> Planning time: 0.517 ms
> Execution time: 33219.218 ms
> 

> 
> Since "density" of IDs is different in "small" and "big" ranges, I
> adjusted size of chunks in order to get around 5000 rows on each
> iteration in both cases, though my experiments show that chunk size does
> not really matter a lot.
> 

From what you posted, the first query retrieves 5005 rows, but the
second 2416. It might be helpful if we are able to compare 5000 vs 5000

Also is worth noticing that the 'estimated' differs from 'actual' on the
second query.
I think that happens because data is differently distributed over the
ranges.
Probably the analyzer does not have enough samples to understand the
real distribution. You might try to increase the number of samples (and
run analyze) or to create partial indexes on the 2 ranges.
Can you give a try to both options and let us know?

> The issue posted at the very beginning of my message was confirmed for
> the *whole* first and second ranges (so it was not just caused by
> randomly cached data).
> 
> To eliminate cache influence, I restarted Postgres server with flushing
> buffers:
> 
> /$ postgresql stop; sync; echo 3 > /proc/sys/vm/drop_caches; postgresql
> start
> 

i would do a sync at the end, after dropping caches.

But the problem here is that you are virtualizing. I think that you
might want to consider the physical layer. Eg:

- does the raid controller have a cache?

- how big is the cache? (when you measure disk speed, that will
influence the result very much, if  you do not run the test on
big-enough data chunk) best if is disabled during your tests

- is the OS caching disk blocks too? maybe you want to drop everything
from there too.

I think that you should be pragmatic and try to run the tests on a
physical machine. If results are then reproducible there too, then you
can exclude the whole virtual layer.

> After this I repeated the test and got next-to-same picture.
> 
> "Small' range: disk read rate is around 10-11 MB/s uniformly across the
> test. Output rate was 1300-1700 rows/s. Read ratio is around 13% (why?
> Shouldn't it be ~ 100% after drop_caches?).
> "Big" range: In most of time disk read speed was about 2 MB/s but
> sometimes it jumped to 26-30 MB/s. Output rate was 70-80 rows/s (but
> varied a lot and reached 8000 rows/s). Read ratio also varied a lot.
> 
> I rendered series from the last test into charts:
> "Small" range: https://i.stack.imgur.com/3Zfml.png
> "Big" range (insane): https://i.stack.imgur.com/VXdID.png
> 
> During the tests I verified disk read speed with iotop

on the VM or on the physical host?


regards,

fabio pardi

On 09/21/2018 08:28 AM, Vladimir Ryabtsev wrote:

>> but you say you observe a difference even after dropping the cache.
> No, I say I see NO significant difference (accurate to measurement
> error) between "with caches" and after dropping caches. And this is
> explainable, I think. Since I read consequently almost all data from the
> huge table, no cache can fit this data, thus it cannot influence
> significantly on results. And whilst the PK index *could* be cached (in
> theory) I think its data is being displaced from buffers by bulkier
> JSONB data.
> 
> Vlad

I think this is not accurate. If you fetch from an index, then only the
blocks containing the matching records are red from disk and therefore
cached in RAM.

regards,

fabio pardi

> is the length of the text equally distributed over the 2 partitions?
Not 100% equally, but to me it does not seem to be a big deal... Considering the ranges independently:

First range: ~70% < 10 KB, ~25% for 10-20 KB, ~3% for 20-30 KB, everything else is less than 1% (with 10 KB steps).

Second range: ~80% < 10 KB, ~18% for 10-20 KB, ~2% for 20-30 KB, everything else is less than 1% (with 10 KB steps).

>From what you posted, the first query retrieves 5005 rows, but the second 2416. It might be helpful if we are able to compare 5000 vs 5000

Yes it was just an example, here are the plans for approximately same number of rows:

Aggregate  (cost=9210.12..9210.13 rows=1 width=16) (actual time=4265.478..4265.479 rows=1 loops=1)

  Buffers: shared hit=27027 read=4311

  I/O Timings: read=2738.728

  ->  Index Scan using articles_pkey on articles  (cost=0.57..9143.40 rows=5338 width=107) (actual time=12.254..873.081 rows=5001 loops=1)

        Index Cond: ((article_id >= 438030000) AND (article_id <= 438035000))

        Buffers: shared hit=4282 read=710

        I/O Timings: read=852.547

Planning time: 0.235 ms

Execution time: 4265.554 ms

Aggregate  (cost=11794.59..11794.60 rows=1 width=16) (actual time=62298.559..62298.559 rows=1 loops=1)

  Buffers: shared hit=15071 read=14847

  I/O Timings: read=60703.859

  ->  Index Scan using articles_pkey on articles  (cost=0.57..11709.13 rows=6837 width=107) (actual time=24.686..24582.221 rows=5417 loops=1)

        Index Cond: ((article_id >= '100021040000'::bigint) AND (article_id <= '100021060000'::bigint))

        Buffers: shared hit=195 read=5244

        I/O Timings: read=24507.621

Planning time: 0.494 ms

Execution time: 62298.630 ms

If we subtract I/O from total time, we get 1527 ms vs 1596 ms — very close timings for other than I/O operations (considering slightly higher number of rows in second case). But  I/O time differs dramatically.

> Also is worth noticing that the 'estimated' differs from 'actual' on the second query. I think that happens because data is differently distributed over the ranges. Probably the analyzer does not have enough samples to understand the real distribution.

I think we should not worry about it unless the planner chose poor plan, should we? Statistics affects on picking a proper plan, but not on execution of the plan, doesn't it?

> or to create partial indexes on the 2 ranges.

Sure, will try it with partial indexes. Should I drop existing PK index, or ensuring that planner picks range index is enough?

> - how big is the cache? (when you measure disk speed, that will influence the result very much, if  you do not run the test on big-enough data chunk) best if is disabled during your tests 

I am pretty sure there is some, usually it's several tens of megabytes, but I ran disk read tests several times with chunks that could not be fit in the cache and with random offset, so I am pretty sure that something around 500 MB/s is enough reasonably accurate (but it is only for sequential read).

> - is the OS caching disk blocks too? maybe you want to drop everything from there too.

How can I find it out? And how to drop it? Or you mean hypervisor OS?

Anyway, don't you think that caching specifics could not really explain these issues?

On Mon, Sep 24, 2018 at 03:28:15PM -0700, Vladimir Ryabtsev wrote:
> > it is not unusual to have 1GB cache or more...  and do not forget to drop
> the cache between tests + do a sync
> I also reviewed import scripts and found the import was done in DESCENDING
> order of IDs.

This seems significant..it means the heap was probably written in backwards
order relative to the IDs, and the OS readahead is ineffective when index
scanning across a range of IDs.  From memory, linux since (at least) 2.6.32 can
optimize this.  You mentioned you're using 4.4.  Does your LVM have readahead
ramped up ?  Try lvchange -r 65536 data/postgres (or similar).

Also..these might be an impractical solution for several reasons, but did you
try either 1) forcing a bitmap scan (of only one index), to force the heap
reads to be ordered, if not sequential?  SET enable_indexscan=off (and maybe
SET enable_seqscan=off and others as needed).

Or, 2) Using a brin index (scanning of which always results in bitmap heap
scan).

> > - how big is the table?
> pg_table_size('articles') = 427 GB
> pg_table_size('pg_toast.pg_toast_221558') = 359 GB

Ouch .. if it were me, I would definitely want to make that a partitioned table..
Or perhaps two unioned together with a view? One each for the sparse and dense
range?

> > You can make use of pg_buffercache in order to see what is actually
> cached.
> It seems that there is no such a view in my DB, could it be that the module
> is not installed?

Right, it's in the postgresql -contrib package.
And you have to "CREATE EXTENSION pg_buffercache".

> > - As Laurenz suggested (VACUUM FULL), you might want to move data around.
> You can try also a dump + restore to narrow the problem to data or disk
> I launched VACUUM FULL, but it ran very slowly, according to my calculation
> it might take 17 hours. I will try to do copy data into another table with
> the same structure or spin up another server, and let you know.

I *suspect* VACUUM FULL won't help, since (AIUI) it copies all "visible" tuples
from the source table into a new table (and updates indices as necessary).  It
can resolve bloat due to historic DELETEs, but since I think your table was
written in reverse order of pkey, I think it'll also copy it in reverse order.
CLUSTER will fix that.  You can use pg_repack to do so online...but it's going
to be painful for a table+toast 1TiB in size: it'll take all day, and also
require an additional 1TB while running (same as VAC FULL).

Justin

On Mon, Sep 24, 2018 at 05:59:12PM -0700, Vladimir Ryabtsev wrote:
> > I *suspect* VACUUM FULL won't help, since (AIUI) it copies all "visible"
...
> I am going copy the slow range into a table nearby and see if it reproduces
> (I hope "INSERT INTO t2 SELECT * FROM t1 WHERE ..." will keep existing
> order of rows). Then I could try the same after CLUSTER.

If it does an index scan, I think that will badly fail to keep the same order
of heap TIDs - it'll be inserting rows in ID order rather than in (I guess)
reverse ID order.

Justin

On Mon, Sep 24, 2018 at 05:59:12PM -0700, Vladimir Ryabtsev wrote:
> > This seems significant..it means the heap was probably written in
> backwards
> order relative to the IDs, and the OS readahead is ineffective when index
> scanning across a range of IDs.
> But again, why is it different for one range and another? It was reversed
> for both ranges.

I don't have an explaination for it.. but I'd be curious to know
pg_stats.correlation for the id column:

SELECT schemaname, tablename, attname, correlation FROM pg_stats WHERE tablename='articles' AND column='article_id'
LIMIT1;
 

Justin

Hi, Vladimir,

Reading the whole thread it seems you should look deeper into IO subsystem.

1) Which file system are you using?

2) What is the segment layout of the LVM PVs and LVs? See https://www.centos.org/docs/5/html/Cluster_Logical_Volume_Manager/report_object_selection.html how to check. If data is fragmented, maybe the disks are doing a lot of seeking?

3) Do you use LVM for any "extra" features, such as snapshots?

4) You can try using seekwatcher to see where on the disk the slowness is occurring. You get a chart similar to this http://kernel.dk/dd-md0-xfs-pdflush.png

5) BCC is a collection of tools that might shed a light on what is happening. https://github.com/iovisor/bcc

Kind regards,

Gasper

I am experiencing a strange performance problem when accessing JSONB content by primary key.

My DB version() is PostgreSQL 10.3 (Ubuntu 10.3-1.pgdg14.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 4.8.4-2ubuntu1~14.04.4) 4.8.4, 64-bit

postgres.conf: https://justpaste.it/6pzz1
uname -a: Linux postgresnlpslave 4.4.0-62-generic #83-Ubuntu SMP Wed Jan 18 14:10:15 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
The machine is virtual, running under Hyper-V.
Processor: Intel(R) Xeon(R) CPU E5-2630 v4 @ 2.20GHz, 1x1 cores
Disk storage: the host has two vmdx drives, first shared between the root partition and an LVM PV, second is a single LVM PV. Both PVs are in a VG containing swap and postgres data partitions. The data is mostly on the first PV.

I have such a table:

CREATE TABLE articles
(
    article_id bigint NOT NULL,
    content jsonb NOT NULL,
    published_at timestamp without time zone NOT NULL,
    appended_at timestamp without time zone NOT NULL,
    source_id integer NOT NULL,
    language character varying(2) NOT NULL,
    title text NOT NULL,
    topicstopic[] NOT NULL,
    objects object[] NOT NULL,
    cluster_id bigint NOT NULL,
    CONSTRAINT articles_pkey PRIMARY KEY (article_id)
)

We have a Python lib (using psycopg2 driver) to access this table. It executes simple queries to the table, one of them is used for bulk downloading of content and looks like this:

select content from articles where id between $1 and $2

I noticed that with some IDs it works pretty fast while with other it is 4-5 times slower. It is suitable to note, there are two main 'categories' of IDs in this table: first is range 270000000-500000000, and second is range 10000000000-100030000000. For the first range it is 'fast' and for the second it is 'slow'. Besides larger absolute numbers withdrawing them from int to bigint, values in the second range are more 'sparse', which means in the first range values are almost consequent (with very few 'holes' of missing values) while in the second range there are much more 'holes' (average filling is 35%). Total number of rows in the first range: ~62M, in the second range: ~10M.

I conducted several experiments to eliminate possible influence of library's code and network throughput, I omit some of them. I ended up with iterating over table with EXPLAIN to simulate read load:

explain (analyze, buffers)
select count(*), sum(length(content::text)) from articles where article_id between %s and %s

Sample output:

Aggregate  (cost=8635.91..8635.92 rows=1 width=16) (actual time=6625.993..6625.995 rows=1 loops=1)
  Buffers: shared hit=26847 read=3914
  ->  Index Scan using articles_pkey on articles  (cost=0.57..8573.35 rows=5005 width=107) (actual time=21.649..1128.004 rows=5000 loops=1)
        Index Cond: ((article_id >= 438000000) AND (article_id <= 438005000))
        Buffers: shared hit=4342 read=671
Planning time: 0.393 ms
Execution time: 6626.136 ms

Aggregate  (cost=5533.02..5533.03 rows=1 width=16) (actual time=33219.100..33219.102 rows=1 loops=1)
  Buffers: shared hit=6568 read=7104
  ->  Index Scan using articles_pkey on articles  (cost=0.57..5492.96 rows=3205 width=107) (actual time=22.167..12082.624 rows=2416 loops=1)
        Index Cond: ((article_id >= '100021000000'::bigint) AND (article_id <= '100021010000'::bigint))
        Buffers: shared hit=50 read=2378
Planning time: 0.517 ms
Execution time: 33219.218 ms

During iteration, I parse the result of EXPLAIN and collect series of following metrics:

- buffer hits/reads for the table,
- buffer hits/reads for the index,
- number of rows (from "Index Scan..."),
- duration of execution.

Based on metrics above I calculate inherited metrics:

- disk read rate: (index reads + table reads) * 8192 / duration,
- reads ratio: (index reads + table reads) / (index reads + table reads + index hits + table hits),
- data rate: (index reads + table reads + index hits + table hits) * 8192 / duration,

- rows rate: number of rows / duration.

Since "density" of IDs is different in "small" and "big" ranges, I adjusted size of chunks in order to get around 5000 rows on each iteration in both cases, though my experiments show that chunk size does not really matter a lot.

The issue posted at the very beginning of my message was confirmed for the *whole* first and second ranges (so it was not just caused by randomly cached data).

To eliminate cache influence, I restarted Postgres server with flushing buffers:

/$ postgresql stop; sync; echo 3 > /proc/sys/vm/drop_caches; postgresql start

After this I repeated the test and got next-to-same picture.

"Small' range: disk read rate is around 10-11 MB/s uniformly across the test. Output rate was 1300-1700 rows/s. Read ratio is around 13% (why? Shouldn't it be ~ 100% after drop_caches?).
"Big" range: In most of time disk read speed was about 2 MB/s but sometimes it jumped to 26-30 MB/s. Output rate was 70-80 rows/s (but varied a lot and reached 8000 rows/s). Read ratio also varied a lot.

I rendered series from the last test into charts:
"Small" range: https://i.stack.imgur.com/3Zfml.png
"Big" range (insane): https://i.stack.imgur.com/VXdID.png

During the tests I verified disk read speed with iotop and found its indications very close to ones calculated by me based on EXPLAIN BUFFERS. I cannot say I was monitoring it all the time, but I confirmed it when it was 2 MB/s and 22 MB/s on the second range and 10 MB/s on the first range. I also checked with htop that CPU was not a bottleneck and was around 3% during the tests.

The issue is reproducible on both master and slave servers. My tests were conducted on slave, while there were no any other load on DBMS, or disk activity on the host unrelated to DBMS.

My only assumption is that different fragments of data are being read with different speed due to virtualization or something, but... why is it so strictly bound to these ranges? Why is it the same on two different machines?

The file system performance measured by dd:

root@postgresnlpslave:/# echo 3 > /proc/sys/vm/drop_caches 

root@postgresnlpslave:/# dd if=/dev/mapper/postgresnlpslave--vg-root of=/dev/null bs=8K count=128K

131072+0 records in

131072+0 records out

1073741824 bytes (1.1 GB, 1.0 GiB) copied, 2.12304 s, 506 MB/s

Am I missing something? What else can I do to narrow down the cause?

P.S. Initially posted on https://stackoverflow.com/questions/52105172/why-could-different-data-in-a-table-be-processed-with-different-performance

Regards,

Vlad

> it is not unusual to have 1GB cache or more...  and do not forget to drop the cache between tests + do a sync
I conducted several long runs of dd, so I am sure that this numbers are fairly correct. However, what worries me is that I test sequential read speed while during my experiments Postgres might need to read from random places thus reducing real read speed dramatically. I have a feeling that this can be the reason.
I also reviewed import scripts and found the import was done in DESCENDING order of IDs. It was so to get most recent records sooner, may be it caused some inefficiency in the storage... But again, it was so for both ranges.

> - how big is your index?
pg_table_size('articles_pkey') = 1561 MB

> - how big is the table?
pg_table_size('articles') = 427 GB
pg_table_size('pg_toast.pg_toast_221558') = 359 GB

> - given the size of shared_buffers, almost 2M blocks should fit, but you say 2 consecutive runs still are hitting the disk. That's strange indeed since you are using way more than 2M blocks.

TBH, I cannot say I understand your calculations with number of blocks...

But to clarify: consecutive runs with SAME parameters do NOT hit the disk, only the first one does, consequent ones read only from buffer cache.

> - As Laurenz suggested (VACUUM FULL), you might want to move data around. You can try also a dump + restore to narrow the problem to data or disk
I launched VACUUM FULL, but it ran very slowly, according to my calculation it might take 17 hours. I will try to do copy data into another table with the same structure or spin up another server, and let you know.

> - You might also want to try to see the disk graph of Windows, while you are running your tests. It can show you if data (and good to know how much) is actually fetching from disk or not.
I wanted to do so but I don't have access to Hyper-V server, will try to request credentials from admins.

Couple more observations:

1) The result of my experiment is almost not affected by other server load. Another user was running a query (over this table) with read speed ~130 MB/s, while with my query read at 1.8-2 MB/s.

2) iotop show higher IO % (~93-94%) with slower read speed (though it is not quite clear what this field is). A process from example above had ~55% IO with 130 MB/s while my process had ~93% with ~2MB/s.

Regards,

Vlad

On 09/26/2018 07:15 PM, Vladimir Ryabtsev wrote:
>> Since you have a very big toast table, given you are using spinning
> disks, I think that increasing the block size will bring benefits.
> But will it worsen caching? I will have lesser slots in cache. Also will
> it affect required storage space?


I think in your case it will not worsen the cache. You will have lesser
slots in the cache, but the total available cache will indeed be
unchanged (half the blocks of double the size). It could affect space
storage, for the smaller blocks. Much depends which block size you
choose and how is actually your data distributed in the ranges you
mentioned. (eg: range 10K -20 might be more on the 10 or more on the 20
side.).

Imagine you request a record of 24 KB, and you are using 8KB blocks. It
will result in 3 different block lookup/request/returned. Those 3 blocks
might be displaced on disk, resulting maybe in 3 different lookups.
Having all in one block, avoids this problem.
The cons is that if you need to store 8KB of data, you will allocate 24KB.
You say you do not do updates, so it might also be the case that when
you write data all at once (24 KB in one go) it goes all together in a
contiguous strip. Therefore the block size change here will bring nothing.
This is very much data and usage driven. To change block size is a
painful thing, because IIRC you do that at db initialization time

Similarly, if your RAID controller uses for instance 128KB blocks, each
time you are reading one block of 8KB, it will return to you a whole
128KB chunk, which is quite a waste of resources.

If your 'slow' range is maybe fragmented here and there on the disk, not
having a proper alignment between Postgres blocks/ Filesystem/RAID
might worsen the problem of orders of magnitude. This is very true on
spinning disks, where the seek time is noticeable.

Note that trying to set a very small block size has the opposite effect:
you might hit the IOPS of your hardware, and create a bottleneck. (been
there while benchmarking some new hardware)

But before going through all this, I would first try to reload the data
with dump+restore into a new machine, and see how it behaves.

Hope it helps.

regards,

fabio pardi

> 
>>> consecutive runs with SAME parameters do NOT hit the disk, only the
> first one does, consequent ones read only from buffer cache.
>> I m  a bit confused.. every query you pasted contains 'read':
>>        Buffers: shared hit=50 read=2378
>> and 'read' means you are reading from disk (or OS cache). Or not? 
> Yes, sorry, it was just my misunderstanding of what is "consecutive". To
> make it clear: I iterate over all data in table with one request and
> different parameters on each iteration (e.g. + 5000 both borders), in
> this case I get disk reads on each query run (much more reads on "slow"
> range). But if I request data from an area queried previously, it reads
> from cache and does not hit disk (both ranges). E.g. iterating over 1M
> of records with empty cache takes ~11 minutes in "fast" range and ~1
> hour in "slow" range, while on second time it takes only ~2 minutes for
> both ranges (if I don't do drop_caches).
> 
> Regards,
> Vlad
> 

On 28/09/18 11:56, Vladimir Ryabtsev wrote:
>
> > It could affect space storage, for the smaller blocks.
> But at which extent? As I understand it is not something about "alignment" to block size for rows? Is it only
low-levelIO thing with datafiles?
 
>

Maybe 'for the smaller blocks' was not very meaningful.
What i mean is 'in terms of wasted disk space: '

In an example:

create table test_space (i int);

empty table:

select pg_total_relation_size('test_space');
 pg_total_relation_size
------------------------
                      0
(1 row)

insert one single record:

insert into test_space values (1);


select pg_total_relation_size('test_space');
 pg_total_relation_size
------------------------
                   8192


select pg_relation_filepath('test_space');
 pg_relation_filepath
----------------------
 base/16384/179329


ls -alh base/16384/179329
-rw------- 1 postgres postgres 8.0K Sep 28 16:09 base/16384/179329

That means, if your block size was bigger, then you would have bigger space allocated for one single record.

regards,

fabio aprdi

On 28/09/18 21:51, Vladimir Ryabtsev wrote:
> > That means, if your block size was bigger, then you would have bigger space allocated for one single record.
> But if I INSERT second, third ... hundredth record in the table, the size remains 8K.


> So my point is that if one decides to increase block size, increasing storage space is not so significant, because it
doesnot set minimum storage unit for a row.
 
>
ah, yes, correct. Now we are on the same page.

Good luck with the rest of things you are going to try out, and let us know your findings.

regards,

fabio pardi

> vlad