search

espruino / EspruinoTools

JavaScript library of tools for Espruino - used for the Web IDE, CLI, etc.
Apache License 2.0
150 stars 90 forks source link

slowWrite is automagically configured, and is not logged even with -v verbose flag and the default is true #178

Open fanoush opened 2 months ago

fanoush commented 2 months ago

Was trying to figure out why uploading file to storage takes many minutes and had finally look into source.

espruino --help, espruino --listconfigs has no hint there is something like slowWrite flag -v logs a lot of stuff including data that is going to be sent but again nothing that would hint what happens while the data is transferred

Finally I had to find and uncomment this line https://github.com/espruino/EspruinoTools/blob/8eb606cff5992a64c3127b8bf32fd0b01ad7873c/core/serial.js#L386 to see what happens.

Sending block "\u0010print()\n\u0010require(\"", wait 50ms
Sending block "Storage\").write(\"ba", wait 50ms
--]
Sending block "ck-sb.JPG\",atob(\"/9", wait 50ms
Sending block "j/4AAQSkZJRgABAQEAY", wait 50ms
Sending block "ABgAAD/4RCIRXhpZgAA", wait 50ms
Sending block "TU0AKgAAAAgABAE7AAI", wait 50ms
Sending block "AAAAHAAAISodpAAQAAA", wait 50ms
Sending block "ABAAAIUpydAAEAAAAOA", wait 50ms
Sending block "AAQcuocAAcAAAgMAAAA", wait 50ms
....

Maybe this line could be enabled with "-v"?

Some magic is here https://github.com/espruino/EspruinoTools/blob/8eb606cff5992a64c3127b8bf32fd0b01ad7873c/plugins/versionChecker.js#L59-L66 but in my case nothing matched so the default of true https://github.com/espruino/EspruinoTools/blob/8eb606cff5992a64c3127b8bf32fd0b01ad7873c/core/serial.js#L47 was silently used with no logging. BTW why the ESP32 message says it uses flow control and then slow writes are set to true, shouldn't it be false because flow control works and can stop the flow?

I was actually using -p tcp://127.0.0.1:2222 so also the driver in https://github.com/espruino/EspruinoTools/blob/8eb606cff5992a64c3127b8bf32fd0b01ad7873c/core/serial_node_socket.js has no workaround like e.g. this https://github.com/espruino/EspruinoTools/blob/8eb606cff5992a64c3127b8bf32fd0b01ad7873c/core/serial_web_bluetooth.js#L192 more places https://github.com/search?q=repo%3Aespruino%2FEspruinoTools%20setSlowWrite&type=code

And looks like the versionChecker.js is parsing console name from process.env (USB, Telnet, ...) instead of setting it from the real transport that is used. So in my case I was using TCP port but my console was not named "Telnet". I am not sure adding "SWDCON" next to "Telnet" is good workaround.

Another puzzling thing was that I found this code https://github.com/espruino/EspruinoTools/blob/8eb606cff5992a64c3127b8bf32fd0b01ad7873c/core/serial.js#L354-L358 that contains matches for Storage.write with some 500ms delays but it does not match because default is "--config STORE_LINE_NUMBERS=true" and there is extra stuff after "x10" with line number - like u0010\u001b[10drequire(\"Storage\").write. When fixed it does not match anyway (maybe because of https://github.com/espruino/EspruinoTools/blob/8eb606cff5992a64c3127b8bf32fd0b01ad7873c/core/serial.js#L338 )

Some suggestions to improve this:

Can the slowWrite be false by default? If not can the serial_node_socket set it to false like in other place and Telnet is removed from the check? Can the slowWrite flag be overriden from command line or --config parameter so it is more visible?

fanoush commented 2 months ago

