Page Comparison

We need a simple way to trace our application since note driver task trace depends on cannot work well in NEO3. Related tickets:

[NEO3-6077] Study and prototype a solution for time performance measurement on K81 - Phase2 - Jira (atlassian.net)

[NEO3-3764] [KIOSKV FW v1.00.139.2246.D]The response timing of ACT is too slow to compatible with K3 - Jira (atlassian.net)

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

...

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 names list that are excluded from trace instrumentation to trace_exclude_files.txt like below.

tal/src/tal_buffer.c
tal_semaphore.c

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

IFD_
TAL_get_instance

The functions begin TAL_get_instance() and the functions beginning with “IFD_“ will not be tracedinstrumented.

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, we add once below code is added in k81start.c, above gcc option in 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

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

...

<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 output from my Linux PC. Makefile and trace_exclude_xxx.txt are in k81_reader/

\uD83D\uDCCB 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.)

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