Slow WiFi.

[jfjlaros]

I thought it would be a good idea to be able to test the WiFi code myself, so I purchased an Esp32 DevKit v1. This board has both WiFi and Bluetooth on board. New examples can be found here:

• WiFi
• Bluetooth

@chrisflesher I used your example as a template, but I noticed a couple of things while testing the WiFi interface using the test code below. Perhaps you can help me.

• I had to remove the client.flush() and delay(1) lines when using the SocketSerial class on the client side. Otherwise, the client library would randomly crash. Do you need these lines in your example and what happens if you remove them?
• The throughput is really low, even with the fix we discussed a few days ago. I get only about four calls per second, do you have the same experience?

Test code:

from simple_rpc import Interface
interface = Interface('socket://1.2.3.4:1025')
for _ in range(50):
    interface.ping(10)

[chrisflesher]

I think client.flush is an empty function in WiFi101 so it should be safe to take out (I had put it there in case they ever implemented it). The delay was something from another example that I kept in there... I assumed it was doing something but didn't test it. I'll try your branch tomorrow to see if my setup still works without it.

I was able to get ~100 function calls per second by patching pyserial as you suggested. Before the patch I was getting ~3 calls per second which seems similar to what you are getting, maybe the patch is not working as expected on your machine?

[jfjlaros]

Well, the patch does something. Without it I only get about two calls per second.

I will check the ESP32 WiFi libraries for any inserted delays. Thanks for the pointers.

[chrisflesher]

I tried the following program just now with latest arduino-simple-rpc and simpleRPC (from jfjlaros master), removed the client.flush() and delay(1) from the wifi example. Am getting good transfer rates with my Adafruit Feather M0:

from serial.urlhandler import protocol_socket
protocol_socket.time.sleep = lambda x: None
import simple_rpc

c = simple_rpc.Interface('socket://192.168.1.50:10000')
for k in range(50):
    print(c.ping(k))

[jfjlaros]

I traced the problem down to Stream.readBytes(), which takes about 240ms to complete in this setup. I will try to see if I can reproduce this in isolation.

The strange thing is, that the Bluetooth example works fine, so it is not something deep in de ESP32 libraries.

[chrisflesher]

It might be the specific implementation for your microcontrollers Serial.h file of readBytes?

…

On Thu, Jan 21, 2021, 12:52 PM Jeroen F.J. Laros ***@***.***> wrote: I traced the problem down to Serial.readBytes(), which takes about 240ms to complete in this setup. I will try to see if I can reproduce this in isolation. The strange thing is, that the Bluetooth example works fine, so it is not something deep in de ESP32 libraries. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#22 (reply in thread)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAKFJ2VO5YG2UX6IFIKGZD3S3BZWNANCNFSM4WLL2BLA> .

[jfjlaros]

It doesn't look like it, it is not consistent.

When I look at the network traffic, there is a long period between sending a command (requesting an RPC method) and receiving the acknowledgement. The subsequent sending of the parameter values and the return values are fast.

My guess is that there is something going on with the serial-over-tcp code specifically. I will do some more debugging tomorrow.

[chrisflesher]

One idea is to flash an LED when you receive the data to see where the delay is occouring. This was helpful for me when debugging the issue previously.

…

On Thu, Jan 21, 2021 at 4:59 PM Jeroen F.J. Laros ***@***.***> wrote: It doesn't look like it, it is not consistent. When I look at the network traffic, there is a long period between sending a command (requesting an RPC method) and receiving the acknowledgement. The subsequent sending of the parameter values and the return values are fast. My guess is that there is something going on with the serial-over-tcp code specifically. I will do some more debugging tomorrow. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#22 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAKFJ2SSQZRSIYGIXQQ6FWLS3CWWRANCNFSM4WLL2BLA> .

[jfjlaros]

I am using this snippet to do some rudimentary timing analysis. Fortunately I have the luxury of having multiple communication devices on this board.

[chrisflesher]

Not sure if I'm helping but some other ideas for debugging: - Using wireshark to see when ethernet packets are arriving - Investigating the arduino-simple-rpc write process, if it is writing multiple small packets it may speed things up to combine them into one large packet before transmitting? - Investigating the ESP32 WiFi implementation of `readBytes`

[jfjlaros]

I was using wireshark for the network traffic analysis and I indeed noticed that the data is highly fragmented. Although this does not seem to be the source of the problem, it is something to look into at a later stage.

To give you an impression, this is the pattern I see when calling ping(10) multiple times.

  time | direction | flags   | data
-------+-----------+---------+-----------
000000 |     ->    | PSH,ACK | 0x00
247471 |     <-    |     ACK |
247527 |     ->    | PSH,ACK | 0x0a000000
250849 |     <-    | PSH,ACK | 0x0a000000

So from this perspective, it looks like the first call to readBytes() takes a long time, but subsequent reads are fast.

When I look at the timings on the board, I see the following:

delta | label        | description
------+--------------+--------------------------------------------
 0000 | interface    | call to `interface()`, no data
 0000 | interface    | call to `interface()`, no data
 0000 | interface    | call to `interface()`, no data
 0000 | interface    | call to `interface()`, no data
 0000 | read         | call to `readBytes()`, received 0x00
 0015 | read command | read command in `interface()` finished
 0191 | read         | call to `readBytes()`, received 0x0a000000
 0001 | write        | call to `writeBytes()`, sent 0x0a000000
 0192 | select       | select function in `interface()` finished
 0231 | interface    | call to `interface()` finished

From this perspective, the second call to readBytes() takes a long time.

So it seems that the first call to readBytes() works fine, but for some reason no ACK is sent until a timeout occurs (which seems to be around 200ms). This stalls the client, preventing it to send the payload for the second call to readBytes().

[jfjlaros]

I can reproduce this problem in isolation. Two subsequent calls to readBytes() seems to trigger this.

[jfjlaros]

I filed a bug report for this issue.

[jfjlaros]

The issue was solved.