• State Not Answered
  • Replies 12 replies
  • Subscribers 75 subscribers
  • Views 2823 views
  • Users 0 members are here
Attachments (2) Download All
Nordic Case Info
  • Case ID: 243330
Options
This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

nrf9160 MQTT delay / network problem?

torgil

I see unexpected delays when running MQTT sample. The issue seems to be network related. When connecting delay is "normal" but after a few seconds roundtrip delay increases. Probably network related? Using Telia  in Sweden.

2020-01-28 09:07:04.386316 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [.], ack 22, win 29200, length 0
2020-01-28 09:07:04.386642 IP 10.1.0.21.1883 > 193.181.245.212.40707: Flags [FP.], seq 39:41, ack 52, win 29200, length 2
2020-01-28 09:07:04.386751 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 1:5, ack 22, win 29200, length 4
2020-01-28 09:07:05.018045 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [.], ack 10, win 4239, length 0
2020-01-28 09:07:06.068864 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 10:39, ack 50, win 29200, length 29
2020-01-28 09:07:06.226137 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [P.], seq 50:75, ack 39, win 4210, length 25
2020-01-28 09:07:06.264280 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [.], ack 75, win 29200, length 0
2020-01-28 09:07:06.372303 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [P.], seq 75:79, ack 39, win 4210, length 4
2020-01-28 09:07:06.372336 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [.], ack 79, win 29200, length 0
2020-01-28 09:07:06.372463 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 39:43, ack 79, win 29200, length 4
2020-01-28 09:07:06.772095 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [.], ack 43, win 4206, length 0
2020-01-28 09:07:07.368346 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 43:72, ack 79, win 29200, length 29
2020-01-28 09:07:07.506123 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [P.], seq 79:104, ack 72, win 4177, length 25
2020-01-28 09:07:07.544271 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [.], ack 104, win 29200, length 0
2020-01-28 09:07:07.658183 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [P.], seq 104:108, ack 72, win 4177, length 4
2020-01-28 09:07:07.658222 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [.], ack 108, win 29200, length 0
2020-01-28 09:07:07.658303 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 72:76, ack 108, win 29200, length 4
2020-01-28 09:07:08.376324 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 72:76, ack 108, win 29200, length 4
2020-01-28 09:07:09.820274 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 72:76, ack 108, win 29200, length 4
2020-01-28 09:07:12.708309 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 72:76, ack 108, win 29200, length 4
2020-01-28 09:07:18.484299 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 72:76, ack 108, win 29200, length 4
2020-01-28 09:07:23.332201 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [.], ack 76, win 4173, length 0
2020-01-28 09:07:23.332244 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 76:105, ack 108, win 29200, length 29
2020-01-28 09:07:23.506144 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [P.], seq 108:133, ack 105, win 4144, length 25
2020-01-28 09:07:23.544256 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [.], ack 133, win 29200, length 0
2020-01-28 09:07:23.652238 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [P.], seq 133:137, ack 105, win 4144, length 4
2020-01-28 09:07:23.652270 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [.], ack 137, win 29200, length 0
2020-01-28 09:07:23.652349 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 105:109, ack 137, win 29200, length 4
2020-01-28 09:07:23.812136 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [.], ack 109, win 4140, length 0
2020-01-28 09:07:26.006977 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 109:138, ack 137, win 29200, length 29
2020-01-28 09:07:26.138150 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [P.], seq 137:162, ack 138, win 4111, length 25
2020-01-28 09:07:26.176304 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [.], ack 162, win 29200, length 0
2020-01-28 09:07:26.292114 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [P.], seq 162:166, ack 138, win 4111, length 4
2020-01-28 09:07:26.292160 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [.], ack 166, win 29200, length 0
2020-01-28 09:07:26.292288 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 138:142, ack 166, win 29200, length 4
2020-01-28 09:07:26.532227 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [.], ack 142, win 4107, length 0
2020-01-28 09:07:29.011125 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 142:171, ack 166, win 29200, length 29
2020-01-28 09:07:29.592270 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 142:171, ack 166, win 29200, length 29
2020-01-28 09:07:30.764299 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 142:171, ack 166, win 29200, length 29
2020-01-28 09:07:33.108265 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 142:171, ack 166, win 29200, length 29
2020-01-28 09:07:37.796318 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 142:171, ack 166, win 29200, length 29
2020-01-28 09:07:47.172264 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 142:171, ack 166, win 29200, length 29
2020-01-28 09:08:05.924282 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [P.], seq 142:171, ack 166, win 29200, length 29
2020-01-28 09:08:39.972991 IP 193.181.245.194.34634 > 10.1.0.21.1883: Flags [P.], seq 166:168, ack 142, win 4107, length 2
2020-01-28 09:08:40.012260 IP 10.1.0.21.1883 > 193.181.245.194.34634: Flags [.], ack 168, win 29200, length 0

