Note: This is a beta release of Red Hat Bugzilla 5.0. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Also email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback here.
Bug 1511109 - RFE: attempt to quiet vdo remove messages
Summary: RFE: attempt to quiet vdo remove messages
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: vdo
Version: 7.5
Hardware: x86_64
OS: Linux
unspecified
low
Target Milestone: rc
: ---
Assignee: Thomas Jaskiewicz
QA Contact: Jakub Krysl
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-11-08 17:27 UTC by Corey Marthaler
Modified: 2019-03-06 01:00 UTC (History)
4 users (show)

Fixed In Version: 6.1.0.67
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-04-10 15:47:46 UTC


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHEA-2018:0871 None None None 2018-04-10 15:48:08 UTC

Description Corey Marthaler 2017-11-08 17:27:19 UTC
Description of problem:
The following seems quite noisy for a simple remove operation.

[root@harding-02 ~]# vdo create --name foo --device /dev/mapper/mpatha
Creating VDO foo
Starting VDO foo
Starting compression on VDO foo
VDO instance 4 volume is ready at /dev/mapper/foo


[root@harding-02 ~]# vdo remove --name foo
Removing VDO foo
Stopping VDO foo




[88649.049715] kvdo4:dmsetup: suspending device 'foo'
Nov  8 11:22:59 harding-02 kernel: kvdo4:dmsetup: suspending device 'foo'
Nov  8 11:22:59 harding-02 multipathd: dm-18: remove map (uevent)
Nov  8 11:22:59 harding-02 multipathd: dm-18: devmap not registered, can't remove
Nov  8 11:22:59 harding-02 systemd: Stopping LVM2 PV scan on device 253:18...
Nov  8 11:22:59 harding-02 lvm: /sys/dev/block/253:18/dm/uuid: fgets failed: Invalid argument
Nov  8 11:22:59 harding-02 lvm: Device 253:18 not found. Cleared from lvmetad cache.
Nov  8 11:22:59 harding-02 systemd: Stopped LVM2 PV scan on device 253:18.
[88649.133706] kvdo4:packerQ: compression is disabled
[88649.139117] kvdo4:packerQ: compression is enabled
[88649.144432] kvdo4:dmsetup: device 'foo' suspended
Nov  8 11:22:59 [88649.149961] kvdo4:packerQ: compression is disabled
harding-02 kerne[88649.156851] kvdo4:packerQ: compression is enabled
l: kvdo4:packerQ[88649.163741] kvdo4:dmsetup: : compression isstopping device 'foo' disabled
Nov  
8 11:22:59 harding-02 kernel: kv[88649.175751] kvdo4:dmsetup: do4:packerQ: comSetting UDS index target state to closedpression is enab
led
Nov  8 11:2[88649.186896] uds: kvdo4:dedupeQ: 2:59 harding-02 Closed block context (5)kernel: kvdo4:dm[88649.193125] kvdo4:dmsetup: Setting UDS index target state to closed

[88649.204220] 
setup: device 'f[88649.206177] uds: kvdo4:dedupeQ: oo' suspended
NClosing index session (7, ffff88aaa92e16c0)
ov  8 11:22:59 harding-02 kernel[88649.218616] uds: kvdo4:dedupeQ: : kvdo4:packerQ:index_0: beginning save (vcn 4294967295)
 compression is disabled
