| Message ID | 20170718211930.123077-1-salyzyn@android.com (mailing list archive) |
|---|---|
| State | Not Applicable, archived |
| Headers | show |
On Tue, 18 Jul 2017, Mark Salyzyn wrote: > Go directly to the rtc for persistent wall clock time and print. > Useful if REALTIME is required to be logged in a low level power > management function or when clock activities are suspended. An > aid to permit user space alignment of kernel activities. That's a horrible idea, really. And there is no point at all. > +void rtc_show_time(const char *prefix_msg) > +{ > + struct timespec ts; > + struct rtc_time tm; > + > + getnstimeofday(&ts); It calls getnstimeofday(), which is wrong to begin with as we switch everything in kernel to the 64bit variants. > + rtc_time64_to_tm(ts.tv_sec, &tm); This is even more wrong as rtc_time64_to_tm is for 64 bit wide second values.... > + pr_info("%s %d-%02d-%02d %02d:%02d:%02d.%09lu UTC\n", > + prefix_msg ? prefix_msg : "Time:", > + tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, > + tm.tm_hour, tm.tm_min, tm.tm_sec, ts.tv_nsec); Why on earth do you need to print that information in RTC format? What's wrong with just doing: pr_info("My so important log message %lld\n", ktime_get_real_seconds()); and then decoding the seconds in post processing? That's completely sufficient as you intend that for logging. Correlation with user space CLOCK_REALTIME is even simpler as this is the same as reading it from user space. If your main intention is logging/debugging, then you can just use tracepoints. The tracer allows correlation to user space tracing already. So unless you can come up with a reasonable explanation why all this voodoo is required, this is going nowhere. Thanks, tglx
On 07/18/2017 02:52 PM, Thomas Gleixner wrote: > On Tue, 18 Jul 2017, Mark Salyzyn wrote: > >> Go directly to the rtc for persistent wall clock time and print. >> Useful if REALTIME is required to be logged in a low level power >> management function or when clock activities are suspended. An >> aid to permit user space alignment of kernel activities. > That's a horrible idea, really. And there is no point at all. > >> +void rtc_show_time(const char *prefix_msg) >> +{ >> + struct timespec ts; >> + struct rtc_time tm; >> + >> + getnstimeofday(&ts); > It calls getnstimeofday(), which is wrong to begin with as we switch > everything in kernel to the 64bit variants. oops, good catch. > >> + rtc_time64_to_tm(ts.tv_sec, &tm); > This is even more wrong as rtc_time64_to_tm is for 64 bit wide second > values.... Again, oops, changed rtc_time_to_tm to rtc_time64_to_tm as requested, did not change other pieces. > >> + pr_info("%s %d-%02d-%02d %02d:%02d:%02d.%09lu UTC\n", >> + prefix_msg ? prefix_msg : "Time:", >> + tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, >> + tm.tm_hour, tm.tm_min, tm.tm_sec, ts.tv_nsec); > Why on earth do you need to print that information in RTC format? What's > wrong with just doing: > > pr_info("My so important log message %lld\n", ktime_get_real_seconds()); Legacy (these prints have been in Android tree since 2013) for all our battery and power analysis tools are keyed off RTC format. There is some momentum, default should be epoch seconds/nanoseconds as that is a good example; and another option can select RTC (the option can be an internal patch to alter the format ... ick) > > and then decoding the seconds in post processing? That's completely > sufficient as you intend that for logging. Correlation with user space > CLOCK_REALTIME is even simpler as this is the same as reading it from user > space. This is part of triage and post-analysis, there is no user space call that can be made after the fact to correlate MONOTONIC time with REALTIME. The historgram for the relationship between the two time formats is built up in user space based on batched analysis of the kernel logs. Although the values slip because of ntp and other sources, suspend/resume/hibernate/restore and shutdown are definitive points of interest for analysis. The analysis is performed on klogd data which has a longer logging span than the internal buffer. > > If your main intention is logging/debugging, then you can just use > tracepoints. The tracer allows correlation to user space tracing already. tracepoints are disabled on field devices. As is debugfs. This is not logging/debugging, but field battery and power analysis. Some of the data shows up in the Battery Settings screen on the devices. We also _benefit_ from this information when correlating kernel logs with user space logs during triage. > > So unless you can come up with a reasonable explanation why all this voodoo > is required, this is going nowhere. > > Thanks, > > tglx > > > >
On Tue, 18 Jul 2017, Mark Salyzyn wrote: > On 07/18/2017 02:52 PM, Thomas Gleixner wrote: > > Why on earth do you need to print that information in RTC format? What's > > wrong with just doing: > > > > pr_info("My so important log message %lld\n", > > ktime_get_real_seconds()); > > Legacy (these prints have been in Android tree since 2013) for all our battery > and power analysis tools are keyed off RTC format. There is some momentum, > default should be epoch seconds/nanoseconds as that is a good example; and > another option can select RTC (the option can be an internal patch to alter > the format ... ick) Can we please fix the tools and not introduce that horror in the kernel? > > and then decoding the seconds in post processing? That's completely > > sufficient as you intend that for logging. Correlation with user space > > CLOCK_REALTIME is even simpler as this is the same as reading it from user > > space. > This is part of triage and post-analysis, there is no user space call that can > be made after the fact to correlate MONOTONIC time with REALTIME. The > historgram for the relationship between the two time formats is built up in > user space based on batched analysis of the kernel logs. Although the values > slip because of ntp and other sources, suspend/resume/hibernate/restore and > shutdown are definitive points of interest for analysis. The analysis is > performed on klogd data which has a longer logging span than the internal > buffer. Printing ktime_get_real_seconds() gives you the wall time. I was merily explaining that this is the same as reading CLOCK_REALTIME from userspace. Just for the record: You cannot use that stuff deep in the suspend/resume code because timekeeping is suspended there as well and that call to getnstimeofday() is going to trigger a WARNON() when called after timekeeping was suspended. So please be more precise about the limitations of this. > > If your main intention is logging/debugging, then you can just use > > tracepoints. The tracer allows correlation to user space tracing already. > tracepoints are disabled on field devices. As is debugfs. This is not > logging/debugging, but field battery and power analysis. Some of the data > shows up in the Battery Settings screen on the devices. We also _benefit_ from > this information when correlating kernel logs with user space logs during > triage. There was some discussion about making the clock source for dmesg time stamps selectable, so you can use MONOTONIC, REALTIME, BOOTTIME. The patches looked sensible, but there was some showstopper vs. the user space dmesg utility. See: http://lkml.kernel.org/r/1456250040-22351-1-git-send-email-prarit@redhat.com I rather see that resolved and these patches merged than having yet another half baken special purpose debug band aid. Maybe Prarit can shed some light on the state of this. Thanks, tglx
[TL;DR] On 07/18/2017 03:35 PM, Thomas Gleixner wrote: > Can we please fix the tools and not introduce that horror in the kernel? IMHO, we can switch this patch to epoch.ns time; but the momentum on the tools will end up with us internally patching it back to RTC format at least until we can get our act together ... I have accepted that risk, we always like to see all changes upstream though. Would an additional config parameter appease the situation? > Just for the record: You cannot use that stuff deep in the suspend/resume > code because timekeeping is suspended there as well and that call to > getnstimeofday() is going to trigger a WARNON() when called after > timekeeping was suspended. So please be more precise about the limitations > of this. Yes, I should have been clearer about that, in fact my comments in 0/4 were _backwards_ when I reread them ;-/. One of the issues is the somewhat helpful suspend millisecond duration requires a persistent clock, which is _not_ available on all hardware. Printing the time on entry and exit from suspend and resume is always possible because we are staying away from that lower level issue. I should probably roll the details of 0/4 comments into 1/4, the intro has not served its purpose. It should also be made clearer that these single messages serve _two_ purposes, the primary one is power analysis; the secondary one is log synchronization. > There was some discussion about making the clock source for dmesg time > stamps selectable, so you can use MONOTONIC, REALTIME, BOOTTIME. The > patches looked sensible, but there was some showstopper vs. the user space > dmesg utility. See: The timestamps are useful for the 'second' purpose of these patches when dmesg time is BOOTTIME or MONOTONIC, and can be turned off if REALTIME is selected. Having rtc_show_time a single point for switching this no doubt helps, not hinders, that dmesg issue. The inflection points would still serve a purpose, still need suspend/resume/hibernate/restore. The reboot messages are _only_ useful to us with their timestamps, as I checked and the only tools that use those are for log synchronization. We may be able to do away with them on REALTIME dmesg'ing; but the standardization of the message as a marker would have a legacy purpose (!) NB: We have a similar configuration for the user space logger, which can be configured to report in MONOTONIC time. We have yet to have a vendor use the feature, opting for REALTIME logging for user space activities. Our klogd (which runs at background priority and is batched) manages a histogram relationship between MONOTONIC and REALTIME helped by these prints and incorporates the REALTIME dmesg logs merged into our user space logging database. -- Mark
On Tue, 18 Jul 2017, Mark Salyzyn wrote: > On 07/18/2017 03:35 PM, Thomas Gleixner wrote: > > There was some discussion about making the clock source for dmesg time > > stamps selectable, so you can use MONOTONIC, REALTIME, BOOTTIME. The > > patches looked sensible, but there was some showstopper vs. the user space > > dmesg utility. See: > > The timestamps are useful for the 'second' purpose of these patches when > dmesg time is BOOTTIME or MONOTONIC, and can be turned off if REALTIME > is selected. Having rtc_show_time a single point for switching this no doubt > helps, > not hinders, that dmesg issue. > > The inflection points would still serve a purpose, still need > suspend/resume/hibernate/restore. The reboot messages are _only_ useful to > us with their timestamps, as I checked and the only tools that use those are > for log synchronization. We may be able to do away with them on REALTIME > dmesg'ing; but the standardization of the message as a marker would have a > legacy purpose (!) > > NB: We have a similar configuration for the user space logger, which can be > configured to report in MONOTONIC time. We have yet to have a vendor > use the feature, opting for REALTIME logging for user space activities. > Our klogd (which runs at background priority and is batched) manages a > histogram relationship between MONOTONIC and REALTIME helped by these > prints and incorporates the REALTIME dmesg logs merged into our user > space logging database. There is another option to remedy this and the dmesg tooling issues: Instead of switching the time stamps in dmesg to a different clock we might as well have an optional secondary timestamp. So instead of: [ 341.590930] wlan0: associated you would get: [ 341.590930] [ sec.usec] wlan0: associated where the second time stamp would be CLOCK_REALTIME/BOOTTIME. That should also solve Prarits problem, hmm? Thanks, tglx
On 07/19/2017 03:23 AM, Thomas Gleixner wrote: > On Tue, 18 Jul 2017, Mark Salyzyn wrote: >> On 07/18/2017 03:35 PM, Thomas Gleixner wrote: >>> There was some discussion about making the clock source for dmesg time >>> stamps selectable, so you can use MONOTONIC, REALTIME, BOOTTIME. The >>> patches looked sensible, but there was some showstopper vs. the user space >>> dmesg utility. See: >> >> The timestamps are useful for the 'second' purpose of these patches when >> dmesg time is BOOTTIME or MONOTONIC, and can be turned off if REALTIME >> is selected. Having rtc_show_time a single point for switching this no doubt >> helps, >> not hinders, that dmesg issue. >> >> The inflection points would still serve a purpose, still need >> suspend/resume/hibernate/restore. The reboot messages are _only_ useful to >> us with their timestamps, as I checked and the only tools that use those are >> for log synchronization. We may be able to do away with them on REALTIME >> dmesg'ing; but the standardization of the message as a marker would have a >> legacy purpose (!) >> >> NB: We have a similar configuration for the user space logger, which can be >> configured to report in MONOTONIC time. We have yet to have a vendor >> use the feature, opting for REALTIME logging for user space activities. >> Our klogd (which runs at background priority and is batched) manages a >> histogram relationship between MONOTONIC and REALTIME helped by these >> prints and incorporates the REALTIME dmesg logs merged into our user >> space logging database. > > There is another option to remedy this and the dmesg tooling issues: > > Instead of switching the time stamps in dmesg to a different clock we might > as well have an optional secondary timestamp. So instead of: > > [ 341.590930] wlan0: associated > > you would get: > > [ 341.590930] [ sec.usec] wlan0: associated > > where the second time stamp would be CLOCK_REALTIME/BOOTTIME. > > That should also solve Prarits problem, hmm? It would but I would prefer a single time stamp be printed than two. I think two timestamps is adding confusion to the output from a end-users point of view. Mark, why don't we get together and fixup my original patchset to make sure it meets your needs? It will fix both of our issues albeit not necessarily in the text format you want it. P. > > Thanks, > > tglx > >
On Wed, 19 Jul 2017, Prarit Bhargava wrote: > On 07/19/2017 03:23 AM, Thomas Gleixner wrote: > > There is another option to remedy this and the dmesg tooling issues: > > > > Instead of switching the time stamps in dmesg to a different clock we might > > as well have an optional secondary timestamp. So instead of: > > > > [ 341.590930] wlan0: associated > > > > you would get: > > > > [ 341.590930] [ sec.usec] wlan0: associated > > > > where the second time stamp would be CLOCK_REALTIME/BOOTTIME. > > > > That should also solve Prarits problem, hmm? > > It would but I would prefer a single time stamp be printed than two. I think > two timestamps is adding confusion to the output from a end-users point of view. Fair enough. I came up with that idea when I looked at the old thread. The discussion about tools (e.g. dmesg) dried out at some point and looked unresolved. Thanks, tglx
On 07/19/2017 08:28 AM, Thomas Gleixner wrote: > On Wed, 19 Jul 2017, Prarit Bhargava wrote: >> On 07/19/2017 03:23 AM, Thomas Gleixner wrote: >>> There is another option to remedy this and the dmesg tooling issues: >>> >>> Instead of switching the time stamps in dmesg to a different clock we might >>> as well have an optional secondary timestamp. So instead of: >>> >>> [ 341.590930] wlan0: associated >>> >>> you would get: >>> >>> [ 341.590930] [ sec.usec] wlan0: associated >>> >>> where the second time stamp would be CLOCK_REALTIME/BOOTTIME. >>> >>> That should also solve Prarits problem, hmm? >> >> It would but I would prefer a single time stamp be printed than two. I think >> two timestamps is adding confusion to the output from a end-users point of view. > > Fair enough. I came up with that idea when I looked at the old thread. The > discussion about tools (e.g. dmesg) dried out at some point and looked > unresolved. tglx, There were two outstanding issues with my patchset. The first, as you mention above, is the issue with tooling. I will handle the chicken-and-egg issue with the kernel modification and tooling. I will post patches for dmesg & systemd once the kernel patchset lands in a "next" tree; other tools will have to be patched as we find them. The second issue is a sysfs stability and output issue that I have a question on. Since I'm changing the value of print.time from a bool to an int, the output of /sys/modules/printk/parameters/time would change from Y/N to 0-3. The file is not listed in Documentation/ABI/stable so I think I can change it. Can you confirm that this is the case? I wary of changing anything under sysfs and I'm not sure who else would know if I can change the output of that file. If it is the case that the output can be changed, then I'm going to suggest that we allow, for example, human-readable format "printk.time=monotonic" along with "printk.time=2" as kernel parameters. I would also like your thoughts on that idea. If the file cannot be changed I will have to add an additional module parameter to printk. Does "timestamp" sound okay to you? I will go with whatever you suggest. Thanks, P.
On 07/19/2017 05:03 AM, Prarit Bhargava wrote: > > On 07/19/2017 03:23 AM, Thomas Gleixner wrote: >> On Tue, 18 Jul 2017, Mark Salyzyn wrote: >>> On 07/18/2017 03:35 PM, Thomas Gleixner wrote: >>>> There was some discussion about making the clock source for dmesg time >>>> stamps selectable, so you can use MONOTONIC, REALTIME, BOOTTIME. The >>>> patches looked sensible, but there was some showstopper vs. the user space >>>> dmesg utility. See: >>> The timestamps are useful for the 'second' purpose of these patches when >>> dmesg time is BOOTTIME or MONOTONIC, and can be turned off if REALTIME >>> is selected. Having rtc_show_time a single point for switching this no doubt >>> helps, >>> not hinders, that dmesg issue. >>> >>> The inflection points would still serve a purpose, still need >>> suspend/resume/hibernate/restore. The reboot messages are _only_ useful to >>> us with their timestamps, as I checked and the only tools that use those are >>> for log synchronization. We may be able to do away with them on REALTIME >>> dmesg'ing; but the standardization of the message as a marker would have a >>> legacy purpose (!) >>> >>> NB: We have a similar configuration for the user space logger, which can be >>> configured to report in MONOTONIC time. We have yet to have a vendor >>> use the feature, opting for REALTIME logging for user space activities. >>> Our klogd (which runs at background priority and is batched) manages a >>> histogram relationship between MONOTONIC and REALTIME helped by these >>> prints and incorporates the REALTIME dmesg logs merged into our user >>> space logging database. >> There is another option to remedy this and the dmesg tooling issues: >> >> Instead of switching the time stamps in dmesg to a different clock we might >> as well have an optional secondary timestamp. So instead of: >> >> [ 341.590930] wlan0: associated >> >> you would get: >> >> [ 341.590930] [ sec.usec] wlan0: associated >> >> where the second time stamp would be CLOCK_REALTIME/BOOTTIME. >> >> That should also solve Prarits problem, hmm? > It would but I would prefer a single time stamp be printed than two. I think > two timestamps is adding confusion to the output from a end-users point of view. Agreed, and so many tools will be in pain (toybox, busybox, for instance). Not that I disagree, but API changes should always get an environmental assessment ... > Mark, why don't we get together and fixup my original patchset to make sure it > meets your needs? It will fix both of our issues albeit not necessarily in the > text format you want it. I am currently retesting with the rtc format patch rolled out separately, could probably roll into your set. -- Mark
Hi! > > > > pr_info("My so important log message %lld\n", ktime_get_real_seconds()); > > Legacy (these prints have been in Android tree since 2013) for all our > battery and power analysis tools are keyed off RTC format. There is some > momentum, default should be epoch seconds/nanoseconds as that is a good > example; and another option can select RTC (the option can be an internal > patch to alter the format ... ick) Yes, android development is broken. Please fix it, rather then trying to break kernel to match. Thank you, Pavel
diff --git a/include/linux/rtc.h b/include/linux/rtc.h index 0a0f0d14a5fb..779401c937d5 100644 --- a/include/linux/rtc.h +++ b/include/linux/rtc.h @@ -22,6 +22,11 @@ extern int rtc_year_days(unsigned int day, unsigned int month, unsigned int year extern int rtc_valid_tm(struct rtc_time *tm); extern time64_t rtc_tm_to_time64(struct rtc_time *tm); extern void rtc_time64_to_tm(time64_t time, struct rtc_time *tm); +#ifdef CONFIG_RTC_SHOW_TIME +extern void rtc_show_time(const char *prefix_msg); +#else +static inline void rtc_show_time(const char *prefix_msg) { } +#endif ktime_t rtc_tm_to_ktime(struct rtc_time tm); struct rtc_time rtc_ktime_to_tm(ktime_t kt); diff --git a/kernel/time/Kconfig b/kernel/time/Kconfig index ac09bc29eb08..4da093ae3e37 100644 --- a/kernel/time/Kconfig +++ b/kernel/time/Kconfig @@ -145,3 +145,14 @@ config HIGH_RES_TIMERS endmenu endif + +config RTC_SHOW_TIME + bool "rtc_show_time instrumentation" + select RTC_LIB + help + Activate rtc_show_time(const char *msg) wall clock time + instrumentation. + + The instrumentation is used to help triage and synchronize + kernel logs using CLOCK_MONOTONIC and user space activity + logs utilizing CLOCK_REALTIME references. diff --git a/kernel/time/Makefile b/kernel/time/Makefile index 938dbf33ef49..66f17e641052 100644 --- a/kernel/time/Makefile +++ b/kernel/time/Makefile @@ -17,3 +17,4 @@ obj-$(CONFIG_GENERIC_SCHED_CLOCK) += sched_clock.o obj-$(CONFIG_TICK_ONESHOT) += tick-oneshot.o tick-sched.o obj-$(CONFIG_DEBUG_FS) += timekeeping_debug.o obj-$(CONFIG_TEST_UDELAY) += test_udelay.o +obj-$(CONFIG_RTC_SHOW_TIME) += rtc_show_time.o diff --git a/kernel/time/rtc_show_time.c b/kernel/time/rtc_show_time.c new file mode 100644 index 000000000000..bbf4f92abf4f --- /dev/null +++ b/kernel/time/rtc_show_time.c @@ -0,0 +1,23 @@ +/* + * rtc time printing utility functions + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License version 2 as + * published by the Free Software Foundation. + */ + +#include <linux/rtc.h> + +void rtc_show_time(const char *prefix_msg) +{ + struct timespec ts; + struct rtc_time tm; + + getnstimeofday(&ts); + rtc_time64_to_tm(ts.tv_sec, &tm); + pr_info("%s %d-%02d-%02d %02d:%02d:%02d.%09lu UTC\n", + prefix_msg ? prefix_msg : "Time:", + tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, + tm.tm_hour, tm.tm_min, tm.tm_sec, ts.tv_nsec); +} +EXPORT_SYMBOL(rtc_show_time);
Go directly to the rtc for persistent wall clock time and print. Useful if REALTIME is required to be logged in a low level power management function or when clock activities are suspended. An aid to permit user space alignment of kernel activities. Feature activated by CONFIG_RTC_SHOW_TIME. Signed-off-by: Mark Salyzyn <salyzyn@android.com> v2 - move implementation to kernel timekeeping from rtc_lib files - use rtc_time64_to_tm() instead of rtc_time_to_tm() - use inline in include/linux/rtc.h for !CONFIG_RTC_SHOW_TIME --- include/linux/rtc.h | 5 +++++ kernel/time/Kconfig | 11 +++++++++++ kernel/time/Makefile | 1 + kernel/time/rtc_show_time.c | 23 +++++++++++++++++++++++ 4 files changed, 40 insertions(+) create mode 100644 kernel/time/rtc_show_time.c