[core 2.5.0] Loop Count much lower than with 2.4.2

TD-er commented 5 years ago

Basic Infos

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

Platform

Hardware: [ESP-12|ESP-01|ESP-07|ESP8285 device|other]
Core Version: [0fd86a07f0b22aa43f24dc6158b6d8093b607765]
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: https://github.com/esp8266/Arduino/issues/5476#issuecomment-447115849

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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

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

TD-er commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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

TD-er commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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.

SensorSendTaskdoes call sendData. So if sendDatatakes quite some time, the other one will too.

In short:

SensorSendTaskdoes 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.

sendDatadoes 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 commented 5 years ago

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 commented 5 years ago

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

earlephilhower commented 5 years ago

This scheduler does use STL containers. You had moved some stuff of that to flash? Could that affect performance?

No, std::* was always in flash until I made it appear in IRAM it when I added the -nox library. That wouldn't explain a difference.

d-a-v commented 5 years ago

Can you instrument separately in sendData sub-bocks like (at least) this one CPlugin_ptr[event->ProtocolIndex](CPLUGIN_PROTOCOL_SEND, event, dummyString); and these two ones LoadTaskSettings(event->TaskIndex); (they are potentially taking time).

TD-er commented 5 years ago

Adding timers you mean, so we can compare those parts?

d-a-v commented 5 years ago

Yes

TD-er commented 5 years ago

I added a bit more (commit will be pushed in a minute)

As can be seen, the backgroundTasks() and handle_schedule() function are taking quite a bit longer.

TD-er commented 5 years ago

Running for about 10 minutes:

Core 2.5.0:

Description	#calls	call/sec	min (ms)	Avg (ms)	max (ms)
Load File	11	0.02	19.153	19.551	21.246
Loop	842552	1309.42	0.479	0.737	391.926
Plugin call 50 p/s	32103	49.89	2.291	2.385	2.727
Plugin call 10 p/s	6429	9.99	2.572	2.633	2.924
Plugin call 10 p/s U	6429	9.99	0.276	0.299	0.340
Plugin call 1 p/s	644	1.00	2.928	3.301	22.692
SensorSendTask()	11	0.02	98.892	102.294	107.163
sendData()	11	0.02	96.084	99.625	104.560
Compute formula	11	0.02	0.014	0.014	0.015
setNewTimerAt()	42468	66.00	0.175	0.197	0.269
Delay queue MQTT	11	0.02	1.847	1.868	1.885
WiFi.isConnected()	2488246	3867.00	0.015	0.024	0.113
rulesProcessing()	55	0.09	14.259	15.177	17.924
backgroundtasks()	1643099	2553.55	0.138	0.189	391.306
handle_schedule() idle	800107	1243.45	0.243	0.317	391.463
handle_schedule() task	42446	65.97	0.383	2.767	107.564

Core 2.4.2:

Description	#calls	call/sec	min (ms)	Avg (ms)	max (ms)
Load File	10	0.02	18.154	18.473	19.223
Loop	2454654	4049.56	0.151	0.237	259.272
Plugin call 50 p/s	30267	49.93	1.323	1.409	1.856
Plugin call 10 p/s	6060	10.00	1.456	1.550	2.033
Plugin call 10 p/s U	6060	10.00	0.155	0.210	0.262
Plugin call 1 p/s	606	1.00	2.017	2.295	15.314
SensorSendTask()	10	0.02	67.307	72.162	78.346
sendData()	10	0.02	65.414	70.261	76.438
Compute formula	10	0.02	0.010	0.010	0.011
setNewTimerAt()	40034	66.05	0.146	0.177	0.248
Delay queue MQTT	10	0.02	1.567	1.615	1.644
WiFi.isConnected()	7326792	12087.36	0.004	0.004	0.111
rulesProcessing()	50	0.08	7.650	9.592	13.117
backgroundtasks()	4869693	8033.77	0.031	0.059	258.065
handle_schedule() idle	2414639	3983.55	0.065	0.098	3.018
handle_schedule() task	40014	66.01	0.264	1.707	78.615

TD-er commented 5 years ago

And the same nodes, running for 24'447 sec:

Some counters probably have had some overflow, since the average value displayed is lower than the minimum. But the trend is very well visible. Running code on the core 2.5.0 is slower than on core 2.4.2

earlephilhower commented 5 years ago

Just a note, the graphic image posts are much harder to use than the text ones you started with. Can't dump it into a .ODS or .XLS and compare automatically.

That said, since you know your code better than we do, do you have one specific section that's egregious and can be isolated? I know your app is reporting fewer loops/s, but doing perf analysis at that level from the outside is not a fast process.

If there's some small, isolated thing (i.e. this routine X takes 100 numbers, averages them, and sends to a MQTT endpoint) where it's more approachable we'd stand a better chance. Especially if it's something you can hack out into a separate sketch (even if the input and out data its sending is garbage), that means it can be repro'd and instrumented at the low-level needed to identify what's up and if it's in the core, a lib, of the SDK. The smaller the code bit and fewer libs needed, the better, for this kind of thing.

TD-er commented 5 years ago

I understand. One of the striking things in these timing results to me is the delay in the rules handling. The active rules are not communicating to the outside world, just reacting on an event and setting a GPIO pin. There are 2 main things at work then:

Reading from SPIFFS
Parsing Strings (and lots of String operations)

Those String operations can do a lot of memory allocations too, which could also explain the difference when sending data to a controller, since it is then placed in some buffer.

So my 2 main suspects right now are:

SPIFFS handling
Memory allocation

I think for both a fairly small test could be written. Did the SDK change or the core 2.5.0 update also include some changes in moving code to flash? If more code is now executed from flash, that could also explain these slow-downs.

earlephilhower commented 5 years ago

To make it clear, code was always in flash. I introduced a bug in the -noexceptions option where instead of placing those std:: functions in flash it ate up IRAM. IRAM is 16KB total, ~10KB taken by the hidden SDK functions, and the rest is used for interrupt-safe routines, certain library routines that may be called from the WiFi stack, etc. Today the code is all landing in flash unless you say "place in IRAM" which is the correct behavior, and matches prior releases.

Memory management lives in cores/esp8266/umm_malloc/umm_malloc.c and is pretty much untouched in the past 2+ years AFAICT. Couple bug fixes in the log, but not seeing any red flags.

SPIFFS can be very variable and slow in my experience. I didn't dig into it, but it seems to have very high variability in response time even on the same hardware (so it's not flash speed related). The git log's (cores/esp8266/spiffs_api.c) is also pretty much untouched for 3 years now.

Would love to get a test that can be used for isolated A/B comparisons, because I think it's elsewhere...

devyte commented 5 years ago

@earlephilhower could something be hitting the SDK exception handler for reading unaligned addresses?

igrr commented 5 years ago

Might be worth disabling unaligned access handler, at least in debug builds?

earlephilhower commented 5 years ago

@devyte, if @TD-er's running the same code on both builds then the code would crash hard on the older version, so I think it's probably not too likely.

@igrr's point about disabling in debug builds might be good, but @TD-er's app most likely can't even build in debug mode (umm_malloc grows a lot w/heap checking and there are many IRAM/IRQ user routines in his build).

devyte commented 5 years ago

@earlephilhower that it should crash in 2.4.2 did cross my mind, but... let's rule it out. If the handler is disabled, 2.5.0 shpuld crash, right? @igrr I didn't know the sdk unaligned access handler could be disabled. How would that be done?

TD-er commented 5 years ago

if @TD-er's running the same code on both builds then the code would crash hard on the older version, so I think it's probably not too likely.

The only difference in both builds is the used set of build flags as defined here

@igrr's point about disabling in debug builds might be good, but @TD-er's app most likely can't even build in debug mode (umm_malloc grows a lot w/heap checking and there are many IRAM/IRQ user routines in his build).

Maybe the "minimal" set could be built for a 4M flash environment. (using -DPLUGIN_BUILD_MINIMAL_OTA as build flag) It uses the minimal amount of plugins. Alternative is to use these flags:

CONTROLLER_SET_NONE
PLUGIN_SET_NONE
NOTIFIER_SET_NONE

Then there is only the web interface, rule engine and almost no external libraries.

Do you have any suggestions on what to make a benchmark test for?