Nov  8 11:22:59 harding-02 kernel: kvdo4:packerQ: compression is enabled
Nov  8 11:22:59 harding-02 kernel: kvdo4:dmsetup: stopping device 'foo'
Nov  8 11:22:59 harding-02 kernel: kvdo4:dmsetup: Setting UDS index target state to closed
Nov  8 11:22:59 harding-02 kernel: uds: kvdo4:dedupeQ: Closed block context (5)
Nov  8 11:22:59 harding-02 kernel: 
Nov  8 11:22:59 harding-02 kernel: kvdo4:dmsetup: 
Nov  8 11:22:59 harding-02 kernel: Setting UDS index target state to closed
Nov  8 11:22:59 harding-02 kernel: 
Nov  8 11:22:59 harding-02 kernel: 
Nov  8 11:22:59 harding-02 kernel: uds: kvdo4:dedupeQ: Closing index session (7, ffff88aaa92e16c0)
Nov  8 11:22:59 harding-02 kernel: uds: kvdo4:dedupeQ: index_0: beginning save (vcn 4294967295)
[88649.443198] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.454318] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 [88649.466970] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.479607] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
harding-02 kerne[88649.492250] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.504880] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
[88649.517472] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.528583] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
[88649.541160] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.552273] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
l: uds: kvdo4:de[88649.564869] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.577522] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
dupeQ: queue 'zo[88649.590148] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.602764] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
neIndexWorker' b[88649.615393] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.628024] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
atch lengths: 22[88649.640717] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.653294] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
[88649.665885] uds: kvdo4:dedupeQ:  samples in [1 .queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.678538] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
. 1] sum 22 sums[88649.691187] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.703835] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
[88649.716446] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.727565] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
[88649.740149] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.751392] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
[88649.763988] uds: kvdo4:dedupeQ: q 22
Nov  8 11:queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.776647] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
[88649.789243] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.800364] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
23:00 harding-02[88649.813003] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
[88649.825619] uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneInd[88649.855468] uds: kvdo4:dedupeQ: exWorker' batch Closed index session (0, ffff88aaa92e16c0)
lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupe[88649.902203] kvdo4:dmsetup: Q: queue 'zoneIndevice 'foo' stoppeddexWorker' wait 
microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' batch lengths: 22 samples in [1 .. 1] sum 22 sumsq 22
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: queue 'zoneIndexWorker' wait microseconds: 21 samples in [12 .. 1000] sum 5278 sumsq 3086016
Nov  8 11:23:00 harding-02 kernel: uds: kvdo4:dedupeQ: Closed index session (0, ffff88aaa92e16c0)
Nov  8 11:23:00 harding-02 kernel: kvdo4:dmsetup: device 'foo' stopped
Nov  8 11:23:00 harding-02 multipathd: dm-18: remove map (uevent)




Version-Release number of selected component (if applicable):
3.10.0-772.el7.x86_64

lvm2-2.02.176-2.el7    BUILT: Fri Nov  3 07:46:53 CDT 2017
lvm2-libs-2.02.176-2.el7    BUILT: Fri Nov  3 07:46:53 CDT 2017
lvm2-cluster-2.02.176-2.el7    BUILT: Fri Nov  3 07:46:53 CDT 2017
lvm2-lockd-2.02.176-2.el7    BUILT: Fri Nov  3 07:46:53 CDT 2017
lvm2-python-boom-0.8-2.el7    BUILT: Fri Nov  3 07:48:54 CDT 2017
cmirror-2.02.176-2.el7    BUILT: Fri Nov  3 07:46:53 CDT 2017
device-mapper-1.02.145-2.el7    BUILT: Fri Nov  3 07:46:53 CDT 2017
device-mapper-libs-1.02.145-2.el7    BUILT: Fri Nov  3 07:46:53 CDT 2017
device-mapper-event-1.02.145-2.el7    BUILT: Fri Nov  3 07:46:53 CDT 2017
device-mapper-event-libs-1.02.145-2.el7    BUILT: Fri Nov  3 07:46:53 CDT 2017
device-mapper-persistent-data-0.7.3-2.el7    BUILT: Tue Oct 10 04:00:07 CDT 2017
sanlock-3.5.0-1.el7    BUILT: Wed Apr 26 09:37:30 CDT 2017
sanlock-lib-3.5.0-1.el7    BUILT: Wed Apr 26 09:37:30 CDT 2017
vdo-6.1.0.34-8    BUILT: Fri Nov  3 06:58:45 CDT 2017
kmod-kvdo-6.1.0.34-7.el7    BUILT: Fri Nov  3 06:44:06 CDT 2017

Comment 3 Louis Imershein 2017-11-08 17:37:55 UTC
While I agree it's noisy, it's also a pretty rare operation, and we want to make it easy to debug if it goes wrong.  So I'd like to hear from engineering and QE on their thoughts on this one before I give it a pm_ack.

-louis