A TCP trace shows lots of retries:

[2020-01-28 09:05:12.327492] tests/subscribe/topic test
[2020-01-28 09:07:06.069478] tests/subscribe/topic test
[2020-01-28 09:07:06.372625] tests/publish/topic test
[2020-01-28 09:07:07.368836] tests/subscribe/topic test
[2020-01-28 09:07:07.658487] tests/publish/topic test
[2020-01-28 09:07:08.659070] tests/subscribe/topic test
[2020-01-28 09:07:23.652455] tests/publish/topic test
[2020-01-28 09:07:26.007115] tests/subscribe/topic test
[2020-01-28 09:07:26.292424] tests/publish/topic test
[2020-01-28 09:07:29.011263] tests/subscribe/topic test

Any idea whats going on here?

The MQTT simple sample startedLTE Link Connecting ...+CEREG: 2,"0093","018D2B20",7,0,0,"11100000","11100000"+CEREG: 5,"0093","018D2B20",7,,,"11100000","11100000"LTE Link Connected!AT+COPS=3,2OKAT+COPS?+COPS: 0,2,"24001",7OKAT%XCBAND%XCBAND: 20OKAT+CGDCONT?IPv4 Address found 91.106.198.236+CGDCONT: 0,"IP","lpwa.telia.iot","10.81.186.2",0,0OKAT+CGACT?+CGACT: 0,1OK[mqtt_evt_handler:190] MQTT client connected!Subscribing to: tests/subscribe/topic len 21[mqtt_evt_handler:240] SUBACK packet id: 1234[mqtt_evt_handler:205] MQTT PUBLISH result=0 len=4Received: testPublishing: testto topic: tests/publish/topic len: 19[mqtt_evt_handler:230] PUBACK packet id: 50480[mqtt_evt_handler:205] MQTT PUBLISH result=0 len=4Received: testPublishing: testto topic: tests/publish/topic len: 19[mqtt_evt_handler:230] PUBACK packet id: 26790[mqtt_evt_handler:205] MQTT PUBLISH result=0 len=4Received: testPublishing: testto topic: tests/publish/topic len: 19[mqtt_evt_handler:230] PUBACK packet id: 25677[mqtt_evt_handler:205] MQTT PUBLISH result=0 len=4Received: testPublishing: testto topic: tests/publish/topic len: 19[mqtt_evt_handler:230] PUBACK packet id: 48551

Parents
  • 0

    A more detailed output with timing. After successful boot and connection the button on the DK board is pressed at 14:13:57.444. The published message is recieved by the server at 14:14:15.105028. A delay of about 18 seconds.

    Publishing a message to to the "subscribed" topic is done at 14:14:26.688523. This message is recieved at the DK board at 14:15:25.397 (almost 60 sekunds later) and the replay is sent right away and recieved at the server one second later. 

    Any ideas or good explanations for this behaviour?

    [2020-01-28 14:13:35.797] *** Booting Zephyr OS version 2.1.0  ***
