instance deletion takes a while and blocks nova-compute

[Junien F]

Hi,

I have a cloud running xenial/mitaka (with 18.02 charms).

Sometimes, an instance will take minutes to delete. I tracked down the time taken to be file deletion :

Apr 23 07:23:00 hostname nova-compute[54255]: 2018-04-23 07:23:00.920 54255 INFO nova.virt.libvirt.driver [req-35ccfe64-9280-4de6-ae88-045ca91bf90f bc0ab055427645aca4ed09266e85b1db 1cb457a8302543fea067e5f14b5241e7 - - -] [instance: 97731f51-63be-4056-869f-084b38580b9a] Deleting instance files /srv/nova/instances/97731f51-63be-4056-869f-084b38580b9a_del

Apr 23 07:27:33 hostname nova-compute[54255]: 2018-04-23 07:27:33.767 54255 INFO nova.virt.libvirt.driver [req-35ccfe64-9280-4de6-ae88-045ca91bf90f bc0ab055427645aca4ed09266e85b1db 1cb457a8302543fea067e5f14b5241e7 - - -] [instance: 97731f51-63be-4056-869f-084b38580b9a] Deletion of /srv/nova/instances/97731f51-63be-4056-869f-084b38580b9a_del complete

As you can see, 4 minutes and 33 seconds have elapsed between the 2 lines. nova-compute logs absolutely _nothing_ during this time. Periodic tasks are not run, etc... Generally, a deletion takes a few seconds top.

The logs above are generally immediately followed by :

Apr 23 07:27:33 hostname nova-compute[54255]: 2018-04-23 07:27:33.771 54255 DEBUG oslo.messaging._drivers.impl_rabbit [req-35ccfe64-9280-4de6-ae88-045ca91bf90f bc0ab055427645aca4ed09266e85b1db 1cb457a8302543fea067e5f14b5241e7 - - -] Received recoverable error from kombu: on_error /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/impl_rabbit.py:683

(which is error: [Errno 104] Connection reset by peer)

because nova-compute doesn't even maintain the rabbitmq connection (on the rabbitmq server I can see errors about "Missed heartbeats from client, timeout: 60s").

So nova-compute appears to be "frozen" during several minutes. This can cause problems because events can be missed, etc...

We have telegraf on this host, and there's little to no CPU, disk, network or memory activity at that time. Nothing relevant in kern.log either. And this is happening on 3 different architectures, so this is all very puzzling.

Is nova-compute supposed to be totally stuck while deleting instance files ? Have you ever seen something similar ?

I'm going to try to repro on queens.

Thanks
---
AlsaDevices:
 total 0
 crw-rw---- 1 root audio 116, 1 Jun 23 14:23 seq
 crw-rw---- 1 root audio 116, 33 Jun 23 14:23 timer
AplayDevices: Error: [Errno 2] No such file or directory
ApportVersion: 2.20.1-0ubuntu2.18
Architecture: ppc64el
ArecordDevices: Error: [Errno 2] No such file or directory
AudioDevicesInUse: Error: command ['fuser', '-v', '/dev/snd/seq', '/dev/snd/timer'] failed with exit code 1:
DistroRelease: Ubuntu 16.04
IwConfig: Error: [Errno 2] No such file or directory
Lsusb:
 Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
 Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Package: nova (not installed)
PciMultimedia:

ProcEnviron:
 TERM=screen-256color
 PATH=(custom, no user)
 LANG=en_US.UTF-8
 SHELL=/bin/bash
ProcFB:

ProcKernelCmdLine: root=UUID=bf574d52-09d7-4c9d-beb8-ccc542d50654 ro console=tty0 console=ttyS1,115200 panic=30 raid=noautodetect
ProcLoadAvg: 10.43 10.79 9.76 11/2237 15123
ProcSwaps:
 Filename Type Size Used Priority
 /swap.img file 8388544 0 -1