Comment 4 Andy Walsh 2017-11-08 17:52:44 UTC
I tend to agree with Louis.  Creating and removing volumes isn't something that you're going to be doing repetitively (unless you're testing or running into issues).  And if you were to run into a problem, the more info the better, IMO.

Though, I will note that creating/removing an LVM volume doesn't generate so much noise, so I'm open to opinions on it for sure.

Comment 5 Jakub Krysl 2017-11-09 09:32:32 UTC
I agree with Corey, so much noise might be even confusing for common user, who might think something is wrong. But also this information is crucial for debugging, so hiding it under verbosity level is probably the way to go here.
vdo already has --verbose, so why not add -v /-vv / -vvv as is the custom with many other utilities?

Comment 6 Louis Imershein 2017-11-09 21:19:51 UTC
Ok, I've given a pm_ack, however we still need one from QE and devel before we should pick this one up.

Comment 8 Jakub Krysl 2017-11-21 13:29:00 UTC
vdo-6.1.0.55-10

[ 5025.087355] kvdo1:dmsetup: suspending device 'vdo' 
[ 5025.228600] kvdo1:packerQ: compression is disabled 
[ 5025.233443] kvdo1:packerQ: compression is enabled 
[ 5025.238430] kvdo1:dmsetup: device 'vdo' suspended 
[ 5025.243238] kvdo1:packerQ: compression is disabled 
[ 5025.248101] kvdo1:packerQ: compression is enabled 
[ 5025.252911] kvdo1:dmsetup: stopping device 'vdo' 
[ 5025.260447] kvdo1:dmsetup: Setting UDS index target state to closed 
[ 5025.269245] kvdo1:dmsetup: Setting UDS index target state to closed 
[ 5025.285464] uds: kvdo1:dedupeQ: index_0: beginning save (vcn 4294967295) 
[ 5028.166949] kvdo1:dmsetup: device 'vdo' stopped

The noisiness is gone, but there are some duplications. Is there a way to get rid of them too?

Comment 9 Thomas Jaskiewicz 2017-11-22 00:42:47 UTC
Highly likely we can remove some duplications.  I will take a look at it.

Comment 10 Jakub Krysl 2017-11-22 08:53:31 UTC
Ok, giving back.

Comment 11 Thomas Jaskiewicz 2017-11-28 22:05:05 UTC
The "Setting UDS Index target state ..." duplicate has been removed.
Were there any other messages that you had in mind to remove or change?

Comment 12 Jakub Krysl 2017-11-29 09:07:11 UTC
Thanks Tom.

The other part is this:
[ 5025.087355] kvdo1:dmsetup: suspending device 'vdo' 
[ 5025.228600] kvdo1:packerQ: compression is disabled 
[ 5025.233443] kvdo1:packerQ: compression is enabled 
[ 5025.238430] kvdo1:dmsetup: device 'vdo' suspended 
[ 5025.243238] kvdo1:packerQ: compression is disabled 
[ 5025.248101] kvdo1:packerQ: compression is enabled 
[ 5025.252911] kvdo1:dmsetup: stopping device 'vdo' 

As you can see the kvdo disables compression and enables it again. Twice. What is the reason for this behavior and is it possible to remove one / both of them?

Comment 13 Thomas Jaskiewicz 2017-11-29 22:13:08 UTC
Both suspend and stop want to make sure we have completed all I/O requests that have been started.  The pair of disabled/enabled messages are how we kick all the requests that are waiting in the packer queue and force them to complete.

It is a simple change to not do this disable/enable pair if we know that there are no requests in progress.  In practice, this means that the second pair will never be needed since there will be no requests in progress.

Also, because the device should be idle, the first pair will also not be needed.

Comment 15 Jakub Krysl 2017-12-04 13:06:20 UTC
vdo-6.1.0.72-12:

[  735.651507] kvdo0:dmsetup: suspending device 'vdo'
[  735.862196] kvdo0:dmsetup: device 'vdo' suspended
[  735.883451] kvdo0:dmsetup: stopping device 'vdo'
[  735.905596] kvdo0:dmsetup: uds: kvdo0:dedupeQ: index_0: beginning save (vcn 4294967295)

[  735.941478] Setting UDS index target state to closed
[  736.093439] kvdo0:dmsetup: device 'vdo' stopped

The UDS duplicate is gone and so are all the compression messages.

Comment 18 errata-xmlrpc 2018-04-10 15:47:46 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2018:0871


Note You need to log in before you can comment on or make changes to this bug.