To identify, adjust sleep period of sample app threads?

[tedhavelka]

Hello Devzone Community,

My name is Ted, and I am continuing my effort to configure a Zephyr based, Nordic aws_iot sample app based firmware to run and support nRF9160 lowest specified power consumption. I am in the process of putting all application threads to sleep, so that Zephyr's idle thread can put the application processor into a low power sleep mode. Nordic Power Profiler waveforms of measured current draw, however, indicate that I've failed in this. Some part of the overall firmware binary appears to be yet running. Lowest average current I achieve is ~190 microamps.

My Devzone account doesn't permit me to upload photos, but here is a link to two captures from Nordic's power profile which I took earlier today.  My apology that I must include an external link here and not the images directly:

*  wiki.neelanurseries.com/.../20220311

The first one shows a general pattern of current regularly spiking from a few microamps to around three milliamps.  The zoomed capture shows the ten millisecond spikes, a more distinct fast spike and a more blunted longer duration one.

These are taken during a 45 second period when all my application threads are sleeping -- for 45 seconds -- and LTE modem is turned off, and GPIOs to hardware enable points of our board are also turned off, effectively powering down the hardware outside the nRF9160.

From these waveforms I observe that some ARM processor activity appears to be consuming current every ten milliseconds. But though I have put my app threads into a nearly minute long sleep period, and have searched for the sleep periods set on aws_iot sample app threads, I cannot see any firmware configured device or service that is configured to run every ten milliseconds.

This work is based on Nordic's aws_iot sample app, as it appears in ncs v1.6.1. The sample app creates three or four Zephyr threads. Zephyr itself creates a  thread for `int main()` and an idle thread. Work of my own adds a few more threads at run time. These latest threads I can readily put to sleep for minutes or even hours, with a call to k_sleep() in a given thread's effective main function.

I have enabled Zephyr's thread_analyzer feature, and can observe simple reporting at run time of the threads of this firmware. Here is a typical Zephyr output I can see via a serial connection, and using a simple CLI to invoke a handful of commands:

Excerpt 1: Zephyr thread summary report

```1) 'thread_accelerometer' stack size 2048 bytes, stack used 960 bytes, 46%
2) 'thread_dev_work' stack size 3072 bytes, stack used 1504 bytes, 48%
3) 'thread_simple_cli' stack size 4096 bytes, stack used 1768 bytes, 43%
4) 'thread_led' stack size 512 bytes, stack used 136 bytes, 26%
5) 'download_client' stack size 4096 bytes, stack used 104 bytes, 2%
6) 'at_cmd_socket_thread' stack size 1472 bytes, stack used 688 bytes, 46%
7) 'time_thread' stack size 1024 bytes, stack used 728 bytes, 71%
8) 'connection_poll_thread' stack size 3072 bytes, stack used 296 bytes, 9%
9) '0x20015ab0' stack size 1024 bytes, stack used 168 bytes, 16%
10) 'sysworkq' stack size 2048 bytes, stack used 168 bytes, 8%
11) 'idle 00' stack size 320 bytes, stack used 56 bytes, 17%```

Here I modify the report to annotate each thread's origin, which affects how easily or not I can adjust a thread's sleep time:

Excerpt 2:

```1) 'thread_accelerometer' . . . home authored application
2) 'thread_dev_work' . . . home authored application
3) 'thread_simple_cli' . . . home authored application
4) 'thread_led' . . . home authored application
5) 'download_client' . . . aws_iot sample app
6) 'at_cmd_socket_thread' . . . aws_iot sample app
7) 'time_thread' . . . aws_iot sample app
8) 'connection_poll_thread' . . . aws_iot sample app
9) '0x20015ab0' . . . ?, not known
10) 'sysworkq' . . . Zephyr 2.6.0
11) 'idle 00' . . . Zephyr 2.6.0```

So far I have been able to track down in Zephyr's dwt.h library header file that the time thread has a default sleep period of 3600 seconds. Tracing thread 'at_cmd_socket_thread' which is implemented in ncs/nrf/subsys/net/lib/aws_iot/src/aws_iot.c I cannot tell what this thread's effective sleep period is.

Question (1): Can a Devzone team member or community member help me identify where this thread's sleep time is realized?

I have yet to find the implementation details for thread 'download_client', 'connection_poll_thread' and '0x20015ab0'. The last of these threads I have concern for. It is not named, and so I cannot be sure whether it is a Zephyr construct or a Nordic sample app construct. This unnamed thread has shown in the thread analyzer report since I enabled Zephyr's analyzer.

