Re: WAL prefetch

I continue my experiments with WAL prefetch.
I have embedded prefetch in Postgres: now walprefetcher is started 
together with startup process and is able to help it to speedup recovery.
The patch is attached.

Unfortunately result is negative (at least at my desktop: SSD, 16Gb 
RAM). Recovery with prefetch is 3 times slower than without it.
What I am doing:

Configuration:
     max_wal_size=min_wal_size=10Gb,
     shared)buffers = 1Gb
Database:
      pgbench -i -s 1000
Test:
      pgbench -c 10 -M prepared -N -T 100 -P 1
      pkill postgres
      echo 3 > /proc/sys/vm/drop_caches
      time pg_ctl -t 1000 -D pgsql -l logfile start

Without prefetch it is 19 seconds (recovered about 4Gb of WAL), with 
prefetch it is about one minute. About 400k blocks are prefetched.
CPU usage is small (<20%), both processes as in "Ds" state.

vmstat without prefetch shows the following output:

procs -----------memory---------- ---swap-- -----io---- -system-- 
------cpu-----
  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy 
id wa st
0  2 2667964 11465832   7892 2515588    0    0 344272     2 6129 22290  
8  4 84  5  0
  3  1 2667960 10013900   9516 3963056    6    0 355606  8772 7412 25228 
12  6 74  8  0
  1  0 2667960 8526228  11036 5440192    0    0 366910   242 6123 19476  
8  5 83  3  0
  1  1 2667960 7824816  11060 6141920    0    0 166860 171638 9581 
24746  4  4 79 13  0
  0  4 2667960 7822824  11072 6143788    0    0   264 376836 19292 
49973  1  3 69 27  0
  1  0 2667960 7033140  11220 6932400    0    0 188810 168070 14610 
41390  5  4 72 19  0
  1  1 2667960 5739616  11384 8226148    0    0 254492 57884 6733 19263  
8  5 84  4  0
  0  3 2667960 5024380  11400 8941532    0    0     8 398198 18164 
45782  2  5 70 23  0
  0  0 2667960 5020152  11428 8946000    0    0   168 69128 3918 10370  
2  1 91  6  0

with prefetch:

procs -----------memory---------- ---swap-- -----io---- -system-- 
------cpu-----
  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy 
id wa st
0  2 2651816 12340648  11148 1564420    0    0 178980    96 4411 14237  
5  2 90  3  0
  2  0 2651816 11771612  11712 2132180    0    0 169572     0 6388 
18244  5  3 72 20  0
  2  0 2651816 11199248  12008 2701960    0    0 168966   162 6677 
18816  5  3 72 20  0
  1  3 2651816 10660512  12028 3241604    0    0 162666    16 7065 
21668  6  5 69 20  0
  0  2 2651816 10247180  12052 3653888    0    0 131564 18112 7376 
22023  6  3 69 23  0
  0  2 2651816 9850424  12096 4064980    0    0 133158   238 6398 17557  
4  2 71 22  0
  2  0 2651816 9456616  12108 4459456    0    0 134702    44 6219 16665  
3  2 73 22  0
  0  2 2651816 9161336  12160 4753868    0    0 111168 74408 8038 20440  
3  3 69 25  0
  3  0 2651816 8810336  12172 5106068    0    0 134694     0 6251 16978  
4  2 73 22  0
  0  2 2651816 8451924  12192 5463692    0    0 137546    80 6264 16930  
3  2 73 22  0
  1  1 2651816 8108000  12596 5805856    0    0 135212    10 6218 16827  
4  2 72 22  0
  1  3 2651816 7793992  12612 6120376    0    0 135072     0 6233 16736  
3  2 73 22  0
  0  2 2651816 7507644  12632 6406512    0    0 134830    90 6267 16910  
3  2 73 22  0
  0  2 2651816 7246696  12776 6667804    0    0 122656 51820 7419 19384  
3  3 71 23  0
  1  2 2651816 6990080  12784 6924352    0    0 121248 55284 7527 19794  
3  3 71 23  0
  0  3 2651816 6913648  12804 7000376    0    0 36078 295140 14852 
37925  2  3 67 29  0
  0  2 2651816 6873112  12804 7040852    0    0 19180 291330 16167 
41711  1  3 68 28  0
  5  1 2651816 6641848  12812 7271736    0    0 107696    68 5760 15301  
3  2 73 22  0
  3  1 2651816 6426356  12820 7490636    0    0 103412     0 5942 15994  
3  2 72 22  0
  0  2 2651816 6195288  12824 7720720    0    0 104446     0 5605 14757  
3  2 73 22  0
  0  2 2651816 5946876  12980 7970912    0    0 113340    74 5980 15678  
3  2 71 24  0
  1  2 2651816 5655768  12984 8262880    0    0 137290     0 6235 16412  
3  2 73 21  0
  2  0 2651816 5359548  13120 8557072    0    0 137608    86 6309 16658  
3  2 73 21  0
  2  0 2651816 5068268  13124 8849136    0    0 137386     0 6225 16589  
3  2 73 21  0
  2  0 2651816 4816812  13124 9100600    0    0 120116 53284 7273 18776  
3  2 72 23  0
  0  2 2651816 4563152  13132 9353232    0    0 117972 54352 7423 19375  
3  2 73 22  0
  1  2 2651816 4367108  13144 9549712    0    0 51994 239498 10846 
25987  3  5 73 19  0
  0  0 2651816 4366356  13164 9549892    0    0   168 294196 14981 
39432  1  3 79 17  0


So as you can see, read speed with prefetch is smaller: < 130Mb/sec, 
while without prefetch up to 366Mb/sec.
My hypothesis is that prefetch flushes dirty pages from cache and as a 
result, more data has to be written and backends are more frequently 
blocked in write.

In any case - very upsetting result.
Any comments are welcome.

-- 
Konstantin Knizhnik
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company