arm64/rk805: hide RTC logging behind sysctl not bootverbose

[bz]

Summary

Introduce a dedicated sysctl for logging the Rea/Set RTC messages.
On systems booted with bootverbose those otherwise log on console
regularly which otherwise might be silent.

Reviewed by:
MFC After: 2 weeks
Differential Revision: ...

[bz]

Anyone? Otherwise I'll commit this within the next week.

[imp]

But what I want to know is why do we regularly read the time? Normally this is read only at boot or resume. It is only written when we step the time (which is quite rare).

[manu]

I don't see those message after boot on the console so same as imp I'm wondering why you see them.
That seems to indicate that something else is not working correctly for you and you just hide the problem.

[bz]

In D30361#688599, @imp wrote:

But what I want to know is why do we regularly read the time? Normally this is read only at boot or resume. It is only written when we step the time (which is quite rare).

I think READ only happened once but "Set" looked liked this (from an old console log); every 30 minutes.

rk805_pmu0: Set RTC at 2021-05-20 12:57:55[.735434751]
rk805_pmu0: Set RTC at 2021-05-20 13:27:55[.744813235]
rk805_pmu0: Set RTC at 2021-05-20 13:57:55[.823935389]
rk805_pmu0: Set RTC at 2021-05-20 14:27:55[.860810910]
rk805_pmu0: Set RTC at 2021-05-20 14:57:56[.004937166]
rk805_pmu0: Set RTC at 2021-05-20 15:27:56[.036814627]
rk805_pmu0: Set RTC at 2021-05-20 15:57:56[.040689195]
rk805_pmu0: Set RTC at 2021-05-20 16:27:56[.049566994]
rk805_pmu0: Set RTC at 2021-05-20 16:57:56[.128440982]
rk805_pmu0: Set RTC at 2021-05-20 17:27:56[.162319023]
rk805_pmu0: Set RTC at 2021-05-20 17:57:56[.237192834]
rk805_pmu0: Set RTC at 2021-05-20 18:27:56[.237820157]
rk805_pmu0: Set RTC at 2021-05-20 18:57:56[.280695402]
rk805_pmu0: Set RTC at 2021-05-20 19:27:56[.372820592]
rk805_pmu0: Set RTC at 2021-05-20 19:57:56[.397446215]
rk805_pmu0: Set RTC at 2021-05-20 20:27:56[.401574287]
rk805_pmu0: Set RTC at 2021-05-20 20:57:56[.436200120]
rk805_pmu0: Set RTC at 2021-05-20 21:27:56[.468324481]
rk805_pmu0: Set RTC at 2021-05-20 21:57:56[.471199906]
rk805_pmu0: Set RTC at 2021-05-20 22:27:56[.584075874]
rk805_pmu0: Set RTC at 2021-05-20 22:57:56[.620702015]
rk805_pmu0: Set RTC at 2021-05-20 23:27:56[.623327841]
rk805_pmu0: Set RTC at 2021-05-20 23:57:56[.629704578]
rk805_pmu0: Set RTC at 2021-05-21 00:27:56[.744778200]

[bz]

In D30361#688602, @manu wrote:

I don't see those message after boot on the console so same as imp I'm wondering why you see them.
That seems to indicate that something else is not working correctly for you and you just hide the problem.

I boot bootverbose which otherwise is very quiet for normal operation.

[manu]

In D30361#688609, @bz wrote:

In D30361#688602, @manu wrote:

I don't see those message after boot on the console so same as imp I'm wondering why you see them.
That seems to indicate that something else is not working correctly for you and you just hide the problem.

I boot bootverbose which otherwise is very quiet for normal operation.

I also bootverbose

[imp]

In D30361#688605, @bz wrote:

I think READ only happened once but "Set" looked liked this (from an old console log); every 30 minutes.

What is calling that? What is setting the time every 30 minutes?

[manu]

In D30361#688616, @imp wrote:

In D30361#688605, @bz wrote:

I think READ only happened once but "Set" looked liked this (from an old console log); every 30 minutes.

What is calling that? What is setting the time every 30 minutes?

I didn't had ntpd running, now I have and I do see the printf.
Haven't looked at what is causing that but I would prefer to find the real reason before hidding those message under a sysctl that no one will ever set.

[bz]

In D30361#688616, @imp wrote:

In D30361#688605, @bz wrote:

I think READ only happened once but "Set" looked liked this (from an old console log); every 30 minutes.

What is calling that? What is setting the time every 30 minutes?

If I had to bet it's sys/kern/kern_ntptime.c::periodic_resettodr() which has a default of 1800.

[imp]

In D30361#688621, @bz wrote:

In D30361#688616, @imp wrote:

In D30361#688605, @bz wrote:

I think READ only happened once but "Set" looked liked this (from an old console log); every 30 minutes.

What is calling that? What is setting the time every 30 minutes?

If I had to bet it's sys/kern/kern_ntptime.c::periodic_resettodr() which has a default of 1800.

Yea, that's crazy.

