Trace throttling - #3362
Conversation
There was a problem hiding this comment.
it 'trace throttling' what the kernel calls 'rate_limit' ?
If yes, any reason why we would use a different wording?
There was a problem hiding this comment.
@plbossart yes, sorry, forgot to mention the original work by @lgirdwood, now in the PR description. He called his method throttling, but yes, I think it's quite similar to the kernel rate-limiting and I'd call it that way too
There was a problem hiding this comment.
Ah ok, must be british/US words. custom/bespoke, zucchini/courgette. tomayto/tomahto, etc. :-)
I think it's a really good addition when we get lots of errors for the same issue (e.g. buffer w/ zero space, etc).
There was a problem hiding this comment.
yep, my wording - lets align it with the kernel to keep is simple.
There was a problem hiding this comment.
This one should stay as comp_info as it's only emitted at topology loading.
|
@lgirdwood something like this? |
There was a problem hiding this comment.
This one should stay as comp_info as it's only emitted at topology loading.
@lgirdwood sure, the second patch is just a couple of use-examples, the final PR will only contain patch 1, we can add any users as needed |
lgirdwood
left a comment
lgirdwood
left a comment
There was a problem hiding this comment.
Looks good - just need the comments describing algo and passing CI.
lgirdwood
left a comment
lgirdwood
left a comment
There was a problem hiding this comment.
I think we are good to go for the core code. Can you include the agent warning as initial user in non draft PR update and remove these example users.
@lgirdwood sure, but let me first wait for the CI build to complete - there are many configuration options - with trace, without trace, as a library, for unit testing, which I'd rather have a CI test for |
@lgirdwood one more comment to the agent case: it currently uses |
|
@lgirdwood also, I did follow your original implementation in 995da5a here, but TBH I'm not sure the frequency-based rate-limiting is all that useful and meaningful. It suppresses trace messages purely based on the number of times they have been issued - without taking the time into consideration at all. So, if you use it for whatever message, even if it only appears once per second or once per streaming start or whatever - most of them will disappear. I wouldn't mind removing that counter-based mode and keeping only the time-based one. |
lgirdwood
left a comment
lgirdwood
left a comment
There was a problem hiding this comment.
Needs a few more comments around the more complex conditional logic.
There was a problem hiding this comment.
can we have a comment here describing decision.
There was a problem hiding this comment.
@lgirdwood done. Interesting, CI isn't restarting automatically. I don't expect it to be smart enough to notice, that only comments changed from the previous version... We can kick it manually or rely on its apparent intelligence.
The impact of the check is actually quite significant since traces are supposed to be very fast (heck, why do we just send 5 numbers [for 4-parameter trace messages] over some channel [like etrace or dtrace] for every trace message? Not because it is simply fast?) |
|
IMHO some of the advantages in principle (provided perfect both implementations) of the explicit kernel-style throttling are (1) no metering overhead for all messages, (2) no accidental suppression of important messages, whereas an advantage of the universal throttling is (1) automatic rate-limiting of "all" messages (I think a correct implementation wouldn't throttle warnings and errors). I don't count memory overhead - I don't think 16 bytes per throttled message are critical :-)
The only choice is whether to apply this to all messages or only to some. Note, that (3) above is a bit tricky and I don't think either of the two versions currently implement it well. Ideally you would want to print "5 messages from function X line Y have been dropped" after a time-out expires after the last of those messages. But it isn't very easy to achieve that. Ideally you would want to run a global periodic task, regularly checking for all such blocked messages, but that adds complexity and overhead. A less intrusive approach would be to perform those checks during the next trace call. This isn't perfect, because trace calls can also stop for undefined length of time. But at least there is a good chance that some traces will be printed again after some time, and you can even force some. Note, that my approach is currently even more limited in this respect: the "N blocked" message is only sent when that specific message is triggered again, and this might not happen for a very long time. It can be extended though by adding a global list of blocked messages and tracking them there. |
|
@akloniex Can throttling be disabled, if for some reason I want to keep messages? I guess not, cos I don't see any kconfig here. IRT which solution is better. Argument that it is done like this in kernel, is not good imho, as on the contrary I see usually loggers have dynamic throttling (like @akloniex solution), for example android logger. I'd go against @akloniex solution only if it'd be really CPU intensive, but if I'm correct it has const cost. |
|
Let's think about a generic solution. Typically when some activity happens in the FW, that generates a sequence of trace messages they come with a less than 10us interval. And there can be about 10 of them, mostly different ones. What would be a typical "babbling" threshold? 1ms? I.e. if a message repeats every 1ms we should consider it flooding and throttle it, right? So, 10 messages, coming all at 10us intervals in the end of that chain are all still candidates for throttling and should be monitored, right? So, I'd say we need more than 5 entries that @akloniex had in his implementation. And how many are enough? 8? 16? So on each trace call we'd have to scan the list of up to 16 entries, search for a previous occurrence, if found - move to the top of the list as the newest monitor, and evict expired ones. So we'd rather need a linked list than an array. We want to keep them sorted them and add and drop them. So I think the current implementation would need a few changes. Then there are also some messages that do print in short bursts, e.g. and they look harmless and don't really need to be throttled. I think one of drawbacks of the generic solution would be potentially losing bursting messages. |
|
all that being said, if we still don't have an agreement, I think we need to measure a performance hit from @akloniex 's automatic implementation (at least in its present form) |
These are very good points @lyakh and I agree that we can improve current @akloniex implementation. Partially that is why I favor generic solution - it gives us more space to tune it for our needs. I have asked @akloniex to do latency and MCPS measurements, so as long as those values will be on acceptable level then I would recommend it. If we find results not satisfying then I don't have problem to go with kernel based implementation. As for the warning & error messages imho we should suppress them as well (aggregate to single line not remove/hide). We do not need the entire wall of repeated warning/error messages, while the root cause of the problem is usually before the first error pop up. |
|
I've put perf counters in logging function for 3 cases:
ad 1. Avg plat: 71.6 cpu: 1460.1 All measurements taken on same APL platform, during the same test case being tested. Load for my implementation is clearly most 'peaky' and overall most cpu-heavy, which was expected. |
@akloniex the burst messages as @lyakh pointed out are something that we do not want to suppress. I am thinking that maybe we could somehow combine yours two approaches. For example instead of define throttling trace function create dedicated burst message function that will bypass generic suppress mechanism while all the other traces by default will be actively tracked & suppressed if necessary? |
|
@mwasko We could do that. I don't see any other method of bypassing the generic filter, other than manually defining traces that are allowed to pass the filter. |
|
@mwasko @lyakh @akloniex The trace mechanism must have negligible impact on MCPS and never filter the golden trace messages. I think we all agree the annoyance here is that too much trace data decreases the trace SNR and means we risk loosing the important error entry conditions (due to the periodic nature of the pipelines quickly filling the trace log). Something really simple and cheap is needed here. i.e. /* only emit the trace after every X messages (where X is power of 2) - this example is 4k */
#define trace_error_permit_every4k(trace_context, message) \
if ((trace_context->count & 0xfff) == 0) { \
trace_error(trace_context, message); /* really print the trace */ \
trace_error(trace_context, "message was repeated 4096 times"); \
} \
trace_context->count++;
/* emit the first 16 trace and then after every X messages (where X is power of 2) - this example is 4k */
#define trace_error16_permit_every4k(trace_context, message) \
if (trace_context->count < 16) { \
trace_error(trace_context, message); \
} else if ((trace_context->count & 0xfff) == 0) { \
trace_error(trace_context, message); /* really print the trace */ \
trace_error(trace_context, "message was repeated 4096 times"); \
} \
trace_context->count++;This is opt-in and ideal for recurrent pipeline errors (above top example prints every 4 seconds) preserving the log SNR. The second example prints the first 16 errors and then every 4k. Both above are cheap with only 32bit addition and logical ANDs. @akloniex can you do the perf check with the above macros in the same position as your earlier tests. Context->count is a uint32_t. |
@lrgirdwo that's a bit too simple. Firstly the context is per file / subsystem, so, you'll punish "innocent" traces if you place the counter into the context. Secondly this will drop random messages - even those emitting 1 message per connection or whatever. You really need to measure the frequency per message. |
|
@lyakh I think we have to make simpler debugging the initial goal here (i.e. debugging critical pipeline errors) as I think you are getting into more performance and event measurement trace throttling (i.e. "info: my buffer was empty" was printed 17 times in the last second). Secondly I want to avoid any DSP loading differences associated with trace i.e. we should never have "feature X worked when trace config Y is enabled". I'm not saying we should have a higher level trace intelligence as you and @akloniex have been working on, but it should be a config option used by developers.
Yep, there will be 1 word added to each trace context. No big deal.
No random or important messages will be dropped. You will see the first X messages and a message every Y messages. The first X messages are critical for the debug of the issue as mostly everything thereafter is noise. This is intended for fixing errors.
Not for errors. For errors you just need the initial context as the rest is superfluous. |
@lgirdwood sorry, that isn't what I meant. Look in dai.c, it has half a dozen
Ah, so your assumption is, that only error messages can flood the log? So we only need to throttle (some) error messages? So we would only use these rate-limiting traces for error and warning messages, that have a potential for flooding and that shouldn't be printed at all otherwise. Ok, understand, not sure whether that's really how it is - whether it's impossible, that a "normal," possibly "info" level message floods the trace? |
Hmm, there should not be half a dozen different trace contexts in one file. I would expect most 1 or 2 trace contexts per feature (so could need fixing). Btw I can only see 2 in dai.c
The errors that flood the log today are all recurrent agent, scheduler, IRQ or pipeline runtime errors. So I would treat error and warning traces here as likely to flood. i.e. agent flooded log on zephyr (and could not be stopped ever after it started). |
@lgirdwood sorry, that isn't what I was trying to say: there are 2 |
Thanks got you now, it should be fine passing a local counter here (and these can be grouped if necessary). i..e /* emit the first 16 trace and then after every X messages (where X is power of 2) - this example is 4k */
#define trace_error16_permit_every4k(trace_context, count, message) \
if (count < 16) { \
trace_error(trace_context, message); \
} else if ((count & 0xfff) == 0) { \
trace_error(trace_context, message); /* really print the trace */ \
trace_error(trace_context, "message was repeated 4096 times, total %d, count"); \
} \
count++;I really do see this as 2 features now (which can be independently developed) 1. Trace throttling for development 2. Trace throttling for debug |
|
What about implementing this mechanism fully in sof-logger ? Then none 'golden message' will be permanently dropped, it will be easy to enable/disable/configure (without fw recompilation, so it will be feature for both development and debug), no extra DSP cost (and advanced tracing logic). In logger number of dropped messages can be easily calculated and counted independently for each trace message (not trace context). Single drawback which I can see is we don't gain trace memory window bandwidth (it will be kept as it is right now). |
That could be good if the kernel also holds a buffer with the entire trace (DMA trace output, not etrace) |
|
No objection from me with throttling in sof-logger providing we are all happy with available trace bandwidth ? (which seems good today). |
@lgirdwood @ktrzcinx sure, or just use grep. If you know that you want to filter when you start the logger and if no messages are dropped, you can as well just use grep. |
|
@lyakh grep is nice for single items, but most users care about multiple events i.e. the error, events leading upto the error, the error handling/recovery. |
Implementing more sophisticated suppress mechanism in sof-logger is an option but probably would have to be enabled by 'default', otherwise we would still receive flooded traces from the field. Regardless to that I would still recommend at least some basic mechanism that will control & throttle FW trace message rates.
@lyakh grep is nice to entirely filter out messages but will not suppress ten's repeated messages into one line trace with info about suppression. |
|
Let's not conflate separate capabilities. Take the kernel example. you can All these three cases have their respective merits. More capabilities don't hurt here. |
|
@lgirdwood @lyakh @mwasko |
|
Since the burst messages can be handled with threshold parameters tuning within @akloniex solution then I would like to recommend it as a way to go for message throttling/suppress. I have also discussed the eventual performance impact with @mmaka1 and it is negligible for message tracing. @akloniex please create a PR with your changes for review. We can also discuss the approach further on Tuesday call. |
|
@lyakh shall we close this one ? |
|
@lgirdwood sure |
8 participants
The first patch is mostly ready, constants can be tuned and made configurable, some other adjustments can be made, maybe the simple number-based throttling should be dropped completely. The second patch is just an example. From the first patch commit message:
trace: add trace throttling
Add two methods of trace message throttling: by time and by number. Throttling by time allows up to "burst" messages within a timeout, after that it blocks further messages from the same source. After the timeout expires, next time the same source sends a trace, the number of suppressed messages is printed and the throttling is reset.
Throttling by number is simpler: every time the trace count reaches the burst number, further messages from the same source are suppressed until the pre-configured number is reached. Then the same "suppressed" message is sent and throttling is reset.
Based in part on 995da5a