Date: Mon, 8 May 2017 19:49:22 +0200
From: Vincent Veyron <vv.lists@wanadoo.fr>
To: pgsql-performance@postgresql.org
Subject: Speed differences between two servers
Message-Id: <20170508194922.b049d1b73c8b681e982cadd9@wanadoo.fr>
Mime-Version: 1.0
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

Hello,

I use two dedicated bare metal servers (Online and Kimsufi). The first one =
takes much longer to execute a procedure that recreates a database by trunc=
ating its tables, then copying the data from a set of text files; it is how=
ever much faster for more typical SELECT and INSERT queries done by users.

Here is the timing for the procedure :

#Kimsufi server
time psql -f myfile.sql mydb
real	0m12.585s
user	0m0.200s
sys	0m0.076s

#Online server
time psql -f myfile.sql mydb
real	1m15.410s
user	0m0.144s
sys	0m0.028s

As you can see, the Kimsufi server takes 12 seconds to complete the procedu=
re, while the Online one needs 75 seconds.

For more usual queries however, the ratio is reversed, as shown by explain =
analyze for a typical query:

#Kimsufi server
marica=3D> explain (analyze, buffers) SELECT t1.id_contentieux, t1.ref_doss=
ier, t1.ref_assureur, noms_des_tiers(t1.id_contentieux) as id_tiers, t1.lib=
elle, t1.affaire, 1 as authorized
FROM tblcontentieux t1 WHERE id_contentieux IN (SELECT id_contentieux FROM =
tblcontentieux_log WHERE plainto_tsquery('vol') @@ tsv_libelle)  AND id_cli=
ent =3D 13 ORDER BY 2
;
                                                                           =
 QUERY PLAN=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=
=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=
=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=
=20=20=20=20=20
---------------------------------------------------------------------------=
---------------------------------------------------------------------------=
------------
 Sort  (cost=3D543.29..543.56 rows=3D106 width=3D116) (actual time=3D19.870=
..19.885 rows=3D75 loops=3D1)
   Sort Key: t1.ref_dossier
   Sort Method: quicksort  Memory: 35kB
   Buffers: shared hit=3D689
   ->  Nested Loop  (cost=3D430.59..539.73 rows=3D106 width=3D116) (actual =
time=3D4.103..19.143 rows=3D75 loops=3D1)
         Buffers: shared hit=3D689
         ->  HashAggregate  (cost=3D430.31..430.49 rows=3D18 width=3D4) (ac=
tual time=3D2.077..2.266 rows=3D124 loops=3D1)
               Group Key: tblcontentieux_log.id_contentieux
               Buffers: shared hit=3D112
               ->  Bitmap Heap Scan on tblcontentieux_log  (cost=3D29.11..4=
29.95 rows=3D142 width=3D4) (actual time=3D0.712..1.550 rows=3D147 loops=3D=
1)
                     Recheck Cond: (plainto_tsquery('vol'::text) @@ tsv_lib=
elle)
                     Heap Blocks: exact=3D105
                     Buffers: shared hit=3D112
                     ->  Bitmap Index Scan on tblcontentieux_log_tvs_libell=
e_idx  (cost=3D0.00..29.07 rows=3D142 width=3D0) (actual time=3D0.632..0.63=
2 rows=3D147 loops=3D1)
                           Index Cond: (plainto_tsquery('vol'::text) @@ tsv=
_libelle)
                           Buffers: shared hit=3D7
         ->  Index Scan using tblcontentieux_pkey on tblcontentieux t1  (co=
st=3D0.28..4.59 rows=3D1 width=3D116) (actual time=3D0.018..0.019 rows=3D1 =
loops=3D124)
               Index Cond: (id_contentieux =3D tblcontentieux_log.id_conten=
tieux)
               Filter: (id_client =3D 13)
               Rows Removed by Filter: 0
               Buffers: shared hit=3D372
 Planning time: 3.666 ms
 Execution time: 20.176 ms

#Online server
marica=3D> explain (analyze,buffers) SELECT t1.id_contentieux, t1.ref_dossi=
er, t1.ref_assureur, noms_des_tiers(t1.id_contentieux) as id_tiers, t1.libe=
lle, t1.affaire, 1 as authorized
FROM tblcontentieux t1 WHERE id_contentieux IN (SELECT id_contentieux FROM =
tblcontentieux_log WHERE plainto_tsquery('vol') @@ tsv_libelle)  AND id_cli=
ent =3D 13 ORDER BY 2;
                                                                           =
 QUERY PLAN=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=