Question (2): is static code analysis the only way to learn "who" in the Zephyr and other source codes is creating the unnamed thread?

Until I can identify the unnamed thread, I won't know whether I can cleanly properly adjust its sleep period. If it is a kernel thread, my app space firmware won't automatically have privileges to make any changes to a kernel thread. I believe there are some extra steps to be able to do so, if that is even possible.

I recognize also that I cannot simply change sleep times of the aws_iot sample app threads, and expect celular level and MQTT client-broker connections to continue to function. I'll need to study and find a way to cleanly close connections before putting such threads to sleep.

Thanks ahead of time to all who can shed some light and help on these deep sleep and nRF9160 power saving questions!

- Ted

[tedhavelka]

Hello Didrik,

Thank you for sharing the details regarding VSCode and its integration with thread aware debugging.  I am setting up VSCode now, and am interested to see which debugger is used -- gdb or another? -- and to learn how to use this.

Since our last exchange in this thread I have completed a few incremental low power tests of firmware running on our custom nRF9160 board.  Two key things I was able to configure and run:  (1) to print Zephyr's thread summary report as a nearly first line of code in application void main() routine, and (2) complete disabling of my own custom threads.

The programming error I found a few days ago involved a thread continuing to execute with a sleep time of only 10 milliseconds.  This accounts for the 100Hz current spike I was seeing, and which averaged to about 191 microamps.  With all threads sleeping for a minute or longer, I was able to reach ~85 microamps but continue to see a usually ~25Hz current spike which averages to ~67 microamps:

   *  https://wiki.neelanurseries.com/index.php/20220318

( I included a copy of my Kconfig, which contains most of the aws_iot sample app symbols, plus some RTT related symbols you shared with me in my related post 85435. )

In my own Zephyr based app code I have UART0 enabled;  a dts file selects this on-chip peripheral as Zephyr's preferred console.  An device tree overlay file further configures UART2, which I use for a custom command line interface, under normal development run time conditions.  Per your answers plus help in post 85435 I put both these UARTs into a suspended mode with a call of the form:

  

rstatus = pm_device_state_set(device_uart, PM_DEVICE_STATE_SUSPEND, NULL, NULL);

Question (1):  is an average current of ~85 microamps indicative of an nRF9180 SICA B1A running with all UARTs and high speed clocks off?

As I have still not reached within a magnitude of the spec'd 1.4 microamps I am especially unsure whether I have correctly turned off the UART devices which are normally in use.  By the way, I'd also tried redirecting logging from Zephyr's default UART choice to an RTT link, but could not ever get messages going on the second terminal.

So with my custom app threads simply never started, and not running, I see that Zephyr out the gate reports five threads in its list of threads:

- main.c - main() starting,

   1) 'time_thread'              stack size 1024 bytes, stack used 32 bytes, 3%
   2) '0x20015628'               stack size 1024 bytes, stack used 32 bytes, 3%
   3) 'sysworkq'                 stack size 2048 bytes, stack used 168 bytes, 8%
   4) 'idle 00'                  stack size 320 bytes, stack used 32 bytes, 10%
   5) 'main'                     stack size 4096 bytes, stack used 944 bytes, 23%

- app_main - custom app based on AWS IoT sample app started, version: v1.0.0
- app_main - initializing cJSON library . . .
- app_main - calling nrf_modem_lib_dfu_handler() . . .
- DEV 0315 - SKIPPING USE OF ORIGINAL AWS_IOT SAMPLE APP CODE
- DEV 0316 - pausing 10 seconds to allow for thread stack review `st` . . .

The unnamed thread appears here in this shortest list I can obtain.  There's no readily earlier time I can access Zephyr's thread analyzer than at the start of my own main line code.

I'd held questions about this unnamed thread:  is it possibly a thread that's continuing to run while I put all other threads to sleep?  Your suggestions to try VSCode's debugging facilities I hope will help me rule this in or out.

After calling aws_iot sample app functions my application's thread list looks like this:

   1) 'download_client'          stack size 4096 bytes, stack used 104 bytes, 2%
   2) 'at_cmd_socket_thread'     stack size 1472 bytes, stack used 688 bytes, 46%
   3) 'thread_simple_cli'        stack size 4096 bytes, stack used 1768 bytes, 43%
   4) 'time_thread'              stack size 1024 bytes, stack used 728 bytes, 71%
   5) '0x20015628'               stack size 1024 bytes, stack used 168 bytes, 16%
   6) 'sysworkq'                 stack size 2048 bytes, stack used 168 bytes, 8%
   7) 'idle 00'                  stack size 320 bytes, stack used 56 bytes, 17%

