Issues with configuring PSM on the nRF9160

[Tester013]

I'm currently attempting to get the nRF 9160 to enter PSM mode when not transmitting along with the asset_tracker_v2 application just so we can do some power consumption measurements for the 9160. However, I'm running into an issue where the nRF9160 seems to stop transmitting to nRF Cloud whenever I've set up the PSM mode.

To enable PSM mode I've included lte_lc_psm_req(true); in main.c. I've also tried an alternative implementation by defining the following function and calling setup_psm(); in the main, to the same effect.

void setup_psm(void)
{
	char psm_settings[] = CONFIG_LTE_PSM_REQ_RPTAU;
	printk("PSM bits: %c%c%c\n", psm_settings[0], psm_settings[1],
	       psm_settings[2]);
	printk("PSM Interval: %c%c%c%c%c\n", psm_settings[3], psm_settings[4],
	       psm_settings[5], psm_settings[6], psm_settings[7]);
	int err = lte_lc_psm_req(true);
	if (err < 0) {
		printk("Error setting PSM: %d Errno: %d\n", err, errno);
	}
}

The following is the output on the terminal when I run the modified asset_tracker_v2 application:

*** Booting Zephyr OS build v3.0.99-ncs1  ***

Attempting to boot slot 0.

Attempting to boot from address 0x8200.

Verifying signature against key 0.

Hash: 0x0c...0d

Firmware signature verified.

Firmware version 1

Booting (0x8200).

*** Booting Zephyr OS build v3.0.99-ncs1  ***

I: Starting bootloader

I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3

I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3

I: Boot source: none

I: Swap type: none

I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3

I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3

I: Boot source: none

I: Swap type: none

I: Bootloader chainload address offset: 0x28000

I: Jumping to the first image slot

*** Booting Zephyr OS build v3.0.99-ncs1  ***

APPLICATION START!

[00:00:00.508,209] 