ProcVersion: Linux version 4.4.0-128-generic (buildd@bos02-ppc64el-001) (gcc version 5.4.0 20160609 (Ubuntu/IBM 5.4.0-6ubuntu1~16.04.9) ) #154-Ubuntu SMP Fri May 25 14:13:59 UTC 2018
ProcVersionSignature: Ubuntu 4.4.0-128.154-generic 4.4.131
RelatedPackageVersions:
 linux-restricted-modules-4.4.0-128-generic N/A
 linux-backports-modules-4.4.0-128-generic N/A
 linux-firmware 1.157.20
RfKill: Error: [Errno 2] No such file or directory
Tags: xenial uec-images xenial uec-images xenial uec-images
Uname: Linux 4.4.0-128-generic ppc64le
UnreportableReason: The report belongs to a package that is not installed.
UpgradeStatus: No upgrade log present (probably fresh install)
UserGroups:

_MarkForUpload: False
cpu_cores: Number of cores present = 20
cpu_coreson: Number of cores online = 20
cpu_dscr: DSCR is 0
cpu_freq:
 min: 1.201 GHz (cpu 48)
 max: 3.710 GHz (cpu 112)
 avg: 2.615 GHz
cpu_runmode:
 Could not retrieve current diagnostics mode,
 No kernel interface to firmware
cpu_smt: SMT is off

[Junien F (axino)]

Also, nova-scheduler or nova-api-os-compute will log the following lines (a few times per minute) while this is happening :

Apr 23 07:24:47 juju-8c74e6-4-lxd-7 nova-scheduler[15786]: 2018-04-23 07:24:47.785 15786 DEBUG nova.servicegroup.drivers.db [req-1573c400-116c-4825-b108-3291a014b0e9 bc0ab055427645aca4ed09266e85b1db 1cb457a8302543fea067e5f14b5241e7 - - -] Seems service nova-compute on host hostname is down. Last heartbeat was 2018-04-23 07:22:56. Elapsed time is 111.785844 is_up /usr/lib/python2.7/dist-packages/nova/servicegroup/drivers/db.py:82

[Corey Bryant (corey.bryant)]

Hi Junien,

Thanks for reporting this. It would be great to see if it's reproducible on queens. A couple of questions:
* Is nova-compute actually up the whole time this is happening?
* Are you running with debug on?
* Could we get any more details by attaching strace to nova-compute?

Thanks,
Corey

[Junien F (axino)]

Hi Corey,

* I assume nova-compute is up the whole time because its PID doesn't change
* I'm running with debug on
* I'm going to try getting more details with strace, but the problem is I can't repro the problem - it just sometimes happen...

No luck on repro-ing on queens so far, but the cloud is much, much less used.

[Junien F (axino)]

OK, the bug happened again with strace attached to nova-compute. Once again, there's little to no IO/network while it happens. memory is stable. CPU is at least 50% idle (and the rest of it largely user mode). Nothing in dmesg.

nova-compute logs are as follow :
2018-04-25 14:48:04.587 54255 INFO nova.virt.libvirt.driver [req-85551d96-713d-499d-b7ff-9f911fb0842d bc0ab055427645aca4ed09266e85b1db 1cb457a8302543fea067e5f14b5241e7 - - -] [instance: bd17aeef-240b-489c-8bb6-b37167155174] Deleting instance files /srv/nova/instances/bd17aeef-240b-489c-8bb6-b37167155174_del

2018-04-25 14:52:06.350 54255 INFO nova.virt.libvirt.driver [req-85551d96-713d-499d-b7ff-9f911fb0842d bc0ab055427645aca4ed09266e85b1db 1cb457a8302543fea067e5f14b5241e7 - - -] [instance: bd17aeef-240b-489c-8bb6-b37167155174] Deletion of /srv/nova/instances/bd17aeef-240b-489c-8bb6-b37167155174_del complete

So it took 4 minutes to remove the files. Looking at strace, it's mostly a single thread doing (unrelated) stuff in the meantime : https://pastebin.canonical.com/p/w63Z62r4zN/ (sorry, Canonical-only link).

The first line is the unlink, and you can see the syscall finishing at the bottom. Looking at this, I'm fairly convinced that it's the unlink() itself that took 4 minutes. So perhaps a kernel bug ?

I'm now running "perf record sleep 60" in a loop to try and diagnose what the hell the system is doing during that time.

[Corey Bryant (corey.bryant)]

Thanks for continuing to dig into this.

Comparing your nova-compute logs and the strace unlink details, the timestamps do seem to point to unlink causing the delay. Pasting the strace unlink output below inline with the nova-compute logs in order of occurrence:

nova-compute log:
2018-04-25 14:48:04.587 54255 INFO nova.virt.libvirt.driver [req-85551d96-713d-499d-b7ff-9f911fb0842d bc0ab055427645aca4ed09266e85b1db 1cb457a8302543fea067e5f14b5241e7 - - -] [instance: bd17aeef-240b-489c-8bb6-b37167155174] Deleting instance files /srv/nova/instances/bd17aeef-240b-489c-8bb6-b37167155174_del

strace unlink:
54255 14:48:04.593792 unlink("/srv/nova/instances/bd17aeef-240b-489c-8bb6-b37167155174_del/disk" <unfinished ...>

strace unlink:
54255 14:52:06.349167 <... unlink resumed> ) = 0
54255 14:52:06.349430 unlink("/srv/nova/instances/bd17aeef-240b-489c-8bb6-b37167155174_del/disk.info") = 0

nova-compute log:
2018-04-25 14:52:06.350 54255 INFO nova.virt.libvirt.driver [req-85551d96-713d-499d-b7ff-9f911fb0842d bc0ab055427645aca4ed09266e85b1db 1cb457a8302543fea067e5f14b5241e7 - - -] [instance: bd17aeef-240b-489c-8bb6-b37167155174] Deletion of /srv/nova/instances/bd17aeef-240b-489c-8bb6-b37167155174_del complete

This might be worth passing by kernel folks to get their opinion.

[James Page (james-page)]

Raising a task for the kernel for an opinion on how to triage this problem further; Marking the nova task as Medium but leaving as New for now until we figure out what's going on - this is not a show stopped but is a pain.

[Ubuntu Kernel Bot (ubuntu-kernel-bot)]

This bug is missing log files that will aid in diagnosing the problem. While running an Ubuntu kernel (not a mainline or third-party kernel) please enter the following command in a terminal window:

apport-collect 1766543

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

[Junien F (axino)]

By the way the task blocks on the following :

==> /proc/54255/task/54255/stack <==
[<c000000000103a1c>] wakeup_preempt_entity.isra.6+0x7c/0x90
[<c000000000015df8>] __switch_to+0x1f8/0x350
[<c00000000054cd9c>] get_request+0x29c/0x910
[<c000000000550d64>] blk_queue_bio+0x164/0x500
[<c00000000054e274>] generic_make_request+0x154/0x310
[<c00000000054e504>] submit_bio+0xd4/0x1f0
[<c0000000003b805c>] ext4_io_submit+0x7c/0xb0
[<c0000000003b2938>] ext4_writepages+0x4a8/0xdd0
[<c000000000243090>] do_writepages+0x60/0xc0
[<c000000000230988>] __filemap_fdatawrite_range+0xf8/0x170
[<c000000000416378>] jbd2_journal_begin_ordered_truncate+0xe8/0x130
[<c0000000003b5c70>] ext4_evict_inode+0x530/0x5e0
[<c00000000030d488>] evict+0xf8/0x2a0
[<c0000000002fe668>] do_unlinkat+0x1a8/0x3a0
[<c000000000009284>] system_call+0x38/0xe4

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information

[Junien F (axino)]

apport information