Comment 10 for bug 1797566

Took a look at the environment again with John this morning:

1) found noticeable I/O use percentage by [jbd2/vda1-8] kernel thread (ext4 journal) in the Juju VM with a very low utilized bandwidth;

2) there was a bogus transaction which was not properly applied.

machine-0: 08:08:04 ERROR juju.worker.dependency "mgo-txn-resumer" manifold worker returned unexpected error: cannot resume transactions: cannot find document {cloudimagemetadata released:Australia Central 2:xenial:amd64:Hyper-V::default ubuntu cloud images} for applying transaction 5bc09f4d0348dc50cc9a3b2d_b33796ad

After forcing this transaction into a different state and thus resolving the problem with it, transaction processing times dropped from 200 seconds to about 30s. At the same time, the deployment process moved forward from adding machines to adding units so it is not 100% clear whether it had such a positive effect on the transaction processing speed.

~~~~

After this I stopped the Juju controller VM, moved it to a RAID-1 on top of 2 SSDs and brought it up.

Not surprisingly, on SSDs transaction processing times are much better because the latency is roughly 100 times smaller with the SSD mdraid1 in comparison to SATA HDD mdraid5:

machine-0: 11:21:37 TRACE juju.state.txn ran transaction in 0.022s []txn.Op{

ubuntu@jumphost:~$ sudo ioping /dev/mapper/sata-system
4 KiB from /dev/mapper/sata-system (block device 2 TiB): request=1 time=13.9 ms
4 KiB from /dev/mapper/sata-system (block device 2 TiB): request=2 time=10.6 ms
4 KiB from /dev/mapper/sata-system (block device 2 TiB): request=3 time=23.1 ms
4 KiB from /dev/mapper/sata-system (block device 2 TiB): request=4 time=19.1 ms
4 KiB from /dev/mapper/sata-system (block device 2 TiB): request=5 time=5.83 ms
4 KiB from /dev/mapper/sata-system (block device 2 TiB): request=6 time=13.4 ms
4 KiB from /dev/mapper/sata-system (block device 2 TiB): request=7 time=8.80 ms
^C
--- /dev/mapper/sata-system (block device 2 TiB) ioping statistics ---
7 requests completed in 6.48 s, 73 iops, 295.2 KiB/s
min/avg/max/mdev = 5.83 ms / 13.5 ms / 23.1 ms / 5.52 ms
ubuntu@jumphost:~$ sudo ioping /dev/mapper/ssds-root
4 KiB from /dev/mapper/ssds-root (block device 446.1 GiB): request=1 time=196 us
4 KiB from /dev/mapper/ssds-root (block device 446.1 GiB): request=2 time=132 us
4 KiB from /dev/mapper/ssds-root (block device 446.1 GiB): request=3 time=107 us
4 KiB from /dev/mapper/ssds-root (block device 446.1 GiB): request=4 time=101 us
4 KiB from /dev/mapper/ssds-root (block device 446.1 GiB): request=5 time=98 us
4 KiB from /dev/mapper/ssds-root (block device 446.1 GiB): request=6 time=214 us
4 KiB from /dev/mapper/ssds-root (block device 446.1 GiB): request=7 time=234 us
4 KiB from /dev/mapper/ssds-root (block device 446.1 GiB): request=8 time=234 us
4 KiB from /dev/mapper/ssds-root (block device 446.1 GiB): request=9 time=90 us
^C
--- /dev/mapper/ssds-root (block device 446.1 GiB) ioping statistics ---
9 requests completed in 8.16 s, 6.40 k iops, 25.0 MiB/s
min/avg/max/mdev = 90 us / 156 us / 234 us / 58 us

So, I think it could be a combination of multiple factors:

1) running mongodb on top of ext4 with qcow2 on top of mdraid5 underneath;
2) problematic behavior in the Juju transaction processing layer occurring when the underlying storage has a high latency.

I do not have a clear view as to why the issue manifested itself only after a relatively long lifetime (at least about a week) and with re-deployments involved.

Bootstrapping a new controller on top of a VM with its image placed on RAID5 as before should be useful in further troubleshooting.