[sheepdog-users] Very high wait time during recovery

[Liu Yuan]

On Mon, Apr 13, 2015 at 11:33:31PM +0200, Simon Hürlimann wrote:
> Hi
> 
> I'm using a 3 node Setup of sheepdog 0.7.5-1 as provided by Ubuntu
> 12.04.4 LTS with qemu. The VDIs have two copies.
> 
> I'm experiencing high wait time in the guests, even leading to some
> short outages during recovery or node kills. An actual occurrence was
> when I've 'dog node kill' one of the nodes. The other two nodes start
> recovery to ensure the two copy policy as far as I understand. During
> this, I get the following logs:
> 
> Apr 13 20:24:54   INFO [main] recover_object_main(624) object
> 7b7f0400001414 is recovered (1/70169)
> Apr 13 20:24:54   INFO [main] recover_object_main(624) object
> 7b7f0400000c5f is recovered (2/70169)
> [...]
> Apr 13 20:25:29   INFO [main] recover_object_main(624) object
> 3eb96700002d9f is recovered (1346/70169)
> Apr 13 20:25:29   INFO [main] recover_object_main(624) object
> b8729c00000255 is recovered (1347/70169)
> Apr 13 20:25:29   INFO [main] recover_object_main(624) object
> 3eb9670000003a is recovered (1348/70169)
> Apr 13 20:25:29  ERROR [io 28218] do_epoch_log_read(54) failed to open
> epoch 54 log, No such file or directory
> Apr 13 20:25:29  ERROR [io 28230] do_epoch_log_read(54) failed to open
> epoch 53 log, No such file or directory
> [...]
> Apr 13 20:25:29  ERROR [io 28234] do_epoch_log_read(54) failed to open
> epoch 2 log, No such file or directory
> Apr 13 20:25:29  ERROR [io 28235] do_epoch_log_read(54) failed to open
> epoch 1 log, No such file or directory
> Apr 13 20:25:29   INFO [main] recover_object_main(624) object
> b8729c00000329 is recovered (1350/70169)
> Apr 13 20:25:29   INFO [main] recover_object_main(624) object
> 3eb96700003017 is recovered (1351/70169)
> [...]
> Apr 13 20:26:16   INFO [main] recover_object_main(624) object
> 38499b00000041 is recovered (2053/70169)
> Apr 13 20:26:17   INFO [main] recover_object_main(624) object
> 43f30a0000003c is recovered (2054/70169)
> Apr 13 20:26:18   INFO [main] recover_object_main(624) object
> 7b7f0400001414 is recovered (1/45485)
> Apr 13 20:26:18   INFO [main] recover_object_main(624) object
> 7b7f0400000c5f is recovered (2/45485)
> Apr 13 20:26:18   INFO [main] recover_object_main(624) object
> eefb9700000f35 is recovered (3/45485)
> [...]
> Apr 13 20:26:19   INFO [main] recover_object_main(624) object
> eefb9700005897 is recovered (34123/45485)
> Apr 13 20:26:27   WARN [gway 28175] wait_forward_request(177) poll
> timeout 1, disks of some nodes or network is busy. Going to poll-wait again
> Apr 13 20:27:38  ERROR [gway 28175] wait_forward_request(212) fail
> c4cbc3000001cf, Node is killed
> Apr 13 20:27:38  ERROR [gway 28194] wait_forward_request(212) fail
> c4cbc3000001cf, Node is killed
> [...]
> Apr 13 20:27:38  ERROR [gway 28175] wait_forward_request(212) fail
> c4cbc3000001cf, Node is killed
> Apr 13 20:27:38  ERROR [gway 28194] wait_forward_request(212) fail
> c4cbc3000001cf, Node is killed
> Apr 13 20:27:38   INFO [main] recover_object_main(624) object
> 7b7f0400001414 is recovered (1/70169)
> Apr 13 20:27:38   INFO [main] recover_object_main(624) object
> 7b7f0400000c5f is recovered (2/70169)
> Apr 13 20:27:38   INFO [main] recover_object_main(624) object
> eefb9700000f35 is recovered (3/70169)
> [...]
> 
> Is this something that is fixed in newer versions?

Yes (as I hope). The newer version utlize multi-threaded recovery instead of
single thread recovery in your version. The speedy recovery is supposed to heal
the long response time problem.

Please try newer version and report back.

Thanks,
Yuan