This is with my own custom written threads all disabled, none of them called to start.  So something in the mix of hardware and threads continues to draw current in spikes about every 25 milliseconds to 34 milliseconds.  This leads to my next question regarding the current consumption pattern I observe.

Question (2)  is there a clue in the current spikes, appearing at about 25Hz, and intermittently peaking at 4mA and alternately 0.5mA?  Any part of SICA B1A hardware consume power in this way?

As a final important technical point you mention the difference between configuring the LTE modem to enter a power savings mode (PSM) versus shutting off the modem with the AT command `AT+CFUN=4`.  Thank you for the reminder that the PSM modes are often preferable for being more efficient.  This leads to my last question regarding the immediate and near term effects of issuing the LTE modem command `AT+CPSMS=1,,,"10101010","00101000"` or similar.

Question (3) - When firmware enables PSM mode in the nRF9160 modem, is the "wake period + sleep period" entered immediately?

Question (4) - When the new PSM times are configured, does the PSM mode begin by keep the modem on for its active period, or does it begin by keeping the modem in power savings mode for its suspended, low power period?  E.g. which part of the power cycle occurs first?

Will continue tests and study here.  Thank you for your help so far, Didrik.  Good weekend to you!

- Ted

[Didrik Rokhaug]

tedhavelka said:

Question (1):  is an average current of ~85 microamps indicative of an nRF9180 SICA B1A running with all UARTs and high speed clocks off?

Yes, if UART RX or HF clocks were running, you should see a power draw of >500uA.

tedhavelka said:

Question (3) - When firmware enables PSM mode in the nRF9160 modem, is the "wake period + sleep period" entered immediately?

Question (4) - When the new PSM times are configured, does the PSM mode begin by keep the modem on for its active period, or does it begin by keeping the modem in power savings mode for its suspended, low power period?  E.g. which part of the power cycle occurs first?

To send data, or communicate with the network, you need an RRC connection. How long you stay in RRC Connected mode depends on the network. After the RRC connection has been inactive for a while, the device is released from the RRC connection and enters RRC Idle mode. How long you stay here depends on the Active Time, and how often you must listen for incomming data depends on the eDRX settings. After the Active Time finishes, the device enters PSM and turn the radio completely off.

tedhavelka said:

Question (2)  is there a clue in the current spikes, appearing at about 25Hz, and intermittently peaking at 4mA and alternately 0.5mA?  Any part of SICA B1A hardware consume power in this way?

I'll have to come back to you on this.

[tedhavelka]

Good morning Didrik,

Thank you for fast reply to my latest questions on nRF9160 current draw and PSM active and inactive periods.  To clarify my first question from above, can I be confident that I have correctly powered down all high frequency clocks in the 9160 SiP when I measure only 65 microamps to 85 microamps average current draw over a minute's time?

I'll watch for further help on the question of the roughly 25Hz current use spike activity.

- Ted

[Didrik Rokhaug]

tedhavelka said:

To clarify my first question from above, can I be confident that I have correctly powered down all high frequency clocks in the 9160 SiP when I measure only 65 microamps to 85 microamps average current draw over a minute's time?

Yes, they are not running. If they had been running the high frequency clocks would have drawn more current.

tedhavelka said:

I'll watch for further help on the question of the roughly 25Hz current use spike activity.

I've talked with one of our current consumption experts, and he's ideas was that it could be either GPIOTE IN event (edge detection on a GPIO pin), or the UART ENABLE base current (with RX disabled).

Looking at the UART driver implementation, it looks like the driver disables the peripheral properly, so I don't think the current draw comes from there. However, the GPIO edge detection might have been set up by one of the sensor drivers you have included in your project.

Also, looking at the code of the drivers, it looks like both can create a thread, without giving it a name, if CONFIG_<sensor>_TRIGGER_OWN_THREAD is set. Is either of those two configs set in your project?

Also, did you meassure the current draw of the .hex file in the current meassurement blog post?

You can also use the blinky sample with CONFIG_SERIAL=n to verify your current meassurement setup. By running an application with a known current consumption on the nRF9160, we can see check if the extra current consumption comes from somewhere else on the board.