String allocations/modifications
Connection test
Flash I/O
Arduino calls to lookup pin states (just guessing here)

Then I can create a test which outputs to a page. And what format do you like? CSV (valus separated by ';' )

devyte commented 5 years ago

@TD-er I haven't tested anything here, but if I may, I suggest doing something along these lines: For each entry in the table that shows timing is almost the same bbetween 2.4.2 and 2.5.0 beta2, remove that test from the sketch. For each entry that shows a runtime that is too short, remove that test as well. Remove other things that also make sense, like you propose above with plugin none, etc. From whatever is left, pick one test, e.g. with the highest timing diff, go inside, and measure time wherever it makes sense to do so. Get new tables to compare versions. Follow the above recursively until it gets narrowed down to some core function call.

earlephilhower commented 5 years ago

@TD-er, I think @devyte's suggestion is pretty low-effort on your part and would eliminate one potential source, so maybe we can give that a go?

It looks like the unaligned access stuff is installed at runtime, not link, by the OS. A straightforward if inelegant way to disable this:

Remove user_exceptions.o from libmain.a

cd tools/sdk/lib
cp libmain.a libmain.bak
ar d libmain.a user_exceptions.o

Then in your main .ino add

extern "C" {
extern void __wrap_system_restart_local();
void load_non_32_wide_handler()
{
    __wrap_system_restart_local();
}
};

It'll then do a stack dump on misaligned accesses and pinpoint the offending routine if PMEM is being used as byte-wide memory.

TD-er commented 5 years ago

I can do that later this evening. But then I also must make sure I can actually read the stackdumps. Last time I checked, I was not able to run the Arduino-IDE plugin to decode stack dumps. (Windows 10)

Would be nice to have that option though, since now I am "debugging-in-the-dark", which takes a lot of time.

earlephilhower commented 5 years ago

We've got you covered! :) One of the fixes in 2.5.0 (and part of the reason for the new toolchain build) was that GDB.EXE wasn't included in the espressif toolchain bundle. GDB is required to decode address->line of code in the EspExceptionDecoder.

The new toolset has GDB for all platforms, so this should "just work" (assuming you're using ESPExceptionDecoder). If not, please let us know in a new bug.

TD-er commented 5 years ago

Just a small update from my side. My mind was not really into debugging this the last few days, so that's why there's no update yet. I hope to get to it later this week.

earlephilhower commented 5 years ago

@TD-er, hope you had a good break. Do you have any more info to share?

TD-er commented 5 years ago

@earlephilhower Well, it wasn't a "good" break, but I guess I'm back now. I don't have much to share yet, apart from running the latest build just made, based on the 'staging' branch is still experiencing low loopcounts. Apart from that, there haven't been many serious tests going on regarding this issue.

d-a-v commented 5 years ago

@TD-er Can you comment/disable the update of ummHeapInfo.freeSize2 in cores/esp8266/umm_malloc/umm_malloc.c and try your perf test again ?

TD-er commented 5 years ago

@d-a-v Changed it to:

    if( UMM_NBLOCK(blockNo) & UMM_FREELIST_MASK ) {
      ++ummHeapInfo.freeEntries;
      ummHeapInfo.freeBlocks += curBlocks;
/*
      ummHeapInfo.freeSize2 += (unsigned int)curBlocks
                             * (unsigned int)sizeof(umm_block)
                             * (unsigned int)curBlocks
                             * (unsigned int)sizeof(umm_block);
*/

It is now building.

TD-er commented 5 years ago

It is running now on 2 nodes. "Breadboard2" with:

BME280
OLED Framed plugin

"CO2_tracker1" with:

GPS plugin
BME280
Senseair S8 CO2

On the "Breadboard2"

before: 51.20% (LC=1171)
now: 49.10% (LC=963)

On "CO2_tracker1":

before: 32.10% (LC=1757)
now: 31.10% (LC=1844)

N.B. the CPU load is based on the number of loops not needed to run a set task. The amount of idle time is summed and used to compute the CPU load.

See the comparison in this Excel sheet

I don't think it does improve things a lot. All seems to be within the margin of error.

d-a-v commented 5 years ago

I measured loop itself (time between end of loop and beginning of next loop and it is unchanged, around 5.8us, with 2.4.2 and 2.5.0beta). Then the cause is not the firmware update. It is somewhere inside our core library.

@TD-er can you isolate one single relevant test or function call for us to reproduce and dig into ?

TD-er commented 5 years ago

@d-a-v Sadly today I didn't have the time I hoped to have for these tests, so for now I don't have a single test which shows the impact of the delay.

d-a-v commented 5 years ago

Will you be able to try with #5763 ?

TD-er commented 5 years ago

So I just build with a define for NONOSDK221 ?

TD-er commented 5 years ago

I tried building it several times (PlatformIO staged, so it should use your master branch), but I keep getting this as a build: ESP82xx Core 2.6.0-dev, NONOS SDK 3.0.0-dev(c0f7b44), LWIP: 2.1.2 PUYA support N.B. The "Core 2.5.0-dev" is something I add in the build. I added the NONOSDK221 as a define in the build. I also tried to add board_build.sdk = NONOSDK221 to the platform.ini section for this build, but it keeps reporting the NONOS SDK 3.0.0-dev.

So can you give me some hints on what I need to do to make it building a NONOS SDK 2.2.1?

d-a-v commented 5 years ago

include and library paths must be updated check for patches to platform.txt and tools/pio.py files

-- on mobile

Le 17 février 2019 13:54:46 Gijs Noorlander notifications@github.com a écrit :

I tried building it several times (PlatformIO staged, so it should use your master branch), but I keep getting this as a build: ESP82xx Core 2.6.0-dev, NONOS SDK 3.0.0-dev(c0f7b44), LWIP: 2.1.2 PUYA support N.B. The "Core 2.5.0-dev" is something I add in the build. I added the NONOSDK221 as a define in the build. I also tried to add board_build.sdk = NONOSDK221 to the platform.ini section for this build, but it keeps reporting the NONOS SDK 3.0.0-dev. So can you give me some hints on what I need to do to make it building a NONOS SDK 2.2.1? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

TD-er commented 5 years ago

Not sure why, but the files I get when using PlatformIO feature/stage is not having the latest changes you have in that PR.

Sometimes I just feel a bit lost in all abstractions made for PlatformIO to make it all "easier" to work with. I still don't know what is configured where, what files are defined where and collected from where. It is a bit too obfuscated to see through at once and I feel like I need to make some drawing or something to get where all parts are coming from. These abstractions are great for normal workflows, but if you want to use a specific part from the core libs, it isn't that clear where to set things to get it right.

TD-er commented 5 years ago

Ah, now I get it, it wasn't merged yet. Will fetch this PR manually and try to build then

TD-er commented 5 years ago

OK, I did a checkout of your PR and built it. But still the "NONOS SDK 3.0.0-dev(c0f7b44), LWIP: 2.1.2 PUYA support" So what do I need to change, and where is it located? This is the top of my git log :

commit d0e49a65500c0528bc4063f841971bfd1b203b55 (HEAD)
Merge: 14f1b1d4 3dd54fd3
Author: david gauchard <gauchard@laas.fr>
Date:   Sun Feb 17 04:29:06 2019 +0000

    Merge 3dd54fd3689636d95fa3eb3328d39f2f536979b9 into 14f1b1d4a74a2e65207f23aedabcc7038ffae652

d-a-v commented 5 years ago

With platformio, you need to change in tools/platformio-build.py the two occurences of NONOSDK3V0 to NONOSDK221. I don't know how it could be made better, not being a pio user.

edit: maybe by using boards.txt.py like for arduino ide

TD-er commented 5 years ago

That worked :)

ESP82xx Core 2.6.0-dev, NONOS SDK 2.2.1(cfd48f3), LWIP: 2.1.2 PUYA support

I will let it run for a few minutes to see what the loop-count is and get you an Excel sheet with before- and after timings of that node.

Edit: First impression:

core 2.4.2: 12.90% (LC=6134)
SDK 3.0.0: 19.20% (LC=2471)
SDK 2.2.1: 12.40% (LC=6902)

TD-er commented 5 years ago

And here the comparison of the 3 versions I already mentioned in the previous post. Compare_core250_SDK3-0-0_vs_SDK2-1-1.zip

And test build used for this

esp8266 / Arduino