Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

logging: frontends: stmesp: Add turbo logs #79492

Open
wants to merge 7 commits into
base: main
Choose a base branch
from

Conversation

nordic-krch
Copy link
Contributor

Add 'turbo' logging feature. When enabled, short logs (no argument or one numeric, 32 bit argument) are handled in a special way that is much faster than the default one (>10x faster). Additionally, there is an option to remove all other logs from the system which allows to not include almost any logging framework code in the binary (~170 bytes of code is needed). It may be especially valuable for memory constraint targets (ppr, flpr) where with only 170 byte of code (+code for each log message) we can provide limited formatted string logging support.

'Turbo' logging is using following tricks to achieve that:

  • logging strings are put into a memory section and additional memory section is created which holds addresses of those strings. Index in that array is used to identify a string (32 bit address is encoded into a smaller number, 15 bits is more than enough). This index is used for a STMESP register set (there are 2^16 available). STMESP channel encodes string.
  • Logging level is stringified and prepended to a string
  • Source ID is encoded by using DM16 (so far not used).
  • Log without arguments is written as DMTS16
  • Log with one argumetn is written as DM16+DMTS32

samples/boards/nordic/coresight_stm
Without turbo logs:

flpr: Timing for log message with 0 arguments: 1.20us
flpr: Timing for log message with 1 argument: 2.20us
flpr: Timing for log message with 2 arguments: 1.80us
flpr: Timing for log message with 3 arguments: 2.30us
flpr: Timing for log_message with string: 3.80us
flpr: Timing for tracepoint: 0.10us
flpr: Timing for tracepoint_d32: 0.10us
app: Timing for log message with 0 arguments: 1.80us
app: Timing for log message with 1 argument: 1.90us
app: Timing for log message with 2 arguments: 2.0us
app: Timing for log message with 3 arguments: 2.10us
app: Timing for log_message with string: 4.40us
app: Timing for tracepoint: 0.5us
app: Timing for tracepoint_d32: 0.10us
ppr: Timing for log message with 0 arguments: 25.40us
ppr: Timing for log message with 1 argument: 27.20us
ppr: Timing for log message with 2 arguments: 27.70us
ppr: Timing for log message with 3 arguments: 27.60us
ppr: Timing for log_message with string: 65.50us
ppr: Timing for tracepoint: 0.65us
ppr: Timing for tracepoint_d32: 0.30us

and with turbo logs:

flpr: Timing for log message with 0 arguments: 0.10us
flpr: Timing for log message with 1 argument: 0.20us
flpr: Timing for log message with 2 arguments: 2.20us
flpr: Timing for log message with 3 arguments: 2.20us
flpr: Timing for log_message with string: 3.90us
flpr: Timing for tracepoint: 0.0us
flpr: Timing for tracepoint_d32: 0.10us
app: Timing for log message with 0 arguments: 0.10us
app: Timing for log message with 1 argument: 0.20us
app: Timing for log message with 2 arguments: 2.10us
app: Timing for log message with 3 arguments: 2.0us
app: Timing for log_message with string: 4.60us
app: Timing for tracepoint: 0.5us
app: Timing for tracepoint_d32: 0.5us
ppr: Timing for log message with 0 arguments: 2.10us
ppr: Timing for log message with 1 argument: 3.10us
ppr: Timing for log message with 2 arguments: 27.80us
ppr: Timing for log message with 3 arguments: 27.40us
ppr: Timing for log_message with string: 68.20us
ppr: Timing for tracepoint: 0.55us
ppr: Timing for tracepoint_d32: 0.30us

It is based on #79419 and #79420.

@nordic-krch
Copy link
Contributor Author

@nordic-segl fyi. If that goes in then test for coresight_stm will need to be updated with new timings.

There are many places where source_id is retrieved and it
depends on runtime filtering being enabled. So far it was
all exposed but lets encapsulate that into a helper function.

Signed-off-by: Krzysztof Chruściński <krzysztof.chruscinski@nordicsemi.no>
Change logging level definitions to just numbers instead of
numbers with unsigned indicator (e.g. 1 instead of 1U). Levels
from Kconfig comes as just numbers and often levels are used
for IS_ENABLED-type of macros where values are concatenated
into tokens and it actually makes the difference if value is
1 or 1U. It allows minor cleanup in the internal macros.

Signed-off-by: Krzysztof Chruściński <krzysztof.chruscinski@nordicsemi.no>
Create a macro that encapsulates all filtering and use it in standard
and hexdump macros.

Signed-off-by: Krzysztof Chruściński <krzysztof.chruscinski@nordicsemi.no>
Set initial filtering settings in the log core init only if
runtime filtering is enabled. It saves few bytes when runtime
filtering is off.

Signed-off-by: Krzysztof Chruściński <krzysztof.chruscinski@nordicsemi.no>
Add 'turbo' logging feature. When enabled, short logs (no argument
or one numeric, 32 bit argument) are handled in a special way that
is much faster than the default one (5-10x faster). Additionally,
there is an option to remove all other logs from the system which
allows to not include almost any logging framework code in the
binary (~170 bytes of code is needed). It may be especially
valueable for memory constraint targets (ppr, flpr) where with
only 170 byte of code (+code for each log message) we can provide
limited formatted string logging support.

'Turbo' logging is using following to achieve that:
- logging strings are put into a memory section and additional
memory section is created which holds addresses of those strings.
Index in that array is used to identify a string (32 bit address
is encoded into a smaller number, 15 bits is more than enough).
This index is used for a STMESP register set (there are 2^16
available). So STMESP channel encodes string.
- Logging level is stringified and prepended to a string
- Source ID is encoded by using DM16 (so far not used).
- Log without arguments is written as DMTS16
- Log with one argumetn is written as DM16+DMTS32

Signed-off-by: Krzysztof Chruściński <krzysztof.chruscinski@nordicsemi.no>
@nordic-krch nordic-krch force-pushed the stm_superlog branch 2 times, most recently from e535bf5 to 3df7afc Compare October 9, 2024 05:53
Add support for handling optimized short log messages (aka turbo logs).
There are 2 types of turbo log messages:
- No arguments. D16MTS is used for that on channel > 32768
- One numeric argument. DM16 followed by D32MTS is used.

Additionally, in order to be able to get source name for log messages
coming from owned by cpuapp co-processors (PPR and FLPR) there must
be a way of passing location of constant source data from PPR/FLPR to
cpuapp which handles ETR data. This method is added in the commit as
well. PPR/FLPR sends D32M during the boot with address of constant
source data section. Demultiplexer stores those addresses and it is
able to retrieve source name for log messages from PPR/FLPR.

Signed-off-by: Krzysztof Chruściński <krzysztof.chruscinski@nordicsemi.no>
Add support for optimized short log messages (aka turbo logs). They are
supported on cpuapp and co-processors owned by cpuapp (FLPR and PPR).
In general, it can be supported if cpuapp has access to logging strings
used for the log message. Currently mode is supported only in standalone
logging. When it is extended for dictionary logging then it will also
be supported on other cores (e.g. cpurad).

Signed-off-by: Krzysztof Chruściński <krzysztof.chruscinski@nordicsemi.no>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants