-
|
I'm trying to offload some UART IO work into a worker: #1193 Since in this approach, main task delegate all UART IO into the worker, so there are lots of message passing between them. I found the delay between "postMessage" and "onmessage" changes a lot (I'm using new Date().getTime() to get a rough tick count to measure preformance) To my understanding, (I'm running on ESP32-S3) each worker runs on FreeRTOS task, and FreeRTOS message queues are used for inter-task communication. I checked the ESP32 codebase, preemption is supported in my configuration and the tick Hz is 1000. So the delay while system is idle should be ~1-2ms. So I guess this time I'm running into performance issues into this tiny 240MHz chip... My guesses are:
Any suggestions? |
Beta Was this translation helpful? Give feedback.
Replies: 3 comments 18 replies
-
|
I'm not sure what is going on. I'd like to understand better what how much data you are pushing through the system:
Using async/await is fine, of course. But nothing is free. Each await allocates memory and so puts a little pressure on the GC. That eventually adds up. Also the calling resolved promises will block messages received from the worker. The virtual machine can only do one thing at a time. Can you quantify "LOTS"? I'm curious about how many promises are resolved per second. If you aren't sure, we can add some simple logging to
This is correct. And you see the 1 ms latency in the worker example, so we know that is possible. Do make sure that you have both cores enabled. I think the ESP-IDF default is just one. The Moddable SDK sdkconfig settings enable both -- if you are using that.
What you are doing is accurate. |
Beta Was this translation helpful? Give feedback.
-
|
Yeah it's hard to explain what's going on... We have a hardware abstraction protocol that tunnels all peripherals through a UART. And we're using this mechanism to run automated tests, which indeed stress the system a lot. the call chain looks like this: Each atCmd() call send some data (~20-50 bytes) to the worker, the worker send data through UART. Then atCmd() wait for a data coming back from communication module (like "OK") and continue. Below is the original log with lots of details.
There're a few things from the log:
|
Beta Was this translation helpful? Give feedback.
-
|
Thanks for the additional details. The UART and promise activity doesn't obviously look overwhelming. I see two possibilities that are delaying the delivery of the worker messages:
Unfortunately, I don't have time to investigate much today, so (2) will need to wait. I suggest we gather a little more data to help with (1):
We can do that by adding some logging in // start
int start = modMilliseconds();
fprintf(stderr, "\n# fxRunPromiseJobs");
// end
int end = modMilliseconds();
fprintf(stderr, "\n# fxRunPromiseJobs - %d\n", end - start);Note that |
Beta Was this translation helpful? Give feedback.
-
|
@phoddie Thanks for your help! And here is the log, focused on the gap between worker 'posted Message writeDone' and main thread 'onmessage writeDone', and this time it took 47ms. From what I can see, the async jobs seem ok: the job (the one posting 'writeDone') finished 1ms after posting the message. And in between there is on job run for 1ms, nothing significant. But the GC seems problematic: two GC tooks 52ms in total. Also notice the first GC (the [2506] line) started before worker thread posting 'write Done' I think that the reason. The log above was collected with other system activities suppressed. In normal situation GC happens much more frequently: And here is the 'instruments' log after the log above (I guess for the worker and main thread) |
Beta Was this translation helpful? Give feedback.
-
|
That's some helpful data, thank you. It is great to see that the worker managing serial is running fully asynchronously.
That's correct. The garbage collector is taking most of the time. It is running more frequently than I had expected based on the initial report. So, let's focus there. From the instrumentation line for the main VM, we can see:
You have lots of free system memory, so we have room to adjust the memory allocations if needed. And perhaps it is needed. There are two heaps for each VM - the slot heap (16 byte blocks) and the chunk heap (variable size blocks) What's important to understand is that when either heap is full, the GC runs to make room. Both your chunk and slot heaps are very close to full (97% for chunk heap and 99% for slots). The lack of free space means the GC will run relatively often to make space. That appears to match what we see. As a naive change, let's double the size of both the slot and chunk heaps to increase the free space. That should reduce the frequency of the garbage collections. The updated allocations would look something like this in your manifest: "creation": {
"static": 0,
"chunk": {
"initial": 157696,
"incremental": 0
},
"heap": {
"initial": 59340,
"incremental": 0
},
"stack": 10240
},Keep in mind that the stack and heap initial/incremental are expressed in slots, so the number of bytes allocated is 16x the value. The chunk initial/incremental are expressed in bytes. FWIW – your stack size is huge. An 8 KB stack is usually more than enough (512 slots). There's probably no harm with having it so large, but it does stand out and eventually you might want that memory for something else. |
Beta Was this translation helpful? Give feedback.
-
|
@phoddie That make sense. Besides doubling the initial allocation, what does "incremental" mean? I think one of the issues is the allocation should grow with a strategy (like std::vector<> which doubles every time). If we can get a good incremental strategy, then the initial allocation configuration becomes less critical. |
Beta Was this translation helpful? Give feedback.
-
|
@linfan68 Your intuition about the use of "incremental" is on target. It is described in the manifest and XS in C docs. For embedded projects, we almost always want to set the incremental values to 0. That prevents the virtual machine from growing at runtime, so that it cannot use more memory than expected -- which could disrupt operation of other parts of the system. It is also more efficient to initially allocate the memory needed for a VM, rather than incrementally growing the VM. For devices with lots of memory like yours, having a non-zero value for incremental can be convenient, even if sub-optimal. If nothing more, it would be helpful during development to see where the memory allocation stabilizes. Those values can then be used to set the initial allocations.
These kind of heuristics can be useful. We haven't taken a doubling approach in XS as it will consume memory faster which can be dangerous on a memory constrained device. It is easy enough to experiment with different behaviors. I think the following will do what you describe. For slots, after this line: moddable/xs/sources/xsMemory.c Line 1648 in d471f26 add: the->minimumHeapCount *= 2;For chunks, after this line: moddable/xs/sources/xsMemory.c Line 570 in d471f26 add: if (the->firstBlock)
the->minimumChunksSize *= 2;Please give that a try and share how it goes. If the direction is promising we can think about how to integrate something like that. |
Beta Was this translation helpful? Give feedback.
-
|
@phoddie I got a chance to try this change, but still get one more issue. produces the following result: By changing "static: 0" to "static: 64 * 1024" in worker config, worker memory looks correct: |
Beta Was this translation helpful? Give feedback.
-
|
Thanks for confirming that it mostly works. I thought I tested the case with static of 0, but maybe not. I will take a look. |
Beta Was this translation helpful? Give feedback.
-
|
Either I didn't test it or I made a mistake committing the change. All you need to do is change this line: moddable/xs/platforms/mc/xsHosts.c Line 490 in 2f9eb25 Replace the first Thanks for the report. Good find. |
Beta Was this translation helpful? Give feedback.
-
|
I just got a chance to try this and it works as expected! |
Beta Was this translation helpful? Give feedback.
-
|
Very nice. Thanks for confirming. It is included in Moddable SDK 4.1, that was just released today. |
Beta Was this translation helpful? Give feedback.
That's some helpful data, thank you.
It is great to see that the worker managing serial is running fully asynchronously.
That's correct.
The garbage collector is taking most of the time. It is running more frequently than I had expected based on the initial report. So, let's focus there.
From the instrumentation line for the main VM, we can see:
You have lots of free system memory, so…