hwclock test failed on Power9 due to 0.x sec differences / time out waiting for time change

This bug is missing log files that will aid in diagnosing the problem. While running an Ubuntu kernel (not a mainline or third-party kernel) please enter the following command in a terminal window:

apport-collect 1802233

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

Spotted on 4.15 Xenial, one of two power8 boxes failed with:
TestFail: Failed to set hwclock back to Warthog's birthday. Output of hwclock is 'Wed Oct 20 04:09:59 2004 .840175 seconds'

This issue could be found on node "dradis" as well.

Next step is for the kernel team to assess whether this is a test case issue, or a real kernel bug.

If you use it in verbose mode it works. It could be that it is slow to read from the rtc and the verbose mode just enough time to sync?

ubuntu@tiselius:~$ sudo /sbin/hwclock --set --date "2004/10/25 04:10:00"; sudo /sbin/hwclock --verbose
hwclock from util-linux 2.33.1
System Time: 1557759815.855012
Trying to open: /dev/rtc0
Using the rtc interface to the clock.
Last drift adjustment done at 1098677400 seconds after 1969
Last calibration done at 1098677400 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
ioctl(4, RTC_UIE_ON, 0): Invalid argument
Waiting in loop for time from /dev/rtc0 to change
...got clock tick
Time read from Hardware Clock: 2004/10/25 04:10:01
Hw clock time : 2004/10/25 04:10:01 = 1098677401 seconds since 1969
Time since last adjustment is 1 second
Calculated Hardware Clock drift is 0.000000 seconds
2004-10-25 04:09:59.806484+00:00
ubuntu@tiselius:~$

So looks like it is slow to sync with RTC.

ubuntu@tiselius:~$ sudo /sbin/hwclock --set --date "2004/11/21 04:10:00"; sudo strace -e ioctl "/sbin/hwclock"
ioctl(4, RTC_UIE_ON) = -1 EINVAL (Invalid argument)
ioctl(4, RTC_RD_TIME, {tm_sec=0, tm_min=10, tm_hour=4, tm_mday=21, tm_mon=10, tm_year=104, ...}) = 0
ioctl(4, RTC_RD_TIME, {tm_sec=0, tm_min=10, tm_hour=4, tm_mday=21, tm_mon=10, tm_year=104, ...}) = 0

when the hwclock command fails, the ioctl that fails is RTC_RD_TIME.. but running it with --verbose probably gives it just enough time to complete the sync.

Or you could use the command as follows:
ubuntu@tiselius:~$ sudo /sbin/hwclock --set --date "2004/11/22 04:10:00"; sudo /sbin/hwclock --delay=0.5
2004-11-22 04:09:59.898618+00:00
ubuntu@tiselius:~$

Tested with the latest mainline kernel on Baltar:
ubuntu@baltar:~$ uname -a
Linux baltar 5.1.1-050101-generic #201905110631 SMP Sat May 11 07:16:36 UTC 2019 ppc64le ppc64le ppc64le GNU/Linux

This issue still exist.

On the Witherspoon the hwclock does not seem to set at all.

ubuntu@bobone:~$ uname -a
Linux bobone 4.18.0-18-generic #19~18.04.1-Ubuntu SMP Fri Apr 5 10:21:11 UTC 2019 ppc64le ppc64le ppc64le GNU/Linux

ubuntu@bobone:~$ sudo /sbin/hwclock --set --date "2004/11/22 04:10:00"; sudo /sbin/hwclock
2019-05-15 14:36:33.802253+0000

ubuntu@bobone:~$ sudo /sbin/hwclock --set --date "2004/11/22 04:10:00"; sudo /sbin/hwclock --debug
hwclock from util-linux 2.31.1
System Time: 1557931207.255519
Trying to open: /dev/rtc0
Using the rtc interface to the clock.
Last drift adjustment done at 1101096600 seconds after 1969
Last calibration done at 1101096600 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
ioctl(4, RTC_UIE_ON, 0): Invalid argument
Waiting in loop for time from /dev/rtc0 to change
...got clock tick
Time read from Hardware Clock: 2019/05/15 14:40:08
Hw clock time : 2019/05/15 14:40:08 = 1557931208 seconds since 1969
Time since last adjustment is 456834608 seconds
Calculated Hardware Clock drift is 0.000000 seconds
2019-05-15 14:40:07.171582+0000

-- Witherspoon firmware --
Server: IBM-witherspoon-OP9-v2.2-9.56
BMC: ibm-v2.3-476-g2d622cb-r30-0-g862e40a

------- Comment From <email address hidden> 2019-05-17 15:22 EDT-------
We had bugs reported in past also about hwclock not working on P9.
LTC 155321 is one of such bugs. Its likely openBMC issue here.
As per latest comment in bug 155321