=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=
=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=20=
=20=20=20=20=20
---------------------------------------------------------------------------=
---------------------------------------------------------------------------=
------------
 Sort  (cost=3D492.01..492.27 rows=3D104 width=3D116) (actual time=3D10.660=
..10.673 rows=3D75 loops=3D1)
   Sort Key: t1.ref_dossier
   Sort Method: quicksort  Memory: 35kB
   Buffers: shared hit=3D686
   ->  Nested Loop  (cost=3D390.14..488.52 rows=3D104 width=3D116) (actual =
time=3D1.363..10.066 rows=3D75 loops=3D1)
         Buffers: shared hit=3D686
         ->  HashAggregate  (cost=3D389.85..390.03 rows=3D18 width=3D4) (ac=
tual time=3D0.615..0.725 rows=3D124 loops=3D1)
               Group Key: tblcontentieux_log.id_contentieux
               Buffers: shared hit=3D109
               ->  Bitmap Heap Scan on tblcontentieux_log  (cost=3D13.08..3=
89.51 rows=3D139 width=3D4) (actual time=3D0.156..0.465 rows=3D147 loops=3D=
1)
                     Recheck Cond: (plainto_tsquery('vol'::text) @@ tsv_lib=
elle)
                     Heap Blocks: exact=3D106
                     Buffers: shared hit=3D109
                     ->  Bitmap Index Scan on tblcontentieux_log_tvs_libell=
e_idx  (cost=3D0.00..13.04 rows=3D139 width=3D0) (actual time=3D0.126..0.12=
6 rows=3D147 loops=3D1)
                           Index Cond: (plainto_tsquery('vol'::text) @@ tsv=
_libelle)
                           Buffers: shared hit=3D3
         ->  Index Scan using tblcontentieux_pkey on tblcontentieux t1  (co=
st=3D0.28..4.02 rows=3D1 width=3D116) (actual time=3D0.010..0.011 rows=3D1 =
loops=3D124)
               Index Cond: (id_contentieux =3D tblcontentieux_log.id_conten=
tieux)
               Filter: (id_client =3D 13)
               Rows Removed by Filter: 0
               Buffers: shared hit=3D372
 Planning time: 1.311 ms
 Execution time: 10.813 ms


Both are bare metal servers, with 4GB of RAM; the dataset is small (compres=
sed dump is 3MB). The main differences that I found are in disk I/O as show=
n by hdparm, and processor type :

#Kimsufi server=20
hdparm -tT /dev/sda
 Timing cached reads:   1744 MB in  2.00 seconds =3D 872.16 MB/sec
 Timing buffered disk reads: 482 MB in  3.00 seconds =3D 160.48 MB/sec
Processor Intel(R) Atom(TM) CPU N2800   @ 1.86GHz (4 cores, cache size  : 5=
12 KB)
Disk 2TB, 7200rpm, db on 500MB partition

#Online server
hdparm -tT /dev/sda
 Timing cached reads:   2854 MB in  2.00 seconds =3D 1427.05 MB/sec
 Timing buffered disk reads: 184 MB in  3.00 seconds =3D  61.26 MB/sec
Processor Intel(R) Atom(TM) CPU  C2350  @ 1.74GHz (2 cores, cache size  : 1=
024 KB)
Disk 1TB, 7200rpm, db on 1TB partition

I've created two pastebins with the output of the following commands for ea=
ch server:
# hdparm /dev/sda
# hdparm -i /dev/sda
# df
# cat /proc/cpuinfo
# cat /proc/meminfo

#Kimsufi server
https://pastebin.com/3860hS92

#Online server
https://pastebin.com/FT1HFbD7


My questions:=20

-Does the difference in 'buffered disk reads' explain the 6 fold increase i=
n execution time for truncate/copy on the Online server?

-Why are regular queries much faster on this same server?


--=20
					Bien =E0 vous, Vincent Veyron=20

https://legalcase.libremen.com/
Legal case management software


--=20
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance