high cpu usage on ARM9 plattform with Linux 2.6.11 (Target armv4tl)

[thaeger71]

Hi there,
I managed to compile the sample "paho_c_sub" which uses MQTTAsync against the fitting uclibc and other libraries and let run this on my arm device. Everything seemed to work, but CPU usage is very high, between 85-95% even if the client is not subscribed to a topic, just the pure connection occurs this CPU usage. Has sombody a hint for me what the reason could be for this ? If I enable trace with level PROTOCOL I get this output:

=========================================================
Trace Output
Product name: Eclipse Paho Asynchronous MQTT C Client Library
Version: 1.3.0
Build level: 2019-02-21T15:27:46Z
OpenSSL version: OpenSSL 1.0.2r-dev xx XXX xxxx
OpenSSL flags: compiler: /home/build/arm-515/berofixfs/src/arm/work/buildroot/build_arm/staging_dir/bin/arm-linux-uclibc-gcc -I. -I.. -I../include -fPIC -DOPENSSL_PIC -DOPENSSL_THREADS -D_REENTRANT -DDSO_DLFCN -DHAVE_DLFCN_H -O3 -fomit-frame-pointer -Wall
OpenSSL build timestamp: built on: reproducible build, date unspecified
OpenSSL platform: platform: linux-generic32
OpenSSL directory: OPENSSLDIR: "/home/build/src/cross-openssl/compiled-openssl/openssl"
/proc/version: Linux version 2.6.11.7-1.08.9beroNet (build@gollumng) (gcc version 3.4.3) #10 Thu Jul 16 11:13:08 CEST 2009