========

The issue if already fixed by https://github.com/openbmc/phosphor-time-manager/commit/25b4ce95f9d0bea33fbf0364e72f304542a19bc5 and it's picked in OpenBMC at https://github.com/openbmc/openbmc/commit/7d35280296a118ec2b2e8b8711b6cc65a77f00cb

But the fix changes the "default" setting, if the settings already exists in BMC, it still takes effect.

So suggest to re-test the issue with a fresh OpenBMC build. It should already be fixed.

Would a similar BMC firmware release from AMI fix this issue for Bostons systems? and is there an ETA for when that will be available to us.

------- Comment From <email address hidden> 2019-05-21 11:58 EDT-------
(In reply to comment #24)
> Would a similar BMC firmware release from AMI fix this issue for Bostons
> systems? and is there an ETA for when that will be available to us.

Hi Stewart,

Please let know if a BMC firmware release exists that fixes this issue on
Boston ? This is similar issue reported in LTC bug 155321 for Witherspoon.

------- Comment From <email address hidden> 2019-05-21 21:46 EDT-------
(In reply to comment #25)
> (In reply to comment #24)
> > Would a similar BMC firmware release from AMI fix this issue for Bostons
> > systems? and is there an ETA for when that will be available to us.
>
>
> Hi Stewart,
>
> Please let know if a BMC firmware release exists that fixes this issue on
> Boston ? This is similar issue reported in LTC bug 155321 for Witherspoon.

You'd have to ask Supermicro

Changing owner to "bugproxy" as the next steps are with IBM on the Witherspoon and Boston firmware.

Michael,

Is there any information from supermicro that you can share with us over here? If this is not going to be fixed then we might have to modify the testcase to use a workaround. Please let us know.

------- Comment From <email address hidden> 2019-06-04 16:47 EDT-------
is there issue associate with this problem?
How does one recreate this problem?

@youhour are you able to see the comments in the launchpad bug?

If not you could reproduce the issue using a command like:

$ sudo /sbin/hwclock --set --date "2004/10/25 04:10:00"; sudo /sbin/hwclock

------- Comment From <email address hidden> 2019-06-06 13:19 EDT-------
bugproxy, I did see the command. However, it was not clear if that what trigger the failure. The details of the problem isn't clear.

Any way, you have not answer my first question yet... is there github issue associate with this problem?

Here are some more question...
is NTP enable on your system? If NTP is enabled, BMC will not allow end-user to change SEL time.

is this a problem report from the field or this is just a bug found in the lab?

------- Comment From <email address hidden> 2019-06-06 13:27 EDT-------
Oh, another question. What problem would a customer see if this problem is not fixed?

Sorry did not realize that all the comments were not correctly mirrored over. A launchpad bug was reported by the Ubuntu kernel team as a result of their testing in the lab. We were not sure if this was a BMC issue, a hardware issue or kernel bug, so there is no github report as of now. If you think this is related to the BMC I can open a github bug. Also please tell us how to open bugs for BMC on Bostons.

== P9 Boston ==
There seems to be a delay between setting the hwclock and reading from it.
ubuntu@tiselius:~$ sudo /sbin/hwclock --set --date "2004/11/21 04:10:00"; sudo strace -e ioctl "/sbin/hwclock"
ioctl(4, RTC_UIE_ON) = -1 EINVAL (Invalid argument)
ioctl(4, RTC_RD_TIME, {tm_sec=0, tm_min=10, tm_hour=4, tm_mday=21, tm_mon=10, tm_year=104, ...}) = 0
ioctl(4, RTC_RD_TIME, {tm_sec=0, tm_min=10, tm_hour=4, tm_mday=21, tm_mon=10, tm_year=104, ...}) = 0

when the hwclock command fails, the ioctl that fails is RTC_RD_TIME.. but running it with --verbose probably gives it just enough time to complete the sync.

Or you could use the command as follows:
ubuntu@tiselius:~$ sudo /sbin/hwclock --set --date "2004/11/22 04:10:00"; sudo /sbin/hwclock --delay=0.5
2004-11-22 04:09:59.898618+00:00
ubuntu@tiselius:~$

== P9 Witherspoon ==
On the Witherspoon the hwclock does not seem to set at all.

ubuntu@bobone:~$ uname -a
Linux bobone 4.18.0-18-generic #19~18.04.1-Ubuntu SMP Fri Apr 5 10:21:11 UTC 2019 ppc64le ppc64le ppc64le GNU/Linux

ubuntu@bobone:~$ sudo /sbin/hwclock --set --date "2004/11/22 04:10:00"; sudo /sbin/hwclock
2019-05-15 14:36:33.802253+0000

ubuntu@bobone:~$ sudo /sbin/hwclock --set --date "2004/11/22 04:10:00"; sudo /sbin/hwclock --debug
hwclock from util-linux 2.31.1
System Time: 1557931207.255519
Trying to open: /dev/rtc0
Using the rtc interface to the clock.
Last drift adjustment done at 1101096600 seconds after 1969
Last calibration done at 1101096600 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
ioctl(4, RTC_UIE_ON, 0): Invalid argument
Waiting in loop for time from /dev/rtc0 to change
...got clock tick
Time read from Hardware Clock: 2019/05/15 14:40:08
Hw clock time : 2019/05/15 14:40:08 = 1557931208 seconds since 1969
Time since last adjustment is 456834608 seconds
Calculated Hardware Clock drift is 0.000000 seconds
2019-05-15 14:40:07.171582+0000

------- Comment From <email address hidden> 2019-06-07 14:04 EDT-------
I don't know if this is a BMC issue either. With your latest note, I still do not understand the problem on Boston. Whether this is a HWCLOCK setting issue or HWCLOCK setting is working but have a long delay... Can you help clarify that?

Here is how you create a problem tracking for Boston.

1) You will need github ID
2) If you do not have access, send your github ID to Maurice Zipse to request for access. If you do not have github ID, get one.
3) Link to github issue: https://github.com/open-power/boston-openpower/issues/
4) Click on "New issue" top right to create a new issue for P9 Boston. Provide details of the problem so that we can understand your issue.

