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

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

[Carlos R. Mafra]

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.

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

[Arjan van de Ven]

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

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

[Arjan van de Ven]

On Sat, 25 Oct 2008 07:05:42 -0700
Arjan van de Ven <arjan@linux.intel.com> 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

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

[Carlos R. Mafra]

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 <arjan@linux.intel.com> 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

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

[Marcin Slusarz]

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 <arjan@linux.intel.com> 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))
> > 
> > -- 

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

[Carlos R. Mafra]

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 <arjan@linux.intel.com> 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))
> > > 
> > > -- 

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

[Marcin Slusarz]

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))
> > > > 
> > > > -- 

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

[Arjan van de Ven]

On Sat, 25 Oct 2008 20:03:27 +0200
Marcin Slusarz <marcin.slusarz@gmail.com> 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

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

[Ray Lee]

On Sat, Oct 25, 2008 at 12:12 PM, Arjan van de Ven <arjan@infradead.org> wrote:
> On Sat, 25 Oct 2008 20:03:27 +0200
> Marcin Slusarz <marcin.slusarz@gmail.com> 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.

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

[Andrew Morton]

On Sat, 25 Oct 2008 12:38:22 -0700 "Ray Lee" <ray-lk@madrabbit.org> wrote:

> On Sat, Oct 25, 2008 at 12:12 PM, Arjan van de Ven <arjan@infradead.org> wrote:
> > On Sat, 25 Oct 2008 20:03:27 +0200
> > Marcin Slusarz <marcin.slusarz@gmail.com> 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.