Bug 11112

Summary:	On turning on UIE interrupt on rtc, next read/select returns immediately and not on update boundary
Product:	Timers	Reporter:	W Unruh (unruh)
Component:	Realtime Clock	Assignee:	David Brownell (dbrownell)
Status:	RESOLVED CODE_FIX
Severity:	normal
Priority:	P1
Hardware:	All
OS:	Linux
Kernel Version:	2.6.24	Subsystem:
Regression:	---	Bisected commit-id:
Attachments:	updated test program rtc-at91rm9200 patch rtc-cmos patch

Description W Unruh 2008-07-17 15:25:15 UTC

Latest working kernel version: None known
Earliest failing kernel version:2.6.17
Distribution:Mandriva 2007-2008.1
Hardware Environment:i586 various
Software Environment:
Problem Description:The first select or read from the rtc/rtc0 after the UIE interrupts have been turned on does not block but returns immediately at arbitrary time. Subsequent select/red do block to the update of the second on the rtc.


Steps to reproduce:

The following program produces the sample output 

			RTC Driver Test Example.


Read using select(2) on /dev/rtc:
 1  0.   401  190
 2  0.229592  190
 3  1.229536  190
 4  2.229521  190
 5  3.229468  190

The first column is the test number, the second is the seconds since the UIE was turned on, and the third is the "data" returned by the read call  in Hex.

This means that the first select/read on the rtc returns after .4msec. The next returns at .22 sec which presumably is the first second update of the rtc after the UIE was turned on. The following ones occur at the 1 second intervals (plus or minus a few microseconds).
On successive calls that first time is always less than a msec, the second occurs at a random time between a msec and a second later, and the rest are always a second later than the previous one, as they should be. 

It seems as if when the UIE interrupt is turned on, the interrupt routine has an old value which it immediately returns to the select call, giving a spurious reading. Thereafter it returns what is expected at the one second updates of the rtc. 
Note that the third value above is the hex output of the data from the read of the rtc. Ie, it says that only one interrupt has occured since the last time, and it is of type 0x90.

Here is the test program. It is based on the test program published in linux/Documentation/rtc.txt
with timing added to the program to see when each of the read functions finished

Note that the same thing happens if instead of using select, I use the blocking read function.

/*
 *     Real Time Clock Driver Test/Example Program
 *
 *      Compile with:
 *         gcc -s -Wall -Wstrict-prototypes rtctest.c -o rtctest
 *
 *      Copyright (C) 1996, Paul Gortmaker.
 *
 *      Released under the GNU General Public License, version 2,
 *      included herein by reference.
 *
 */

#include <stdio.h>
#include <linux/rtc.h>
#include <sys/ioctl.h>
#include <time.h>
#include <sys/time.h>
#include <sys/types.h>
#include <fcntl.h>
#include <unistd.h>
#include <stdlib.h>
#include <errno.h>


/*
 * This expects the new RTC class driver framework, working with
 * clocks that will often not be clones of what the PC-AT had.
 * Use the command line to specify another RTC if you need one.
 */
static const char default_rtc[] = "/dev/rtc0";


int main(int argc, char **argv)
{
   int i, fd, retval, irqcount = 0;
   unsigned long tmp, data;
   struct rtc_time rtc_tm;
   const char *rtc = default_rtc;
   struct timeval stv,etv;
   struct timezone tz;
   long sec,usec;


   switch (argc) {
   case 2:
      rtc = argv[1];
      /* FALLTHROUGH */
   case 1:
      break;
   default:
      fprintf(stderr, "usage:  rtctest [rtcdev]\n");
      return 1;
   }

   fd = open(rtc, O_RDONLY);

   if (fd ==  -1) {
      perror(rtc);
      exit(errno);
   }

   fprintf(stderr, "\n\t\t\tRTC Driver Test Example.\n\n");

   /* Turn on update interrupts (one per second) */
   gettimeofday(&stv,&tz);
   retval = ioctl(fd, RTC_UIE_ON, 0);
   if (retval == -1) {
      if (errno == ENOTTY) {
         fprintf(stderr,
            "\n...Update IRQs not supported.\n");
      }
      perror("RTC_UIE_ON ioctl");
      exit(errno);
   }


   fprintf(stderr, "\nRead using select(2) on /dev/rtc:\n");
   fflush(stderr);
   for (i=1; i<6; i++) {
      struct timeval tv = {5, 0};     /* 5 second timeout on select */
      fd_set readfds;

      FD_ZERO(&readfds);
      FD_SET(fd, &readfds);
      /* The select will wait until an RTC interrupt happens. */
      retval = select(fd+1, &readfds, NULL, NULL, &tv);
      if (retval == -1) {
              perror("select");
              exit(errno);
      }
      /* This read won't block unlike the select-less case above. */
      retval = read(fd, &data, sizeof(unsigned long));
      if (retval == -1) {
              perror("read");
              exit(errno);
      }
      gettimeofday(&etv,&tz);
      sec=etv.tv_sec-stv.tv_sec;
      usec=etv.tv_usec-stv.tv_usec;
      fprintf(stderr, " %d  %ld.%6lu  %x\n",i,sec,usec,data);
      fflush(stderr);
      irqcount++;
   }

   /* Turn off update interrupts */
   retval = ioctl(fd, RTC_UIE_OFF, 0);
   if (retval == -1) {
      perror("RTC_UIE_OFF ioctl");
      exit(errno);
   }


done:
   fprintf(stderr, "\n\n\t\t\t *** Test complete ***\n");

   close(fd);

   return 0;
}