=========================================================
20190312 141029.166 Stack mismatch. Entry:MQTTAsync_sleep Exit:Thread_start
20190312 141029.166 Stack mismatch. Entry:MQTTAsync_cycle Exit:MQTTAsync_connect
20190312 141029.166 Connecting to serverURI 172.20.20.175:1883 with MQTT version 4
20190312 141029.276 Stack mismatch. Entry:MQTTAsync_receiveThread Exit:MQTTAsync_sleep
20190312 141029.278 Stack mismatch. Entry:MQTTAsync_sendThread Exit:MQTTAsync_cycle
20190312 141029.279 5 beroFix16144 -> CONNECT cleansession: 1 (0)
20190312 141029.282 5 beroFix16144 <- CONNACK rc: 0
20190312 141029.284 5 beroFix16144 -> SUBSCRIBE msgid: 1 (0)
20190312 141029.288 5 beroFix16144 <- SUBACK msgid: 1
20190312 141029.288 Stack mismatch. Entry:MQTTProtocol_retry Exit:MQTTAsync_checkTimeouts
20190312 141030.286 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:Socket_getReadySocket
20190312 141030.286 Stack mismatch. Entry:MQTTAsync_sleep Exit:MQTTAsync_checkTimeouts
20190312 141030.396 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:MQTTAsync_sleep
20190312 141030.397 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_cycle
20190312 141030.397 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_checkTimeouts
20190312 141031.396 Stack mismatch. Entry:MQTTAsync_cycle Exit:Socket_getReadySocket
20190312 141031.506 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:MQTTAsync_sleep
20190312 141031.506 Stack mismatch. Entry:MQTTAsync_sleep Exit:MQTTAsync_cycle
20190312 141031.508 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_checkTimeouts
20190312 141032.506 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:Socket_getReadySocket
20190312 141032.508 Stack mismatch. Entry:MQTTAsync_sleep Exit:MQTTAsync_checkTimeouts
20190312 141032.616 Stack mismatch. Entry:MQTTAsync_cycle Exit:MQTTAsync_sleep
20190312 141032.617 Stack mismatch. Entry:MQTTProtocol_retry Exit:MQTTAsync_checkTimeouts
20190312 141033.616 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:Socket_getReadySocket
20190312 141033.616 Stack mismatch. Entry:MQTTAsync_sleep Exit:MQTTAsync_checkTimeouts
20190312 141033.726 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:MQTTAsync_sleep
20190312 141033.727 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_cycle
20190312 141033.727 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_checkTimeouts
20190312 141034.726 Stack mismatch. Entry:Thread_wait_cond Exit:Socket_getReadySocket
20190312 141034.726 Stack mismatch. Entry:MQTTAsync_sleep Exit:Thread_wait_cond
20190312 141034.836 Stack mismatch. Entry:MQTTAsync_cycle Exit:MQTTAsync_sleep
20190312 141035.946 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:MQTTAsync_sleep
20190312 141035.947 Stack mismatch. Entry:MQTTAsync_sleep Exit:MQTTAsync_cycle
20190312 141035.947 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_checkTimeouts
20190312 141036.946 Stack mismatch. Entry:MQTTAsync_cycle Exit:Socket_getReadySocket
20190312 141037.056 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:MQTTAsync_sleep
20190312 141037.056 Stack mismatch. Entry:MQTTAsync_sleep Exit:MQTTAsync_cycle
20190312 141037.058 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_checkTimeouts
20190312 141038.056 Stack mismatch. Entry:MQTTAsync_cycle Exit:Socket_getReadySocket
20190312 141038.056 Stack mismatch. Entry:isReady Exit:Thread_wait_cond
20190312 141038.167 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:MQTTAsync_sleep
20190312 141038.167 Stack mismatch. Entry:MQTTAsync_sleep Exit:MQTTAsync_cycle
20190312 141038.167 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_checkTimeouts
20190312 141039.166 Stack mismatch. Entry:Thread_wait_cond Exit:Socket_getReadySocket
20190312 141039.166 Stack mismatch. Entry:MQTTAsync_sleep Exit:Thread_wait_cond
20190312 141039.276 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:MQTTAsync_sleep
20190312 141039.277 5 beroFix16144 -> PINGREQ (0)
20190312 141039.280 5 beroFix16144 <- PINGRESP
20190312 141039.281 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_checkTimeouts
20190312 141040.276 Stack mismatch. Entry:MQTTAsync_cycle Exit:Socket_getReadySocket
20190312 141041.497 Stack mismatch. Entry:MQTTad_wait_cond Exit:Thread_wait_cond
20190312 141042.608 Stack mismatch. Entry:MQTTProtocol_retry Exit:Thread_wait_cond
20190312 141043.606 Stack mismatch. Entry:Thread_wait_cond Exit:Socket_getReadySocket
20190312 141043.606 Stack mismatch. Entry:MQTTAsync_sleep Exit:Thread_wait_cond
20190312 141043.716 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_sleep
20190312 141044.826 Stack mismatch. Entry:MQTTProtocol_retry Exit:MQTTAsync_checkTimeouts
20190312 141045.896 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:MQTTAsync_sleep
20190312 141045.937 Stack mismatch. Entry:MQTTAsync_sleep Exit:MQTTAsync_cycle
20190312 141045.937 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_checkTimeouts
20190312 141046.936 Stack mismatch. Entry:MQTTAsync_cycle Exit:Socket_getReadySocket
20190312 141047.046 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:MQTTAsync_sleep
20190312 141047.046 Stack mismatch. Entry:MQTTAsync_sleep Exit:MQTTAsync_cycle
20190312 141047.048 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_checkTimeouts
20190312 141048.046 Stack mismatch. Entry:MQTTAsync_cycle Exit:Socket_getReadySocket
20190312 141048.156 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:MQTTAsync_sleep
20190312 141048.156 Stack mismatch. Entry:MQTTAsync_sleep Exit:MQTTAsync_cycle
20190312 141048.156 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_checkTimeouts
20190312 141049.157 Stack mismatch. Entry:MQTTAsync_cycle Exit:Socket_getReadySocket
20190312 141049.266 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:MQTTAsync_sleep
20190312 141049.267 5 beroFix16144 -> PINGREQ (0)
20190312 141049.267 Stack mismatch. Entry:MQTTAsync_sleep Exit:MQTTAsync_cycle
20190312 141049.270 5 beroFix16144 <- PINGRESP
20190312 141049.271 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_checkTimeouts
20190312 141050.266 Stack mismatch. Entry:MQTTAsync_cycle Exit:Socket_getReadySocket
20190312 141050.266 Stack mismatch. Entry:isReady Exit:Thread_wait_cond
20190312 141050.376 Stack mismatch. Entry:MQTTAsync_checkTimeouts Exit:MQTTAsync_sleep
20190312 141050.376 Stack mismatch. Entry:MQTTAsync_sleep Exit:MQTTAsync_cycle
20190312 141050.378 Stack mismatch. Entry:Socket_getReadySocket Exit:MQTTAsync_checkTimeouts

