Skip to content

hwclock Timed out waiting for time change Error #1387

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
Ataraxiall opened this issue Jul 8, 2021 · 25 comments
Closed

hwclock Timed out waiting for time change Error #1387

Ataraxiall opened this issue Jul 8, 2021 · 25 comments

Comments

@Ataraxiall
Copy link

Good morning,

I have installed an RTC module with and when trying to read the time it gives me this error.

hwclock -r -v --rtc /dev/rtc1 hwclock from util-linux 2.37.154-c2ca2 System Time: 1625749015.843650 Using the rtc interface to the clock. Last drift adjustment done at 1625749005 seconds after 1969 Last calibration done at 1625749005 seconds after 1969 Hardware clock is on UTC time Assuming hardware clock is kept in UTC time. Waiting for clock tick... ioctl(3, RTC_UIE_ON, 0): Invalid argument Waiting in loop for time from /dev/rtc1 to change hwclock: Timed out waiting for time change. ...synchronization failed

Any idea?

Thanks!

@karelzak
Copy link
Collaborator

What hardware?

It seems your RTC does not support RTC_UIE_ON, in this case, hwclock uses a busy-loop with RTC_RD_TIME ioctl and it waits for the next tick (change of the second in clock). For some reason, the change is bigger than 1.5 seconds.

Frankly, the best solution is to ask kernel RTC developers, I'm not sure what happened in your case. Maybe hwclock should be more patient and tried to sync in more attempts.

@Ataraxiall
Copy link
Author

Hi,

Thanks for the response.

My HW is this

https://wiki.friendlyarm.com/wiki/index.php/Matrix_-_RTC

Is possible to change the 1.5sec?

Thanks!

@karelzak
Copy link
Collaborator

The 1.5 check is correct if we want to sync with 1sec tick, the question is why it's so slow and why it does not support RTC_UIE_ON.

Please, try the following patch:

