Re: UPDATEDs slowing SELECTs in a fully cached database

On 07/12/2011 08:13 AM, Ivan Voras wrote:
> On 12/07/2011 02:09, lars wrote:
>
>> Oh, and iowait hovers around 20% when SELECTs are slow:
>>
>> avg-cpu: %user %nice %system %iowait %steal %idle
>> 1.54 0.00 0.98 18.49 0.07 78.92
>>
>> When SELECTs are fast it looks like this:
>> avg-cpu: %user %nice %system %iowait %steal %idle
>> 8.72 0.00 0.26 0.00 0.00 91.01
>>
>> Note that this is a 12 core VM. So one core at 100% would show as 8.33%
>> CPU.
>
> Now only if you could do an "iostat -x" and show the output in both
> cases...
>
>
Sure (sorry for missing details):

iostat -x during selects when all's fine:
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            8.25    0.00    0.00    0.00    0.00   91.75

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s
avgrq-sz avgqu-sz   await  svctm  %util
xvdap1            0.00     1.00    0.00    2.00     0.00    24.00
12.00     0.00    0.00   0.00   0.00
xvdf              0.00     0.00    0.00    0.00     0.00     0.00
0.00     0.00    0.00   0.00   0.00
xvdg              0.00     0.00    0.00    0.00     0.00     0.00
0.00     0.00    0.00   0.00   0.00

xvdap1 is OS volumn.
xvdf holds the database files
xvdg holds the WAL

No IO on database/WAL volumes, one core is pegged close to 100% CPU.

------------------------------------

iostat -x during update:
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            1.05    0.00    0.58    4.00    0.00   94.37

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s
avgrq-sz avgqu-sz   await  svctm  %util
xvdap1            0.00     0.00    0.00    0.00     0.00     0.00
0.00     0.00    0.00   0.00   0.00
xvdf              0.00     0.00    7.00    0.00   128.00     0.00
18.29     0.00    0.00   0.00   0.00
xvdg              0.00  7352.00    0.00  804.00     0.00 62368.00
77.57    66.07   68.83   0.86  69.20

Just updating the WAL.

-----------------------------------

and while it's checkpointing:
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0.64    0.00    0.32    8.88    0.00   90.16

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s
avgrq-sz avgqu-sz   await  svctm  %util
xvdap1            0.00     0.00    0.00    0.00     0.00     0.00
0.00     0.00    0.00   0.00   0.00
xvdf              0.00  2548.00    2.00 1658.00    32.00 33408.00
20.14   144.18   86.69   0.60 100.00
xvdg              0.00  5428.00    0.00  778.00     0.00 58480.00
75.17    77.44  100.22   1.21  94.00

Updating the WAL, and database volume due to checkpointing.

----------------------------------

iostat -x after I stopped the update process and checkpointing is done:
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            0.00    0.00    0.00    0.00    0.00  100.00

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s
avgrq-sz avgqu-sz   await  svctm  %util
xvdap1            0.00     0.00    0.00    0.00     0.00     0.00
0.00     0.00    0.00   0.00   0.00
xvdf              0.00     0.00    0.00    0.00     0.00     0.00
0.00     0.00    0.00   0.00   0.00
xvdg              0.00     0.00    0.00    0.00     0.00     0.00
0.00     0.00    0.00   0.00   0.00

No activity at all.

---------------------------------

iostat -x after I started the select queries after the updates:
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
            2.09    0.00    1.49   12.15    0.00   84.26

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s
avgrq-sz avgqu-sz   await  svctm  %util
xvdap1            0.00     0.00    0.00    0.00     0.00     0.00
0.00     0.00    0.00   0.00   0.00
xvdf              0.00     8.00    0.00    2.00     0.00    80.00
40.00     0.00    2.00   2.00   0.40
xvdg              0.00  7844.00    1.00 1098.00     8.00 82336.00
74.93    58.27   59.39   0.70  77.20

Heavy writes to the WAL volume.

select * from pg_stat_activity;
  datid | datname | procpid | usesysid | usename  | application_name |
client_addr | client_hostname | client_port |
backend_start         |          xact_start           |          qu
ery_start          | waiting |                         current_query

-------+---------+---------+----------+----------+------------------+-------------+-----------------+-------------+-------------------------------+-------------------------------+------------
-------------------+---------+---------------------------------------------------------------
  16385 | lars    |    2654 |    16384 | lars     |                  |
127.0.0.1   |                 |       44972 | 2011-07-12
18:44:09.479581+00 | 2011-07-12 18:50:32.629412+00 | 2011-07-12
18:50:32.629473+00 | f       | select count(*) from test where tenant =
$1 and created_date = $2
  16385 | lars    |    2658 |       10 | postgres | psql
|             |                 |          -1 | 2011-07-12
18:49:02.675436+00 | 2011-07-12 18:50:32.631013+00 | 2011-07-12
18:50:32.631013+00 | f       | select * from pg_stat_activity;
  16385 | lars    |    2660 |    16384 | lars     | psql
|             |                 |          -1 | 2011-07-12
18:49:45.711643+00 |                               |
                    | f       | <IDLE>
(3 rows)