[core 2.5.0] Loop Count much lower than with 2.4.2

[TD-er]

Basic Infos

• This issue complies with the issue POLICY doc.
• I have read the documentation at readthedocs and the issue is not addressed there.
• I have tested that the issue is present in current master branch (aka latest git).
• I have searched the issue tracker for a similar issue.
• If there is a stack dump, I have decoded it.
• I have filled out all fields below.

Platform

• Hardware: [ESP-12|ESP-01|ESP-07|ESP8285 device|other]
• Core Version: [0fd86a0]
• Development Env: [Platformio]
• Operating System: [Windows|Ubuntu]

Settings in IDE

• Module: [Generic ESP8266 Module|other]
• Flash Mode: [dio]
• Flash Size: [4MB/1MB]
• lwip Variant: [PIO_FRAMEWORK_ARDUINO_LWIP2_LOW_MEMORY_LOW_FLASH]
• Reset Method: [-]
• Flash Frequency: [40Mhz]
• CPU Frequency: [80Mhz]
• Upload Using: [OTA|SERIAL]
• Upload Speed: [115200] (serial upload only)

Problem Description

Loop Count in loops per sec. is much lower than with core 2.4.2. It was also mentioned here: #5476 (comment)

I have several test setups running core 2.4.2 and core 2.5.0 (see latest nightly builds of ESPeasy)
For example 2 Sonoff POW r2 nodes running the exact same configuration, the loopcount (per sec) of both differs quite a lot:

Core 2.4.2:

Core 2.5.0 beta1:

N.B. Not sure yet why in the node running 2.4.2 less things are being shown.

In general (among my test nodes) the loop-count is:

• 4000 - 11000 when using core 2.4.2
• 1100 - 2300 when using core 2.5.0 (4200 when doing nothing)

As can be seen from both Sonoff POW r2 nodes, the loop-count is:

• 4200 for core 2.4.2
• 1148 for core 2.5.0

[d-a-v]

SensorSendTask and sendData are highlighted in 2.5 but not present in 2.4, but you posted them before.

What's strange to me is

lwip Variant: [PIO_FRAMEWORK_ARDUINO_LWIP2_LOW_MEMORY_LOW_FLASH]

because it is Arduino IDE's option "lwIP-v2 (lower memory) (no features)", which has the same/default settings as in release 2.4.2 (although upstream lwIP has changed from 2.0 to 2.1.2 in between).

Do you have the same results with PIO_FRAMEWORK_ARDUINO_LWIP2_LOW_MEMORY (which is current default Arduino IDE configuration)?

You can also try to use previous lwIP version in core 2.5:

cd tools/sdk/lwip2
make download
cd builder
git checkout arduino-2.4.2
cd ..
make clean
make install

and replace liblwip-536 by liblwip_536 in tools/platformio-build.py L164

Next step would be to try the same SDK version as we had in 2.4.2.

[TD-er]

SensorSendTask and sendData are highlighted in 2.5 but not present in 2.4, but you posted them before.

I already found why that was in my (new installed) core 2.4.2 node.
I forgot to set the plugin interval timer for that one (ESPeasy config related), after setting that it is now reporting the timers for these function calls too.

and replace liblwip-536 by liblwip_536 in tools/platformio-build.py L164

Isn't that the same or do I need some more coffee?
Can I also use a different define to switch LWIP or do I need to build it like you described?

[d-a-v]

Isn't that the same or do I need some more coffee?

Get more coffee :) (edit: dash / underscore)

[TD-er]

Running with PIO_FRAMEWORK_ARDUINO_LWIP2_LOW_MEMORY is the same:

Loop		244840	1187.64	0.391	0.816	512.279

I will now test with previous LWIP in core 2.5.0 (just finished my coffee ;) )

[TD-er]

Hmm, I cannot run make download like described.

gijs@Imagine:~/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2$ make
all               builder/          clean             download          downloadmaster    downloadupstream  install           latestmaster      latestupstream
gijs@Imagine:~/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2$ make download
make: Nothing to be done for 'download'.

[d-a-v]

Then is it already downloaded in builder/
Is this directory empty ?

[TD-er]

No it is not empty
Seems I don't have the complete build toolchain?

gijs@Imagine:~/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2$ cd builder/
gijs@Imagine:~/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder$ git checkout arduino-2.4.2
M       lwip2-src
Previous HEAD position was c434c6f less verbose make (use standard V=1 to make it verbose)
HEAD is now at 163bb82 fix setting down interface on the esp side (ip must not be set to 0, and properly re/set FLAG_UP)
gijs@Imagine:~/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder$ cd ..
gijs@Imagine:~/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2$ make clean
make -C builder -f Makefile.arduino clean
make[1]: Entering directory '/home/gijs/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder'
make -f makefiles/Makefile.build-lwip2 \
                target=arduino \
                SDK=../.. \
                LWIP_ESP=../../lwip/include \
                LWIP_LIB=liblwip2.a \
                LWIP_LIB_RELEASE=../../lib/liblwip2.a \
                LWIP_INCLUDES_RELEASE=../include \
                TOOLS=../../../xtensa-lx106-elf/bin/xtensa-lx106-elf- \
                TCP_MSS=536 BUILD=build-536 \
                clean
make[2]: Entering directory '/home/gijs/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder'
rm -rf build-536 liblwip2.a glue-lwip/lwip-err-t.h glue-lwip/lwip-git-hash.h
make[2]: Leaving directory '/home/gijs/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder'
make -f makefiles/Makefile.build-lwip2 \
                target=arduino \
                SDK=../.. \
                LWIP_ESP=../../lwip/include \
                LWIP_LIB=liblwip2_1460.a \
                LWIP_LIB_RELEASE=../../lib/liblwip2_1460.a \
                LWIP_INCLUDES_RELEASE=../include \
                TOOLS=../../../xtensa-lx106-elf/bin/xtensa-lx106-elf- \
                TCP_MSS=1460 BUILD=build-1460 \
                clean
make[2]: Entering directory '/home/gijs/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder'
rm -rf build-1460 liblwip2_1460.a glue-lwip/lwip-err-t.h glue-lwip/lwip-git-hash.h
make[2]: Leaving directory '/home/gijs/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder'
make[1]: Leaving directory '/home/gijs/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder'
gijs@Imagine:~/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2$ make install
make -C builder -f Makefile.arduino install
make[1]: Entering directory '/home/gijs/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder'
make -f makefiles/Makefile.build-lwip2 \
                target=arduino \
                SDK=../.. \
                LWIP_ESP=../../lwip/include \
                LWIP_LIB=liblwip2.a \
                LWIP_LIB_RELEASE=../../lib/liblwip2.a \
                LWIP_INCLUDES_RELEASE=../include \
                TOOLS=../../../xtensa-lx106-elf/bin/xtensa-lx106-elf- \
                TCP_MSS=536 BUILD=build-536 \
                install
make[2]: Entering directory '/home/gijs/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder'
( \
echo "// script-generated, extracted from espressif SDK's lwIP arch/cc.h"; \
echo "#define LWIP_NO_STDINT_H 1"; \
grep -e LWIP_ERR_T -e ^typedef ../../lwip/include/arch/cc.h \
) > glue-lwip/lwip-err-t.h
makefiles/make-lwip-hash
make -f makefiles/Makefile.glue-esp BUILD=build-536 TCP_MSS=536
make[3]: Entering directory '/home/gijs/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder'
../../../xtensa-lx106-elf/bin/xtensa-lx106-elf-gcc -std=gnu99 -Wall -Wextra -c -Os -g -Wpointer-arith -Wl,-EL -fno-inline-functions -nostdlib -mlongcalls -mtext-section-literals -falign-functions=4 -MMD -ffunction-sections -fdata-sections -D__ets__ -DICACHE_FLASH -U__STRICT_ANSI__ -DLWIP_OPEN_SRC -DLWIP_BUILD -DUSE_OPTIMIZE_PRINTF -DTARGET=arduino -DTCP_MSS=536 -Ibuild-536 -I../../include -I../../lwip/include -Iglue glue-esp/lwip-esp.c -o build-536/glue-esp/lwip-esp.o
make[3]: ../../../xtensa-lx106-elf/bin/xtensa-lx106-elf-gcc: Command not found
makefiles/Makefile.rules:7: recipe for target 'build-536/glue-esp/lwip-esp.o' failed
make[3]: *** [build-536/glue-esp/lwip-esp.o] Error 127
make[3]: Leaving directory '/home/gijs/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder'
makefiles/Makefile.build-lwip2:47: recipe for target 'liblwip2.a' failed
make[2]: *** [liblwip2.a] Error 2
make[2]: Leaving directory '/home/gijs/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder'
Makefile.arduino:6: recipe for target 'install' failed
make[1]: *** [install] Error 2
make[1]: Leaving directory '/home/gijs/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/tools/sdk/lwip2/builder'
Makefile:3: recipe for target 'install' failed
make: *** [install] Error 2

[d-a-v]

Ah this is platformio, builder/Makefile.arduino would need an update of this variable
TOOLS=../../../xtensa-lx106-elf/bin/xtensa-lx106-elf- pointing to the right gcc directory.

You can also take already compiled binaries from 2.4.2 release (liblwip2.a - sorry in fact there is no dash/underscore, I'll get some coffee too)

In any case you need to add this line in tools/sdk/ld/eagle.app.v6.common.ld.h

    *liblwip2.a:(.literal .text .literal.* .text.*)                <- to add
    *liblwip2-536.a:(.literal .text .literal.* .text.*)            <- already present

[TD-er]

I have downloaded the binary, added it to the ld.h file and also changed this line

and replace liblwip-536 by liblwip_536 in tools/platformio-build.py L164
, only then into 'liblwip2
Also reset the PIO_FRAMEWORK_ARDUINO_LWIP2_LOW_MEMORY_LOW_FLASH parameter.

But the resulting binary does not boot.
Any other tips?

[d-a-v]

Any other tips?

I tried myself, and indeed it is not as simple as it seems. I will find some time to provide a lwIP-2.0.3 binary compatible with core 2.5.0 if the other leads are not conclusive.

Can you point to the source code of these sendData and SensorSendTask to check which parts of the core are involved ?

[TD-er]

Can you point to the source code of these sendData and SensorSendTask to check which parts of the core are involved ?

These are my own functions and they take about the same time on both cores.

• sendData
• SensorSendTask

SensorSendTask does call sendData. So if sendData takes quite some time, the other one will too.

In short:

SensorSendTask does collect the data from a plugin and performs some string replacements + calculates some formulas if needed.
This collecting data can also involve some reading from the sensor. Not all plugins in ESPeasy are yet converted to do the reading in the background, so some may do quite a lot while reading.

sendData does send the sensor data to one or more selected controllers and triggers some rules.
The rules are our own script language. At least it is about reading from SPIFFS and parsing rules (could benefit from some optimizations).
The rules parsing may also do a lot using String objects.
Apart from the rules, some parts of the settings file are also read from SPIFFS.

A controller is something which sends data to a remote computer, formatted for a specific use case (e.g. Domoticz MQTT, OpenHAB, Http, UDP, ESPeasy-p2p, etc.)
For almost all controllers, I have added some kind of buffer system to allow the controllers to send data (and retry) at some predefined pace specific for that controller. (e.g. Thingspeak only allows a message per N seconds for the free accounts and you don't want to wait for that)
So for most controllers, this sendData is mainly about storing it into a buffer.
The stored messages will later be processed by our own scheduler, so the actual network traffic is not being counted in the sendData call (except for the few plugins not yet using a buffer)

[TD-er]

About the impact of those functions:

These timings are covering about 7900 seconds (2h19m)
There were 132 calls to these functions, which is about once a minute.
That's about 100 msec per minute. The rest of the time is spent in other areas of the code.

In a loop() it is mainly a call for the scheduler.
This scheduler does use STL containers. You had moved some stuff of that to flash? Could that affect performance?
See msecTimerHandlerStruct which is essentially the scheduler's heart.

By the way, these functions should be in the standard core lib:

long timeDiff(unsigned long prev, unsigned long next);
long timePassedSince(unsigned long timestamp);
boolean timeOutReached(unsigned long timer);
long usecPassedSince(unsigned long timestamp);
boolean usecTimeOutReached(unsigned long timer);

[TD-er]

As a test, I have changed the flash frequency to 80 MHz

Frequency	Description	#calls	call/sec	min (ms)	Avg (ms)	max (ms)
40 MHz	Loop	10806208	1367.80	0.516	0.668	896.423
80 MHz	Loop	441145	2554.65	0.303	0.374	258.775

Same node running same config @ core 2.5.0