udiskd high CPU usage with 4.0 git

udiskd high CPU usage with 4.0 git

[Prakash Punnoor]

[-- Attachment #1: Type: text/plain, Size: 816 bytes --]

Hi,

I noticed the udisks daemon (version 2.1.4) suddenly started using high
cpu (one core at 100%) with linux 4.0 git kernel. I bisected it to:

750f199ee8b578062341e6ddfe36c59ac8ff2dcb

And reverting it from current master (at
2cf3afcd4cbe0e32b8722fc291e9255de1b4d6c6) fixes my problem indeed.

I attached dmesg and config from
2cf3afcd4cbe0e32b8722fc291e9255de1b4d6c6 with
750f199ee8b578062341e6ddfe36c59ac8ff2dcb reverted. Any more infos
needed? I am actually using a raid5 array, if that matters:

Personalities : [raid6] [raid5] [raid4]
md127 : active raid5 sdd1[1] sdb1[3] sdc1[0]
      3907023872 blocks super 1.2 level 5, 512k chunk, algorithm 2 [3/3]
[UUU]

unused devices: <none>


The array uses systemd automount feature (x-systemd.automount).

Please CC me, as I am not subscribed.


Regards,

Prakash

[-- Attachment #2: config_2cf3afcd4cbe0e32b8722fc291e9255de1b4d6c6.xz --]
[-- Type: application/x-xz, Size: 15684 bytes --]

[-- Attachment #3: dmesg_2cf3afcd4cbe0e32b8722fc291e9255de1b4d6c6.xz --]
[-- Type: application/x-xz, Size: 13944 bytes --]

Re: udiskd high CPU usage with 4.0 git

[NeilBrown]

[-- Attachment #1: Type: text/plain, Size: 1281 bytes --]

On Sun, 08 Mar 2015 18:14:39 +0100 Prakash Punnoor <prakash@punnoor.de> wrote:

> Hi,
> 
> I noticed the udisks daemon (version 2.1.4) suddenly started using high
> cpu (one core at 100%) with linux 4.0 git kernel. I bisected it to:
> 
> 750f199ee8b578062341e6ddfe36c59ac8ff2dcb
> 
> And reverting it from current master (at
> 2cf3afcd4cbe0e32b8722fc291e9255de1b4d6c6) fixes my problem indeed.
> 
> I attached dmesg and config from
> 2cf3afcd4cbe0e32b8722fc291e9255de1b4d6c6 with
> 750f199ee8b578062341e6ddfe36c59ac8ff2dcb reverted. Any more infos
> needed? I am actually using a raid5 array, if that matters:
> 
> Personalities : [raid6] [raid5] [raid4]
> md127 : active raid5 sdd1[1] sdb1[3] sdc1[0]
>       3907023872 blocks super 1.2 level 5, 512k chunk, algorithm 2 [3/3]
> [UUU]
> 
> unused devices: <none>
> 
> 
> The array uses systemd automount feature (x-systemd.automount).
> 
> Please CC me, as I am not subscribed.
> 
> 
> Regards,
> 
> Prakash

Thanks for the report.
I can't reproduce this, or see what would cause it.

Can you please reproduce the problem and then run

  strace -o /tmp/udisks.trace -f -p `pidof udisksd`

for a few seconds, then interrupt and post the resulting '/tmp/udisks.trace'.

Thanks,
NeilBrown

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 811 bytes --]

Re: udiskd high CPU usage with 4.0 git

[Prakash Punnoor]

[-- Attachment #1: Type: text/plain, Size: 1342 bytes --]

On 09.03.2015 00:30, NeilBrown wrote:
> On Sun, 08 Mar 2015 18:14:39 +0100 Prakash Punnoor <prakash@punnoor.de> wrote:
> 
>> Hi,
>>
>> I noticed the udisks daemon (version 2.1.4) suddenly started using high
>> cpu (one core at 100%) with linux 4.0 git kernel. I bisected it to:
>>
>> 750f199ee8b578062341e6ddfe36c59ac8ff2dcb
>>
>> And reverting it from current master (at
>> 2cf3afcd4cbe0e32b8722fc291e9255de1b4d6c6) fixes my problem indeed.
>>
>> I attached dmesg and config from
>> 2cf3afcd4cbe0e32b8722fc291e9255de1b4d6c6 with
>> 750f199ee8b578062341e6ddfe36c59ac8ff2dcb reverted. Any more infos
>> needed? I am actually using a raid5 array, if that matters:
>>
>> Personalities : [raid6] [raid5] [raid4]
>> md127 : active raid5 sdd1[1] sdb1[3] sdc1[0]
>>       3907023872 blocks super 1.2 level 5, 512k chunk, algorithm 2 [3/3]
>> [UUU]
>>
>> unused devices: <none>
>>
>>
>> The array uses systemd automount feature (x-systemd.automount).
>>
>> Please CC me, as I am not subscribed.
>>
>>
>> Regards,
>>
>> Prakash
> 
> Thanks for the report.
> I can't reproduce this, or see what would cause it.
> 
> Can you please reproduce the problem and then run
> 
>   strace -o /tmp/udisks.trace -f -p `pidof udisksd`
> 
> for a few seconds, then interrupt and post the resulting '/tmp/udisks.trace'.

Hi, attached the trace.

Regards,

Prakash



[-- Attachment #2: udisks.trace.xz --]
[-- Type: application/x-xz, Size: 7464 bytes --]

Re: udiskd high CPU usage with 4.0 git

[Torsten Kaiser]

On Mon, Mar 9, 2015 at 12:30 AM, NeilBrown <neilb@suse.de> wrote:
> On Sun, 08 Mar 2015 18:14:39 +0100 Prakash Punnoor <prakash@punnoor.de> wrote:
>
>> Hi,
>>
>> I noticed the udisks daemon (version 2.1.4) suddenly started using high
>> cpu (one core at 100%) with linux 4.0 git kernel. I bisected it to:
>>
>> 750f199ee8b578062341e6ddfe36c59ac8ff2dcb

I had the same problem upgrading from 4.0-rc1 to 4.0-rc3.
I have just finished bisecting and "fixing" it.

My bisect points to the same commit.

Looking at udisksd with strace sees a loop of polling and then
accessing several md related sysfs files.
The only file that udisksd monitors and was changes by that commit was
"sync_action".

If I revert this part of the commit, my system works normal again:

 static struct md_sysfs_entry md_scan_mode =
- __ATTR_PREALLOC(sync_action, S_IRUGO|S_IWUSR, action_show, action_store);
+ __ATTR(sync_action, S_IRUGO|S_IWUSR, action_show, action_store);

It seems that polling is broken for peralloc files.

The cause seems to be that kernfs_seq_show() updates ->event, while
the new sysfs_kf_read() does not.
So the polling will always trigger and udisksd goes into an inifinite
loop looking for changes that are not there.

I fixed my local system by copying the line "of->event =
atomic_read(&of->kn->attr.open->event);" from kernfs_seq_show() into
sysfs_kf_read(). (I also needed to move the definition of struct
kernfs_open_node from kernfs/file.c to kefs-internal.h)

udisksd now again behaves normal, but I'm not sending this change as a
patch, because I do not know about the locking and livetime of these
objects to evaluate, if that is really the correct fix.


Thanks,

Torsten

Re: udiskd high CPU usage with 4.0 git

[NeilBrown]

[-- Attachment #1: Type: text/plain, Size: 2125 bytes --]

On Mon, 09 Mar 2015 16:46:41 +0100 Prakash Punnoor <prakash@punnoor.de> wrote:

> On 09.03.2015 00:30, NeilBrown wrote:
> > On Sun, 08 Mar 2015 18:14:39 +0100 Prakash Punnoor <prakash@punnoor.de> wrote:
> > 
> >> Hi,
> >>
> >> I noticed the udisks daemon (version 2.1.4) suddenly started using high
> >> cpu (one core at 100%) with linux 4.0 git kernel. I bisected it to:
> >>
> >> 750f199ee8b578062341e6ddfe36c59ac8ff2dcb
> >>
> >> And reverting it from current master (at
> >> 2cf3afcd4cbe0e32b8722fc291e9255de1b4d6c6) fixes my problem indeed.
> >>
> >> I attached dmesg and config from
> >> 2cf3afcd4cbe0e32b8722fc291e9255de1b4d6c6 with
> >> 750f199ee8b578062341e6ddfe36c59ac8ff2dcb reverted. Any more infos
> >> needed? I am actually using a raid5 array, if that matters:
> >>
> >> Personalities : [raid6] [raid5] [raid4]
> >> md127 : active raid5 sdd1[1] sdb1[3] sdc1[0]
> >>       3907023872 blocks super 1.2 level 5, 512k chunk, algorithm 2 [3/3]
> >> [UUU]
> >>
> >> unused devices: <none>
> >>
> >>
> >> The array uses systemd automount feature (x-systemd.automount).
> >>
> >> Please CC me, as I am not subscribed.
> >>
> >>
> >> Regards,
> >>
> >> Prakash
> > 
> > Thanks for the report.
> > I can't reproduce this, or see what would cause it.
> > 
> > Can you please reproduce the problem and then run
> > 
> >   strace -o /tmp/udisks.trace -f -p `pidof udisksd`
> > 
> > for a few seconds, then interrupt and post the resulting '/tmp/udisks.trace'.
> 
> Hi, attached the trace.
> 
>

Thanks. 
The significant part is:

329   poll([{fd=4, events=POLLIN}, {fd=8, events=0}, {fd=9, events=0}, {fd=11, events=POLLIN}, {fd=13, events=0}, {fd=12, events=0}], 6, 513377) = 2 ([{fd=4, revents=POLLIN}, {fd=12, revents=POLLERR}])

repeating frequently, so fd4 and fd12 are always ready.
I don't know about fd4, but fd12 is:

329   read(12, "idle\n", 1024)          = 5


so that is .../md/sync_action
It is simply always readable.  I thought I had checked that, but it seems not.

Anyway I have a fix which I will post shortly.

thanks again,
NeilBrown

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 811 bytes --]

Re: udiskd high CPU usage with 4.0 git

[NeilBrown]

[-- Attachment #1: Type: text/plain, Size: 2087 bytes --]

On Sat, 14 Mar 2015 21:16:51 +0100 Torsten Kaiser
<just.for.lkml@googlemail.com> wrote:

> On Mon, Mar 9, 2015 at 12:30 AM, NeilBrown <neilb@suse.de> wrote:
> > On Sun, 08 Mar 2015 18:14:39 +0100 Prakash Punnoor <prakash@punnoor.de> wrote:
> >
> >> Hi,
> >>
> >> I noticed the udisks daemon (version 2.1.4) suddenly started using high
> >> cpu (one core at 100%) with linux 4.0 git kernel. I bisected it to:
> >>
> >> 750f199ee8b578062341e6ddfe36c59ac8ff2dcb
> 
> I had the same problem upgrading from 4.0-rc1 to 4.0-rc3.
> I have just finished bisecting and "fixing" it.
> 
> My bisect points to the same commit.
> 
> Looking at udisksd with strace sees a loop of polling and then
> accessing several md related sysfs files.
> The only file that udisksd monitors and was changes by that commit was
> "sync_action".
> 
> If I revert this part of the commit, my system works normal again:
> 
>  static struct md_sysfs_entry md_scan_mode =
> - __ATTR_PREALLOC(sync_action, S_IRUGO|S_IWUSR, action_show, action_store);
> + __ATTR(sync_action, S_IRUGO|S_IWUSR, action_show, action_store);
> 
> It seems that polling is broken for peralloc files.
> 
> The cause seems to be that kernfs_seq_show() updates ->event, while
> the new sysfs_kf_read() does not.
> So the polling will always trigger and udisksd goes into an inifinite
> loop looking for changes that are not there.
> 
> I fixed my local system by copying the line "of->event =
> atomic_read(&of->kn->attr.open->event);" from kernfs_seq_show() into
> sysfs_kf_read(). (I also needed to move the definition of struct
> kernfs_open_node from kernfs/file.c to kefs-internal.h)
> 
> udisksd now again behaves normal, but I'm not sending this change as a
> patch, because I do not know about the locking and livetime of these
> objects to evaluate, if that is really the correct fix.

Thanks for the bisection and analysis!  Always easier when someone else does
the hard work :-)

There is a much simpler patch (as you probably suspected).  I'll post it in a
moment.

Thank,
NeilBrown

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 811 bytes --]

Re: udiskd high CPU usage with 4.0 git

[Torsten Kaiser]

On Mon, Mar 16, 2015 at 12:44 AM, NeilBrown <neilb@suse.de> wrote:
> On Sat, 14 Mar 2015 21:16:51 +0100 Torsten Kaiser
> <just.for.lkml@googlemail.com> wrote:
>> udisksd now again behaves normal, but I'm not sending this change as a
>> patch, because I do not know about the locking and livetime of these
>> objects to evaluate, if that is really the correct fix.
>
> Thanks for the bisection and analysis!  Always easier when someone else does
> the hard work :-)
>
> There is a much simpler patch (as you probably suspected).  I'll post it in a
> moment.

Linux-4.0-rc4 is still broken as expected, but after applying your
patch from "[PATCH] kernfs: handle poll correctly on 'direct_read'
files" my udisksd process behaves normal again.

Thanks for the quick answer + fix!

Torsten