 Hi, y'all. My name is Aastha Grover and I'm a contributor to the Zephyr project since 2019 and I work for Intercorporation. I've been contributing lately towards the logging subsystem, especially towards the logging format implementation. In past, I've also contributed towards twister test suite and other areas. If you have any questions after the presentation, I can be reached on Discord and you can also find me on Github by my handle AasthaGR, which you can see here. Here is the agenda listed for my presentation today. I will be giving an overview of the logging subsystem and how to start using the logging APIs for most basic use cases and following that. I will be talking about the architecture of the logging subsystem, the log process and the workflow. And then I will briefly show the log APIs that are available for users and developers and the different modes of logging. How each one of them can be used and the advantages of one over the other. I'll cover all of that today. Then we'll see the extension of logging to the multi-domain and also how memory allocation works for the messages. Finally, I will show the logging formats supported in Zephyr and talk about their pros and cons and how we can switch the logging formats at runtime, which is a feature provided by the subsystem itself and supported in Zephyr. I will cover any basic style as we go. After the presentation, feel free to ask any questions on Discord channel if you need to. When we talk of logging, why was logging needed in the first place? Any ideas? It's purpose is multi-fold. It can be used for debugging purposes even for tracing or can even just be used to output any informatory logs. Logs from Zephyr are usually human readable strings and they give printf like results and logging subsystem can also do the string formatting using the support for CB printf functionality in Zephyr and it also supports all the format specifiers. But how is logging different from the simple print case? It provides you with some more features than a simple print case would provide, which would include any source identification like where the logs are coming from, the severity levels and also time of log generation that is time stamping. We can log from any context in Zephyr, which is also a feature of the logging subsystem. But to log from any context, it would mean that we can log not just from threads, but even from the interrupt context, even the high priority interrupts. We can also dump the HexTum data using other log APIs like LogHexTum and we'll go over the log APIs supported in Zephyr in the upcoming slides. When we log, we want to capture the informatory logs, the debugging logs or the error logs even. But it depends on what the source or application needs and there can be different log levels for different parts of the system. But some of the severity levels supported in Zephyr are information, warning, debug and error modes and each level is defined as a macro in Zephyr. Finally, it's important to note that how do we output the logs? How do we see them? You can see them either on the UART serial console or can also store them in the file system and send them over to the Bluetooth or NET subsystems. We can also process the logs logging backends depending upon what backends are enabled and supported. Now, getting to the basics, let's start with how to log using Zephyr in first place. To enable logging in a Zephyr application, you literally just need these three things. You enable the logging using the kconfig.config underscore log in the prjconf of the application, which is the configuration file for the application. And make sure to include the logging header log.h in the source file, which will enable you to use logger APIs provided by logging subsystem. Just register the log module after including the log.h header. Just register the log module using a unique name and use the APIs like log INF or log error following that. On the left side, you can see the snapshot of Zephyr Hello World application and its output when used the log API inside that. Like we have used log INF Hello Please in this application. The output here has few elements though. The first one is that it contains the timestamp of generation, the log generation, then the severity level, the module name, and then the log message. So that's about the basics. We used log INF here, but there are other APIs that the logging subsystem provides us. Let's glance at few of them here. Here X specifies the severity level type, which could be error, information, debug, or warning. We have normal log APIs like log underscore X, and then we also have log INST underscore X, which captures the logs associated with the particular instance of the module. And there is also an API to dump the Hextump data like log Hextump underscore X. And the important ones I think to note here are that you need to register the module before you can log from that module. And you do that by using the log module register API. And in case there are multiple files in the module, you just need to register it once, but make sure to declare the module in every source file which wants to use the logging. And module can be declared using log module declare API as we have specified here. Plus, we have some more logging APIs like log print K and log raw APIs, which lets you print the raw log messages. And X here just specifies the severity level type, which could be error, information, debug, or warning again. So let's see this now. But how does this all happen? And it might be interesting to know for everybody how the logging process flow looks like and the important components of the subsystem itself. The subsystem has a core, which holds the core functionality, a front end and a back end. And depending upon what architecture or what parts of the system we are dealing with, there might be different back ends enabled. And there can be more than one back ends active at single point of time. There are multiple back ends up to nine back ends that are supported in suffer. And the core is where we have the base of the logging subsystem, which decides if the control flow lands up using a front end and back end or just the front end or disables the front end altogether. There are K config options like config log front end only, which indicates that we can just have a front end enabled and not the back ends or anything else. And the front ends are engaged by default. When you use the log API or call them in your application, they are responsible for log filtering, which can be build time or run time. It's also responsible for allocating the buffer and also to create and commit the messages. So that's for the front ends. And front ends are also optimized to log messages faster, like if we are logging for example, logging from an interrupt context. We don't want to spend too much time in the interrupt and do not block the other parts of the system. So it's optimized for that. So that was about the architecture of the logging subsystem on the high level. So now we have seen already that the logging process contains the following. We need to filter the log messages depending upon what logs we are looking for. And we need to allocate the buffer to the message and finally create the message and commit the message, commit and output the message basically. A log message is something which can be defined as a self-contained continuous block of memory in the context of memory and it is mostly suited for copying the message to because there are some parts where we need to copy the message to. And log message is usually self-contained. We don't want the memory to be sparseed. So we try to allocate a continuous block to a log message. It contains a message descriptor which identifies the message and usually comprises of a source ID domain and also severity level. And it also contains a timestamp or the formatted string details if we have passed a string and also the optional data. Just glance here at how the message format looks like. Note that there are two bits allocated to the buffer for log message and I'll talk more about that in detail in the following slides. There is also a flag for log message which is just one bit and then there are domain ID and severity level each of them allocated the three bits. There is a CV printf package length which can take up to 10 bits. The data length is can be up to 12 bits and there is a pointer to the source descriptor as well and also the timestamp which can be 32 or 64 bits depending upon what system is being used and there can be optional padding if required and apart from that there is just CV printf package hextam data and alignment padding which can be there in the message itself and these are the last few ones are the optional members. Now we manage the messages and allocate some memory for each of the member item. We use a circular buffer to allocate the continuous block of memory for the log messages and this circular buffer is also referred to as multi producer single consumer packet buffer which is also known as MPSCP buff and when this buffer gets full the messages also need to be sequentially freed and as we see we sometimes need to make a copy of the messages so the back-end processing of these log messages is synchronous so we can make a copy if we are selecting a type of mode that we'll talk about in the following slides which is deferred processing. So this circular buffer is also known as MPSCP buff in other in short and it operates in the fee for order which means first in first out order and the allocation policy says that if buffer is full or the requested space cannot be allocated then there are two options that we have here first is that we have the overwrite enabled via a config log mode overflow kconfig option and then the oldest packets in which the oldest packets are dropped and until the requested space is allocated and this option generally degrades the performance because we are dropping the old packets and there is the second option no overwrite in this option read and write index pairs are used to see if there is any available space if space cannot be allocated and overwrite is disabled then we return a null pointer or the context blocks if the allocation was with a timeout and in context of the memory the packet is produced and then it is consumed producing has two steps to it the requested amount of data is allocated and then the producer fills the data and finally we when we produce the packet we would consume it consuming the packet also has two steps it would the consumer would claim the packet which means they would get the pointer to the to the packet itself and the length of the packet and then the packet would be freed up this approach consuming the packet and freeing the packet and required would reduce the memory copying so it's good now let's go over the header bits how the header bits are structured in the memory buffer as we saw there that there are two bits assigned to the header which is associated with each packet in the buffer one bit is for the valid bit which is set to one when packet is when packet would contain the a valid packet the other bit is for the busy bit which would be set to one when the packet is being consumed and is not free for use so so this bit would signify that the packet is claimed but not free and here you can see the table internally to evaluate if the packet is valid claimed or free so when both bits are set to zero we say that the space is free for use when when the valid bit is set is set to one but the busy bit is zero then we would say that it is a valid packet but when both are one it would mean that it's a claimed valid packet it's it's valid plus busy so claimed valid packet and when only busy bit is set it means that it's a skip packet which which is used to indicate the padding at the end of the buffer and you know padding is required for multiple reasons while allocating the memory to the buffer from the buffer now we can have so many logs and we need some way to identify them or filter them based on the source or module and also based on what we need it will not only help to to not overload the system but also to reduce the image size and there are two types of filtering that we can have one of them is the compile time filtering which we use when the logs are being built and the compile time filtering can be on the basis of module or even severity levels the other one is runtime filtering which filters on the basis of source and the source can be a module or even a specific instance of the module and runtime filtering is independent for each backend that means that every backend can have their own filters set so remember that we have like more than one backend active at a time and we can also have filters for each of them which are completely independent of each other now I'll go over a little bit about the details to the runtime filtering we can have the filter structure so we have the filter structure which is declared in RAM for every source of logging that we have and this filter structure has 10 3-bit slots that are declared in RAM each slot contains the or stores the current filter for the backend in the system and in Zephyr we can have nine backend supported so we have 10 slots nine for backends and one slot the slot zero which has bits zero to two is used to is used to aggregate the maximal filter setting for given logging source an aggregate slot would determine if the log message is created for given entry because it indicates that there is at least one backend that is expecting that log entry so start zero is kind of a global setting like minimal of all and backend slots would be examined when the messages messages processed by the core to see if the backend accepts the message or not so and in runtime filtering the binary footprint is increased though because the logs get compiled in so it just increases the footprint in that ways now we have seen how memory gets allocated and why is it important to filter the logs which can impact the performance based on what kconfig options are enabled and some other factors the logging subsystem also has provides us with an option for logging where we can where there can be a trade-off between the system performance and the amount of memory or footprint that is occupied so here we go for the three modes of logging on that zephyr supports there is the deferred mode the immediate mode and the minimal mode for deferred mode the log messages are buffered and processed later in the known context and for deferred mode is definitely a time consuming process because it gives us a rich formatting and also precise time stamping plus it also gives us both build time and compile time filtering options and can be used for any backend and this deferred mode is definitely synchronous and also close to being non-intrusive where non-intrusive as if the as if this mode or the logging never existed so it's it doesn't interfere with other parts of the system and for the immediate mode the output is immediate and follows the process flow of the application um the immediate mode would definitely impact the performance though when time consuming operations are performed from the high priority context or the high priority interrupts and it has its own disadvantages but it's still useful while debugging um immediate mode has only a support for limited backends but that's the con for the immediate mode the minimal mode however consumes very less memory and has the lowest footprint but it doesn't have any like nice look giving features like color formatting or time stamping or any filtering options it redirects the logs to the printk so it just has similar results with some benefits of logging though so um we have talked about a lot of about the logging subsystem but um um which has its own challenges and when it comes to logging from multiple sources there is one of the challenge it has which is for the multi-domain logging when we log we can have any number of sources but apart from them even from a single core there can be multiple domains for example a core can also have multiple domains like if you have seen the arm trust core zone it has two domains secure and non-secure but what exactly is the domain i'll i'll establish the definition here for clarity that domain is something which has its independent binary build or the binary image but to note here we cannot access memory of other domain so the memory access is restricted across cross domains we cannot access cross domain memory and there are there are these approaches to multi-domain logging that we could opt for the first one is described very simply but it's much more complicated that you can log inside every domain independently but this approach is not scalable as the system would be would be overloaded with the logs the other approach is to use the multi-domain logging interface that the logging subsystem provides using this approach the log messages inside each domain goes to one root domain the messages are passed from one domain to another using a log link interface a link between the domains where one link back in can transfer messages to the another link back in and the log link interface receives log messages from other domains it creates a copy and put a local log message copy into a message queue and the log link interface implementation is very similar to the the complementary back-end implementation so it looks similar but has a different function to to transfer the messages between cross domains when we talk of domains we have different types of domains when we talk of multi-domain logging there is the end domain a relay domain and and the root domain the root domain has one or more links and and also has the back-end that can output the logs to the user there is the relay domain which has links to other domains but does not have any back-ends for output it just has a cross domain back-end either to another relay or to the root domain the the end domain is the one which has a logging core implementation and also across domain back-end and in this picture we have two cores and each core has two domains secure and non-secure and this is how the communication looks like between the end domain relay domain and root domain and for more information on that I encourage you to go through the documentation too now I'll talk about the most important aspect of logging from user's perspective which is the type of logging formats which are supported in Zephyr there is this MIPI-SISTI logging format and it's basically a universal data format and is supported by many many many systems and it's used for sharing the debug entries information between the test systems and the devices like SOCs or platforms and using this format it simplifies the integration of the embedded software with the with any debug hardware or dots etc it's used for developing the test products it's kind of a hex data but each part has its own specification so each part signifies something and you can look up more information about about the MIPI-SISTI in the in the repository in Zephyr project which is maintained by the project itself yeah and then there is the normal text format which is the one which is enabled by default if you if you do not enable any format then you would just you would just enable the text format MIPI-SISTI however can be enabled using the kconfig option config log MIPI-SISTI enable which will provide you all the support plus would include the MIPI-SISTI library and there is also a dictionary log format which is quite compact and can be enabled using the log dictionary config log dictionary support option and this outputs data in the binary format and encodes the arguments to formatted strings in their native storage formats and we have also support for custom logging formats and support for which is provided using the config log custom format support option so any custom log format can be easily added to Zephyr because the interface is such to be able to accommodate for any custom format and I personally have implemented the MIPI-SISTI support in Zephyr so feel free to drop in any questions for that if you have any on discord or if you're planning to use that format I've also added support for dynamic switching of logging formats at runtime basically a user can pass the output format needed to the supported APIs like they can use log format set which sets the log format that is passed by the user for the backend that they have passed into the API and or else they can use log format set all active backends API which would take the log type that user wants to set for all the current active backends there are limitations to use this feature specifically in the deferred logging mode it would result in the number of dropped messages when there are large number of messages that needs to be printed and due to that you won't see complete results if you turn on this feature in the deferred mode so I highly recommend to use this in immediate mode only and here is an example of how the dynamic switching of logging format would look like at runtime this is an example from one of the Zephyr sample application for switching of logging formats the first block shows here the MIPI SISTI format output and then we switch to the text and then again we switch back to the MIPI SISTI logs I find this feature really cool so yeah try it out and let me know if you have any questions here that's all I had for today and here are some of the references that you could find helpful I encourage all the viewers to look at the Zephyr documentation for logging subsystem and also the contribution guide the links of both are embedded in the presentation so you'd find it on my slides and there are the mailing list for users and developers where you can post your questions and also there is a discord channel for logging and tracing please use that to post any questions and inputs so any questions comments for me I'm available to answer on discord thank you very much for watching this presentation and my talk today