Use syslog to trace Neo3 for time performance measurement on K81

We need a simple way to trace our application since note driver task trace depends on cannot work well in NEO3. Related tickets:https://idtechproducts.atlassian.net/browse/NEO3-6077(Refer to the ticket comment to enable task trace on nuttx)

https://idtechproducts.atlassian.net/browse/NEO3-3764

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.

It depends on syslog, so IDT Firmware Logging should be enabled first.

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

The functions defined in the files this Makefile will compile will be instrumented.

You can add the file list that are excluded from instrumentation to trace_exclude_files.txt like below.

tal/src/tal_buffer.c
tal_semaphore.c

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

IFD_
TAL_get_instance

TAL_get_instance() and the functions beginning with “IFD_“ will not be instrumented.

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. Add below code in your application. For example, once below code is added in k81start.c, above gcc option is added to idtapps/neo3/idt_apps/k81_reader/Makefile and idtapps/neo3/idt_apps/k81_system/Makefile, trace log will be output with all user functions defined in the path idtapps/neo3/idt_apps/k81_reader and k81_system if trace_exclude_files.txt or trace_exclude_functions.txt is not created or empty.

#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

The files and functions do not need to be traced should be listed as many as possible in trace_exclude_files.txt or/and trace_exclude_functions.txt because of limited cache. The maximum syslog cache size in K5 is only 15K.

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 nuttx ELF file, <syslog> is the log output on console or the syslog file saved in /var/log/sys. If you just use python trace.py without parameter, the “nuttx” and “syslog” in current directory will be the default ELF file and log file.

Below are the tool and files from my Linux PC. Makefile and trace_exclude_xxx.txt are in k81_reader/

GCC Instrumentation-Options description

-finstrument-functions

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.)

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.)