[RFC] Zephyr instrumentation subsystem #57371

gromero · 2023-04-28T09:15:54Z

Hello Zephyr community!

This is the PoC / initial implementation for the proposed Zephyr instrumentation subsystem. It leverages the compiler function instrumentation to collect tracing and profiling information in Zephyr RTOS.

This has been tested against the ST b_u585i_iot02a board. Please note that, since it relies on the retained_mem driver, if another board is used for testing the proper device-tree overlay for the target board needs to be added to boards/ dir accordingly.

Please see samples/subsys/instrumentation/src/main.c sample for details on how to experiment with it.

RFC: #57373

Thanks!

Cheers,
Gustavo & Kevin

nordicjm

Some initial comments on retained memory usage - would suggest using retention subsystem.

nordicjm · 2023-04-28T09:25:55Z

subsys/instrumentation/common/instr_common.c

+
+*/
+
+const static struct device *retained_mem_dev = DEVICE_DT_GET(DT_ALIAS(retainedmemdevice));


Would use a chosen node for this, similar to this: https://github.com/zephyrproject-rtos/zephyr/blob/main/tests/boot/mcuboot_recovery_retention/boards/nrf52840dk_nrf52840_mem.overlay

@nordicjm chosen in this example is select boot mode, which is not really necessary, but I'm not sure I'm following you here. Could you please expand on it?

In a board dts or an overlay, you could have something like this:

