[BUG] Logger output sometimes combines .c filename with .h line number

[cujomalainey]

Describe the bug
comp_over/underrun seem to generate bad meta data about themselves. See the below log
[ 69363746.827066] ( 17.343750) c0 dai 11.67 src/audio/dai.c:704 ERROR comp_overrun(): sink->free = 768, copy_bytes = 0
that was generated by a call to comp_overrun at src/audio/dai.c:1073 the actual log line comes from src/include/sof/audio/component.h:704 Notice how log grabbed the path of the former and line number of the latter, leading to a really confusing lookup

To Reproduce
log comp_under/overrun?

Reproduction Rate
100%

Expected behavior
file path would point to proper log location (in this case the header)

Impact
debugging annoyance

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: N/A
   • SOF: tgl-13-drop-stable
2. Name of the topology file
   • Topology: N/A
3. Name of the platform(s) on which the bug is observed.
   • Platform: TGL

[marc-hb]

Thanks @cujomalainey , good catch.

The _DECLARE_LOG_ENTRY() dictionary macro uses a mix of: 1. the standard __LINE__ macro, and: 2. the custom RELATIVE_FILE macro implemented in scripts/cmake/misc.cmake and introduced by commit 24f3160. As you can see in that commit, the purpose of RELATIVE_FILE is to remove prefixes like /home/curtis/SOF/ prefixes from paths. As it is implemented in CMake however, RELATIVE_FILE is always a .c file, never a .h file whereas __LINE__ can be located in a .h file. __LINE__ does point at the .h file for static inline functions as you found. => mismatch.

Reproduction is easy: just add the following code in any frequently called function, example:

--- a/src/include/sof/schedule/ll_schedule.h
+++ b/src/include/sof/schedule/ll_schedule.h
@@ -23,6 +23,11 @@ struct ll_schedule_domain;
 /* ll tracing */
 extern struct tr_ctx ll_tr;
 
+static inline void static_inline_trace(void)
+{
+       tr_warn(&ll_tr, "RELATIVE_FILE and __LINE__ mismatch");
+}
+
 #define ll_sch_set_pdata(task, data) \
        do { (task)->priv_data = (data); } while (0)
 
diff --git a/src/schedule/ll_schedule.c b/src/schedule/ll_schedule.c
index 344274ce036e..9ba066b2f27d 100644
--- a/src/schedule/ll_schedule.c
+++ b/src/schedule/ll_schedule.c
@@ -377,6 +377,8 @@ static int schedule_ll_task(void *data, struct task *task, uint64_t start,
        uint32_t flags;
        int ret = 0;
 
+       static_inline_trace();
+
        irq_local_disable(flags);
 
        /* check if task is already scheduled */

prints:

 c0 ll-schedule        ./schedule/ll_schedule.c:28   10019 WARN RELATIVE_FILE and __LINE__ mismatch

There seems to be a couple RELATIVE_FILE alternatives on stackoverflow, worth a try? Keep in mind the longer term goal is to use Zephyr's logging solution.

As a short-term workaround we could alter the presentation slightly and use a less universal syntax as a warning/clue. Maybe something like this?

 c0 ll-schedule        ./schedule/ll_schedule.c(28)   10019 WARN RELATIVE_FILE and __LINE__ mismatch

https://stackoverflow.com/questions/8487986/file-macro-shows-full-path

[cujomalainey]

Thanks for the explanation Marc. Very interesting. I am also wondering the implications here. The header technically has the logger call but the location of the call to comp_Xrun is much more useful. Maybe we should block logger calls in header files to avoid this? (In other words forcing comp_Xrun to be a macro)

[marc-hb]

I agree logger calls in .h files seem like a bad idea. In this particular case I can see at least two simpler and better solutions than converting the comp_Xrun() functions to macros because these functions are invoked only once each!! So this particular problem can be solved by:

1. either moving these functions from component.h to dai.c, or
2. move only their comp_err() call to dai.c, next to the caller
3. Both?

Macros suck in many ways, for instance the stack of macros used in logging make compilation errors practically unreadable so I'm not looking forward to another layer :-)

[marc-hb]

Maybe we should block logger calls in header files to avoid this?

I couldn't resist the appeal of finding and abusing a compiler warning to find all instances of this. It's happening in only 6 functions:

--- a/src/include/sof/trace/trace.h
+++ b/src/include/sof/trace/trace.h
@@ -166,41 +166,44 @@ int trace_filter_update(const struct trace_filter *elem);
 #define _DECLARE_LOG_ENTRY(lvl, format, comp_class, n_params)  \
        __section(".static_log." #lvl)                          \
        static const struct {                                   \
                uint32_t level;                                 \
                uint32_t component_class;                       \
                uint32_t params_num;                            \
                uint32_t line_idx;                              \
                uint32_t file_name_len;                         \
                uint32_t text_len;                              \
                const char file_name[sizeof(RELATIVE_FILE)];    \
                const char text[sizeof(format)];                \
        } log_entry = {                                         \
                lvl,                                            \
                comp_class,                                     \
                n_params,                                               \
                __LINE__,                                       \
                sizeof(RELATIVE_FILE),                          \
                sizeof(format),                                 \
                RELATIVE_FILE,                                  \
                format                                          \
-       }
+       }; \
+       const int warn_in_h_file __attribute__((unused)) =         \
+               42 / !strcmp(__FILE__ , __BASE_FILE__);    \
+

make -C build_apl_gcc/ -k |& grep 'In function' | sort -u

sof/src/include/sof/audio/component_ext.h: In function 'comp_cmd':
sof/src/include/sof/audio/component_ext.h: In function 'comp_copy':
sof/src/include/sof/audio/component_ext.h: In function 'comp_params':
sof/src/include/sof/audio/component.h: In function 'comp_overrun':
sof/src/include/sof/audio/component.h: In function 'comp_underrun':
sof/src/include/sof/lib/wait.h: In function 'wait_for_interrupt':

[lgirdwood]

Lets fix in Zephyr as we can do things like printf("%s : %d", __func__, __LINE__); as we cant use %s today.

[marc-hb]

Zephyr will change this for sure but %s is not the problem here, the problem is RELATIVE_FILE.

[cujomalainey]

Interesting trick __FILE__ vs __BASE_FILE__. Is base just before the pre processor and file is after?

[marc-hb]

I suspect __BASE_FILE__ is GNU-specific

https://gcc.gnu.org/onlinedocs/cpp/Common-Predefined-Macros.html

This macro expands to the name of the main input file, in the form of a C string constant. This is the source file that was specified on the command line of the preprocessor or C compiler.