diff --git a/sys-utils/hwclock-rtc.c b/sys-utils/hwclock-rtc.c
index 07af9c83c..a033e6419 100644
--- a/sys-utils/hwclock-rtc.c
+++ b/sys-utils/hwclock-rtc.c
@@ -213,6 +213,7 @@ static int busywait_for_rtc_clock_tick(const struct hwclock_control *ctl,
        struct tm nowtime;
        int rc;
        struct timeval begin = { 0 }, now = { 0 };
+       int try_counter = 0;
 
        if (ctl->verbose) {
                printf("ioctl(%d, RTC_UIE_ON, 0): %s\n",
@@ -221,6 +222,7 @@ static int busywait_for_rtc_clock_tick(const struct hwclock_control *ctl,
                       rtc_dev_name);
        }
 
+again:
        if (do_rtc_read_ioctl(rtc_fd, &start_time))
                return 1;
 
@@ -236,8 +238,12 @@ static int busywait_for_rtc_clock_tick(const struct hwclock_control *ctl,
                        break;
                gettime_monotonic(&now);
                if (time_diff(now, begin) > 1.5) {
-                       warnx(_("Timed out waiting for time change."));
-                       return 1;
+                       try_counter++;
+                       warnx(_("[#%d] Timed out waiting for time change (delay: %g)"),
+                                       try_counter, time_diff(now, begin));
+                       if (try_counter >= 10)
+                               return 1;
+                       goto again;
                }
        } while (1);
 

to get more details. It will try it 10 times and print the delay.

@Ataraxiall
Copy link
Author

Hi!

Thanks for you time.
How i can apply that? Copy and paste in ther terminal?

Thank!

karelzak added a commit that referenced this issue Jul 27, 2021
Addresses: #1387
Signed-off-by: Karel Zak <kzak@redhat.com>
@karelzak
Copy link
Collaborator

OK, I have created a branch with the change. Try:

git clone https://github.com/karelzak/util-linux.git
cd util-linux
git checkout -f hwclock-releap-busywait
./autogen.sh
./configure
make hwclock
sudo ./hwclock -r -v --rtc /dev/rtc1 

@Ataraxiall
Copy link
Author

Hello,

Dont work..

hwclock from util-linux 2.37.202-3ade7
System Time: 1627390513.001929
Using the rtc interface to the clock.
Last drift adjustment done at 1627389902 seconds after 1969
Last calibration done at 1627389902 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
ioctl(3, RTC_UIE_ON, 0): Invalid argument
Waiting in loop for time from /dev/rtc1 to change
hwclock: [#0] Timed out waiting for time change (delay: 1.500650 sec)
hwclock: [#1] Timed out waiting for time change (delay: 1.500663 sec)
hwclock: [#2] Timed out waiting for time change (delay: 1.500106 sec)
hwclock: [#3] Timed out waiting for time change (delay: 1.500483 sec)
hwclock: [#4] Timed out waiting for time change (delay: 1.500029 sec)
hwclock: [#5] Timed out waiting for time change (delay: 1.500772 sec)
hwclock: [#6] Timed out waiting for time change (delay: 1.500721 sec)
hwclock: [#7] Timed out waiting for time change (delay: 1.500053 sec)
hwclock: [#8] Timed out waiting for time change (delay: 1.500369 sec)
hwclock: [#9] Timed out waiting for time change (delay: 1.500766 sec)

:(

@karelzak
Copy link
Collaborator

Well, try to change 1.5 to 1.6 in the code ;-) https://github.com/karelzak/util-linux/blob/hwclock-releap-busywait/sys-utils/hwclock-rtc.c#L239 (sys-utils/hwclock-rtc.c line 239).

@karelzak
Copy link
Collaborator

Or we can round the number.

@gschmottlach-xse
Copy link

I have encountered the same error on my embedded target. Probably 50% of the time I get the "Timed out waiting for time change" error when trying to use hwclock to show the RTC time. I even applied the above patch but as @Ataraxiall experienced, the error continues. My platform is a Xilinx 7000 based target based on Xilinx PetaLinux 2022.1 (Kernel 5.15.19-rt40) with the PREEMPT_RT patches applied. I build my system with Yocto hornister (util-linux_2.37.2.bb) and I have a Micro Crystal RTC (RV-3028-C7) so there is an existing Linux driver. I've used a JTAG debugger to set breakpoints in the rtc-rv3028 driver and the IOCTL(RTC_RD_TIME) ultimately lands in rtc-rv3028.c:rv3028_get_time() where the RTC time is read via calls to regmap_bulk_read(). This triggers I2C reads to the RTC chip itself.

From the Linux command-line on the target I can easily read the current RTC with this command:

$ cat /sys/bus/i2c/devices/0-0052/rtc/rtc0/time
17:03:05

This too ends up in the same rv3028_get_time() function. Using this command I can get the RTC time as fast as I can repeat the command. There is no perceptible delay or timeout. So there appears to be something different about the IOCTL(RTC_RD_TIME) pathway. It seems if I insert additional "printf's" in the above patch so there is more console I/O the process executes "slower" and the number of re-occurring timeout errors diminish. With this in mind I developed another work-around. The patch is shown below:

Index: util-linux-2.37.2/sys-utils/hwclock-rtc.c
===================================================================
--- util-linux-2.37.2.orig/sys-utils/hwclock-rtc.c
+++ util-linux-2.37.2/sys-utils/hwclock-rtc.c
@@ -13,6 +13,7 @@
 #include <sys/time.h>
 #include <time.h>
 #include <unistd.h>
+#include <sched.h>
 
 #include "monotonic.h"
 #include "nls.h"
@@ -198,6 +199,27 @@ static int do_rtc_read_ioctl(int rtc_fd,
 	return 0;
 }
 
+static long calc_busywait_delay()
+{
+    struct timespec tm;
+    long usec_delay = 1;
+    int scheduler;
+    int rc;
+
+    /* Get the scheduler of the calling process */
+    scheduler = sched_getscheduler(0);
+    if ( (scheduler == SCHED_RR) || (scheduler == SCHED_OTHER) ) {
+        rc = sched_rr_get_interval(0, &tm);
+        if ( rc != 0 ) {
+            usec_delay = 1000;
+        } else {
+            usec_delay = (tm.tv_sec * 1000000) + (tm.tv_nsec / 1000); 
+        }
+    }
+
+    return usec_delay;
+}
+
 /*
  * Wait for the top of a clock tick by reading /dev/rtc in a busy loop
  * until we see it. This function is used for rtc drivers without ioctl
@@ -213,6 +235,7 @@ static int busywait_for_rtc_clock_tick(c
 	struct tm nowtime;
 	int rc;
 	struct timeval begin = { 0 }, now = { 0 };
+	long delay = calc_busywait_delay();
 
 	if (ctl->verbose) {
 		printf("ioctl(%d, RTC_UIE_ON, 0): %s\n",
@@ -239,6 +262,7 @@ static int busywait_for_rtc_clock_tick(c
 			warnx(_("Timed out waiting for time change."));
 			return 1;
 		}
+		usleep(delay);
 	} while (1);
 
 	if (rc)

Basically, I introduce a delay (usleep) between successive ioctl() calls to read the RTC. This delay is generally based on the execution quantum of the scheduler. On my target platform this is typically 10 msec. With the above patch, I have not been able to reproduce the "timeout" error I was getting 50% of the time when trying to show the RTC time with hwclock -r. This is more likely a work-around than a real fix but I hope others encountering similar issues (with a schedule to meet) might want to try this solution. Unfortunately, I don't have time to dive much further into this problem to discover the root cause of the timeout. Perhaps it's related to using a kernel with the PREMPT_RT patches applied. It seems there is some issue with hitting the RTC clock too quickly that causes the problem. Since the RTC is accessed via I2C and then abstracted via the regmap interface in the kernel, maybe there is a timing limitation here.

I hope someone might have more insights into this issue and can devise a better fix (or can at least describe the underlying root cause). Until then, I think this patch might work for others experiencing the same issue.

@karelzak
Copy link
Collaborator

Maybe the delay is not so bad idea. Frankly, the busy loop is a pretty nasty thing, and I can imagine that kernel tries to optimize this behavior. And for example, for read/write on EAGAIN, we already use delay in the loops (in other tools), so why not here? :-)

@SyntaxColoring
Copy link

@gschmottlach-xse, we're using the same RTC as you (RV-3028). We recently started seeing similar problems when we run hwclock --hctosys.

Perhaps it's related to using a kernel with the PREMPT_RT patches applied.

We don't have those patches, so I don't think the problem is related to them, unless the two of us are seeing two separate problems.

We're going to try some debugging. I'll reply here if we find anything useful.

@gschmottlach-xse
Copy link

Unfortunately, my hack/patch above is not 100% successful at preventing the timeout although it is much less frequent. I hope you can figure out the root cause of this issue because I'd like to correct it. The strange thing is if you cat /sys/class/rtc/rtc0/time from the shell the time steadily increasing every second (e.g. there does not appear to be pause where it reports the same value for several seconds). Ultimately, the call to get the "current" time ends up in the same spot in the RV-3028 driver whether it's triggered through hwclock or cat of the system parameter. This almost leads me to believe the issue may be outside the driver but I have no other evidence other than a hunch. I hope you are successful finding a proper fix and are willing to share.

Good luck!

@SyntaxColoring
Copy link

SyntaxColoring commented Jul 29, 2022

@gschmottlach-xse

It seems there is some issue with hitting the RTC clock too quickly that causes the problem.

This is basically our theory, too, but we still can't quite explain it.

The RV-3028's application manual describes a suspicious feature where it will "lock" its clock registers during I2C transactions. While we're reading the registers over I2C, it will postpone updating them, to avoid a torn-read hazard. If the clock would have incremented during the read, it's supposed to apply that update whenever the I2C transaction ends, after the stop condition. See section 4.5.

I've confirmed with a logic analyzer that the kernel driver is sending that I2C stop condition when I expect it to. So the chip should have a chance to apply its clock update. The application note does require a "Bus free time before a new transmission" of 4.7 µs, but we're far above that.

So it seems like there's either:

  • A silicon bug in our chips
  • An electrical problem on our boards
  • An operational nuance of these chips that everybody has missed so far

:(


The strange thing is if you cat /sys/class/rtc/rtc0/time from the shell the time steadily increasing every second (e.g. there does not appear to be pause where it reports the same value for several seconds).

I think the overhead of spawning processes and going through sysfs is effectively doing the same thing as your patch: slowing down the polling with artificial delays.

On my Pi-based system, if I run hwclock --show or hwclock --hctosys (without your patch), there's about ~35 µs between the many I2C transactions that hwclock triggers.

On the other hand, if I run this:

while true; do cat /sys/class/rtc/rtc0/time; done

There's about 4000 µS between each pair of status-register-reading and clock-register-reading I2C transactions.

[read status reg] [read clock reg]               [read status reg] [read clock reg] ...
                                 |<-- 4000 µS -->|

As measured with a logic analyzer.


So far, I think we're approaching the same place as you. It seems like adding artificial delays in between individual I2C transactions mitigates the problem. But it remains unclear whose fault the problem is, or what a proper fix would be.

@gschmottlach-xse
Copy link

Given your findings, if you manage to come up with a more consistent (and effective) patch than mine, please post it. I doubt it's an electrical problem on your board since we are apparently suffering the same fate. More likely an operational nuance or an undisclosed silicon errata. I can live with a 4msec pause between polling the chip if that makes it 100% reliable. Please share your findings if this approach proves effective.

@SyntaxColoring
Copy link

@gschmottlach-xse Why does your patch calculate a delay based on the execution quantum of the scheduler? Why not sleep for some constant, hard-coded duration?

@gschmottlach-xse
Copy link

I was hoping to avoid a hard-coded sleep since I didn't have a good measurement (like you have with your scope) of the amount of time to pause between transactions with the RTC. If you can get things working reliably using a hard-coded value between successive RTC requests then I would be happy. I just want a predictable experience and avoid the timeouts.

@SyntaxColoring
Copy link

SyntaxColoring commented Aug 10, 2022

We ended up inserting an artificial 2-4 ms delay in the Linux device driver for the RV-3028.

Here is our kernel patch.

This appears to work more consistently than the patch suggested above to insert these delays at the hwclock level. On a test where the hwclock patch succeeded 50% of the time, the kernel patch succeeds 100% of the time.

Mind you, this is only based on testing with a single problematic board. It remains to be seen how effective this kernel patch will be in mass use. [Update 2023-05-14: as far as I know, we haven't seen this problem since applying the patch 9 months ago, so it seems effective.]


If anybody else runs into this and wants to keep digging, here are my I2C captures, with some notes. They compare the hwclock delay workaround, the Linux driver delay workaround, and no workaround.

I had to split the archive up into multiple files to work around a GitHub upload limit. Extract with:

cat "RV-3028 logic analyzer captures".*.tar.gz | tar xzvf -

@gschmottlach-xse
Copy link

Thanks for your patch. I'll apply the same to our kernel and see if it improves our situation.

@gschmottlach-xse
Copy link

@SyntaxColoring - after a number of consecutive runs, it seems my timeouts are now elminated. Either we both have poorly designed boards (not likely) or there is indeed an issue with the RTC chip, driver, or elsewhere. Regardless, your patch seems to have reliably solved my problem. - Thanks

@karelzak
Copy link
Collaborator

@SyntaxColoring thanks!

Closing ...

@SyntaxColoring
Copy link

If anybody else runs into this in the future, I'm curious what kind of hardware they're on.

The workaround that I posted is specific to problematic RV-3028 chips. But the original poster, @Ataraxiall, reported using a different chip.

@gauthamikosanam
Copy link

Hi
I am using raspberry pi 3B+ board....I am getting error if I do sudo hwclock
hwclock: selec() to /dev/rtc0 to wait for clock tick timed out.....
Can you give solution for ths?

@SyntaxColoring
Copy link

@gauthamikosanam Is that the exact error message? If yes, it doesn't look like anything we've seen so far in this thread.

If your RTC hardware is an RV-3028, you can try the Linux kernel patch that I described above. Otherwise, I don't know, but I'd guess you're seeing an unrelated problem.

@gauthamikosanam
Copy link

I am using rtc-isl1208 ic and working on raspberryPi 4. I am able to detect the slave address i.e 0x6f.
I am opening the device as
char filename = "/dev/i2c-10";
if(wiringPiSetup () == -1) exit (1);
if((fd = open(filename, O_RDWR)) < 0) {
/
ERROR HANDLING: you can check errno to see what went wrong */
perror("Failed to open the RTC i2c bus");
exit(1);
}
if(ioctl(fd,I2C_SLAVE,I2C_RTCADDR) < 0){
printf("IOCTL error opening file= %s\n ",strerror(errno));
return 1;
}
wiringPiI2CWriteReg8(fd,CONTROL_REG,0x10);
First time i want to set the time from system time .
wiringPiI2CWriteReg8(fd,SC,decToBcd(cur_time->tm_sec));
wiringPiI2CWriteReg8(fd,MN,decToBcd(cur_time->tm_min));
wiringPiI2CWriteReg8(fd,HR,decToBcd(cur_time->tm_hour));
wiringPiI2CWriteReg8(fd,DT,decToBcd(cur_time->tm_mday));
wiringPiI2CWriteReg8(fd,MO,decToBcd(cur_time->tm_mon + 1 ));
wiringPiI2CWriteReg8(fd,YR,decToBcd(cur_time->tm_year % 100));
Again I am reading from the time register
int sec = bcdToDec(wiringPiI2CReadReg8(fd,SC) & 0x7F);
int min = bcdToDec(wiringPiI2CReadReg8(fd,MN) & 0x7F);
int hour = bcdToDec(wiringPiI2CReadReg8(fd,HR) & 0x3F);
int date = bcdToDec(wiringPiI2CReadReg8(fd,DT) & 0x3F);
int mon = bcdToDec(wiringPiI2CReadReg8(fd,MO) & 0x1F);
int year = bcdToDec(wiringPiI2CReadReg8(fd,YR));
printf(" RTC Time %02d:%02d:%02d %02d/%02d/%02d\n",hour,min,sec,date,mon,year);
From second time onwards I dont want to take the system time and run again....
Here I am not able to get the updated time....its not updating....anything I did mistake....?

@gauthamikosanam
Copy link

If I do sudo hwclock -r
getting this error
hwclock: Cannot access the hardware clock via any known method
hwclock: Use the --verbose option to see the details of our search for an access method
For rasperry Pi do we need to install any driver for rtc isl1208?
any suggestion ?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants