UART/FS Logging Backend with GRTC-driven EGU Interrupt slows down logging output

[br_adams_01]

Hello,

I am working on incorporating flash logging into an application that has a GRTC-driven EGU interrupt (capture/compare event). Here is where I am setting up the EGU and connecting it to the GRTC Capture/Compare event with a PPI channel. The GRTC is used for timed interrupts so that I do not have to use the Zephyr timer module (uses more energy).

Called from main upon application startup

void init_ppi_egu() {
#if defined(__ZEPHYR__)
	IRQ_CONNECT(NRFX_IRQ_NUMBER_GET(NRF_EGU_INST_GET(10)), IRQ_PRIO_LOWEST,
				NRFX_EGU_INST_HANDLER_GET(10), 0, 0);
#endif
    nrfx_err_t status;
    int err;
	nrf_egu_task_t egu_event = NRF_EGU_TASK_TRIGGER0;
	uint8_t ppi_chan_grtc_int;
    nrfx_egu_t egu_inst = NRFX_EGU_INSTANCE(10);
    void * p_context = "Some context";
    status = nrfx_egu_init(&egu_inst, 5, egu_handler, p_context);
    nrfx_egu_int_enable(&egu_inst, (uint32_t)1);
    if (nrfx_gppi_channel_alloc(&ppi_chan_grtc_int) != NRFX_SUCCESS) {
		printk("Failed allocating PPI chan for grtc interrupt\n");
	}
    nrfx_gppi_channel_endpoints_setup(ppi_chan_grtc_int,
					  nrf_grtc_event_address_get(NRF_GRTC, nrf_grtc_sys_counter_compare_event_get(grtc_channel)),
					  nrfx_egu_task_address_get(&egu_inst, egu_event));
    nrfx_gppi_channels_enable(BIT(ppi_chan_grtc_int));
}

In a separate config file, flash_logging.conf:

CONFIG_FLASH=y
CONFIG_FLASH_MAP=y
CONFIG_FLASH_PAGE_LAYOUT=y
CONFIG_FLASH_LOG_LEVEL_DBG=y

CONFIG_LOG_BACKEND_FS=y

CONFIG_FILE_SYSTEM=y
CONFIG_FILE_SYSTEM_LITTLEFS=y
CONFIG_LOG_MAX_LEVEL=3
CONFIG_LOG_TIMESTAMP_64BIT=n
CONFIG_LOG_RUNTIME_FILTERING=y
CONFIG_LOG_BACKEND_UART=y
CONFIG_SHELL_LOG_BACKEND=n

# Log backend config
CONFIG_LOG_BACKEND_FS_FILE_SIZE=40960
CONFIG_LOG_BACKEND_FS_FILES_LIMIT=3

If both flash logging AND the EGU interrupt is used, the UART output is only giving me ~1 log line every second in the log, but the EGU interrupt is working.

If I don't call the init_ppi_egu function out of main, and I just run the application as normal, the logging outputs at normal speed (for flash logging enabled).

Also, if I disable flash logging, and leave the EGU interrupt as is, the logging outputs at normal speed (for flash logging disabled).

I already tried messing with the egu10 peripheral interrupt priority and set it lower to see if maybe that was the issue, but it did not help.

Is there anything that I may be doing wrong?


Many thanks!

[Vidar Berg]

Hello, 

Does enabling this interrupt result in significantly more log messages being printed (with flash backend disabled)? And what is the frequency of this interrupt, and is it a short ISR? 

The flash backend should be considerably slower and may be blocking the uart backend.

The GRTC is used for timed interrupts so that I do not have to use the Zephyr timer module (uses more energy).

I haven't profiled this (maybe you have), but I would not expect there to be a significant difference here. Zephyr timers use the same GRTC peripheral as the interrupt source.

Thanks,

Vidar

[br_adams_01]

Vidar,

Enabling the interrupt with flash backend disabled results in the same amount of log messages being printed within a certain time-frame (no change in logging speed). The interrupt frequency varies, as we set a value in the compare register for the GRTC and then the interrupt gets triggered when the counter value reaches the compare value. When that happens, we set another compare value either at that instant or at some later point in the program when we need to use the timed interrupt again (by setting the next interrupt time based on the current counter value plus a set time in microseconds). As I stated above, I have profiled both, and the GRTC actually does use less energy (by about 60 uA). It's especially beneficial when the counter/timer needs to run for the entire runtime on a battery powered device.

This is some measurements that I did in the past (end of last year) with idle current with GRTC vs. Zephyr timer module.

The green trace represents the Zephyr timer module and the yellow trace represents the GRTC. There is about a 56 uA increase when using the Zephyr timer module for timed workqueue functions.


So instead we use a GRTC/EGU interrupt connected with a PPI channel, and then we use the ISR (very short) to submit a workqueue function to do X action.

Yes, the flash logging backend is slower from observation, but not too slow. When using the GRTC/EGU interrupt, however, it causes significant slowdowns to the flash logging backend (along the order of about 1-2 log lines every second).