Use syslog to trace Neo3 for time performance measurement on K81

We need a simple way to trace our application since note driver cannot work well in NEO3.

Related tickets: NEO3-6077 - Getting issue details... STATUS

NEO3-3764 - Getting issue details... STATUS

\uD83D\uDCD8 How to add trace on specified files/functions

1. Enable/disable the debug trace configuration.

config DEBUG_TRACE
bool "Enable debug trace"
default n
depends on IDT_FW_LOGGING
---help---
Automatically start trace in defined APIs with a Start log at the beginning
and an End log at the end of the API.

You can Enable/Disable trace by make menuconfig after adding this config in nuttx/idt/Kconfig.

2. Add gcc options in Makefile.

ifeq ($(CONFIG_DEBUG_TRACE),y)
EXCLUDEFILENAME = trace_exclude_files.txt
EXCLUDEFUNCNAME = trace_exclude_functions.txt
EXCLUDEFILES := $(shell for file in `cat $(EXCLUDEFILENAME)`; do echo -n $$file, ; done)
EXCLUDEFUNCS := $(shell for func in `cat $(EXCLUDEFUNCNAME)`; do echo -n $$func, ; done)
CFLAGS += -finstrument-functions
ifneq ($(EXCLUDEFILES), )
CFLAGS += -finstrument-functions-exclude-file-list='$(EXCLUDEFILES)'
endif
ifneq ($(EXCLUDEFUNCS), )
CFLAGS += -finstrument-functions-exclude-function-list='$(EXCLUDEFUNCS)'
endif
endif

You can add the file names that are excluded from trace to trace_exclude_files.txt like below.

tal/src/tal_buffer.c
tal_semaphore.c

And function names that are excluded from tracing to trace_exclude_functions.txt like below.

IFD_
TAL_get_instance

The functions begin with “IFD_“ will not be traced.

3. Add syslog to profiling functions in your APP.

Because syslog mask is 2 in config, the priority of syslog shoule be LOG_CRIT here. The priority value should <= logmask. For example, we add below code in k81start.c, above gcc option in k81_reader/Makefile and k81_system/Makefile, trace log will be output with all user functions in k81_reader and k81_system if trace_exclude_files.txt or trace_exclude_functions.txt is not created.

#ifdef CONFIG_DEBUG_TRACE
void __attribute__((__no_instrument_function__))
__cyg_profile_func_enter(void *this_func, void *call_site)
{
    syslog(LOG_CRIT, "[Start].%p\n", this_func);
}

void __attribute__((__no_instrument_function__))
__cyg_profile_func_exit(void *this_func, void *call_site)
{
    syslog(LOG_CRIT, "[End].%p\n", this_func);
}
#endif

4. Use trace.py to change address to function name.

Run the tool trace.py on Linux PC to output the trace with functions and files like below.

<2>May 11 06:35:52.037 pc_k81reader_reader_ss[Start].idg_cmd_data k81reader.c:717
<2>May 11 06:35:52.037 pc_k81reader_reader_ss[Start].idg_0240_unified_act_transaction k81reader_tal.c:351
<2>May 11 06:35:52.037 pc_k81reader_reader_ss[Start].TAL_get_state tal_states_machine.c:136
<2>May 11 06:35:52.038 pc_k81reader_reader_ss[End].TAL_get_state tal_states_machine.c:136
<2>May 11 06:35:52.038 pc_k81reader_reader_ss[Start].TAL_wait_for_workstate tal_states_machine.c:209
<2>May 11 06:35:52.038 pc_k81reader_reader_ss[Start].TAL_retrieve_workstate tal_states_machine.c:155
<2>May 11 06:35:52.038 pc_k81reader_reader_ss[End].TAL_retrieve_workstate tal_states_machine.c:155
<2>May 11 06:35:52.039 pc_k81reader_reader_ss[End].TAL_wait_for_workstate tal_states_machine.c:209
<2>May 11 06:35:52.039 pc_k81reader_reader_ss[Start].readerutils_GetTagData k81reader_utility.c:298
<2>May 11 06:35:52.039 pc_k81reader_reader_ss[End].readerutils_GetTagData k81reader_utility.c:298
<2>May 11 06:35:52.039 pc_k81reader_reader_ss[Start].TAL_save_respinfo tal_main.c:1855
<2>May 11 06:35:52.040 pc_k81reader_reader_ss[End].TAL_save_respinfo tal_main.c:1855

Usage: python trace.py <ELFfile> <logfile>

$python trace.py nuttx syslog

Output trace file tracelog_20230512-091652.txt finished.

<nuttx> is the ELF file, <syslog> is the log output on console or the syslog file saved in /var/log/sys.

Below are the tool and files output from my Linux PC.

\uD83D\uDCCB GCC Instrumentation-Options description

Generate instrumentation calls for entry and exit to functions. Just after function entry and just before function exit, the following profiling functions are called with the address of the current function and its call site. (On some platforms, __builtin_return_address does not work beyond the current function, so the call site information may not be available to the profiling functions otherwise.)

void __cyg_profile_func_enter (void *this_fn,
                               void *call_site);
void __cyg_profile_func_exit  (void *this_fn,
                               void *call_site);

The first argument is the address of the start of the current function, which may be looked up exactly in the symbol table.

This instrumentation is also done for functions expanded inline in other functions. The profiling calls indicate where, conceptually, the inline function is entered and exited. This means that addressable versions of such functions must be available. If all your uses of a function are expanded inline, this may mean an additional expansion of code size. If you use extern inline in your C code, an addressable version of such functions must be provided. (This is normally the case anyway, but if you get lucky and the optimizer always expands the functions inline, you might have gotten away without providing static copies.)

A function may be given the attribute no_instrument_function, in which case this instrumentation is not done. This can be used, for example, for the profiling functions listed above, high-priority interrupt routines, and any functions from which the profiling functions cannot safely be called (perhaps signal handlers, if the profiling routines generate output or allocate memory).