We need to estimate how long it would take to accumulate 0.5s of error for this call to be useful (since we're not waiting for top of second to set it).

100ppm error this is 5000 seconds (or 83 minutes). That's the max error ntpd can tolerate. The typical ntpd error is closer to 10ppm or 1ppm. 10ppm would dictate closer to twice a day (every 13-14 hours).

I think the default should change to something more like 40k-50k seconds. I'll take care of that.

Even with that change, this would be a bit noisy, so I'm OK with it. manu?

[manu]

In D30361#688626, @imp wrote:

In D30361#688621, @bz wrote:

In D30361#688616, @imp wrote:

In D30361#688605, @bz wrote:

I think READ only happened once but "Set" looked liked this (from an old console log); every 30 minutes.

What is calling that? What is setting the time every 30 minutes?

If I had to bet it's sys/kern/kern_ntptime.c::periodic_resettodr() which has a default of 1800.

Yea, that's crazy.

We need to estimate how long it would take to accumulate 0.5s of error for this call to be useful (since we're not waiting for top of second to set it).

100ppm error this is 5000 seconds (or 83 minutes). That's the max error ntpd can tolerate. The typical ntpd error is closer to 10ppm or 1ppm. 10ppm would dictate closer to twice a day (every 13-14 hours).

I think the default should change to something more like 40k-50k seconds. I'll take care of that.

Even with that change, this would be a bit noisy, so I'm OK with it. manu?

I don't know, for me bootverbose is not only for boot only messages but also include diagnostic at runtime, so I'm not surprised to see random messages on the console.
But also those message are not that useful so ...
I think I would prefer to not display the message by default and only print them if setting the time failed.
The get time message will only appear once it seems so printing it under bootverbose seems ok to me.

[bz]

Even with that change, this would be a bit noisy, so I'm OK with it. manu?

I don't know, for me bootverbose is not only for boot only messages but also include diagnostic at runtime, so I'm not surprised to see random messages on the console.
But also those message are not that useful so ...
I think I would prefer to not display the message by default and only print them if setting the time failed.
The get time message will only appear once it seems so printing it under bootverbose seems ok to me.

In that case should we entirely drop it as sys/kern/subr_rtc.c::settime_task_func() will log that case already if bootverbose is enabled (so we'd already get a log entry)?

[imp]

Oh, wait, that's ntpd's steering error, not the RTC error, which is uncorrelated to anything else w/o good intel about the system... 30 minutes is too often, but how to compute something better is well beyond the scope of this review...

[manu]

In D30361#688637, @bz wrote:

Even with that change, this would be a bit noisy, so I'm OK with it. manu?

I don't know, for me bootverbose is not only for boot only messages but also include diagnostic at runtime, so I'm not surprised to see random messages on the console.
But also those message are not that useful so ...
I think I would prefer to not display the message by default and only print them if setting the time failed.
The get time message will only appear once it seems so printing it under bootverbose seems ok to me.

In that case should we entirely drop it as sys/kern/subr_rtc.c::settime_task_func() will log that case already if bootverbose is enabled (so we'd already get a log entry)?

Yes I think that the print in subr_rtc is enough.

[imp]

In D30361#688637, @bz wrote:

Even with that change, this would be a bit noisy, so I'm OK with it. manu?

I don't know, for me bootverbose is not only for boot only messages but also include diagnostic at runtime, so I'm not surprised to see random messages on the console.
But also those message are not that useful so ...
I think I would prefer to not display the message by default and only print them if setting the time failed.
The get time message will only appear once it seems so printing it under bootverbose seems ok to me.

In that case should we entirely drop it as sys/kern/subr_rtc.c::settime_task_func() will log that case already if bootverbose is enabled (so we'd already get a log entry)?

Yea. Unless we can add additional details as to why, we should drop it...

[bz]

arm64/rk805: remove RTC Set logging

NTP code triggers a regular write of the RTC which logs on console
when booted bootverbose.  Remove the printf as settime_task_func()
will already log errors under bootverbose (which is really what we
are interested in).  We leave the RTC Read which should only happen
once on boot.

[imp]

In D30361#688645, @bz wrote:

arm64/rk805: remove RTC Set logging

NTP code triggers a regular write of the RTC which logs on console
when booted bootverbose.  Remove the printf as settime_task_func()
will already log errors under bootverbose (which is really what we
are interested in).  We leave the RTC Read which should only happen
once on boot.

"When ntpd is synchronizing the system time, it also periodically (30m) syncs the
the RTC time. Remove printf in rk805_settime which triggers every 30m, as
settime_task_func() will log errors under bootverbose. We leave the RTC Read
logging, which should happen only once at boot."

might be better. The key point is that this is normal activity from ntpd, not something
weird it is doing.

[manu]

Accepted with imp commit message suggestion :)

[bz]

In D30361#688656, @manu wrote:

Accepted with imp commit message suggestion :)

Happy to go with @imp 's text :-)

[imp]

Reviewed by: imp

[bz]

Thanks both of you!