[icraggs]

A normal level trace capture of the very beginning of execution might explain a bit more. The Stack mismatch message should not occur, and could be the cause (or maybe effect) of the high CPU use.

[jumoog]

The CPU has maybe nothing like AES-NI and OpenSSL needs alot CPU. I have the same problem with my Router with RISC Processor

[thaeger71]

Here is a trace with normal level, the "Stack mismatch" does not occure here:

https://drive.google.com/uc?export=download&id=1tWcuNi5rT2xMPU4bGV56T1UBSKXvV6KX

[thaeger71]

Hi jumoog,

in my example I don't use a ssl connection. Would it create load even though ssl is not in use ?

[thaeger71]

the paho_cs_sub client doesn't create a high load, even if I use ssl .......

[jumoog]

oh okay it was just a guess

[thaeger71]

I also tried MQTTAsync_subscribe which runs with libpaho3a.so, without ssl, and it still has cpu load of 98%.
So the trace is still showing this Stack mismatch error, but this error comes not in a high freqnecy which would explain this very high load.
So I have a question, the thing wich comes with very high frequency is:

20190312 145925.933 (0) (4)> Thread_wait_cond:411
20190312 145925.933 (0) (4)< Thread_wait_cond:419 (0)
20190312 145925.933 (0) (4)> MQTTAsync_checkTimeouts:1730
20190312 145925.933 (0) (4)< MQTTAsync_checkTimeouts:1778

I'am not a therading specialist and don't know exactly how threading is working in MQTTAsync....what does this messages mean execatly ?

[icraggs]

1. The stack mismatch error is definitely not correct. If you aren't using the develop branch code already, then I would try that to see if that goes away.

2. Running paho_c_sub on MacOS, with no messages being received, part of the trace looks like this:

Trace : 3, 20190313 164025.788 (41967616) (2)> Socket_getReadySocket:237
Trace : 3, 20190313 164025.788 (41431040) (1)< Thread_wait_cond:419 (60)
Trace : 3, 20190313 164025.788 (41431040) (1)> MQTTAsync_checkTimeouts:1730
Trace : 3, 20190313 164025.788 (41431040) (1)< MQTTAsync_checkTimeouts:1778
Trace : 3, 20190313 164026.788 (41431040) (1)> Thread_wait_cond:411
Trace : 3, 20190313 164026.788 (41967616) (3)> Socket_continueWrites:928
Trace : 3, 20190313 164026.788 (41967616) (3)< Socket_continueWrites:952 (0)
Trace : 3, 20190313 164026.788 (41967616) (3)> isReady:213
Trace : 3, 20190313 164026.788 (41967616) (3)< isReady:218 (0)
Trace : 3, 20190313 164026.788 (41967616) (2)< Socket_getReadySocket:309 (0)

Note the 1 sec delay between the entry to getReadySocket (2)> and exit (2)<. The core of this is a select OS call which should delay by 1 sec if there is no traffic on the sockets.

It's possible one of the calls in uclibc is behaving a bit unexpectedly.

[icraggs]

OK, in that trace, it looks like Thread_wait_cond() is returning immediately. It's also returning 0, which if it's waiting should return 'timed out'. The rest of the trace looks pretty normal, so I think it's all to do with Thread_wait_cond(). It's returning 0 each time, even though it should be timing out (60 on MacOS).

Maybe it's something to do with the timeout calculation in Thread_wait_cond:

clock_gettime(CLOCK_REALTIME, &cond_timeout);

cond_timeout.tv_sec += timeout;
pthread_mutex_lock(&condvar->mutex);
rc = pthread_cond_timedwait(&condvar->cond, &condvar->mutex, &cond_timeout);
pthread_mutex_unlock(&condvar->mutex);

[thaeger71]

Yes, that was one of my thoughts too. I will try to find out what's maybe wrong with the calculation ...
Will come back to this as soon I have news.

[thaeger71]

I got the problem now, in our uclibc version (very old, 0.9.27) the function "pthread_cond_timedwait" is only a wrapper for "pthread_cond_timedwait_relative". I just disabled the calculation for absolute time in "Thread_wait_cond", just pass the relative timeout and now it works as expected.