but it does not match because default is "--config STORE_LINE_NUMBERS=true" and there is extra stuff after "x10" with line number - like u0010\u001b[10drequire(\"Storage\").write. When fixed it does not match anyway

there was one more gotcha, currently there is no semicolon sent at the end of write(), this expression matches now and splitting storage writes works

      split = findSplitIdx(split, /\x10[^\n]*require\("Storage"\).write\([^\n]*\)[;]*\n/, 500, "Storage.write"); // Write chunk of data

EDIT: created PR for this https://github.com/espruino/EspruinoTools/pull/179

gfwilliams commented 2 months ago

This is very frustrating - I've recently hit this with serial on STM32 as well.

Thanks for https://github.com/espruino/EspruinoTools/pull/179 - I'll have a look at a fix for the line numbers, because it's pointless and will slow things down too. I forgot it's a default as I think I turn it off here.

espruino --listconfigs has no hint there is something like slowWrite flag

Throttle Send (SERIAL_THROTTLE_SEND)
--------------------------------------
Throttle code when sending to Espruino? If you are experiencing lost characters when sending code from the Code Editor pane, this may help.
Type: {
  "0": "Auto",
  "1": "Always",
  "2": "Never"
}
Default: --config SERIAL_THROTTLE_SEND=0
Current: --config SERIAL_THROTTLE_SEND=0

But perhaps we could improve the description of this so it's easier to find?

Maybe this line could be enabled with "-v"?

I guess we could do that - ideally in https://github.com/espruino/EspruinoTools/blob/8eb606cff5992a64c3127b8bf32fd0b01ad7873c/plugins/versionChecker.js#L59-L66 we do add a print statement that mentions throttling is enabled and to disable it with SERIAL_THROTTLE_SEND=2 though?

Can the slowWrite be false by default?

Not unless there's another option, but it's just a setting that can be changed (see above).

Basically if upload is a bit slow usually nobody really notices, but if it breaks I get all kinds of complaints from everyone and it makes Espruino look unreliable. Which is why the slow write is on by default unless I'm sure it'll work on a device.

As a bit of background: Normally on serial it wouldn't be an issue as Espruino's default baud rate was 9600 baud, but then when the port to ESP8266 was created the contributors chose 115200 baud because, you know, speed. But then it was really unreliable and nobody would change back to 9600 baud so I had to add this whole slow write hack in the IDE just to work around it and bring the speed back down to about 9600 baud :(

I hit this recently, and for me, with USB-TTL connections (and I guess with the TCP connection too) I believe there's quite a large output buffer on the PC. So when the board sends back XOFF there's still several thousand chars en-route still, which then fills up the buffer even when it's at ~2k or more. As far as I can tell there's not really any way around that from Web Serial apart from throttling to reduce the amount of chars en route.

That ESP32 line does look broken, but it may be just as well because I think ESP32 would still break if it was enabled, even with flow control (because of the above): https://github.com/espruino/EspruinoTools/blob/8eb606cff5992a64c3127b8bf32fd0b01ad7873c/plugins/versionChecker.js#L65

If not can the serial_node_socket set it to false like in other place and Telnet is removed from the check?

Yes, I imagine that is fine as hopefully TCP will have the flow control built in anyway so we're not worried about losing things... because XON/XOFF 100% won't work given TCP's lag and buffering.

So really, we're a bit stuck. Definitely, we should be outputting more info in the log about when slow write is enabled, and the config option needed to disable it (but for most people, disabling slow write will just break things). The delay on storage write will help but still if Storage has to be compacted that'll add a delay and the upload will fail.

I feel like slow write is a hack, and there are two main 'proper' solutions, both of which are a bit similar:

gfwilliams commented 2 months ago

To be fair, I just tried and logging does say quite clearly:

Set Slow Write = true ('Throttle Send'='Auto')

I'm not sure it should also spam you with 100s of lines saying it's enabled.

fanoush commented 2 months ago

For me the --config SERIAL_THROTTLE_SEND does not affect the slowWrite flag at all. First I started with version 

Espruino Command-line Tool 0.1.47
-----------------------------------

Throttle Send (SERIAL_THROTTLE_SEND)
--------------------------------------
Throttle code when sending to Espruino? If you are experiencing lost characters when sending code from the Code Editor pane, this may help.
Type: "boolean"
Default: --config SERIAL_THROTTLE_SEND=false
Current: --config SERIAL_THROTTLE_SEND=false

and there it is turned off by default and still it was slow. Now I updated to latest npm version 0.1.56 and it changes to list of values like you say but again, it does not affect the slowWrite variable which is true and stays true and it is slow even with --config SERIAL_THROTTLE_SEND=2.

espruino --no-ble --port tcp://127.0.0.1:2222 --storage _code.js:code.js -v --config SERIAL_THROTTLE_SEND=2
0.1.56
Espruino Command-line Tool 0.1.56
-----------------------------------
...
...
Initialising SetTime
Command-line option set Espruino.Config.SERIAL_THROTTLE_SEND to 2
Connecting to 'tcp://127.0.0.1:2222'
Noble: getPorts - disabled
Connected Ok
Sending block "\n", wait 0ms
Received a prompt after sending newline... good!
Sending...
---> "\u0010print(\"<\",\"<<\",JSON.stringify(process.env),\">>\",\">\")\n"
Sending block "\u0010print(\"<\",\"<<\",JSO", wait 50ms
Sending block "N.stringify(process", wait 50ms
Sending block ".env),\">>\",\">\")\n", wait 0ms
Sent
Receiving...
Got "< << {\"VERSION\":\"2v24.15\",\"GIT_COMMIT\":\"793f23ad4\",\"BOARD\":\"E104BT5032A\",\"RAM\":65536,\"FLASH\":524288,\"STORAGE\":81920,\"SERIAL\":\"cd728763-9f160e6b\",\"CONSOLE\":\"SWDCON\",\"MODULES\":\"Flash,Storage,heatshrink\",\"EXPTR\":386588} >> >\r\n>"
..
..
Splitting for reset(), delay 250
Sending block "\u0010reset();\n", wait 250ms

 ____                 _
|  __|___ ___ ___ _ _|_|___ ___
|  __|_ -| . |  _| | | |   | . |
|____|___|  _|_| |___|_|_|_|___|
         |_| espruino.com
 2v24.15 (c) 2024 G.Williams

Espruino is Open Source. Our work is supported
only by saleSending block "\u0010print()\n\u0010require(\"", wait 50ms
Sending block "Storage\").write(\"_c", wait 50ms
s of official boards and donations:
http://espruino.com/Donate

>
Sending block "ode.js\",atob(\"RS5ra", wait 50ms
Sending block "WNrV2F0Y2hkb2coKTsN", wait 50ms
Sending block "CmZ1bmN0aW9uIEtpY2t", wait 50ms
Sending block "XZCgpew0KICBpZiggKH", wait 50ms
Sending block "R5cGVvZihCVE4xKT09J", wait 50ms
Sending block "3VuZGVmaW5lZCcpfHwo", wait 50ms
Sending block "IUJUTjEucmVhZCgpKSA", wait 50ms
Sending block "pIEUua2lja1dhdGNoZG", wait 50ms
Sending block "9nKCk7DQp9DQp2YXIgd", wait 50ms
Sending block "2RpbnQ9c2V0SW50ZXJ2", wait 50ms
Sending block "YWwoS2lja1dkLDIwMDA", wait 50ms
Sending block "pOw0KLy9FLmVuYWJsZV", wait 50ms
Sending block "dhdGNoZG9nKDE1LCBmY", wait 50ms
Sending block "WxzZSk7DQovLy8qDQov", wait 50ms
....
....

says "Command-line option set Espruino.Config.SERIAL_THROTTLE_SEND to 2" but still splits into 19 chars every 50ms.

BTW where do I see the "Set Slow Write = true ('Throttle Send'='Auto')" log you mentioned? Don't see that on screen with "-v". And the --listconfigs says just

Throttle Send (SERIAL_THROTTLE_SEND)
--------------------------------------
Throttle code when sending to Espruino? If you are experiencing lost characters when sending code from the Code Editor pane, this may help.
Type: {
  "0": "Auto",
  "1": "Always",
  "2": "Never"
}
Default: --config SERIAL_THROTTLE_SEND=0
Current: --config SERIAL_THROTTLE_SEND=0
fanoush commented 2 months ago

Yes, I imagine that is fine as hopefully TCP will have the flow control built in anyway so we're not worried about losing things... because XON/XOFF 100% won't work given TCP's lag and buffering.

I was hoping that would work with openocd telnet port vs espruino command -p tcp://127.0.0.1:2222 but either there is still some bug with XON/XOFF and SWDCON/RTT or you are right.

I reduced buffer to 64 chars https://github.com/fanoush/openocd/blob/f-rtt-server-write-retry/src/server/rtt_server.c#L32 and don't read more data from tcp socket until all those are written to buffer over SWD https://github.com/fanoush/openocd/blob/f-rtt-server-write-retry/src/server/rtt_server.c#L114 and all the time the polling from the device should work and XON/XOFF chars from device should go back to the socket and to espruino command yet I don't see it being logged by espruino command while I see it nicely with nrf52840 USB. Even with slowWrites changed into 64,12,256 block length and 10 ms wait. The device buffer should be definitely filled up and I hope T should get the XOFF back but I don't see it. maybe with openocd and TCP removed in future I'll see it?

I feel like slow write is a hack, and there are two main 'proper' solutions, both of which are a bit similar:

Yes, any of those two would be much better solution, lot of data is going out and nothing back to confirm what happens. The OK looks easier/simpler. If you would define some temporary method to do the write + OK response then the uploaded code could be even slighly smaller due to the require("Storage").write( being replaced in each line by something like "W(" - if that is possible to do safely if W was already defined.

gfwilliams commented 2 months ago

where do I see the "Set Slow Write = true

I just checked and what happened was in the IDE we called setSlowWrite(true) when starting a new connection (which we should do) and then when we figure out what we're connected to we see if we can disable it. So if you connect using the IDE you see the message.

But in the CLI we never called setSlowWrite(true) initially so you only see SetSlowWrite = false on a board it trusts.

I believe I've fixed that now if you use the latest from GitHub, and I added a message too

If you would define some temporary method...

Yes, I had considered that for Bangle.js too. For now it's probably safer not to try

fanoush commented 2 months ago

But in the CLI we never called setSlowWrite(true) initially so you only see SetSlowWrite = false on a board it trusts.

I believe I've fixed that now if you use the latest from GitHub, and I added a message too

Yes, thanks, the https://github.com/espruino/EspruinoTools/commit/b9c0f37b6a64a87e5709c81504ecab5ecc184e48 fixed it, now I can override with --config SERIAL_THROTTLE_SEND=2 and it actually works.

About the OK message, maybe it doesn't need to be after every line but just after last one? What happens for me with SWDCON is that it just takes time but all writes are done correctly even when sent in one big batch so only if after last write there was some \x10print("OK") and the upload would wait for that before quitting or continuing with other stuff that could work. Not sure however what about other transports that could possibly overflow the input buffer or drop data in the middle if it is full. SWDCON now keeps the host waiting with buffer full if it cannot push the input data to Espruino.