Uuids in logs #2410
Uuids in logs #2410
Conversation
tools/logger/convert.c
Outdated
There was a problem hiding this comment.
Confusing comment. Can you detail?
There was a problem hiding this comment.
Not mine, just moved that piece of code. Anyway this is some optional version verification against the fw binary (in addition to mandatory ldc version verification).
There was a problem hiding this comment.
Didn't seem to be moved, anyway such additional verifications may become incorrect as debug ABI and firmware ABI begin to diverge.
There was a problem hiding this comment.
Just look at the original tools/logger/convert.c:433 on the left side, it had been there already. Honestly I do not know what to do with this piece and how it is used by anyone (might be unused and should be just removed, no idea).
There was a problem hiding this comment.
Looks like an old misleading comment. You just check the version of the LDC file that it matches with the debug ABI here. I'd say drop the comment, leave the code.
There was a problem hiding this comment.
Ah, this check is wrong. It compares with the actual firmware version rather than comparing with either the IPC ABI or the debug ABI. Is the PR with the debug ABI merged already?
Somehow the debug ABI must be exposed in debugfs so that you can properly check it.
There was a problem hiding this comment.
No, the debug abi version may be checked as done atm. It is verified between sof-logger and lcd file that is created while compiling the fw, so that consistency is protected and works well. Debug abi patch just replaces main abi version with debug abi version. It guarantees you the format but you are concerned with the content I guess and it is not protected by the abi version. While working on uuid I just moved this second optional verification to separate function because it looked to me like obsolete piece of the code that actually do not offer any additional required protection, so should be replaced (more below) in near future plus I was adding more stuff to convert() and did not want to make it too long. It is actually good that this simple move brought that piece of code to your attention since it, as I mentioned, does not make much sense to me either. Debug data format is protected by the debug abi version but its content is not. In order to have reliable, consistent debug setup, you'd need confirmation that debug data (ldc file in this case) is created of that exact build of the fw that is running on the system and abi version nor build version do not provide that level of protection and replacement is needed. Some kind of fw hash exposed via debug fs that would be compared with a copy inserted into ldc. Since manual control is good enough for me, I am ok to debug w/o anything like that at the moment. But if you are concerned that much, go ahead and implement this control mechanism, would be a good thing to have.
There was a problem hiding this comment.
You are correct in the fact that in fact it is firmware version that needs to be checked. Although I have seen that often the logger will simply bail whenever I get firmware and ldc file mismatching other than via the version.
I will look into the dynamic enabling whenever I get the time, right now I will focus on enabling a new NXP platform so I can only review others' work rather than do any of my own for traces, for one or two weeks I think.
There was a problem hiding this comment.
Let me know when the PR is out of WIP so I can give a full review again.
src/include/sof/audio/component.h
Outdated
There was a problem hiding this comment.
Do we really need to say "uid" instead of "uuid" in the macros?
rimage/file_format.h
Outdated
There was a problem hiding this comment.
This extra whitespace can live in a separate cleanup commit? Although I feel it's actually unnecessary.
paulstelian97
left a comment
paulstelian97
left a comment
There was a problem hiding this comment.
Other than that, this is really good work, I'll wait until every component has a UUID and look into it.
src/include/sof/fw-ready-metadata.h
Outdated
There was a problem hiding this comment.
would this be part of the information reported after FW_READY or as part of the extended manifest you rmentioned?
There was a problem hiding this comment.
Note: this patch originally appears in #2374. Duplicated here as a dependency to allow early comments on the uuid work (which is mentioned in the description). So any conversation regarding that one should be probably moved to #2374.
This new piece is completely symmetrical to other existing data attached to the fw_ready atm. So I added this to fw_ready ipc payload as well until extended manifest is implemented and then should be moved like other static fw-ready payload pieces (1. consistency, 2. complete bundle in one place to be moved).
src/include/sof/audio/component.h
Outdated
There was a problem hiding this comment.
should it be *uid then? Or uintptr_t?
There was a problem hiding this comment.
Probably uintptr_t, the thing is we do not want to actually dereference this address because it points to a section that will not be uploaded to the DSP. Similar to trace messages.
There was a problem hiding this comment.
I was concerned with this type too. However, at some point the uid (named w/o double u to make a slight difference with uuid that is a part of the structure that uid points to) must be converted to a type with fixed size being a part of the interface consumed by a program compiled and running on another cpu. Since the uid is not interpreted internally by the dsp code, I decided to use the target type immediately and pass it through the trace stack. This probably could be an offset inside the section instead of absolute address, computed from a linker variable if possible, to justify the type used by interface and to avoid issues with 64-bit addressing however I am not sure if such flexibility is really required.
There was a problem hiding this comment.
Absolute address is fine (it is used for the trace format message and number of parameters), so I'd insist on uintptr_t. I'm not sure what the format is (I'll look real quick).
There was a problem hiding this comment.
Came back, it is stored as uint32_t in that header. I don't like that but that section will be in the 32-bit range anyway even if we potentially would move to 64-bit DSPs or other cores (Zephyr!), the address for these sections would be in memory that shouldn't be dereferenced.
Guess I'll allow uint32_t due to the precedent.
mmaka1
force-pushed
the
uuid-in-logs
branch
3 times, most recently
from
933a9e2 to
a992d68
Compare
|
@mmaka1 some ninor CI comments on aligngment and memcpy. |
lgirdwood
left a comment
lgirdwood
left a comment
There was a problem hiding this comment.
Looks good, just need some more comments for doxygen since logging is important client feature.
src/include/sof/lib/uuid.h
Outdated
There was a problem hiding this comment.
Maybe a small explanation in the comments about how this is formed and constructed. Doxygen should be able to pick this up too.
Alignment issue is in the #2398. It is duplicated here as a dependency and will be removed once #2398 is merged. (Btw, this is the only reason why this one is still tagged as WIP) memcpy() had been used in the user space application code. Should checkpatch complain about this? |
|
SOFCI TEST |
|
@fredoh9 the CI failed tests for suspend, but there is nothing in the FW logs, otherwise its ok. |
|
@fredoh9 @lgirdwood CI consistently fails inside pm-runtime test on cnl family and I am not able to find anything in the log. Stream is stopped and released after aplay is killed but there is no trace of GLB_PM_MSG: CTX_SAVE message initiated by the driver after the t/o. I am not able to reproduce it on my local systems, ctx_save is always there. |
|
@fredoh9 I'm also seeing a broken pipe error in some of the test logs too (in other PRs), could CI be at fault here and these all be related ? |
|
@mmaka1 @lgirdwood In this case, runtime pm status is not 'suspended' after 10 seconds later from aplay stop. I'm scanning daily test results with PR test's one also. I will get back to you. |
|
@mmaka1 lets try CI again when the conflict is fixed. |
|
SOFCI TEST |
|
I don't see any runtime pm test glitches in this week. |
|
|
|
@fredoh9 Conflict is resolved. Same failures, are there any more detailed logs from the failing systems available? |
Optional fw version verification moved to separate function in order to modularize code of convert(). Signed-off-by: Marcin Maka <marcin.maka@linux.intel.com>
Unique identification in form of Guid is much more scalable for fw parts (components, dais, ...) then existing ids and trace class ids. Signed-off-by: Marcin Maka <marcin.maka@linux.intel.com>
New trace entry parameter is defined: uuid of the source. Technically, this is an address of uuid entry linked inside a special section in elf. Has_ids is removed from the static log entry since eventually all entries will use uuids and -1 detection is good enough detection for those who still do not provide ids. Note: both changes are done in a single patch to avoid two major dbg-abi version bumps. Signed-off-by: Marcin Maka <marcin.maka@linux.intel.com>
Content of static uuid section is appended to the ldc file along with a new special header by rimage. New ldc file part is read by the logger to decode uuid pointers provided in traces into nice names. Signed-off-by: Marcin Maka <marcin.maka@linux.intel.com>
All new definitions are included in ldc file and are used by the logger automatically. Signed-off-by: Marcin Maka <marcin.maka@linux.intel.com>
TRACE_CLASS ids used by parts switch to uuid-based logging marked as unused. Signed-off-by: Marcin Maka <marcin.maka@linux.intel.com>
Log entry parameters format is compacted to reserve more space for the text. Max entry location length is increased to 24 characters. Timestamp and component name/id use colors to improve readability. Signed-off-by: Marcin Maka <marcin.maka@linux.intel.com>
Two new levels: warning and info defined since existing critical+verbose seems not enough. Signed-off-by: Marcin Maka <marcin.maka@linux.intel.com>
Both had logged on VERBOSE level so far. Non-verbose trace switched to INFO level. Signed-off-by: Marcin Maka <marcin.maka@linux.intel.com>
Implemented for generic and device tracing with warn postfix translated to LOG_LEVEL_WARNING. Signed-off-by: Marcin Maka <marcin.maka@linux.intel.com>
Warning traces prefixed and painted in yellow. Signed-off-by: Marcin Maka <marcin.maka@linux.intel.com>
Log entry format is scanned by the logger and if %s is found, then corresponding parameter is interpreted as address of static uuid entry. The original address is replaced by formatted uuid namen and value, painted in blue, before fprintf() is called. Signed-off-by: Marcin Maka <marcin.maka@linux.intel.com>
mmaka1
force-pushed
the
uuid-in-logs
branch
2 times, most recently
from
019cb77 to
ff3078f
Compare
6 participants
This is a preview of fully working uuid-based identification for components and dais.
NOTE: This set of patches depends on #2398, not merged yet, so that commit is included here and will be removed with the rebase operation. If you have any comment regarding 4fb7aff0 [dep] abi: define debug abi version for user space dbg interfaces, please add it to #2398.
Following new features are provided by this PR:
Uuid-based identification for components and dais. Adding a new identifier to a driver requires
DECLARE_SOF_UUID()declaration visible by the driver definition which refers the uuid by.uid = SOF_UUID()initialization (see the last patch for examples). Nothing more is required (no logger recompilation) to print the associated name in the trace log (uuid is also available there, not printed but it is possible if needed).Output of the logger is reformatted to improve readability of the log.
Existing log levels are separated (dedicated values for info and dbg/verbose) and new warning level is defined. <...>_warn() macros are provided as well. Errors are printed in red while warnings are printed in yellow by the logger.
Logger converts address of uuid entries into the name and uuid value, printed in blue, if
%sformat parameter is provided. So that component/dai/task identification is possible at the infrastructure level. E.g. this trace line incomp_new():trace_event(TRACE_CLASS_COMP, "new component %s pipe %d id %d", drv->uid, comp->pipeline_id, comp->id);gives the following output from the logger (click the image to enlarge):So performance traces may be improved to provide readable identification of the measured target component, scheduler traces may provide immediate task identification etc. Btw assigning uuids to tasks will enable trace context identification for "worker threads" as well.