Bug 1438232

Summary: gvfs-udisks2-volume-monitor excessive CPU usage during raid check
Product: [Fedora] Fedora Reporter: Paul Howarth <paul>
Component: udisks2Assignee: Vojtech Trefny <vtrefny>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 25CC: alexl, mcatanzaro, oholy, paul, vtrefny
Target Milestone: ---Keywords: Reopened
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: udisks2-2.6.5-1.fc26 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-05-22 07:02:37 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
udisksctl monitor output none

Description Paul Howarth 2017-04-02 08:06:10 UTC 
Description of problem:
gvfs-udisks2-volume-monitor gobbles 100% CPU when my system is doing its weekly RAID check:

top - 08:47:55 up 44 days, 16:45,  7 users,  load average: 5.16, 5.16, 5.19
Tasks: 643 total,   2 running, 640 sleeping,   0 stopped,   1 zombie
%Cpu(s):  7.0 us,  9.7 sy,  0.0 ni, 65.9 id, 17.1 wa,  0.2 hi,  0.1 si,  0.0 st
KiB Mem : 32626844 total,   556228 free, 21471528 used, 10599088 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  8695992 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
16460 paul      20   0  482324  68548   4120 R 106.0  0.2 604:44.10 gvfs-udisks2-vo
10936 paul      20   0 6415828 2.676g 138860 S  22.6  8.6  15230:37 firefox
 5512 qemu      20   0 4308684 3.063g   7400 S   7.3  9.8   4656:23 qemu-system-x86
 5355 qemu      20   0 5457992 3.906g   4596 S   6.0 12.6   4255:09 qemu-system-x86
   29 root      20   0       0      0      0 S   2.0  0.0  33:33.35 rcuos/2
  956 root      20   0       0      0      0 S   2.0  0.0  41:09.79 md123_raid1
 3094 paul       9 -11 3718908  31916  25184 S   1.3  0.1 475:17.47 pulseaudio
15341 paul      20   0 2295656 291620  51048 S   1.0  0.9 614:51.68 chrome
 3016 paul      20   0 3579680 869972 105736 S   0.7  2.7 261:02.84 gnome-shell
21393 root      20   0       0      0      0 D   0.7  0.0   1:29.50 md123_resync
  469 root       0 -20       0      0      0 S   0.3  0.0   2:57.01 kworker/0:1H
 1362 root      20   0       0      0      0 D   0.3  0.0   7:20.10 jbd2/dm-16-8
 2359 gdm       20   0 1277716  15108   6232 S   0.3  0.0   9:11.07 gnome-settings-
 5092 apache    20   0  299052  12972   7944 S   0.3  0.0   0:01.47 httpd
 5275 paul      20   0 1603492 176464  29992 S   0.3  0.5 109:07.40 virt-manager
12662 root      20   0  539776 261180   4960 S   0.3  0.8   4:31.38 bacula-fd

This really slows down my backup when /etc/cron.d/raid-check kicks off on Sunday mornings.

It looks very similar to issues I (and others) used to have with 
gvfs-gdu-volume-monitor on older versions of Fedora/Ubuntu, e.g.
https://bugzilla.redhat.com/show_bug.cgi?id=600592
https://bugs.launchpad.net/ubuntu/+source/gnome-disk-utility/+bug/890337

Version-Release number of selected component (if applicable):
gvfs-1.30.4-1.fc25.x86_64

How reproducible:
Happens every Sunday morning. Could probably trigger it manually using /usr/sbin/raid-check on a system with mdraid devices.
Comment 1 Ondrej Holy 2017-04-04 08:05:31 UTC 
Thanks for your bug report. It produces probably too many events, which needs to be handled by the monitor...

What events do you see using "udisksctl monitor" during the check? Are some events printed also by "gvfs-mount -o"?
Comment 2 Paul Howarth 2017-04-06 11:33:45 UTC 
Created attachment 1269348 [details]
udisksctl monitor output

(In reply to Ondrej Holy from comment #1)
> Thanks for your bug report. It produces probably too many events, which
> needs to be handled by the monitor...
> 
> What events do you see using "udisksctl monitor" during the check? Are some
> events printed also by "gvfs-mount -o"?

No output from "gvfs-mount -o"; lots of activity from "udisksctl monitor" as per attachment.
Comment 3 Ondrej Holy 2017-04-07 08:25:58 UTC 
Thanks.

Hmm, GVfs rereads configuration of all mounts, volumes, and drives with each "changed" [1] signal for UDisksClient. So, it is a quite problem if something (i.e. raid-check) generates tons of changes. The docs said that it is rate limited, but obviously, it is not enough. Unfortunately, all those events are not interesting for GVfs, because there isn't any output from "gvfs-mount -o"...

Vojtech, don't you have any idea what we can do with it? Maybe would be nice to have a way for configuring rate limiting, and interesting events...

[1] https://udisks.freedesktop.org/docs/latest/UDisksClient.html#UDisksClient-changed
Comment 4 Vojtech Trefny 2017-05-02 08:45:57 UTC 
The "change" signal is emitted for every property change, but it sometimes doesn't make sense -- we emit the signal even for progress related changes (e.g. "SyncRemainingTime" here for the RAID check) and "job objects" (DBus objects representing the progress).

We will fix this in udisks and emit the "change" signal only if the device/format is actually changed and not for these "progress" changes.
Comment 5 Fedora Update System 2017-05-15 12:37:04 UTC 
udisks2-2.6.5-1.fc26 has been submitted as an update to Fedora 26. https://bodhi.fedoraproject.org/updates/FEDORA-2017-b1fd799ba3
Comment 6 Fedora Update System 2017-05-15 22:05:45 UTC 
udisks2-2.6.5-1.fc26 has been pushed to the Fedora 26 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-b1fd799ba3
Comment 7 Fedora Update System 2017-05-16 00:56:38 UTC 
udisks2-2.6.5-1.fc26 has been pushed to the Fedora 26 stable repository. If problems still persist, please make note of it in this bug report.
Comment 8 Paul Howarth 2017-05-16 07:27:16 UTC 
This is an F-25 bug: is there any plan of doing a fix there?
Comment 9 Fedora Update System 2017-05-16 14:05:32 UTC 
storaged-2.6.2-4.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2017-f18713a47e
Comment 10 Vojtech Trefny 2017-05-17 06:10:51 UTC 
Paul Howarth: F25 uses storaged. I've submitted new build with patch to fix this to bodhi.
Comment 11 Fedora Update System 2017-05-17 23:11:52 UTC 
storaged-2.6.2-4.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-f18713a47e
Comment 12 Fedora Update System 2017-05-22 07:02:37 UTC 
storaged-2.6.2-4.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.
Comment 13 Paul Howarth 2017-05-30 13:18:33 UTC 
The storaged update has certainly had a beneficial effect for me (following a reboot) - thanks!
Comment 14 Paul Howarth 2017-06-04 09:43:05 UTC 
Perhaps I commented too soon. This morning it's gobbling CPU again, though maybe not as much as before. I'm getting stuff like this from "udisksctl monitor":

# udisksctl monitor
Monitoring the udisks daemon. Press Ctrl+C to exit.
10:41:00.731: The udisks-daemon is running (name-owner :1.59).
10:41:01.610: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496538943809595
  Rate:                 21525504
10:41:01.610: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4523707911
  SyncRate:                     21525504
10:41:02.610: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496539013148962
  Rate:                 21182464
  Progress:             0.39542758613949125
10:41:02.610: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4593047278
  SyncRate:                     21182464
  SyncCompleted:                0.39542758613949125
10:41:03.610: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496539068882190
  Rate:                 20928512
10:41:03.610: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4648780506
  SyncRate:                     20928512
10:41:04.610: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496538981615726
  Rate:                 21328896
10:41:04.610: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4561514042
  SyncRate:                     21328896
10:41:05.610: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496538977239964
  Rate:                 21349376
10:41:05.611: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4557138280
  SyncRate:                     21349376
10:41:06.610: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496538887459968
  Rate:                 21778432
10:41:06.610: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4467358284
  SyncRate:                     21778432
10:41:07.609: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496538977597529
  Rate:                 21322752
  Progress:             0.39613414824854043
10:41:07.610: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4557495845
  SyncRate:                     21322752
  SyncCompleted:                0.39613414824854043
10:41:08.610: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496538822826620
  Rate:                 22072320
10:41:08.610: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4402724936
  SyncRate:                     22072320
10:41:09.611: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496538768559162
  Rate:                 22347776
10:41:09.611: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4348457478
  SyncRate:                     22347776
10:41:10.610: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496538915849279
  Rate:                 21615616
10:41:10.610: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4495747595
  SyncRate:                     21615616
10:41:11.610: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496538867183970
  Rate:                 21852160
10:41:11.610: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4447082286
  SyncRate:                     21852160
10:41:12.610: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496538938874025
  Rate:                 21473280
  Progress:             0.39703822195579652
10:41:12.610: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4518772341
  SyncRate:                     21473280
  SyncCompleted:                0.39703822195579652
10:41:13.610: /org/freedesktop/UDisks2/jobs/14: org.freedesktop.UDisks2.Job: Properties Changed
  ExpectedEndTime:      1496539154720251
  Rate:                 20494336
10:41:13.610: /org/freedesktop/UDisks2/mdraid/62e4a852_e89afb38_9e06909d_5c8f1dad: org.freedesktop.UDisks2.MDRaid: Properties Changed
  SyncRemainingTime:            4734618567
  SyncRate:                     20494336