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

[Vidar Berg]

Thanks for the additional information. I can understand if the idle current is lower if the timer timeout interval is short (in the low millisecond range rather than in the seconds range), and if your ISR is shorter with less CPU overhead compared to using the GRTC ISR in zephyr.

br_adams_01 said:

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.

Are you using "direct" interrupts as in this case:  Large delay between k_signal_raise and k_poll invocation ?  And could the slowdown be caused by the workqueue item you submitted (could it block the logger thread for a longer period)?

[br_adams_01]

Vidar,

The workqueue item I am referring to does not have any blocking functions within or endless loops within. They are really short workqueue handlers (in my case, one that turns Bluetooth scanning on, and another one that turns Bluetooth scanning off in order to further save power). These workqueue items only execute when the EGU interrupt is triggered. So it should happen quick enough. And I do not think they are direct, as I am using IRQ_CONNECT as opposed to IRQ_DIRECT_CONNECT to tie the IRQ line to the ISR.

[Vidar Berg]

Sorry, I see now from your initial post that you were not using direct interrupts. I missed that earlier.

Some thoughts:

1. There may be a possible conflict with GRTC usage in MPSL and Zephyr (Integration notes). Though I don't know how that could affect the logger thread 

2. Did you submit the same workqueue item from the zephyr timer handler earlier without encountering this issue?

3. In the case where you only get one log message ~1 every second, what's the approx. current consumption and length of the idle periods? Or in other words, does the power profile show that the device is spending the majority of the time in sleep still?

4. Why even use a periodic interrupt to start and stop scanner? Can't the same be achieved more effeciently by setting the window size, interval, and timeout with the scanner API?

5. What's the EGU trigger interval approx.?

I would also be happy to try troubleshoot this further on my end if you are able to share a minimal version of your project. 

[br_adams_01]

I'm glad you mentioned the first point (#1), because I found something I may could try.

According to that integration note, it is stated that reconfiguring the interrupts for the GRTC while MPSL is enabled is not allowed. However, I could try to set the following Kconfig to true, which would allow me to reconfigure the interrupts:

CONFIG_MPSL_DYNAMIC_INTERRUPTS

I have not tried thought #2 yet.

For #3, I have not measured the current consumption in this state.

For #4, if I only use the window size and interval, apparently the RX mode is still enabled, and I get ~5 mA of constant average current as a result. So I have to enable and disable scanning with periodic interrupts to achieve the same effect, but by disabling RX as a result.

For #5, EGU triggers 1 second after program start to turn scanning on, and then EGU triggers again 30 seconds later to turn scanning off. After that, I stop scanning for 30 minutes (1800 seconds) before I trigger the EGU to turn scanning on again, and this happens in a cycle.

I am going to try the above Kconfig and see what happens.

UPDATE: The above Kconfig did not work. However, I will try to change to the Zephyr timer module to see the result.