[1;31m<err> settings: set-value failure. key: data_module/config error(40)



[0m

[00:00:00.516,876] 



[0m<inf> app_event_manager: APP_EVT_START



[0m

[00:00:00.517,700] 



[0m<inf> app_event_manager: DATA_EVT_CONFIG_INIT



[0m

[00:00:00.518,218] 



[0m<inf> app_event_manager: APP_EVT_ACTIVITY_DETECTION_DISABLE



[0m

[00:00:00.573,120] 



[0m<inf> app_event_manager: MODEM_EVT_LTE_CONNECTING



[0m

%CESQ: 57,2,8,1

+CEREG: 2,"2042","00378F1E",7

+CSCON: 1

%CESQ: 52,2,11,1

[00:00:03.878,112] 



[0m<inf> app_event_manager: MODEM_EVT_LTE_DISCONNECTED



[0m

[00:00:03.878,692] 



[0m<inf> app_event_manager: MODEM_EVT_LTE_CELL_UPDATE



[0m

%XTIME: ,"22708190509240","01"

%MDMEV: SEARCH STATUS 2

+CEREG: 5,"2042","00378F1E",7,,,"11100000","11100000"

AT+COPS=3,2

OK

AT+COPS?

+COPS: 0,2,"23415",7

OK

AT%XCBAND

%XCBAND: 20

OK

AT+CGDCONT?

+CGDCONT: 0,"IP","wlapn.com","10.111.7.191",0,0

OK

AT+CGACT?

+CGACT: 0,1

OK

[00:00:04.906,524] 



[0m<inf> app_event_manager: DATA_EVT_DATE_TIME_OBTAINED



[0m

[00:00:05.326,995] 



[0m<inf> app_event_manager: MODEM_EVT_LTE_CONNECTED



[0m

[00:00:05.327,575] 



[0m<inf> app_event_manager: MODEM_EVT_LTE_PSM_UPDATE



[0m

[00:00:05.328,857] 



[1;33m<wrn> cloud_module: Cloud connection establishment in progress



[0m

[00:00:05.328,887] 



[1;33m<wrn> cloud_module: New connection attempt in 32 seconds if not successful



[0m

[00:00:05.329,040] 



[0m<inf> app_event_manager: CLOUD_EVT_CONNECTING



[0m

[00:00:09.040,008] 



[0m<inf> app_event_manager: CLOUD_EVT_CONFIG_RECEIVED



[0m

[00:00:09.047,302] 



[0m<inf> app_event_manager: DATA_EVT_CONFIG_SEND



[0m

[00:00:09.048,034] 



[0m<inf> app_event_manager: CLOUD_EVT_DATA_SEND_QOS



[0m

[00:00:09.829,315] 



[0m<inf> app_event_manager: CLOUD_EVT_CONNECTED



[0m

[00:00:09.830,505] 



[0m<inf> app_event_manager: APP_EVT_DATA_GET - Requested data types (MOD_DYN, BAT, ENV, NEIGHBOR_CELLS, MOD_STAT)



[0m

[00:00:09.832,061] 



[0m<inf> app_event_manager: SENSOR_EVT_ENVIRONMENTAL_NOT_SUPPORTED



[0m

[00:00:09.940,216] 



[0m<inf> app_event_manager: MODEM_EVT_MODEM_STATIC_DATA_READY



[0m

[00:00:09.991,821] 



[0m<inf> app_event_manager: MODEM_EVT_MODEM_DYNAMIC_DATA_READY



[0m

%NCELLMEAS: 0,"00378F1E","23415","2042",64,6300,104,57,13,9585,6300,103,59,16,0,9453

[00:00:10.105,285] 



[0m<inf> app_event_manager: MODEM_EVT_BATTERY_DATA_READY



[0m

[00:00:10.115,173] 



[0m<inf> app_event_manager: MODEM_EVT_NEIGHBOR_CELLS_DATA_READY



[0m

[00:00:10.116,088] 



[0m<inf> app_event_manager: DATA_EVT_DATA_READY



[0m

[00:00:10.120,391] 



[0m<inf> app_event_manager: DATA_EVT_NEIGHBOR_CELLS_DATA_SEND



[0m

[00:00:10.130,828] 



[0m<inf> app_event_manager: DATA_EVT_DATA_SEND_BATCH



[0m

[00:00:10.131,591] 



[0m<inf> app_event_manager: CLOUD_EVT_DATA_SEND_QOS



[0m

[00:00:10.131,866] 



[0m<inf> app_event_manager: CLOUD_EVT_DATA_SEND_QOS



[0m

%CESQ: 50,2,16,2

%CESQ: 48,2,11,1

%NCELLMEAS: 0,"00378F1E","23415","2042",65,6300,104,56,9,30057,6300,103,58,14,0,26955

[00:00:30.518,280] 



[0m<inf> app_event_manager: APP_EVT_DATA_GET_ALL



[0m

[00:00:30.518,951] 



[0m<inf> app_event_manager: APP_EVT_DATA_GET - Requested data types (MOD_DYN, BAT, ENV, NEIGHBOR_CELLS, GNSS)



[0m

[00:00:30.519,866] 



[0m<inf> app_event_manager: SENSOR_EVT_ENVIRONMENTAL_NOT_SUPPORTED



[0m

[00:00:30.576,690] 



[0m<inf> app_event_manager: MODEM_EVT_MODEM_DYNAMIC_DATA_READY



[0m

[00:00:30.656,005] 



[0m<inf> app_event_manager: MODEM_EVT_BATTERY_DATA_READY



[0m

[00:00:30.672,119] 



[0m<inf> app_event_manager: MODEM_EVT_NEIGHBOR_CELLS_DATA_READY



[0m

%CESQ: 46,2,6,0

+CSCON: 0

%CESQ: 57,2,14,2

+CEREG: 5,"2042","00378F14",7,,,"11100000","11100000"

AT+COPS=3,2

OK

AT+COPS?

+COPS: 0,2,"23415",7

OK

AT%XCBAND

%XCBAND: 20

OK

%CESQ: 52,2,13,1

AT+CGDCONT?

+CGDCONT: 0,"IP","wlapn.com","10.111.7.191",0,0

OK

AT+CGACT?

+CGACT: 0,1

OK

[00:00:38.913,330] 



[0m<inf> app_event_manager: MODEM_EVT_LTE_CELL_UPDATE



[0m

%NCELLMEAS: 0,"00378F14","23415","2042",65535,6300,103,55,11,59676,0

[00:01:00.518,280] 



[0m<inf> app_event_manager: APP_EVT_DATA_GET_ALL



[0m

[00:01:00.518,951] 



[0m<inf> app_event_manager: APP_EVT_DATA_GET - Requested data types (MOD_DYN, BAT, ENV, NEIGHBOR_CELLS, GNSS)



[0m

[00:01:00.519,805] 



[0m<inf> app_event_manager: SENSOR_EVT_ENVIRONMENTAL_NOT_SUPPORTED



[0m

[00:01:00.600,769] 



[0m<inf> app_event_manager: MODEM_EVT_MODEM_DYNAMIC_DATA_READY



[0m

[00:01:00.673,858] 



[0m<inf> app_event_manager: MODEM_EVT_BATTERY_DATA_READY



[0m

[00:01:00.688,293] 



[0m<inf> app_event_manager: MODEM_EVT_NEIGHBOR_CELLS_DATA_READY



[0m

%CESQ: 53,2,8,1

%CESQ: 53,2,13,1

%NCELLMEAS: 0,"00378F14","23415","2042",65535,6300,103,53,17,89756,0

[00:01:30.518,280] 



[0m<inf> app_event_manager: APP_EVT_DATA_GET_ALL



[0m

[00:01:30.518,951] 



[0m<inf> app_event_manager: APP_EVT_DATA_GET - Requested data types (MOD_DYN, BAT, ENV, NEIGHBOR_CELLS, GNSS)



[0m

[00:01:30.519,805] 



[0m<inf> app_event_manager: SENSOR_EVT_ENVIRONMENTAL_NOT_SUPPORTED



[0m

[00:01:30.600,036] 



[0m<inf> app_event_manager: MODEM_EVT_MODEM_DYNAMIC_DATA_READY



[0m

[00:01:30.679,443] 



[0m<inf> app_event_manager: MODEM_EVT_BATTERY_DATA_READY



[0m

[00:01:30.693,054] 



[0m<inf> app_event_manager: MODEM_EVT_NEIGHBOR_CELLS_DATA_READY



[0m

%CESQ: 53,2,18,2

%CESQ: 53,2,13,1

%NCELLMEAS: 0,"00378F14","23415","2042",65535,6300,103,52,15,119836,0

[00:02:00.518,280] 



[0m<inf> app_event_manager: APP_EVT_DATA_GET_ALL



[0m

[00:02:00.518,951] 



[0m<inf> app_event_manager: APP_EVT_DATA_GET - Requested data types (MOD_DYN, BAT, ENV, NEIGHBOR_CELLS, GNSS)



[0m

[00:02:00.519,805] 



[0m<inf> app_event_manager: SENSOR_EVT_ENVIRONMENTAL_NOT_SUPPORTED



[0m

[00:02:00.600,250] 



[0m<inf> app_event_manager: MODEM_EVT_MODEM_DYNAMIC_DATA_NOT_READY



[0m

[00:02:00.673,309] 



[0m<inf> app_event_manager: MODEM_EVT_BATTERY_DATA_READY



[0m

[00:02:00.687,896] 



[0m<inf> app_event_manager: MODEM_EVT_NEIGHBOR_CELLS_DATA_READY



[0m

%CESQ: 51,2,8,1

%NCELLMEAS: 0,"00378F14","23415","2042",65535,6300,103,51,9,149916,0

[00:02:30.518,280] 



[0m<inf> app_event_manager: APP_EVT_DATA_GET_ALL



[0m

[00:02:30.518,951] 



[0m<inf> app_event_manager: APP_EVT_DATA_GET - Requested data types (MOD_DYN, BAT, ENV, NEIGHBOR_CELLS, GNSS)



[0m

[00:02:30.519,805] 



[0m<inf> app_event_manager: SENSOR_EVT_ENVIRONMENTAL_NOT_SUPPORTED



[0m

[00:02:30.606,384] 



[0m<inf> app_event_manager: MODEM_EVT_MODEM_DYNAMIC_DATA_READY



[0m

[00:02:30.673,339] 



[0m<inf> app_event_manager: MODEM_EVT_BATTERY_DATA_READY



[0m

[00:02:30.687,744] 



[0m<inf> app_event_manager: MODEM_EVT_NEIGHBOR_CELLS_DATA_READY



[0m

%CESQ: 51,2,13,1

%CESQ: 46,2,9,1

%CESQ: 48,2,3,0

%NCELLMEAS: 0,"00378F14","23415","2042",65535,6300,103,48,6,179996,0

%CESQ: 48,2,8,1

active_wait_timeout is currently set to be 30 seconds

The PSM TAU setting is 10000001 and the requested active time is 00100001.

[Elfving]

Tester013 said:

and from the CEREG, it would seem that PSM is working correctly..? 

Where are you seeing this? To me it seems that it is still not enabling it as "11100000","11100000" is still a zero.

Tester013 said:

I wanted to try a shorter interval so I didn't have to wait around for 10 minutes to see if PSM had indeed been enabled. 

You don't have to wait it out, you can just check it with these AT commands. 

Could you try to increase it even more, to lets say 320H. Just to check if that makes a difference. 

Regards,

Elfving

[Tester013]

Hi, after double checking, it would seem that I've been using LTE-M, which I'm assuming does not support PSM mode? 

In any case, I updated my configuration file to use NB_IoT and set the PSM interval to 320H as per your instructions. Running the AT+CEREG? command, the TAU time seems to match the value requested from AT+CPSMS? but the active time is different. Could this be due to the network?

*** Booting Zephyr OS build v3.0.99-ncs1  ***
I: Starting bootloader
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Swap type: none
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Swap type: none
I: Bootloader chainload address offset: 0x28000
I: Jumping to the first image slot
*** Booting Zephyr OS build v3.0.99-ncs1  ***
APPLICATION START! 
PSM bits: 110
PSM Interval: 00001
PSM Set Up! 
[00:00:00.518,585] 

[0m<inf> app_event_manager: APP_EVT_START

[0m
[00:00:00.578,369] 

[0m<inf> app_event_manager: MODEM_EVT_LTE_CONNECTING

[0m
[00:00:01.511,108] 

[1;33m<wrn> data_module: Active wait timeout: 600

[0m
[00:00:01.511,199] 

[1;33m<wrn> data_module: Active wait timeout: 600

[0m
[00:00:01.511,230] 

[1;33m<wrn> data_module: Movement resolution: 120

[0m
[00:00:01.511,230] 

[1;33m<wrn> data_module: Movement timeout: 3600

[0m
[00:00:01.511,260] 

[1;33m<wrn> data_module: GPS timeout: 60

[0m
[00:00:01.511,260] 

[1;33m<wrn> data_module: Accelerometer threshold: 10.00

[0m
[00:00:01.511,352] 

[0m<inf> app_event_manager: DATA_EVT_CONFIG_INIT

[0m
[00:00:01.511,871] 

[0m<inf> app_event_manager: APP_EVT_ACTIVITY_DETECTION_DISABLE

[0m
%CESQ: 49,2,23,3
+CEREG: 2,"242A","00378F15",9
+CSCON: 1
%CESQ: 50,2,28,4
[00:00:06.054,382] 

[0m<inf> app_event_manager: MODEM_EVT_LTE_DISCONNECTED

[0m
[00:00:06.055,023] 

[0m<inf> app_event_manager: MODEM_EVT_LTE_CELL_UPDATE

[0m
%MDMEV: SEARCH STATUS 2
+CEREG: 5,"242A","00378F15",9,,,"00011110","11000001"
AT+COPS=3,2
OK
%XTIME: ,"22708290543480","01"
AT+COPS?
+COPS: 0,2,"23415",9
OK
AT%XCBAND
%XCBAND: 20
OK
AT+CGDCONT?
+CGDCONT: 0,"IP","wlapn.com","10.111.7.191",0,0
OK
AT+CGACT?
+CGACT: 0,1
OK
[00:00:08.025,085] 

[0m<inf> app_event_manager: MODEM_EVT_LTE_CONNECTED

[0m
[00:00:08.025,726] 

[0m<inf> app_event_manager: MODEM_EVT_LTE_PSM_UPDATE

[0m
[00:00:08.027,069] 

[1;33m<wrn> cloud_module: Cloud connection establishment in progress

[0m
[00:00:08.027,099] 

[1;33m<wrn> cloud_module: New connection attempt in 32 seconds if not successful

[0m
[00:00:08.027,252] 

[0m<inf> app_event_manager: CLOUD_EVT_CONNECTING

[0m
[00:00:08.043,487] 

[0m<inf> app_event_manager: DATA_EVT_DATE_TIME_OBTAINED

[0m
%CESQ: 49,2,23,3
%CESQ: 51,2,28,4
[00:00:20.077,026] 

[0m<inf> app_event_manager: CLOUD_EVT_CONFIG_RECEIVED

[0m
[00:00:20.084,350] 

[0m<inf> app_event_manager: DATA_EVT_CONFIG_SEND

[0m
[00:00:20.085,083] 

[0m<inf> app_event_manager: CLOUD_EVT_DATA_SEND_QOS

[0m
[00:00:21.578,857] 

[0m<inf> app_event_manager: CLOUD_EVT_CONNECTED

[0m
[00:00:21.580,047] 

[0m<inf> app_event_manager: APP_EVT_DATA_GET - Requested data types (MOD_DYN, BAT, ENV, NEIGHBOR_CELLS, MOD_STAT)

[0m
[00:00:21.581,604] 

[0m<inf> app_event_manager: SENSOR_EVT_ENVIRONMENTAL_DATA_READY

[0m
[00:00:21.585,662] 

[0m<dbg> modem_info: parse_ip_addresses: Device has 1 IP addresses

[0m
[00:00:21.585,937] 

[0m<dbg> modem_info: parse_ip_addresses: IP address found: 10.111.7.191

[0m
[00:00:21.586,914] 

[0m<dbg> modem_info: parse_ip_addresses: Device has 1 IP addresses

[0m
[00:00:21.587,188] 

[0m<dbg> modem_info: parse_ip_addresses: IP address found: 10.111.7.191

[0m
[00:00:21.689,422] 

[0m<inf> app_event_manager: MODEM_EVT_MODEM_STATIC_DATA_READY

[0m
[00:00:21.692,413] 

[0m<dbg> modem_info: parse_ip_addresses: Device has 1 IP addresses

[0m
[00:00:21.692,687] 

[0m<dbg> modem_info: parse_ip_addresses: IP address found: 10.111.7.191

[0m
[00:00:21.740,020] 

[0m<inf> app_event_manager: MODEM_EVT_MODEM_DYNAMIC_DATA_READY

[0m
%NCELLMEAS: 0,"00378F15","23415","242A",48,6254,103,52,27,21291,21244
[00:00:21.834,381] 

[0m<dbg> modem_info: parse_ip_addresses: Device has 1 IP addresses

[0m
[00:00:21.834,686] 

[0m<dbg> modem_info: parse_ip_addresses: IP address found: 10.111.7.191

[0m
[00:00:21.881,835] 

[0m<inf> app_event_manager: MODEM_EVT_BATTERY_DATA_READY

[0m
[00:00:21.890,502] 

[0m<inf> app_event_manager: MODEM_EVT_NEIGHBOR_CELLS_DATA_READY

[0m
[00:00:21.891,387] 

[0m<inf> app_event_manager: DATA_EVT_DATA_READY

[0m
[00:00:21.894,531] 

[0m<inf> app_event_manager: DATA_EVT_NEIGHBOR_CELLS_DATA_SEND

[0m
[00:00:21.897,003] 

[1;31m<err> cloud_codec: Value of button is 0 

[0m
[00:00:21.897,033] 

[1;31m<err> cloud_codec: Value of button is 0 

[0m
[00:00:21.897,094] 

[1;31m<err> cloud_codec: Value of button is 0 

[0m
[00:00:21.914,672] 

[0m<inf> app_event_manager: DATA_EVT_DATA_SEND_BATCH

[0m
[00:00:21.915,435] 

[0m<inf> app_event_manager: CLOUD_EVT_DATA_SEND_QOS

[0m
[00:00:21.915,740] 

[0m<inf> app_event_manager: CLOUD_EVT_DATA_SEND_QOS

[0m
%CESQ: 50,2,23,3
AT+CPSMS?
+CPSMS: 1,,,"11000001","00100001"
OK
%CESQ: 51,2,28,4
AT+CEREG?
+CEREG: 5,5,"242A","00378F15",9,,,"00011110","11000001"
OK
AT+COPS=3,2
OK
AT+COPS?
+COPS: 0,2,"23415",9
OK
AT%XCBAND
%XCBAND: 20
OK
AT+CGDCONT?
+CGDCONT: 0,"IP","wlapn.com","10.111.7.191",0,0
OK
AT+CGACT?
+CGACT: 0,1
OK
+CSCON: 0
%CESQ: 50,2,23,3
%CESQ: 50,2,28,4

[Elfving]

I think LTE-M should support PSM mode as well, this is something you will have to take with your network provider.

Yeah it might be that the network is giving you other values than the requested, though it should give you the highest it allows.

Could you also confirm these values using XMONITOR though?

Regards,

Elfving