Comment 1 David Brownell 2008-07-17 17:13:29 UTC

Created attachment 16871 [details]
updated test program

Curious.  I cleaned the code up a bit (including Lindent) and fixed the bug in usec calculation (negative!) ... observed the same thing, using rtc-cmos (but haven't yet tried other RTCs).

I noticed that the HPET glue code has even worse trouble.  Sometimes the first *two* returns seem bogus.  Once I saw the first return be too fast, but the others showed right when expected.  And then there are test runs like this one:

Read using select(2) on /dev/rtc:
 1  0.000671  0290
 2  0.915634  0190
 3  1.890956  0190
 4  3.369143  0190
 5  3.910837  0190

I know the HPET glue is flakey (doesn't synch to hardware at all), but that's not even vaguely good.

Comment 2 W Unruh 2008-07-17 17:29:20 UTC

Yes, that usec code was certainly wrong. Sorry. It just happened to work on
one of my machines each time I used it.

On machines with just rtc (ie older machines without hpet) using Mandriva
7.0 (kernel 2.6.17), the returns seemed to be fine. On the more recent machines which have
an hpet, I get that weird behaviour of the first one being an immediate
return. I did not ever see your case where one of the later returns (4 in
your case on the hpet machines)  was way off.

On Thu, 17 Jul 2008, bugme-daemon@bugzilla.kernel.org wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=11112
>
>
>
>
>
> ------- Comment #1 from dbrownell@users.sourceforge.net  2008-07-17 17:13
> -------
> Created an attachment (id=16871)
> --> (http://bugzilla.kernel.org/attachment.cgi?id=16871&action=view)
> updated test program
>
> Curious.  I cleaned the code up a bit (including Lindent) and fixed the bug
> in
> usec calculation (negative!) ... observed the same thing, using rtc-cmos (but
> haven't yet tried other RTCs).
>
> I noticed that the HPET glue code has even worse trouble.  Sometimes the
> first
> *two* returns seem bogus.  Once I saw the first return be too fast, but the
> others showed right when expected.  And then there are test runs like this
> one:
>
> Read using select(2) on /dev/rtc:
> 1  0.000671  0290
> 2  0.915634  0190
> 3  1.890956  0190
> 4  3.369143  0190
> 5  3.910837  0190
>
> I know the HPET glue is flakey (doesn't synch to hardware at all), but that's
> not even vaguely good.
>
>
>

Comment 3 Anonymous Emailer 2008-07-17 23:25:36 UTC

Reply-To: david-b@pacbell.net

On Thursday 17 July 2008, bugme-daemon@bugzilla.kernel.org wrote:
> On machines with just rtc (ie older machines without hpet) using Mandriva
> 7.0 (kernel 2.6.17), the returns seemed to be fine.

That's also stuff not using the new RTC framework.

> On the more recent machines which have  an hpet, I get that weird
> behaviour of the first one being an immediate return.

There are multiple variables here.  The HPET goofage is IMO a
very separate bug from the "immediate return" thing, which
seems to come from some issue the new framework code.

Comment 4 W Unruh 2008-07-18 08:41:52 UTC

I am not sure. The immediate return was already there under Mandriva 2007
(kernel 2.6.17) on machines using hpet. I submitted a bug fix to chrony to
get around it when I found it about 1.5 yr ago-- should have submitted it
to the kernel as well I guess, but I had no test case then and did not
think about it. 
Ie, the immediate return  was already there on 2.6.17 if the machine had an
hpet emulation for rtc.

On Thu, 17 Jul 2008, bugme-daemon@bugzilla.kernel.org wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=11112
>
>
>
>
>
> ------- Comment #3 from anonymous@kernel-bugs.osdl.org  2008-07-17 23:25
> -------
> Reply-To: david-b@pacbell.net
>
> On Thursday 17 July 2008, bugme-daemon@bugzilla.kernel.org wrote:
>> On machines with just rtc (ie older machines without hpet) using Mandriva
>> 7.0 (kernel 2.6.17), the returns seemed to be fine.
>
> That's also stuff not using the new RTC framework.
>
>
>> On the more recent machines which have  an hpet, I get that weird
>> behaviour of the first one being an immediate return.
>
> There are multiple variables here.  The HPET goofage is IMO a
> very separate bug from the "immediate return" thing, which
> seems to come from some issue the new framework code.
>
>
>

Comment 5 W Unruh 2008-07-18 13:06:51 UTC

OK, I am now very confused. I am not sure if this is the place, but looking
at Mandriva 2008.1, the original did NOT have the  the HPET_EMULATE_RTC
confugured at all, but it did load the rtc-class module. HOwever, that led
to no end of problems on many machines. On one of mine, all reads of rtc
after the first after switching on UIE would block. On other peoples,
  the dates returned by the rtc were wildly out, and would change without
  warning. Ie, the rtc_class thing simply did not work for many people (It
seemed to depend on the exact hardware).

Mandriva have now released a kernel with HPET_EMULATE_RTC switched on again,
and this seems to solved the problems on those hardwares( except the "first read or select on
UIE returns immediately and not on the update" problem).

Reading the config options on RTC_DRV_CMOS it seems to say that you need a
separate device as well as rtc-cmos, or is this driver sufficient to get at
the various classic devices. Ie, what does "Your system will need to define
the platform device used by this driver" mean?

On Thu, 17 Jul 2008, bugme-daemon@bugzilla.kernel.org wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=11112
>
>
>
>
>
> ------- Comment #3 from anonymous@kernel-bugs.osdl.org  2008-07-17 23:25
> -------
> Reply-To: david-b@pacbell.net
>
> On Thursday 17 July 2008, bugme-daemon@bugzilla.kernel.org wrote:
>> On machines with just rtc (ie older machines without hpet) using Mandriva
>> 7.0 (kernel 2.6.17), the returns seemed to be fine.
>
> That's also stuff not using the new RTC framework.
>
>
>> On the more recent machines which have  an hpet, I get that weird
>> behaviour of the first one being an immediate return.
>
> There are multiple variables here.  The HPET goofage is IMO a
> very separate bug from the "immediate return" thing, which
> seems to come from some issue the new framework code.
>
>
>

Comment 6 Anonymous Emailer 2008-07-18 13:15:34 UTC

Reply-To: david-b@pacbell.net

Using rtc-at91rm9200:

Read using select(2) on /dev/rtc:
 1  0.000506  0190
 2  0.216502  0190
 3  1.216509  0190
 4  2.216460  0190
 5  3.216454  0190

Makes me wonder if maybe the drivers should be scrubbing some
old IRQ status ... the framework code didn't look to have any
obvious bugs, but bugs like that could lurk for a long time.

Comment 7 W Unruh 2008-07-18 17:10:09 UTC

Just looking at the code in rtd-dev.c. It looks like the rtc emulate uie is
always used if the RTC_INTF_DEV_UIE_EMUL is set even if the rtc supports
uie interrupts just fine. Or am I misreading the code?

On Fri, 18 Jul 2008, bugme-daemon@bugzilla.kernel.org wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=11112
>
>
>
>
>
> ------- Comment #6 from anonymous@kernel-bugs.osdl.org  2008-07-18 13:15
> -------
> Reply-To: david-b@pacbell.net
>
> Using rtc-at91rm9200:
>
> Read using select(2) on /dev/rtc:
> 1  0.000506  0190
> 2  0.216502  0190
> 3  1.216509  0190
> 4  2.216460  0190
> 5  3.216454  0190
>
> Makes me wonder if maybe the drivers should be scrubbing some
> old IRQ status ... the framework code didn't look to have any
> obvious bugs, but bugs like that could lurk for a long time.
>
>
>

Comment 8 David Brownell 2008-07-18 19:12:57 UTC

Yep, the problem goes away if old IRQ status gets scrubbed.  Patches ready for rm9200, x86/no-hpet, x86-hpet.

Comment 9 David Brownell 2008-07-18 19:30:00 UTC

Created attachment 16882 [details]
rtc-at91rm9200 patch

This shows the canonical fix for drivers with this bug:  scrub old IRQ status before enabling new event IRQs.

Comment 10 David Brownell 2008-07-18 19:38:56 UTC

Created attachment 16883 [details]
rtc-cmos patch

This resolves the problems for me:

 - extra IRQ without HPET
 - extra IRQ with HPET
 - flakey irq reports with HPET

I think the last of those came from the patch which needs to be applied first:

  http://marc.info/?l=linux-kernel&m=121631884829116&w=2

Comment 11 Anonymous Emailer 2008-07-18 21:19:05 UTC

Reply-To: david-b@pacbell.net

On Friday 18 July 2008, bugme-daemon@bugzilla.kernel.org wrote:
> Reading the config options on RTC_DRV_CMOS it seems to say that you need a
> separate device as well as rtc-cmos, or is this driver sufficient to get at
> the various classic devices. Ie, what does "Your system will need to define
> the platform device used by this driver" mean?

It means that it follows the driver model ... if there's a PNP device
defined, or a platform device defined, this driver binds to that device.

But unlike the legacy driver, it will NOT go and poke at the hardware
in the hope that it's guessing right.  That's probably the essence of
what makes the legacy driver a legacy driver:  it completely disregards
the driver model.

Comment 12 W Unruh 2008-07-22 17:11:06 UTC

Here is another example.

Read using select(2) on /dev/rtc:
  1  1.181705  190
  2  2.201611  190
  3  3.671093  190
  4  4.181635  190
  5  5.671149  190

This is as bad as David's example.

Note that this does include the special hpet patch as well.

I have been running a whole series of the tests in a row, and get a few
similar to the above one.

Note also that the first interrupt occured 1.2 sec after interrupts were
switched on (It should have been less than 1 sec.)

Ie, at least the hpet rtc-cmos still has trouble.


On Fri, 18 Jul 2008, bugme-daemon@bugzilla.kernel.org wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=11112
>
>
>
>
>
> ------- Comment #11 from anonymous@kernel-bugs.osdl.org  2008-07-18 21:19
> -------
> Reply-To: david-b@pacbell.net
>
> On Friday 18 July 2008, bugme-daemon@bugzilla.kernel.org wrote:
>> Reading the config options on RTC_DRV_CMOS it seems to say that you need a
>> separate device as well as rtc-cmos, or is this driver sufficient to get at
>> the various classic devices. Ie, what does "Your system will need to define
>> the platform device used by this driver" mean?
>
> It means that it follows the driver model ... if there's a PNP device
> defined, or a platform device defined, this driver binds to that device.
>
> But unlike the legacy driver, it will NOT go and poke at the hardware
> in the hope that it's guessing right.  That's probably the essence of
> what makes the legacy driver a legacy driver:  it completely disregards
> the driver model.
>
>
>

Comment 13 W Unruh 2008-07-22 17:19:50 UTC

There are still problems. Although there is no longer spurious first interrupt, the problem David found in his comment 1 is still there occasionally. 

Here are an couple of examples:
 1  1.181705  190
 2  2.201611  190
 3  3.671093  190
 4  4.181635  190
 5  5.671149  190

Note that the first interrupt occurs 1.2 sec after switchon (it should be less than 1) and the interrupt times are way off. 
 And another
 1  0.854310  0190
 2  2.374260  0190
 3  2.894221  0190
 4  3.964241  0190
 5  5.284241  0190

These were generated by running rtc-uie in a loop with variable sleep times between the calls to rtc-uie.

Mandriva cooker kernel 2.6.26 with all of David's patches installed.

The patches do resolve the spurious first interrupt problem that started all this. 

(Note I do not know if my emails with some of this will go through, but if they do, ignore them in favour of this comment posted from the web)

Comment 14 David Brownell 2008-07-23 14:55:16 UTC

I observed about 10% of a mid-sized sample (40 runs) as having these bizarre symptoms.  That's only with HPET ... most runs, and all without HPET, give nice regular one second intervals.

There are a number of other issues with the HPET interposed IRQs ... like not actually being in phase with the hardware update IRQs, and requiring way too many IRQs (64 Hz!).  One more bug seems unsurprising, though I'd like to know just what's causing this ...

Comment 15 W Unruh 2008-07-23 15:12:54 UTC

Yes, that is also what I found, except on my machine it was (usually)  a
lot less than 10%. Not sure what triggers it. I tried a run of 50 while the
machine was compiling the kernel, and that did not seem to make a
difference, so it does not seem to be interrupt collisions ( and many
milliseconds on a Core2 duo 2.4GHz machine sounds way way too long to be
interrupt collisions.)

Do I open another bug report on this?


> There are a number of other issues with the HPET interposed IRQs ... like not
> actually being in phase with the hardware update IRQs, and requiring way too
> many IRQs (64 Hz!).  One more bug seems unsurprising, though I'd like to know
> just what's causing this ...

What do you mean not being in phase with the hardware update irqs? I
thought it was that the  HPET routine simply captured the rtc generated
irq, and that you had to go through the hpet.c interrupt handler to get the
rtc IRQ. But is the hardware actually behaving differently when the HPET is
activated? Is there not some way of simply writing hpet.c so that hpet does
not intercept the rtc irq, or does it happen in hardware?


>
>
>

Comment 16 Anonymous Emailer 2008-07-23 15:31:02 UTC

Reply-To: david-b@pacbell.net

> Do I open another bug report on this?

Different bug == different bugreport.  :)


> > There are a number of other issues with the HPET interposed IRQs ... like
> not
> > actually being in phase with the hardware update IRQs, and requiring way
> too
> > many IRQs (64 Hz!).  One more bug seems unsurprising, though I'd like to
> know
> > just what's causing this ...
> 
> What do you mean not being in phase with the hardware update irqs? I
> thought it was that the  HPET routine simply captured the rtc generated
> irq, and that you had to go through the hpet.c interrupt handler to get the
> rtc IRQ. But is the hardware actually behaving differently when the HPET is
> activated? Is there not some way of simply writing hpet.c so that hpet does
> not intercept the rtc irq, or does it happen in hardware?

See the HPET spec.  Basically when the HPET is put into "legacy replacement"
mode -- what I call "broken" mode -- the RTC and the i8254 timer interrupts
are completely disconnected, with the first two HPET comparator IRQs spliced
in where they would normally appear.

Comment 17 W Unruh 2008-07-23 16:09:06 UTC

On Wed, 23 Jul 2008, bugme-daemon@bugzilla.kernel.org wrote:

> Reply-To: david-b@pacbell.net
>
>> Do I open another bug report on this?
>
> Different bug == different bugreport.  :)

Will do.

It is even worse than either of us expected. Here is a run where I reset
the counter by -5 every time an "error (difference is bigger than 1ms froma
second.
The time of the interrupt changes discontinuously to a new long term run

The * indicate "errors". Note that at the 18 sec mark the interrupt time
has suddenly shifted by over 9ms from what would appear to be the previous
"correct" interrupt time. Ie, before that the update seemed to occur at
.652 sec and afterwards at .562 sec. Ie, the phase offset between the HPET
and the RTC seems to have shifted by 9ms, which is completely nuts.


1    0.782692  0190
  -3 *  1.652687  0190
  -2    2.652684  0190
  -1    3.652682  0190
  0    4.652685  0190
  1    5.652683  0190
  2    6.652683  0190
  -2 *  8.152767  0190
  -1    8.652708  0190
  0    9.652697  0190
  1    10.652695  0190
  2    11.652697  0190
  3    12.652641  0190
  -1 *  14.152733  0190
  0    14.652642  0190
  1    15.652642  0190
  2    16.652792  0190
  3    17.652640  0190
  -1 *  18.562086  0190
  0    19.562064  0190
  1    20.562039  0190
  2    21.562015  0190

>
>
>>> There are a number of other issues with the HPET interposed IRQs ... like
>>> not
>>> actually being in phase with the hardware update IRQs, and requiring way
>>> too
>>> many IRQs (64 Hz!).  One more bug seems unsurprising, though I'd like to
>>> know
>>> just what's causing this ...
>>
>> What do you mean not being in phase with the hardware update irqs? I
>> thought it was that the  HPET routine simply captured the rtc generated
>> irq, and that you had to go through the hpet.c interrupt handler to get the
>> rtc IRQ. But is the hardware actually behaving differently when the HPET is
>> activated? Is there not some way of simply writing hpet.c so that hpet does
>> not intercept the rtc irq, or does it happen in hardware?
>
> See the HPET spec.  Basically when the HPET is put into "legacy replacement"
> mode -- what I call "broken" mode -- the RTC and the i8254 timer interrupts
> are completely disconnected, with the first two HPET comparator IRQs spliced
> in where they would normally appear.
>
>
>