Hi
I'm using the 'MQTT C Client for Posix and Windows' to implement a MQTT-SN gateway on a raspberry pi. I use the approach where each MQTT-SN creates it own MQTT connection. Therefore I have multiple MQTT.C clients in the same process. Each MQTT.C is accessed by its own thread, so a MQTT.C instance is only accessed by one thread but the different instances are accessed by different threads. Is this valid or does this require some synchronization?
My problem is that I observe a strange behavior when I have 3 and more connections/clients: After some time (between 1 hour or 2 days) the 'MQTTClient_run' thread starts to use nearly all the CPU:
htop:
5632 root 20 0 71348 2340 1860 S 95.0 0.5 38:07.19 │ └─ /home/pi/Code/Run/BtMqttSnGateway /home/pi/Code/Run/bt_gw_settings.xml
5669 root 20 0 71348 2340 1860 S 0.0 0.5 0:00.46 │ ├─ /home/pi/Code/Run/BtMqttSnGateway /home/pi/Code/Run/bt_gw_settings.xml
5651 root 20 0 71348 2340 1860 S 0.0 0.5 0:00.68 │ ├─ /home/pi/Code/Run/BtMqttSnGateway /home/pi/Code/Run/bt_gw_settings.xml
5650 root 20 0 71348 2340 1860 R 95.0 0.5 38:00.80 │ ├─ /home/pi/Code/Run/BtMqttSnGateway /home/pi/Code/Run/bt_gw_settings.xml
5649 root 20 0 71348 2340 1860 S 0.0 0.5 0:00.67 │ ├─ /home/pi/Code/Run/BtMqttSnGateway /home/pi/Code/Run/bt_gw_settings.xml
5648 root 20 0 71348 2340 1860 S 0.0 0.5 0:00.55 │ ├─ /home/pi/Code/Run/BtMqttSnGateway /home/pi/Code/Run/bt_gw_settings.xml
5647 root 20 0 71348 2340 1860 S 0.0 0.5 0:00.00 │ ├─ /home/pi/Code/Run/BtMqttSnGateway /home/pi/Code/Run/bt_gw_settings.xml
5646 root 20 0 71348 2340 1860 R 0.0 0.5 0:00.50 │ ├─ /home/pi/Code/Run/BtMqttSnGateway /home/pi/Code/Run/bt_gw_settings.xml
5636 root 20 0 71348 2340 1860 S 0.0 0.5 0:03.18 │ └─ /home/pi/Code/Run/BtMqttSnGateway /home/pi/Code/Run/bt_gw_settings.xml
gdb:
(gdb) thread
[Current thread is 7 (Thread 0xb4509460 (LWP 5650))]
(gdb) bt
#0 0xb6d956ec in gettimeofday () at ../sysdeps/unix/syscall-template.S:82
#1 0x00085d3c in Log_pretrace () at source/lib/Mqtt.C/src/Log.c:243
#2 0x0008658c in Log_stackTrace (log_level=3, msgno=9, thread_id=-1269787552, current_depth=3, name=0x93f08 "isReady", line=192, rc=0x0) at source/lib/Mqtt.C/src/Log.c:443
#3 0x00082ac0 in StackTrace_entry (name=0x93f08 "isReady", line=192, trace_level=3) at source/lib/Mqtt.C/src/StackTrace.c:107
#4 0x0007ffe8 in isReady (socket=11, read_set=0x12863c, write_set=0xaac5c) at source/lib/Mqtt.C/src/Socket.c:192
#5 0x00080404 in Socket_getReadySocket (more_work=0, tp=0xb4508d88) at source/lib/Mqtt.C/src/Socket.c:268
#6 0x00077228 in MQTTClient_cycle (sock=0xb4508dc4, timeout=1000, rc=0xb4508dc8) at source/lib/Mqtt.C/src/MQTTClient.c:1547
#7 0x000747a0 in MQTTClient_run (n=0x12a9b4) at source/lib/Mqtt.C/src/MQTTClient.c:483
#8 0xb6e40bfc in start_thread (arg=0xb4509460) at pthread_create.c:306
#9 0xb6dd5968 in ?? () at ../ports/sysdeps/unix/sysv/linux/arm/nptl/../clone.S:116 from /lib/arm-linux-gnueabihf/libc.so.6
(gdb)
The MQTT-SN clients send 6 publish messages about all 30 seconds, they are then sent trough the MQTT.C clients to a Mosquitto broker.
When the 'MQTTClient_run' uses all the CPU I do not see more network traffic than wenn it is working 'normal'. Also the MQTT_C_CLIENT_TRACE_LEVEL=PROTOCOL does not show any other logs than the 'normal' ones.
When I use MQTT_C_CLIENT_TRACE_LEVEL=MINIMUM I already see a lot of logging when it is working 'normal' and even when the clients are in their 'quiet 30 seconds'.
20140922 195603.990 (3025179744) (1)> MQTTClient_cycle:1535
20140922 195603.990 (3025179744) (2)> Socket_getReadySocket:216
20140922 195603.990 (3025179744) (3)> isReady:192
20140922 195603.990 (3025179744) (3)< isReady:197 (0)
20140922 195603.990 (3025179744) (3)> Socket_continueWrites:777
20140922 195603.990 (3025179744) (3)< Socket_continueWrites:799 (0)
20140922 195603.990 (3025179744) (3)> isReady:192
20140922 195603.990 (3025179744) (3)< isReady:197 (0)
20140922 195603.990 (3025179744) (3)> isReady:192
20140922 195603.990 (3025179744) (3)< isReady:197 (0)
20140922 195603.990 (3025179744) (3)> isReady:192
20140922 195603.990 (3025179744) (3)< isReady:197 (1)
20140922 195603.993 (3025179744) (2)< Socket_getReadySocket:282 (12)
20140922 195603.993 (3025179744) (2)> MQTTClient_retry:1515
20140922 195603.993 (3025179744) (3)> MQTTProtocol_retry:624
20140922 195603.993 (3025179744) (3)< MQTTProtocol_retry:643
20140922 195603.993 (3025179744) (2)< MQTTClient_retry:1525
20140922 195603.993 (3025179744) (1)< MQTTClient_cycle:1603 (-1)
20140922 195603.993 (3025179744) (1)> MQTTClient_cycle:1535
20140922 195603.993 (3025179744) (2)> Socket_getReadySocket:216
20140922 195603.993 (3025179744) (3)> isReady:192
20140922 195603.993 (3025179744) (3)< isReady:197 (0)
20140922 195603.993 (3025179744) (3)> Socket_continueWrites:777
20140922 195603.993 (3025179744) (3)< Socket_continueWrites:799 (0)
20140922 195603.993 (3025179744) (3)> isReady:192
20140922 195603.993 (3025179744) (3)< isReady:197 (0)
20140922 195603.993 (3025179744) (3)> isReady:192
20140922 195603.993 (3025179744) (3)< isReady:197 (0)
20140922 195603.993 (3025179744) (3)> isReady:192
20140922 195603.993 (3025179744) (3)< isReady:197 (1)
20140922 195603.993 (3025179744) (2)< Socket_getReadySocket:282 (12)
20140922 195603.993 (3025179744) (2)> MQTTClient_retry:1515
20140922 195603.999 (3025179744) (3)> MQTTProtocol_retry:624
20140922 195603.999 (3025179744) (3)< MQTTProtocol_retry:643
20140922 195603.999 (3025179744) (2)< MQTTClient_retry:1525
20140922 195603.999 (3025179744) (1)< MQTTClient_cycle:1603 (-1)
So my questions are:
- Is there synchronization required to be done by the user when using multiple MQTT.C client instances form different threads?
- Or is this behavior rather the result of a bug and how should I try to tackle it?
- How to read/interpret the logging beyond the PROTOCOL level.
Thanks for any help and inputs.
Regards
Franz