Let me know if you have any other question.

Opened issue 1423 on this - unfortunately the boston openpower is closed.

I tried some test fw for the boston:

ubuntu@ltc-boston25:~$ sudo /sbin/hwclock --set --date "2019/06/10 12:55:00"; sudo /sbin/hwclock --verbose
[sudo] password for ubuntu:
hwclock from util-linux 2.33.1
System Time: 1560377530.955292
Trying to open: /dev/rtc0
Using the rtc interface to the clock.
Last drift adjustment done at 1560189300 seconds after 1969
Last calibration done at 1560189300 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
ioctl(4, RTC_UIE_ON, 0): Invalid argument
Waiting in loop for time from /dev/rtc0 to change
...got clock tick
Time read from Hardware Clock: 2019/06/10 17:55:01
Hw clock time : 2019/06/10 17:55:01 = 1560189301 seconds since 1969
Time since last adjustment is 1 second
Calculated Hardware Clock drift is 0.000000 seconds
2019-06-10 12:55:00.022780-05:00
ubuntu@ltc-boston25:~$

But I still have:
ubuntu@ltc-boston25:~$ sudo /sbin/hwclock --set --date "2004/11/21 04:10:00"; sudo strace -e ioctl "/sbin/hwclock"
ioctl(4, RTC_UIE_ON) = -1 EINVAL (Invalid argument)
ioctl(4, RTC_RD_TIME, {tm_sec=0, tm_min=10, tm_hour=10, tm_mday=21, tm_mon=10, tm_year=104, ...}) = 0
<snip>
ioctl(4, RTC_RD_TIME, {tm_sec=1, tm_min=10, tm_hour=10, tm_mday=21, tm_mon=10, tm_year=104, ...}) = 0
ioctl(4, RTC_RD_TIME, {tm_sec=1, tm_min=10, tm_hour=10, tm_mday=21, tm_mon=10, tm_year=104, ...}) = 0
2004-11-21 04:10:00.018862-06:00
+++ exited with 0 +++
ubuntu@ltc-boston25:~$

But it generally seems to work - if I don't include any args it does set correctly still:
ubuntu@ltc-boston25:~$ sudo /sbin/hwclock --set --date "2019/06/10 12:55:00"; sudo /sbin/hwclock
2019-06-10 12:54:59.982163-05:00
ubuntu@ltc-boston25:~$

Anything else you suggest?

I upgraded the firmware on tiselius (boston p9) and ran the testcase and it works as expected.

ubuntu@tiselius:~$ sudo /sbin/hwclock --set --date "2019/06/10 12:55:00"; sudo /sbin/hwclock
2019-06-10 12:54:59.969984+00:00
ubuntu@tiselius:~$

should I wait for the release version of the firmware before I upgrade the other boston systems?

IBM indicated that they do not have an ETA for a GA release of the BMC firmware with this fix. Would the kernel team be ok with working around this issue in the testcase by adding a .5 delay?

From my point of view,
I think we should leave the test case as-is, it helped us to identify this firmware issue. And it might be able to catch another FW issues on other platforms in the future.

For this specific HW, we can make a note for the test result by using this bug report.
Thanks.

@cypressyew that sounds reasonable, the only word of caution here is we should not dismiss future bugs detected on this system as "expected to fail", because the problem is in the 3rd party BMC firmware *and not* in the Pnor FW or Power9 hardware.