retainedmem { compatible = "zephyr,retained-ram"; status = "okay"; #address-cells = <1>; #size-cells = <1>; instru0: instru@0 { compatible = "zephyr,retention"; status = "okay"; reg = <0x0 0x100>; prefix = [08 04]; checksum = <1>; }; }; chosen { zephyr,instrumentation-area = &instru0; };

Then that way you can access it by using static const struct device *retained_mem_dev = DEVICE_DT_GET(DT_CHOSEN(zephyr_instrumentation_area));
This is not a required change.

ah, got it. Thanks for the explanation!

subsys/instrumentation/common/instr_common.c

nordicjm · 2023-04-28T09:28:22Z

subsys/instrumentation/common/instr_common.c

+void* stopper_callee;
+
+/*
+ * TODO(gromero): remove hack and use new RETAINED_MEM_MUTEXES=n config.


Likewise retention subsystem has a similar Kconfig, note that both retained memory and retention subsystem mutex Kconfigs would need to be set to n

@nordicjm Hi. I was not able to find any Kconfig syntax that would allow forcing RETAINED_MEM_MUTEXES=n
and RETENTION_MUTEXES=n from subsys/instrumentation/Kconfig. I put them in prj.conf (which works, but is annoying for the user that would need to know about it and set it per project). Any idea on how to set them in Kconfig?

Indeed it is not possible to de-select a Kconfig from a Kconfig, I will need to rework how it is done

Have posted this: #59254 will have a look at it after the 3.4 release is complete

@nordicjm Hi Jamie. Thank you!

teburd

A first pass look see and spotted some things, will wait for the non-draft to look harder

subsys/instrumentation/timestamp/timestamp.c

teburd · 2023-04-28T17:03:30Z

subsys/instrumentation/common/instr_common.c

+}
+
+__no_instrumentation__
+void instr_event_handler(enum instr_event_types type, void *callee, void *caller)


This doesn't seem to account for SMP in any way. Presumably it would be some metadata in the event or an entirely different stream (probably preferable to avoid locking) per core.

@teburd Right, it doesn't currently account for SMP. But indeed, what I had in mind was to use one stream per CPU to avoid locking/lock contention issues.

The only downside of this is that output streams need to be muxed in some way then, and will have some lock likely around it.

@teburd Not sure if I understood your last comment correctly. From your first comment I understood that to avoid locking issues you're suggesting one buffer -- so one stream -- per CPU (you said "core" but since a core may have multiple CPUs, I assumed it would be actually one buffer/stream per CPU to avoid the locking, because each CPU will execute, for instance, different threads, hence different code and stack to trace/profile) -- which I agreed. I'm confused about which approach you referred to as "this" in your last comment tho :-)

include/zephyr/instrumentation/instrumentation_ringbuffer.h

carlocaione

I'll need to come back later to this

include/zephyr/instrumentation/instrumentation.h

subsys/instrumentation/common/instr_common.c

subsys/instrumentation/timestamp/timestamp.c

gromero · 2023-05-02T19:17:06Z

@nordicjm @teburd @carlocaione @nashif Thanks a lot for the first pass and for the valuable suggestions! I'm working on getting the CI green now, but I'm also going on vacation today, so bear with me. I'll address your comments next :-)

teburd · 2023-05-03T00:55:27Z

Another question that came to mind, could this work with a sampling profiler, e.g. ITM periodically sampling of the program counter?

microbuilder · 2023-05-03T10:36:55Z

Another question that came to mind, could this work with a sampling profiler, e.g. ITM periodically sampling of the program counter?

The underlying polling mechanism would be quite different than the compiler instrumentation this is based on, where entry/exit hooks are inserted at compile time. The subsystem could certainly be updated to accommodate that in a second stage, using the underlying buffer processing tools, transports, etc., but I think doing one job well with the compiler-generated entry/exit hooks first would be more efficient to start.

carlescufi · 2023-05-23T15:56:54Z

Architecture WG:

@gromero notes that this subsystem allows us to instrument all the code without having to modify the code at all
@nashif states that the tracing subsystem is very selective, it requires macros (SYS_PORT_TRACING_) to be inserted in the code. For general developer use this proposal is very useful to enable profiling of the application, the overhead is added per-function (including internal and external APIs)
@microbuilder explains that the instrumentation can be limited to a subset of the code by filtering using exclude filters that work on regexes
@gromero clarifies that the filtering works at compile-time, whereas the trigger/stop functions work at runtime. Both approaches can be combined for fine-grained filtering. He also mentions future improvements where live patching could be used or more refined selection of the functions
gcc has an exclude list that works for both object files and filenames
@carlescufi asks why we cannot use the same transport for both tracing, logging, coredump and now instrumentation
@nashif agrees that we should coalesce transport backends in the future
@gromero mentions that SMP is not supported, @nashif says tracing doesn't support it either

samples/subsys/instrumentation/src/main.c

subsys/instrumentation/Kconfig

gromero · 2023-07-25T13:22:19Z

@gromero Is it me or we've lost documentation in the latest update ?

@erwango Hi Erwan! The only existing "docs" so far are the one from the RFC itself, the one in samples, and the function comments in the .h files.

erwango · 2023-07-25T13:31:07Z

@erwango Hi Erwan! The only existing "docs" so far are the one from the #57373 itself, the one in samples, and the function comments in the .h files.

Oh, my bad I was looking for a README... that's ok, thanks!

include/zephyr/instrumentation/instrumentation.h

nordicjm · 2023-07-31T07:52:30Z

include/zephyr/instrumentation/instrumentation_ringbuffer.h

+
+#include <zephyr/instrumentation/instrumentation.h>
+
+#define DEBUG 0


Don't think this should be here

nordicjm · 2023-07-31T07:52:39Z

include/zephyr/instrumentation/instrumentation_ringbuffer.h

+
+void instr_rb_init(void);
+
+struct instr_record *instr_rb_put_item_claim(enum instr_event_types type);


Needs documentation

nordicjm · 2023-07-31T07:52:49Z

include/zephyr/instrumentation/instrumentation_ringbuffer.h

+struct instr_record *instr_rb_get_item(struct instr_record *record);
+int instr_rb_get_item_wrapping(struct instr_record *record);
+
+/* TODO(gromero): get_item_size() probably not for external use. */


TODO needs to be done

subsys/instrumentation/Kconfig

nordicjm · 2023-07-31T08:06:19Z

subsys/instrumentation/Kconfig

+	default 256
+	range 1 4096
+	help
+	  Maximum number of functions to collect statistics. Set the maximum


Fixed. Thanks.

nordicjm · 2023-07-31T08:10:27Z

subsys/instrumentation/common/instr_common.c

+ *
+ */
+
+const struct device *retention0 = DEVICE_DT_GET(DT_NODELABEL(retention0));


Retention works in uninitialised RAM already, if it needs additional code to work across another core than it can be added as a new retention driver, that's not a problem

nordicjm · 2023-07-31T08:12:00Z

subsys/instrumentation/common/instr_common.c

+#endif
+
+/* See instr_fundamentals_initialized() */
+uint16_t magic = 0xABBA;


This would want to be static

Right, fixed! Thanks.

Nope, that's not right. Making it static defeats the purpose of 'magic'. static variables are initialized before program execution. What is needed here is a dynamic variable, which will be initialized at runtime, this way it's possible to use that variable (magic) to verify that all other important dynamic variables are properly initialized too. I'm reverting this change.

The likelyhood of another variable in a program or library being just called "magic" seems fairly high, so by not making this static you're creating a high chance of variable name collision.

subsys/instrumentation/common/instr_common.c

nordicjm · 2023-07-31T08:18:43Z

subsys/instrumentation/ringbuffer/ringbuffer.c

+	head = 0;
+
+	/* Second, write remaining item bytes not written yet. */
+	second_chunk = instr_rb_get_item_size(rec->header.type) - first_chunk;


Any reason the zephyr ring buffer isn't used?

@nordicjm The reason is that we planned at the beginning to use certain fields in the packet to inform variable length records allowing "maximum compression" when transferring the records from the target to the host. But the data stream is decoded in the host using lib babeltrace. However, we found out that it currently only supports Common Trace Format v1.8, which does not support decoding variable length data based on a length field (only for char[] iirc). Hence I ended up using fixed-length records, which now can be used with the Zephyr ring buffer API (which only supports fixed-length items). I'm investigating now if I can replace it with Zephyr ring buffer API to simply the PR for the moment.

github-actions · 2023-10-06T00:29:46Z

This pull request has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this pull request will automatically be closed in 14 days. Note, that you can always re-open a closed pull request at any time.

gromero · 2023-11-05T17:09:43Z

I just would like to say I'm finding some cycles to address the latest comments on this PR this week.

teburd · 2023-12-06T14:56:26Z

Cool, would be great to see this and improvements on it in the tree

gromero · 2023-12-06T15:23:18Z

I've updated the PR addressing most of the @nordicjm comments. While I wait for the CI to get green I'm investigating if I can replace my variable-length ring buffer API with Zephyr's ring buffer API to simply the PR for the moment.

gromero · 2023-12-08T22:31:57Z

Blocked by issue #66334

microbuilder · 2024-01-10T07:43:11Z

Blocked by issue #66334

This is merged in, so hopefully unblocks progress here?

gromero · 2024-01-18T15:04:38Z

Blocked by issue #66334

This is merged in, so hopefully unblocks progress here?

@microbuilder Yep, thanks!

Ablu · 2024-03-13T08:46:52Z

I was able to get this working in a virtualized environment (mps2_an385).

Steps:

checked out this PR
cherry-pick 6407120 (merged already, but not part of this PR)
allow exposing the serial I/O over socket:

diff --git a/cmake/emu/qemu.cmake b/cmake/emu/qemu.cmake
index 6103fc1cef..6dd1686f0d 100644
--- a/cmake/emu/qemu.cmake
+++ b/cmake/emu/qemu.cmake
@@ -63,14 +63,17 @@ if(QEMU_PTY)
 elseif(QEMU_PIPE)
   # Redirect console to a pipe, used for running automated tests.
   list(APPEND QEMU_FLAGS -chardev pipe,id=con,mux=on,path=${QEMU_PIPE})
   # Create the pipe file before passing the path to QEMU.
   foreach(target ${qemu_targets})
     list(APPEND PRE_QEMU_COMMANDS_FOR_${target} COMMAND ${CMAKE_COMMAND} -E touch ${QEMU_PIPE})
   endforeach()
+elseif(QEMU_SOCKET)
+  # Serve console I/O on a port.
+  list(APPEND QEMU_FLAGS -chardev socket,id=con,mux=on,server=on,host=127.0.0.1,port=4321)
 else()
   # Redirect console to stdio, used for manual debugging.
   list(APPEND QEMU_FLAGS -chardev stdio,id=con,mux=on)
 endif()
 
 # Connect main serial port to the console chardev.
 list(APPEND QEMU_FLAGS -serial chardev:con)

Tweak zara.py to allow using pySerial's support for alternative serial backends:

diff --git a/scripts/zaru.py b/scripts/zaru.py
index a99d85c87a..107b5874b7 100755
--- a/scripts/zaru.py
+++ b/scripts/zaru.py
@@ -206,27 +206,27 @@ def connect_to_target(port, verbose=False):
 
     Connect to target using serial device 'port'. A ping command is sent
     to the target to check if it's alive and responding. If target responds
     'True' is return, otherwise 'False' is returned.
     """
 
     try:
-        sport = serial.Serial(port, baudrate=115200, timeout=0.2, write_timeout=1)
+        sport = serial.serial_for_url(port, baudrate=115200, timeout=0.2, write_timeout=1)
         if verbose:
             print(f"Using '{port}' to connect.")
 
         if ping(sport):
             if verbose:
                 print("Connected to target.")
             return sport
         else:
             print("No response from target. Is the correct FW flashed? Also, check if port is open by another program.")
             sys.exit(1)
-    except serial.SerialException:
-        print(f"Could not open serial device '{port}'.")
+    except serial.SerialException as e:
+        print(f"Could not open serial device '{port}': {e}")
         sys.exit(1)
 
 
 def reboot_target(port, verbose=False):
     """Reboot target.
 
     Reboot target connected to the port 'port'. After the reboot the target is

Run the sample: west build -b mps2_an385 samples/subsys/instrumentation/ -DQEMU_SOCKET=y -t run
Perform tracing:

./scripts/zaru.py  --serial='socket://localhost:4321' trace -v -c get_sem_and_exec_function
./scripts/zaru.py  --serial='socket://localhost:4321' reboot
./scripts/zaru.py  --serial='socket://localhost:4321' trace -v --perfetto --output /tmp/perfetto_zephyr.json

Open /tmp/perfetto_zephyr.json in Perfetto UI.

There are existing knobs to tie the serial to a /dev/pts or pipes. Unfortunately neither are supported by pySerial. Socket seems to be easy enough, but comes with the usual port allocation issues of course. Overall, utilizing pySerial's URI scheme looks fairly flexible to me... But I have no tested this on actual hardware where one might need to tweak baud rate or other settings.

microbuilder · 2024-03-13T11:41:55Z

   sport = serial.serial_for_url(port, baudrate=115200, timeout=0.2, write_timeout=1)

./scripts/zaru.py  --serial='socket://localhost:4321' trace -v -c get_sem_and_exec_function
./scripts/zaru.py  --serial='socket://localhost:4321' reboot
./scripts/zaru.py  --serial='socket://localhost:4321' trace -v --perfetto --output /tmp/perfetto_zephyr.json

We should get that into any eventual documentation as an example.

gromero · 2024-03-14T13:37:16Z

@carlocaione @evgeniy-paltsev cc @nashif @nordicjm @teburd @erwango

Hi! Folks, this PR is done for another review in my view. @carlocaione Erik (@Ablu) addressed your comment on allowing the instrumentation to run on a VM, so you don't have to touch any cable to try it -- see the example in Erik's comment above. I've rebased on main and updated the branch with his changes. So now it's trivial to experiment with the instrumentation using the mps2_an385 board (QEMU VM).

@evgeniy-paltsev, your comments were addressed but are still blocking the PR. Could you please have another look?

In general, how can we move on and get this PR merged? Over the months since my presentation in Prague a handful of people showed interest in this work and also expressed that it's a reasonable approach. Is there anything controversial that needs more discussion?

gromero · 2024-03-14T15:02:08Z

The CI errors seem not related to the changes in this PR. Should I re-trigger?

gromero · 2024-03-14T21:05:02Z

I accidentally closed this RFC PR when trying to understand the CI errors. But no worries, I think it's time to remove the RFC status and update the description text since the code was tested on new boards since its first version and after several review rounds. Please check PR: #70253

gromero requested review from nashif, dcpleung, andyross, carlescufi, galak, MaureenHelm and tejlmand as code owners April 28, 2023 09:15

zephyrbot added area: Toolchains Toolchains area: Build System labels Apr 28, 2023

zephyrbot requested review from jeremybettis, nordicjm and stephanosio April 28, 2023 09:16

zephyrbot assigned tejlmand Apr 28, 2023

gromero mentioned this pull request Apr 28, 2023

Zephyr instrumentation subsystem #57373

Open

nordicjm reviewed Apr 28, 2023

View reviewed changes

teburd reviewed Apr 28, 2023

View reviewed changes

carlocaione self-requested a review April 29, 2023 09:02

carlocaione previously requested changes Apr 29, 2023

View reviewed changes

include/zephyr/instrumentation/instrumentation.h Outdated Show resolved Hide resolved

subsys/instrumentation/common/instr_common.c Outdated Show resolved Hide resolved

nashif assigned nashif and unassigned tejlmand May 1, 2023

nashif reviewed May 1, 2023

View reviewed changes

subsys/instrumentation/timestamp/timestamp.c Outdated Show resolved Hide resolved

gromero force-pushed the instr_subsystem branch from 936825e to 44b9e47 Compare May 2, 2023 19:18

evgeniy-paltsev requested changes May 23, 2023

View reviewed changes

samples/subsys/instrumentation/src/main.c Outdated Show resolved Hide resolved

samples/subsys/instrumentation/src/main.c Outdated Show resolved Hide resolved

erwango reviewed May 24, 2023

View reviewed changes

subsys/instrumentation/Kconfig Outdated Show resolved Hide resolved

gromero force-pushed the instr_subsystem branch 2 times, most recently from ddceaed to aecf328 Compare June 14, 2023 01:50

nordicjm reviewed Jul 31, 2023

View reviewed changes

github-actions bot added Stale and removed Stale labels Oct 6, 2023

gromero force-pushed the instr_subsystem branch from d09b4ee to 998d743 Compare December 6, 2023 12:49

zephyrbot added the area: Samples Samples label Dec 6, 2023

gromero force-pushed the instr_subsystem branch 2 times, most recently from 56b8103 to 93767f7 Compare December 6, 2023 13:11

gromero force-pushed the instr_subsystem branch from 93767f7 to 8c966ad Compare December 6, 2023 14:58

gromero force-pushed the instr_subsystem branch 2 times, most recently from 9e2142c to 5f573cc Compare December 8, 2023 22:29

nordicjm mentioned this pull request Mar 14, 2024

Add a feature to retrieve the previous error/hang stack trace for current boot to increase the debuggability #70187

Open

gromero force-pushed the instr_subsystem branch 2 times, most recently from 92be12d to f86f3b9 Compare March 14, 2024 13:10

gromero closed this Mar 14, 2024

gromero force-pushed the instr_subsystem branch from f86f3b9 to 2ca67b5 Compare March 14, 2024 20:35

gromero mentioned this pull request Mar 14, 2024

Add Instrumentation subsystem #70253

Open


		*/

		const static struct device *retained_mem_dev = DEVICE_DT_GET(DT_ALIAS(retainedmemdevice));


		#include <zephyr/instrumentation/instrumentation.h>

		#define DEBUG 0


		void instr_rb_init(void);

		struct instr_record *instr_rb_put_item_claim(enum instr_event_types type);

[RFC] Zephyr instrumentation subsystem #57371

[RFC] Zephyr instrumentation subsystem #57371

Conversation

gromero commented Apr 28, 2023 • edited Loading

nordicjm left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gromero Jun 14, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

teburd left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

carlocaione left a comment

Choose a reason for hiding this comment

gromero commented May 2, 2023

teburd commented May 3, 2023

microbuilder commented May 3, 2023

carlescufi commented May 23, 2023 • edited Loading

gromero commented Jul 25, 2023 • edited Loading

erwango commented Jul 25, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

github-actions bot commented Oct 6, 2023

gromero commented Nov 5, 2023

teburd commented Dec 6, 2023

gromero commented Dec 6, 2023

gromero commented Dec 8, 2023

microbuilder commented Jan 10, 2024

gromero commented Jan 18, 2024

Ablu commented Mar 13, 2024 • edited Loading

microbuilder commented Mar 13, 2024

gromero commented Mar 14, 2024

gromero commented Mar 14, 2024

gromero commented Mar 14, 2024

gromero commented Apr 28, 2023 •

edited

Loading

gromero Jun 14, 2023 •

edited

Loading

carlescufi commented May 23, 2023 •

edited

Loading

gromero commented Jul 25, 2023 •

edited

Loading

Ablu commented Mar 13, 2024 •

edited

Loading