2008-10-25 09:39:57

by Carlos Mafra

[permalink] [raw]
Subject: [2.6.28-rc1 regression] wmifinfo dockapp takes 100% of cpu (bisected)

Hi,

I have just tested 2.6.28-rc1 and I bisected a particular regression
which I faced to 8ff3e8e85fa6c312051134b3953e397feb639f51 ("select:
switch select() and poll() over to hrtimers") from Arjan (added to Cc:).

The symptom is that one little Window Maker dockapp I use, called wmifinfo,
starts to use 100% of the cpu. I have to kill it to avoid staying at the
maximum 2000 MHz.

The dockapp apparently enters an infinite loop, because I used strace
for a few moments and the log file had more than 1 million lines.
The block of commands which kept repeating itself in the strace log
was:

open("/proc/net/dev", O_RDONLY) = 9
fstat(9, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa374ccb000
read(9, "Inter-| Receive "..., 1024) = 694
read(9, "", 1024) = 0
close(9) = 0
munmap(0x7fa374ccb000, 4096) = 0
ioctl(5, SIOCGIFCONF, {0, {}}) = 0
ioctl(5, SIOCGIFFLAGS, {ifr_name="eth0", ifr_flags=IFF_BROADCAST|IFF_MULTICAST}) = 0
ioctl(5, SIOCGIFHWADDR, {ifr_name="eth0", ifr_hwaddr=00:1a:80:4a:7f:37}) = 0
ioctl(5, SIOCGIFADDR, {ifr_name="eth0", ???}) = -1 EADDRNOTAVAIL (Cannot assign requested address)
ioctl(5, SIOCGIFNETMASK, {ifr_name="eth0", ???}) = -1 EADDRNOTAVAIL (Cannot assign requested address)
lseek(6, 0, SEEK_SET) = 0
read(6, "Iface\tDestination\tGateway \tFlags"..., 1024) = 128
read(6, "", 1024) = 0
lseek(7, 0, SEEK_SET) = 0
read(7, "Inter-| sta-| Quality |"..., 1024) = 238
read(7, "", 1024) = 0
lseek(8, 0, SEEK_SET) = 0
read(8, "Inter-| Receive "..., 1024) = 694
read(8, "", 1024) = 0
read(3, 0x228ff54, 4096) = -1 EAGAIN (Resource temporarily unavailable)
select(4, [3], [3], NULL, NULL) = 1 (out [3])
writev(3, [{">\0\7\0\1\0`\0\1\0`\0\7\0`\0@\0\0\0\0\0\0\0@\0@\0>\0\7\0"..., 616}], 1) = 616
read(3, 0x228ff54, 4096) = -1 EAGAIN (Resource temporarily unavailable)
read(3, 0x228ff54, 4096) = -1 EAGAIN (Resource temporarily unavailable)
select(4, [3], [3], NULL, NULL) = 1 (out [3])
writev(3, [{">\0\7\0\1\0`\0\6\0`\0\7\0`\0\0\0\0\0\0\0\0\0\206\0Z\0", 28}], 1) = 28
read(3, 0x228ff54, 4096) = -1 EAGAIN (Resource temporarily unavailable)
select(4, [3], NULL, NULL, {0, 5000000}) = -1 EINVAL (Invalid argument)
select(4, [3], [3], NULL, NULL) = 1 (out [3])
writev(3, [{">\0\7\0\1\0`\0\5\0`\0\7\0`\0\0\0\0\0\0\0\0\0\206\0Z\0", 28}], 1) = 28
read(3, 0x228ff54, 4096) = -1 EAGAIN (Resource temporarily unavailable)
select(4, [3], NULL, NULL, {0, 5000000}) = -1 EINVAL (Invalid argument)
read(3, 0x228ff54, 4096) = -1 EAGAIN (Resource temporarily unavailable)
select(4, [3], NULL, NULL, {0, 5000000}) = -1 EINVAL (Invalid argument)
read(3, 0x228ff54, 4096) = -1 EAGAIN (Resource temporarily unavailable)
select(4, [3], NULL, NULL, {0, 5000000}) = -1 EINVAL (Invalid argument)
read(3, 0x228ff54, 4096) = -1 EAGAIN (Resource temporarily unavailable)


I got to that commit by git bisect, but I could not revert it cleanly to really
prove it is the cause of the problem. So I apologize in advance if this commit
is not the true culprit.

I can test any patches.


2008-10-25 14:05:52

by Arjan van de Ven

[permalink] [raw]
Subject: Re: [2.6.28-rc1 regression] wmifinfo dockapp takes 100% of cpu (bisected)

Carlos R. Mafra wrote:


Hi,

the line below is the key one:

> select(4, [3], NULL, NULL, {0, 5000000}) = -1 EINVAL (Invalid argument)

the application gives us an invalid timeval; it should have been (5, 0)
However, if the kernel accepted this before the kernel needs to now also accept it
obviously, I'll

2008-10-25 14:13:38

by Arjan van de Ven

[permalink] [raw]
Subject: Re: [2.6.28-rc1 regression] wmifinfo dockapp takes 100% of cpu (bisected)

On Sat, 25 Oct 2008 07:05:42 -0700
Arjan van de Ven <[email protected]> wrote:

> Carlos R. Mafra wrote:
>
>
> Hi,
>
> the line below is the key one:
>
> > select(4, [3], NULL, NULL, {0, 5000000}) = -1 EINVAL (Invalid
> > argument)
>
> the application gives us an invalid timeval; it should have been (5,
> 0) However, if the kernel accepted this before the kernel needs to
> now also accept it obviously, I'll look into it

This patch should fix it; I'm a bit worried that I need to fix up
userlands "mess", but ok. I also checked all other converted functions,
and only select has this problem. The problem is that the conversion
from microseconds to nanoseconds is overflowing ;-(

can you give this one a test?

diff --git a/fs/compat.c b/fs/compat.c
index fe3c9bf..95ceee6 100644
--- a/fs/compat.c
+++ b/fs/compat.c
@@ -1680,9 +1680,16 @@ asmlinkage long compat_sys_select(int n, compat_ulong_t __user *inp,
int ret;

if (tvp) {
+ int i;
if (copy_from_user(&tv, tvp, sizeof(tv)))
return -EFAULT;

+ while (tv.tv_usec > USEC_PER_SEC && i < 1000) {
+ i++;
+ tv.tv_sec ++;
+ tv.tv_usec -= USEC_PER_SEC;
+ }
+
to = &end_time;
if (poll_select_set_timeout(to, tv.tv_sec,
tv.tv_usec * NSEC_PER_USEC))
diff --git a/fs/select.c b/fs/select.c
index 448e440..e4e7cdb 100644
--- a/fs/select.c
+++ b/fs/select.c
@@ -515,9 +515,16 @@ asmlinkage long sys_select(int n, fd_set __user *inp, fd_set __user *outp,
int ret;

if (tvp) {
+ int i = 0;
if (copy_from_user(&tv, tvp, sizeof(tv)))
return -EFAULT;

+ while (tv.tv_usec > USEC_PER_SEC && i < 1000) {
+ i++;
+ tv.tv_sec ++;
+ tv.tv_usec -= USEC_PER_SEC;
+ }
+
to = &end_time;
if (poll_select_set_timeout(to, tv.tv_sec,
tv.tv_usec * NSEC_PER_USEC))

--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org

2008-10-25 16:24:20

by Carlos Mafra

[permalink] [raw]
Subject: Re: [2.6.28-rc1 regression] wmifinfo dockapp takes 100% of cpu (bisected)

On Sat 25.Oct'08 at 7:13:48 -0700, Arjan van de Ven wrote:
> On Sat, 25 Oct 2008 07:05:42 -0700
> Arjan van de Ven <[email protected]> wrote:
>
> > Carlos R. Mafra wrote:
> >
> >
> > Hi,
> >
> > the line below is the key one:
> >
> > > select(4, [3], NULL, NULL, {0, 5000000}) = -1 EINVAL (Invalid
> > > argument)
> >
> > the application gives us an invalid timeval; it should have been (5,
> > 0) However, if the kernel accepted this before the kernel needs to
> > now also accept it obviously, I'll look into it
>
> This patch should fix it; I'm a bit worried that I need to fix up
> userlands "mess", but ok. I also checked all other converted functions,
> and only select has this problem. The problem is that the conversion
> from microseconds to nanoseconds is overflowing ;-(
>
> can you give this one a test?

Your patch did not solve it.

But you are right that the program I use is a mess, it was doing

tv.tv_sec = 0;
tv.tv_usec = 5000000L;

So I changed it to

tv.tv_sec = 5;
tv.tv_usec = 0;

and it worked (with and without your patch).

>From what I understand this is what your patch does,
so it is strange that it didn't work...

> diff --git a/fs/compat.c b/fs/compat.c
> index fe3c9bf..95ceee6 100644
> --- a/fs/compat.c
> +++ b/fs/compat.c
> @@ -1680,9 +1680,16 @@ asmlinkage long compat_sys_select(int n, compat_ulong_t __user *inp,
> int ret;
>
> if (tvp) {
> + int i;
> if (copy_from_user(&tv, tvp, sizeof(tv)))
> return -EFAULT;
>
> + while (tv.tv_usec > USEC_PER_SEC && i < 1000) {
> + i++;
> + tv.tv_sec ++;
> + tv.tv_usec -= USEC_PER_SEC;
> + }
> +
> to = &end_time;
> if (poll_select_set_timeout(to, tv.tv_sec,
> tv.tv_usec * NSEC_PER_USEC))
> diff --git a/fs/select.c b/fs/select.c
> index 448e440..e4e7cdb 100644
> --- a/fs/select.c
> +++ b/fs/select.c
> @@ -515,9 +515,16 @@ asmlinkage long sys_select(int n, fd_set __user *inp, fd_set __user *outp,
> int ret;
>
> if (tvp) {
> + int i = 0;
> if (copy_from_user(&tv, tvp, sizeof(tv)))
> return -EFAULT;
>
> + while (tv.tv_usec > USEC_PER_SEC && i < 1000) {
> + i++;
> + tv.tv_sec ++;
> + tv.tv_usec -= USEC_PER_SEC;
> + }
> +
> to = &end_time;
> if (poll_select_set_timeout(to, tv.tv_sec,
> tv.tv_usec * NSEC_PER_USEC))
>
> --
> Arjan van de Ven Intel Open Source Technology Centre
> For development, discussion and tips for power savings,
> visit http://www.lesswatts.org

2008-10-25 18:04:09

by Marcin Slusarz

[permalink] [raw]
Subject: Re: [2.6.28-rc1 regression] wmifinfo dockapp takes 100% of cpu (bisected)

On Sat, Oct 25, 2008 at 06:25:05PM +0200, Carlos R. Mafra wrote:
> On Sat 25.Oct'08 at 7:13:48 -0700, Arjan van de Ven wrote:
> > On Sat, 25 Oct 2008 07:05:42 -0700
> > Arjan van de Ven <[email protected]> wrote:
> >
> > > Carlos R. Mafra wrote:
> > >
> > >
> > > Hi,
> > >
> > > the line below is the key one:
> > >
> > > > select(4, [3], NULL, NULL, {0, 5000000}) = -1 EINVAL (Invalid
> > > > argument)
> > >
> > > the application gives us an invalid timeval; it should have been (5,
> > > 0) However, if the kernel accepted this before the kernel needs to
> > > now also accept it obviously, I'll look into it
> >
> > This patch should fix it; I'm a bit worried that I need to fix up
> > userlands "mess", but ok. I also checked all other converted functions,
> > and only select has this problem. The problem is that the conversion
> > from microseconds to nanoseconds is overflowing ;-(
> >
> > can you give this one a test?
>
> Your patch did not solve it.
>
> But you are right that the program I use is a mess, it was doing
>
> tv.tv_sec = 0;
> tv.tv_usec = 5000000L;
>
> So I changed it to
>
> tv.tv_sec = 5;
> tv.tv_usec = 0;
>
> and it worked (with and without your patch).
>
> From what I understand this is what your patch does,
> so it is strange that it didn't work...
>
> > diff --git a/fs/compat.c b/fs/compat.c
> > index fe3c9bf..95ceee6 100644
> > --- a/fs/compat.c
> > +++ b/fs/compat.c
> > @@ -1680,9 +1680,16 @@ asmlinkage long compat_sys_select(int n, compat_ulong_t __user *inp,
> > int ret;
> >
> > if (tvp) {
> > + int i;
> > if (copy_from_user(&tv, tvp, sizeof(tv)))
> > return -EFAULT;
> >
> > + while (tv.tv_usec > USEC_PER_SEC && i < 1000) {
^
should be >=

> > + i++;
> > + tv.tv_sec ++;
> > + tv.tv_usec -= USEC_PER_SEC;
> > + }
> > +
> > to = &end_time;
> > if (poll_select_set_timeout(to, tv.tv_sec,
> > tv.tv_usec * NSEC_PER_USEC))
> > diff --git a/fs/select.c b/fs/select.c
> > index 448e440..e4e7cdb 100644
> > --- a/fs/select.c
> > +++ b/fs/select.c
> > @@ -515,9 +515,16 @@ asmlinkage long sys_select(int n, fd_set __user *inp, fd_set __user *outp,
> > int ret;
> >
> > if (tvp) {
> > + int i = 0;
> > if (copy_from_user(&tv, tvp, sizeof(tv)))
> > return -EFAULT;
> >
> > + while (tv.tv_usec > USEC_PER_SEC && i < 1000) {

and here too

> > + i++;
> > + tv.tv_sec ++;
> > + tv.tv_usec -= USEC_PER_SEC;
> > + }
> > +
> > to = &end_time;
> > if (poll_select_set_timeout(to, tv.tv_sec,
> > tv.tv_usec * NSEC_PER_USEC))
> >
> > --

2008-10-25 18:28:47

by Carlos Mafra

[permalink] [raw]
Subject: Re: [2.6.28-rc1 regression] wmifinfo dockapp takes 100% of cpu (bisected)

On Sat 25.Oct'08 at 20:03:27 +0200, Marcin Slusarz wrote:
> On Sat, Oct 25, 2008 at 06:25:05PM +0200, Carlos R. Mafra wrote:
> > On Sat 25.Oct'08 at 7:13:48 -0700, Arjan van de Ven wrote:
> > > On Sat, 25 Oct 2008 07:05:42 -0700
> > > Arjan van de Ven <[email protected]> wrote:
> > >
> > > > Carlos R. Mafra wrote:
> > > >
> > > >
> > > > Hi,
> > > >
> > > > the line below is the key one:
> > > >
> > > > > select(4, [3], NULL, NULL, {0, 5000000}) = -1 EINVAL (Invalid
> > > > > argument)
> > > >
> > > > the application gives us an invalid timeval; it should have been (5,
> > > > 0) However, if the kernel accepted this before the kernel needs to
> > > > now also accept it obviously, I'll look into it
> > >
> > > This patch should fix it; I'm a bit worried that I need to fix up
> > > userlands "mess", but ok. I also checked all other converted functions,
> > > and only select has this problem. The problem is that the conversion
> > > from microseconds to nanoseconds is overflowing ;-(
> > >
> > > can you give this one a test?
> >
> > Your patch did not solve it.
> >
> > But you are right that the program I use is a mess, it was doing
> >
> > tv.tv_sec = 0;
> > tv.tv_usec = 5000000L;
> >
> > So I changed it to
> >
> > tv.tv_sec = 5;
> > tv.tv_usec = 0;
> >
> > and it worked (with and without your patch).
> >
> > From what I understand this is what your patch does,
> > so it is strange that it didn't work...
> >
> > > diff --git a/fs/compat.c b/fs/compat.c
> > > index fe3c9bf..95ceee6 100644
> > > --- a/fs/compat.c
> > > +++ b/fs/compat.c
> > > @@ -1680,9 +1680,16 @@ asmlinkage long compat_sys_select(int n, compat_ulong_t __user *inp,
> > > int ret;
> > >
> > > if (tvp) {
> > > + int i;
> > > if (copy_from_user(&tv, tvp, sizeof(tv)))
> > > return -EFAULT;
> > >
> > > + while (tv.tv_usec > USEC_PER_SEC && i < 1000) {
> ^
> should be >=
>
> > > + i++;
> > > + tv.tv_sec ++;
> > > + tv.tv_usec -= USEC_PER_SEC;
> > > + }
> > > +
> > > to = &end_time;
> > > if (poll_select_set_timeout(to, tv.tv_sec,
> > > tv.tv_usec * NSEC_PER_USEC))
> > > diff --git a/fs/select.c b/fs/select.c
> > > index 448e440..e4e7cdb 100644
> > > --- a/fs/select.c
> > > +++ b/fs/select.c
> > > @@ -515,9 +515,16 @@ asmlinkage long sys_select(int n, fd_set __user *inp, fd_set __user *outp,
> > > int ret;
> > >
> > > if (tvp) {
> > > + int i = 0;
> > > if (copy_from_user(&tv, tvp, sizeof(tv)))
> > > return -EFAULT;
> > >
> > > + while (tv.tv_usec > USEC_PER_SEC && i < 1000) {
>
> and here too


Yes, changing to >= solves the problem here.

Thanks Arjan and Marcin!


> > > + i++;
> > > + tv.tv_sec ++;
> > > + tv.tv_usec -= USEC_PER_SEC;
> > > + }
> > > +
> > > to = &end_time;
> > > if (poll_select_set_timeout(to, tv.tv_sec,
> > > tv.tv_usec * NSEC_PER_USEC))
> > >
> > > --

2008-10-25 18:39:40

by Marcin Slusarz

[permalink] [raw]
Subject: Re: [2.6.28-rc1 regression] wmifinfo dockapp takes 100% of cpu (bisected)

one more thing:

On Sat, Oct 25, 2008 at 08:29:29PM +0200, Carlos R. Mafra wrote:
> > > > diff --git a/fs/compat.c b/fs/compat.c
> > > > index fe3c9bf..95ceee6 100644
> > > > --- a/fs/compat.c
> > > > +++ b/fs/compat.c
> > > > @@ -1680,9 +1680,16 @@ asmlinkage long compat_sys_select(int n, compat_ulong_t __user *inp,
> > > > int ret;
> > > >
> > > > if (tvp) {
> > > > + int i;

"i" should be initialized to 0

> > > > if (copy_from_user(&tv, tvp, sizeof(tv)))
> > > > return -EFAULT;
> > > >
> > > > + while (tv.tv_usec > USEC_PER_SEC && i < 1000) {
> > ^
> > should be >=
> >
> > > > + i++;
> > > > + tv.tv_sec ++;
> > > > + tv.tv_usec -= USEC_PER_SEC;
> > > > + }
> > > > +
> > > > to = &end_time;
> > > > if (poll_select_set_timeout(to, tv.tv_sec,
> > > > tv.tv_usec * NSEC_PER_USEC))
> > > > diff --git a/fs/select.c b/fs/select.c
> > > > index 448e440..e4e7cdb 100644
> > > > --- a/fs/select.c
> > > > +++ b/fs/select.c
> > > > @@ -515,9 +515,16 @@ asmlinkage long sys_select(int n, fd_set __user *inp, fd_set __user *outp,
> > > > int ret;
> > > >
> > > > if (tvp) {
> > > > + int i = 0;
> > > > if (copy_from_user(&tv, tvp, sizeof(tv)))
> > > > return -EFAULT;
> > > >
> > > > + while (tv.tv_usec > USEC_PER_SEC && i < 1000) {
> >
> > and here too
>
>
> Yes, changing to >= solves the problem here.
>
> Thanks Arjan and Marcin!
>
>
> > > > + i++;
> > > > + tv.tv_sec ++;
> > > > + tv.tv_usec -= USEC_PER_SEC;
> > > > + }
> > > > +
> > > > to = &end_time;
> > > > if (poll_select_set_timeout(to, tv.tv_sec,
> > > > tv.tv_usec * NSEC_PER_USEC))
> > > >
> > > > --

2008-10-25 19:12:44

by Arjan van de Ven

[permalink] [raw]
Subject: Re: [2.6.28-rc1 regression] wmifinfo dockapp takes 100% of cpu (bisected)

On Sat, 25 Oct 2008 20:03:27 +0200
Marcin Slusarz <[email protected]> wrote:
> > > if (copy_from_user(&tv, tvp, sizeof(tv)))
> > > return -EFAULT;
> > >
> > > + while (tv.tv_usec > USEC_PER_SEC && i < 1000) {
> ^
> should be >=

yeah thanks for catching that. Note to self: don't code before coffee

I'm not very happy with a while loop; but at least it solves the problem

I'll try to make it nicer than this ...


--
Arjan van de Ven Intel Open Source Technology Centre
For development, discussion and tips for power savings,
visit http://www.lesswatts.org

2008-10-25 19:38:31

by Ray Lee

[permalink] [raw]
Subject: Re: [2.6.28-rc1 regression] wmifinfo dockapp takes 100% of cpu (bisected)

On Sat, Oct 25, 2008 at 12:12 PM, Arjan van de Ven <[email protected]> wrote:
> On Sat, 25 Oct 2008 20:03:27 +0200
> Marcin Slusarz <[email protected]> wrote:
>> > > if (copy_from_user(&tv, tvp, sizeof(tv)))
>> > > return -EFAULT;
>> > >
>> > > + while (tv.tv_usec > USEC_PER_SEC && i < 1000) {
>> ^
>> should be >=
>
> yeah thanks for catching that. Note to self: don't code before coffee
>
> I'm not very happy with a while loop; but at least it solves the problem
>
> I'll try to make it nicer than this ...

Regardless, you may wish to make a set_normalized_timeval and place it
in kernel/time.c right after the current set_nromalized_timespec.
Comparing the two, you'll also want to handle the case where tv_usec
is negative.

2008-10-30 07:04:59

by Andrew Morton

[permalink] [raw]
Subject: Re: [2.6.28-rc1 regression] wmifinfo dockapp takes 100% of cpu (bisected)

On Sat, 25 Oct 2008 12:38:22 -0700 "Ray Lee" <[email protected]> wrote:

> On Sat, Oct 25, 2008 at 12:12 PM, Arjan van de Ven <[email protected]> wrote:
> > On Sat, 25 Oct 2008 20:03:27 +0200
> > Marcin Slusarz <[email protected]> wrote:
> >> > > if (copy_from_user(&tv, tvp, sizeof(tv)))
> >> > > return -EFAULT;
> >> > >
> >> > > + while (tv.tv_usec > USEC_PER_SEC && i < 1000) {
> >> ^
> >> should be >=
> >
> > yeah thanks for catching that. Note to self: don't code before coffee
> >
> > I'm not very happy with a while loop; but at least it solves the problem
> >
> > I'll try to make it nicer than this ...
>
> Regardless, you may wish to make a set_normalized_timeval and place it
> in kernel/time.c right after the current set_nromalized_timespec.

Yes, this comes up fairly regularly and we would benefit from having a
normalize-a-timeval library function.

I don't think it should be implemented via a while loop though. That's
acceptable with timespecs, which can only loop four or so times. But
timevals use microseconds and can loop thousands of times and hence a
normalization function should use division.