[2020-01-28 14:13:35.800] The MQTT simple sample started
[2020-01-28 14:13:35.809] LTE Link Connecting ...
[2020-01-28 14:13:50.807] +CEREG: 2,"0324","018D2920",7,0,0,"11100000","11100000"
[2020-01-28 14:13:52.264] +CEREG: 5,"0324","018D2920",7,,,"11100000","11100000"
[2020-01-28 14:13:52.266] LTE Link Connected!
[2020-01-28 14:13:52.460] IPv4 Address found 91.106.198.236
[2020-01-28 14:13:52.758] [mqtt_evt_handler:192] MQTT client connected!
[2020-01-28 14:13:52.762] Subscribing to: tests/subscribe/topic len 21
[2020-01-28 14:13:52.897] [mqtt_evt_handler:242] SUBACK packet id: 1234
[2020-01-28 14:13:57.444] button_handler
[2020-01-28 14:13:57.447] Publishing: button handler
[2020-01-28 14:13:57.450] to topic: tests/publish/topic len: 19
[2020-01-28 14:13:57.624] button_handler
[2020-01-28 14:13:57.626] Publishing: button handler
[2020-01-28 14:13:57.630] to topic: tests/publish/topic len: 19
[2020-01-28 14:14:08.771] +CEREG: 5,"0093","018D2B20",7,,,"11100000","11100000"
[2020-01-28 14:14:14.88] [mqtt_evt_handler:232] PUBACK packet id: 60274
[2020-01-28 14:14:14.588] [mqtt_evt_handler:232] PUBACK packet id: 620
[2020-01-28 14:15:25.396] [mqtt_evt_handler:207] MQTT PUBLISH result=0 len=4
[2020-01-28 14:15:25.397] Received: test
[2020-01-28 14:15:25.399] Publishing: test
[2020-01-28 14:15:25.430] to topic: tests/publish/topic len: 19
[2020-01-28 14:15:25.946] [mqtt_evt_handler:232] PUBACK packet id: 58750


    [2020-01-28 14:14:15.105028] tests/publish/topic button handler
[2020-01-28 14:14:15.105123] tests/publish/topic button handler
[2020-01-28 14:14:26.688523] tests/subscribe/topic test
[2020-01-28 14:15:26.697140] tests/publish/topic test

Reply
  • 0

    A more detailed output with timing. After successful boot and connection the button on the DK board is pressed at 14:13:57.444. The published message is recieved by the server at 14:14:15.105028. A delay of about 18 seconds.

    Publishing a message to to the "subscribed" topic is done at 14:14:26.688523. This message is recieved at the DK board at 14:15:25.397 (almost 60 sekunds later) and the replay is sent right away and recieved at the server one second later. 

    Any ideas or good explanations for this behaviour?

    [2020-01-28 14:13:35.797] *** Booting Zephyr OS version 2.1.0  ***
[2020-01-28 14:13:35.800] The MQTT simple sample started
[2020-01-28 14:13:35.809] LTE Link Connecting ...
[2020-01-28 14:13:50.807] +CEREG: 2,"0324","018D2920",7,0,0,"11100000","11100000"
[2020-01-28 14:13:52.264] +CEREG: 5,"0324","018D2920",7,,,"11100000","11100000"
[2020-01-28 14:13:52.266] LTE Link Connected!
[2020-01-28 14:13:52.460] IPv4 Address found 91.106.198.236
[2020-01-28 14:13:52.758] [mqtt_evt_handler:192] MQTT client connected!
[2020-01-28 14:13:52.762] Subscribing to: tests/subscribe/topic len 21
[2020-01-28 14:13:52.897] [mqtt_evt_handler:242] SUBACK packet id: 1234
[2020-01-28 14:13:57.444] button_handler
[2020-01-28 14:13:57.447] Publishing: button handler
[2020-01-28 14:13:57.450] to topic: tests/publish/topic len: 19
[2020-01-28 14:13:57.624] button_handler
[2020-01-28 14:13:57.626] Publishing: button handler
[2020-01-28 14:13:57.630] to topic: tests/publish/topic len: 19
[2020-01-28 14:14:08.771] +CEREG: 5,"0093","018D2B20",7,,,"11100000","11100000"
[2020-01-28 14:14:14.88] [mqtt_evt_handler:232] PUBACK packet id: 60274
[2020-01-28 14:14:14.588] [mqtt_evt_handler:232] PUBACK packet id: 620
[2020-01-28 14:15:25.396] [mqtt_evt_handler:207] MQTT PUBLISH result=0 len=4
[2020-01-28 14:15:25.397] Received: test
[2020-01-28 14:15:25.399] Publishing: test
[2020-01-28 14:15:25.430] to topic: tests/publish/topic len: 19
[2020-01-28 14:15:25.946] [mqtt_evt_handler:232] PUBACK packet id: 58750


    [2020-01-28 14:14:15.105028] tests/publish/topic button handler
[2020-01-28 14:14:15.105123] tests/publish/topic button handler
[2020-01-28 14:14:26.688523] tests/subscribe/topic test
[2020-01-28 14:15:26.697140] tests/publish/topic test

Children
No Data
Related
Terms of service