trace: Adaptive rate-limiting of repetitive messages - #3456
Conversation
|
Does anyone know how the Linux kernel handles ratelimiting? Not sure if need to reinvent the wheel. |
This seems different from the Linux kernel which apparently doesn't remember anything about suppressed messages and requires invoking a special It looks more similar to "repeat reduction" in userspace syslogger like https://www.rsyslog.com/doc/master/configuration/action/rsconf1_repeatedmsgreduction.html |
5fc88e5 to
2b6c091
Compare
a79b639 to
73c3de1
Compare
There was a problem hiding this comment.
I thought about changing id_1 and id_2 to pipe_id and comp_id, I didn't do that yet, but maybe it's good PR for that, because those names are duplicated a few times here.
lgirdwood
left a comment
lgirdwood
left a comment
There was a problem hiding this comment.
Just minor questions - one thing that does come up is that any user supplied trace filtering should disable the rate limiting at runtime (since the user is actively controlling trace). We need to make sure this will align.
73c3de1 to
be1c3c6
Compare
lgirdwood
left a comment
lgirdwood
left a comment
There was a problem hiding this comment.
Does this now have the extra flag to disable when the user starts manually creating trace filters ?
|
@lgirdwood Flag to disable adaptive trace filtering/rate-limiting added in separate commit. |
10402fb to
971e464
Compare
|
SOFCI TEST |
lyakh
left a comment
lyakh
left a comment
There was a problem hiding this comment.
let's simplify kconfig and re-review, it's too confusing now and needlessly complex to test
cd9000f to
6058787
Compare
|
@lyakh there is burst support. Added in last commit. |
There was a problem hiding this comment.
this defeats the purpose of platform_shared_commit() above
f739e89 to
49702f6
Compare
|
CI is showing unrelated issue on APL. |
lyakh
left a comment
lyakh
left a comment
There was a problem hiding this comment.
looks much better now, thanks for the improvements! Just a couple more comments and we probably have to decide on a printing format specifier.
| spinlock_t lock; /* locking mechanism */ | ||
|
|
||
| #if CONFIG_TRACE_FILTERING_ADAPTIVE | ||
| struct recent_trace_context trace_core_context[CONFIG_CORE_COUNT]; |
There was a problem hiding this comment.
is this enough for multicore? Cores while printing will cache this data. They'll modify their respective entries, according to their core ID, then if they need to they'll write those cache lines back. But if those cache lines cross borders of array elements, won't they corrupt data for adjacent cores? Don't we need to cache-line align these elements? In fact the trace data is allocated from SOF_MEM_ZONE_SYS_SHARED so that shouldn't be a problem but I have to clarify my doubts about whether locking is required together with platform_shared_commit()
| static void emit_recent_entry(struct recent_log_entry *entry) | ||
| { | ||
| _log_message(trace_log_unfiltered, false, LOG_LEVEL_INFO, _TRACE_INV_CLASS, &dt_tr, | ||
| _TRACE_INV_ID, _TRACE_INV_ID, "Suppressed %u similar messages: %pE", |
There was a problem hiding this comment.
This is interesting. Has this been decided? This is a new format, with it you'll get something like
Suppressed 2 similar messages: perf comp_copy peak plat %d cpu %d
I think we're trying to comply with the standard for printing formats. If not with POSIX then at least with the kernel. In the kernel "%pE" is used for "printing raw buffer as an escaped string." This isn't the same as that, right? But I also don't see a suitable format, so, I'm not sure what a good choice here be. We also could in principle consider printing messages like
Suppressed 2 similar messages: function _rfree_unlocked() line 925
or "file alloc.c line 925." Not sure either of these options is better, but at least we could have standard format strings for them. E.g. if we use function + line number, we could use some form of a %ps / %pS format. @lgirdwood ?
eddc3d1 to
848c7ca
Compare
printing format specifiers should be POSIX compliant and exactly the same as Zephyr. @dcpleung fyi |
@akloniex can you confirm we are using POSIX compliant print specifiers ? |
@lgirdwood we're using |
|
@akloniex I think we are aligned with https://en.wikipedia.org/wiki/Printf_format_string but can you check to be sure. |
@lgirdwood I don't see any print format changes in this version compared to the previous one. As @akloniex mentioned, |
@lyakh Thanks for the resource. |
@akloniex if we insist on printing the format string, then yes, this doesn't exist in the kernel, so, we'd need our own format. However, as I proposed above, we could instead print a function name and an "offset." If we print it like in backtraces with an address offset, that would be compatible with the kernel but not very user-friendly and it would use |
|
@lyakh We cannot print function name, as it's not available in ldc file, because we cannot use any variant of |
Yes, lets use something different in our case. We should not change the meaning of any used by the kernel (since it's a defacto standard). |
This separates trace filtering from actual sending of the message and allows usage of sending function without filtering, when necessary. Signed-off-by: Artur Kloniecki <arturx.kloniecki@linux.intel.com>
Also create trace_log_unfiltered() function, to be used internally by tracing subsystem to emit information about suppressed trace messages. The *unfiltered function could be also used as replacement in _log_message() macro, to disable log filtering for debugging purposes. Signed-off-by: Artur Kloniecki <arturx.kloniecki@linux.intel.com>
Few recent messages are remembered by the filter, and repetitive messages reported in short period of time are suppressed. Solution is compile-time configurable via many Kconfig options, as documented in Kconfig. Signed-off-by: Artur Kloniecki <arturx.kloniecki@linux.intel.com>
When user manually overrides trace filtering settings, adaptive trace rate-limiting is disabled. This assures, that when user deliberately changes filters, all trace messages are being delivered. Signed-off-by: Artur Kloniecki <arturx.kloniecki@linux.intel.com>
To allow proper display of suppressed message info traces, %pQ specifier was chosen to decode pointers to log entries. Helper function asprintf_entry_text() is used to handle the log entry text for display. Signed-off-by: Artur Kloniecki <arturx.kloniecki@linux.intel.com>
Introduce TRACE_BURST_COUNT Kconfig setting, which allows to define amount of messages that are allowed to pass through the filter before suppression kicks in. Signed-off-by: Artur Kloniecki <arturx.kloniecki@linux.intel.com>
848c7ca to
685a9fa
Compare
|
@lgirdwood @lyakh Changed specifier to an unused one - |
thanks! I can go with this. However ideally I'd maybe even try to add this to the aforementioned document in the Linux kernel to make sure they don't use it for something different later. And we still have an option of using something like FILE + LINE. I'm fine whichever way @lgirdwood decides to go from here. |
lyakh
left a comment
lyakh
left a comment
There was a problem hiding this comment.
Thanks for all the improvements!
|
Jenkins shows non booting CML DUT |
8 participants
As discussed recently here: #3362, here's my take on the trace rate-limiting subject.
Many of the options are configurable via Kconfig options, which should allow developers to fine tune, or turn off the feature if they have the need to do so.
The main idea is to track few last messages, and if they're sent again during defined time period, suppress those messages, and count such events. After leaving the filter memory, information about the suppressed message is emitted.
During the review, I suggest reading the Kconfig help messages first, to get a better view how these options mesh with one another.