Hi Franz,
So my questions are:
- Is there synchronization required to be done by the user when using multiple MQTT.C client instances form different threads?
No you should not need extra synchronization. Just about every scenario I've tested though involves using multiple client objects from the same thread, so you might have hit a bug or bugs which isn't shown up in that.
- Or is this behavior the result of a bug and how should I try to tackle it?
I expect it's a bug. How to tackle? Raise a bug in bugzilla, and we can look at it from there. I would normally ask for trace, of which you have provided some already - so we're well on the way :-). I can see the possible cause of the problem already from the trace. getReadySocket() returns the next socket to be processed - in this case 12. But this results in no processing, and we are calling getReadySocket() again right away, which again returns socket 12. I might need to add some more trace to determine what state the failing socket is in, or a trace of the event which started the problem (which I realize might be tricky).
- How to read/interpret the logging beyond the PROTOCOL level.
I should write a description of this trace. It's not too tricky
though.
Timestamp thread id function
nest level function name: line of code
20140922 195603.990 (3025179744) (2)> Socket_getReadySocket:216 > indicates function call
20140922 195603.993 (3025179744) (2)< Socket_getReadySocket:282 (12) < indicates function return, (12) is the return code from the function
So you can raise a bug, or I will. At:
https://bugs.eclipse.org/bugs/enter_bug.cgi?product=Paho
Ian
On 09/22/2014 09:54 PM, Franz Schnyder
wrote:
Hi again
Since I saw that my first post got messed up with some strange
character when viewed via the list archive, I reply the post on plain
text. Sorry for the messed up first message.
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)
I use the v1.0.1 tag form
http://git.eclipse.org/gitroot/paho/org.eclipse.paho.mqtt.c.git.
The MQTT-SN clients send 6 publish messages about all 30 seconds which
are the 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 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 hints.
Regards
Franz
_______________________________________________
paho-dev mailing list
paho-dev@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/paho-dev
--
Ian Craggs
icraggs@xxxxxxxxxx IBM United Kingdom
Paho Project Lead; Committer on Mosquitto
