Skip to content

Improve slcan.py #1490

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 21 commits into from
Feb 4, 2023
Merged

Improve slcan.py #1490

merged 21 commits into from
Feb 4, 2023

Conversation

mikisama
Copy link
Contributor

  1. Improve receiving performance
  2. Fix an issue that the first read may blocking even if the timeout parameter is not None.

1. Improve receiving performance
2. Fix an issue that the first read may blocking even if the `timeout`
   parameter is not `None`.
@mikisama
Copy link
Contributor Author

test code

bus = slcanBus(channel="COM11", bitrate=20000)

tx_msg = Message(
    arbitration_id=0x3C,
    is_extended_id=False,
    is_remote_frame=False,
    dlc=8,
    data=bytes(
        [
            0x01,
            0x02,
            0x10,
            0x01,
            0xFF,
            0xFF,
            0xFF,
            0xFF,
        ]
    ),
)

rx_msg = Message(
    arbitration_id=0x3D,
    is_extended_id=False,
    is_remote_frame=True,
    dlc=8,
)

for _ in range(16):
    bus.send(tx_msg)
    bus.send(rx_msg)
    msg = bus.recv()
    print(msg)

bus.shutdown()

gap is 39ms

old

gap is 1ms

new

| ID:0x3C | ID:0x3D | <-- gap(39ms) --> | ID:0x3C | ID:0x3D |

| ID:0x3C | ID:0x3D | <-- gap(1ms) ---> | ID:0x3C | ID:0x3D |

@@ -161,7 +162,6 @@ def _read(self, timeout: Optional[float]) -> Optional[str]:
while not (
ord(self._OK) in self._buffer or ord(self._ERROR) in self._buffer
):
self.serialPortOrig.timeout = time_left
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why did you remove this?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Setting the serial port timeout in the while loop slow down the RX performance.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there a way to ensure, that the function respects the timeout parameter?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there a way to ensure, that the function respects the timeout parameter?

  • This is the test code for testing the timeout parameter
import time

from can.interfaces.slcan import slcanBus
from can.message import Message

bus = slcanBus(channel="COM11", bitrate=20000, sleep_after_open=0)

tx_msg = Message(
    arbitration_id=0x3C,
    is_extended_id=False,
    is_remote_frame=False,
    dlc=8,
    data=bytes(
        [
            0x01,
            0x02,
            0x10,
            0x01,
            0xFF,
            0xFF,
            0xFF,
            0xFF,
        ]
    ),
)

rx_msg = Message(
    arbitration_id=0x3D,
    is_extended_id=False,
    is_remote_frame=True,
    dlc=8,
)

count = 5
timeout = 1

start_time = time.time()
for _ in range(count):
    bus.send(tx_msg)
    bus.send(rx_msg)
    msg = bus.recv(timeout)
    assert msg is None
    print(msg)
end_time = time.time()
spend_time = end_time - start_time
assert abs((timeout * count) - spend_time) < 0.1
print(f"{spend_time:.3f}")

bus.shutdown()
  • This is the result
    image

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

With this proposed change I think there's still a scenario where the timeout is not enforced.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

read_all sounds good to me.

    def _read(self, timeout: Optional[float]) -> Optional[str]:
        _timeout = serial.Timeout(timeout)

        with error_check("Could not read from serial device"):
            while not _timeout.expired():
                new_data = self.serialPortOrig.read_all()
                if new_data is not None:
                    self._buffer.extend(new_data)
                else:
                    time.sleep(0.001)
                    continue

                for terminator in (self._ERROR, self._OK):
                    if terminator in self._buffer:
                        i = self._buffer.index(terminator) + 1
                        string = self._buffer[:i].decode()
                        del self._buffer[:i]
                        return string

            return None

The serial port must be instantiated with timeout=0.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But what about when there is data in the buffer? What if there were an infinite amount of 'junk'?

@Tbruno25

def read(self, __size: int = ...) -> bytes: ...
def read_all(self):
    return self.read(self.in_waiting)
  1. If there is data in the buffer, the read method only copies it out. Only when the data bytes in the buffer are smaller than the parameter __size, the read method will blocking until the data bytes in the buffer is __size, then copy it out.
  2. Since the in_waiting parameter shows the current number of bytes in the buffer, blocking will not occur. (The time to copy data out is negligibly small)
  3. According to my test, the MAX receive buffer size in win10 is 16384, and ubuntu 20.04 is 4095. I'm not sure whether it can be changed. But I think there will not be infinite junk.
import serial
import time

with serial.Serial("COM11") as ser:
    # send a start command to make
    # the STM32 dev board start sending data.
    ser.write(b"start")

    while True:
        time.sleep(0.5)
        print(f"in_waiting {ser.in_waiting}")

image

image

Copy link
Contributor Author

@mikisama mikisama Jan 27, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@zariiii9003

Looks good. Just a few minor changes requested.

According to my test, the read_all method returns b'' if there is no data that can be read out.

So the if new_data is not None: should be changed to if new_data:, otherwise it will never do time.sleep, which will cause high CPU usage.

    def _read(self, timeout: Optional[float]) -> Optional[str]:
        _timeout = serial.Timeout(timeout)

        with error_check("Could not read from serial device"):
            while not _timeout.expired():
                new_data = self.serialPortOrig.read_all()
                if new_data:
                    self._buffer.extend(new_data)
                else:
                    time.sleep(0.001)
                    continue

                for terminator in (self._ERROR, self._OK):
                    if terminator in self._buffer:
                        i = self._buffer.index(terminator) + 1
                        string = self._buffer[:i].decode()
                        del self._buffer[:i]
                        return string

            return None

The serial port must be instantiated with timeout=0.

By the way, I did not initialize the timeout parameter of serialPortOrig at all and it defaults to None. It seems still works for me.

I'm curious. If you don't set the timeout to 0, what will happen to you?

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm curious. If you don't set the timeout to 0, what will happen to you?

Nothing, i don't have an interface to test this 😄

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

According to my test, the MAX receive buffer size in win10 is 16384, and ubuntu 20.04 is 4095. I'm not sure whether it can be changed. But I think there will not be infinite junk.

Interesting! And I agree -- I wasn't considering the physical limitations of the hardware/kernel. Good catch 🙂

Copy link
Contributor Author

@mikisama mikisama left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The timeout parameter still needs to improve.

@zariiii9003 zariiii9003 added this to the Next Release milestone Jan 27, 2023
@mikisama
Copy link
Contributor Author

mikisama commented Jan 27, 2023

@zariiii9003

There is a slight performance difference between the _read method using pyserial.read_all and pyserial.read.
Any suggestions?

Performance Comparison

# the original version
| ID:0x3C | ID:0x3D | <-- 39ms    ---> | ID:0x3C | ID:0x3D |

# the read_all version
| ID:0x3C | ID:0x3D | <-- 2~3.8ms ---> | ID:0x3C | ID:0x3D |

# the read version
| ID:0x3C | ID:0x3D | <-- 1~2ms   ---> | ID:0x3C | ID:0x3D |

read
read_all

the performance test code

from can.interfaces.slcan import slcanBus
from can.message import Message

bus = slcanBus(channel="COM11", bitrate=20000, sleep_after_open=0)

data_frm = Message(
    arbitration_id=0x3C,
    is_extended_id=False,
    is_remote_frame=False,
    dlc=8,
)

remote_frm = Message(
    arbitration_id=0x3D,
    is_extended_id=False,
    is_remote_frame=True,
    dlc=8,
)

for _ in range(16):
    # send a data frame
    bus.send(data_frm)
    # send a remote frame
    bus.send(remote_frm)
    # receive a data frame if a node respond the remote frame
    msg = bus.recv()
    print(msg)

# bus.shutdown()

_read method using pyserial.read_all

def _read(self, timeout: Optional[float]) -> Optional[str]:
    _timeout = serial.Timeout(timeout)

    with error_check("Could not read from serial device"):
        while True:
            new_data = self.serialPortOrig.read_all()
            if new_data:
                self._buffer.extend(new_data)
            else:
                if _timeout.expired():
                    break
                else:
                    time.sleep(0.001)
                    continue

            for terminator in (self._ERROR, self._OK):
                if terminator in self._buffer:
                    i = self._buffer.index(terminator) + 1
                    string = self._buffer[:i].decode()
                    del self._buffer[:i]
                    return string

        return None

_read method using pyserial.read

def _read(self, timeout: Optional[float]) -> Optional[str]:
    _timeout = serial.Timeout(timeout)
    self.serialPortOrig.timeout = timeout

    with error_check("Could not read from serial device"):
        while True:
            new_data = self.serialPortOrig.read()
            if new_data:
                self._buffer.extend(new_data)
            else:
                if _timeout.expired():
                    break
                else:
                    continue

            for terminator in (self._ERROR, self._OK):
                if terminator in self._buffer:
                    i = self._buffer.index(terminator) + 1
                    string = self._buffer[:i].decode()
                    del self._buffer[:i]
                    return string

        return None

@zariiii9003
Copy link
Collaborator

Can you tell whether the delay is due to time.sleep or the in_waiting call of pyserial?

@mikisama
Copy link
Contributor Author

Can you tell whether the delay is due to time.sleep or the in_waiting call of pyserial?

@zariiii9003

When I remove time.sleep(0.001), their performance is almost the same. But the CPU usage is high.
Maybe pyserial.read is a better choice. What do you think? 🤔

@zariiii9003
Copy link
Collaborator

Yes, i agree, your pyserial.read seems like a good compromise. Regarding the sleep, did you test this on Python 3.11? There have been improvements regards sleep precision.

@mikisama
Copy link
Contributor Author

mikisama commented Jan 28, 2023

Yes, you are right. python 3.11.1 have better performance than python 3.10.8.

# the read_all version with python 3.10.8
| ID:0x3C | ID:0x3D | <-- 2~3.8ms ---> | ID:0x3C | ID:0x3D |

# the read_all version with python 3.11.1
| ID:0x3C | ID:0x3D | <-- 1~2.4ms ---> | ID:0x3C | ID:0x3D |

In python 3.11.1, almost all gaps are 2ms, and some gaps are 1ms
In python 3.10.8, almost all gaps are 3ms, and some gaps are 2ms.

image

@zariiii9003
Copy link
Collaborator

Since self.serialPortOrig.read() only reads a single byte, we can simplify the control flow a bit:

    def _read(self, timeout: Optional[float]) -> Optional[str]:
        _timeout = serial.Timeout(timeout)
        self.serialPortOrig.timeout = timeout

        with error_check("Could not read from serial device"):
            while True:
                new_byte = self.serialPortOrig.read(size=1)
                if new_byte:
                    self._buffer.extend(new_byte)

                if new_byte in (self._ERROR, self._OK):
                    string = self._buffer.decode()
                    del self._buffer[:]
                    return string

                if _timeout.expired():
                    break

            return None

I added size=1 and renamed new_data so it is more obvious to the reader.

@mikisama
Copy link
Contributor Author

Since self.serialPortOrig.read() only reads a single byte, we can simplify the control flow a bit:

    def _read(self, timeout: Optional[float]) -> Optional[str]:
        _timeout = serial.Timeout(timeout)
        self.serialPortOrig.timeout = timeout

        with error_check("Could not read from serial device"):
            while True:
                new_byte = self.serialPortOrig.read(size=1)
                if new_byte:
                    self._buffer.extend(new_byte)

                if new_byte in (self._ERROR, self._OK):
                    string = self._buffer.decode()
                    del self._buffer[:]
                    return string

                if _timeout.expired():
                    break

            return None

I added size=1 and renamed new_data so it is more obvious to the reader.

Yes, Looks better. 👍

to make the code easier to understand and read.
Copy link
Contributor Author

@mikisama mikisama left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Still need to improve.

Can not handle partial receive

After the test, I found a very strange thing.

When the timeout=0, the previous version received fewer None.

Before.
image

After change.
image

Copy link
Contributor Author

@mikisama mikisama left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Still need to improve.

string = self._buffer[:i].decode()
del self._buffer[:i]
return string
else:
if _timeout.expired():
Copy link
Contributor Author

@mikisama mikisama Jan 29, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we really need _timeout to handle timeout?

The timeout can be determined when pyserial.read returns b''.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The timeout of pyserial.read is reset on every read call, so it might add up. The timeout argument of the user should be respected, _timeout takes care of that.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the timeout's add up should be ignored.
For python on windows, the timer's resolution is about 16ms, obviously it is not very accurate.
And I think the timeout add up is not as big as the impact of timer jitter.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That depends on the timeout value, It might be seconds, or minutes, or hours, i don't know what users might be doing.

@zariiii9003
Copy link
Collaborator

You call it with timeout=0, it times out immediately. Call it with timeout=None for a blocking call. That behaviour seems correct to me.

@mikisama
Copy link
Contributor Author

You call it with timeout=0, it times out immediately. Call it with timeout=None for a blocking call. That behaviour seems correct to me.

Yes, calling it with timeout=None is ok, and I rarely set timeout to 0 when I actually use it.
But some unit tests contain recv(0) and all of them failed.

def _read(self, timeout: Optional[float]) -> Optional[str]:
    _timeout = serial.Timeout(timeout)
    self.serialPortOrig.timeout = timeout

    with error_check("Could not read from serial device"):
        while True:
            new_byte = self.serialPortOrig.read(1)
            if new_byte:
                self._buffer.extend(new_byte)

            if new_byte in (self._ERROR, self._OK):
                string = self._buffer.decode()
                del self._buffer[:]
                return string

            if _timeout.expired():
                break

        return None

image

@zariiii9003
Copy link
Collaborator

How about this? I added the in_waiting check before the timeout check.

    def _read(self, timeout: Optional[float]) -> Optional[str]:
        _timeout = serial.Timeout(timeout)
        self.serialPortOrig.timeout = timeout

        with error_check("Could not read from serial device"):
            while True:
                new_byte = self.serialPortOrig.read(size=1)
                if new_byte:
                    self._buffer.extend(new_byte)

                if new_byte in (self._ERROR, self._OK):
                    string = self._buffer.decode()
                    del self._buffer[:]
                    return string

                if self.serialPortOrig.in_waiting:
                    continue

                if _timeout.expired():
                    break

            return None

@mikisama
Copy link
Contributor Author

How about this? I added the in_waiting check before the timeout check.

    def _read(self, timeout: Optional[float]) -> Optional[str]:
        _timeout = serial.Timeout(timeout)
        self.serialPortOrig.timeout = timeout

        with error_check("Could not read from serial device"):
            while True:
                new_byte = self.serialPortOrig.read(size=1)
                if new_byte:
                    self._buffer.extend(new_byte)

                if new_byte in (self._ERROR, self._OK):
                    string = self._buffer.decode()
                    del self._buffer[:]
                    return string

                if self.serialPortOrig.in_waiting:
                    continue

                if _timeout.expired():
                    break

            return None

Unit test passed.
Currently, I don't have a SLCAN device around. I'll have to do a test with a SLCAN device tomorrow and tell you the results.

image

@zariiii9003
Copy link
Collaborator

zariiii9003 commented Jan 30, 2023

What if we call in_waiting only once?

    def _read(self, timeout: Optional[float]) -> Optional[str]:
        _timeout = serial.Timeout(timeout)
        self.serialPortOrig.timeout = timeout

        with error_check("Could not read from serial device"):
            while True:
                for _ in range(max(1, self.serialPortOrig.in_waiting)):
                    new_byte = self.serialPortOrig.read(size=1)
                    if new_byte:
                        self._buffer.extend(new_byte)
					else:
					    break
				    
                    if new_byte in (self._ERROR, self._OK):
                        string = self._buffer.decode()
                        del self._buffer[:]
                        return string

                if _timeout.expired():
                    break

            return None

Edit: i added max, otherwise we'll cause a hot loop and high CPU usage again.

@mikisama
Copy link
Contributor Author

What if we call in_waiting only once?

    def _read(self, timeout: Optional[float]) -> Optional[str]:
        _timeout = serial.Timeout(timeout)
        self.serialPortOrig.timeout = timeout

        with error_check("Could not read from serial device"):
            while True:
                for _ in range(max(1, self.serialPortOrig.in_waiting)):
                    new_byte = self.serialPortOrig.read(size=1)
                    if new_byte:
                        self._buffer.extend(new_byte)
					else:
					    break
				    
                    if new_byte in (self._ERROR, self._OK):
                        string = self._buffer.decode()
                        del self._buffer[:]
                        return string

                if _timeout.expired():
                    break

            return None

Edit: i added max, otherwise we'll cause a hot loop and high CPU usage again.

Better than pyserial.read_all version but not as good as justpyserial.read.
CPU usage is almost unchanged

@mikisama
Copy link
Contributor Author

I try remove the _timeout

def _read(self, timeout: Optional[float]) -> Optional[str]:
    self.serialPortOrig.timeout = timeout

    with error_check("Could not read from serial device"):
        while True:
            new_byte = self.serialPortOrig.read(1)
            if new_byte:
                self._buffer.extend(new_byte)
                if new_byte in (self._ERROR, self._OK):
                    i = self._buffer.index(new_byte) + 1
                    string = self._buffer[:i].decode()
                    del self._buffer[:i]
                    return string
            else:
                break

        return None

Then run this code

from can.interfaces.slcan import slcanBus
from can.message import Message

bus = slcanBus(channel="COM11", bitrate=20000, sleep_after_open=0)

data_frm = Message(
    arbitration_id=0x3C,
    is_extended_id=False,
    is_remote_frame=False,
    dlc=8,
    data=bytes(
        [
            0x01,
            0x02,
            0x10,
            0x01,
            0xFF,
            0xFF,
            0xFF,
            0xFF,
        ]
    ),
)

remote_frm = Message(
    arbitration_id=0x3D,
    is_extended_id=False,
    is_remote_frame=True,
    dlc=8,
    data=None,
)

TIMEOUT = 1
# TIMEOUT = 10
# TIMEOUT = 100

for _ in range(64):
    # send a data frame
    bus.send(data_frm)
    # send a remote frame
    bus.send(remote_frm)
    # receive a data frame if a node respond the remote frame
    # I make the stm32 device not ack the remote frame, so `recv` will always bloking and return `None`
    msg = bus.recv(TIMEOUT)
    assert msg is None
    print(msg)

# bus.shutdown()

TIMEOUT=1 and we got 1006.03ms
image

TIMEOUT=10 and we got 10.00914s =>10009.14ms
image

TIMEOUT=100 and we got 1:40.01856 => 100018.56ms
image

The pyserial.timeout was more accurate than we expected.
The timeout add-up effect is not obvious.

@zariiii9003
Copy link
Collaborator

But how can you ensure the timeout? Try this example:

import time
from threading import Thread

from can.interfaces.slcan import slcanBus


def send_thread(_bus: slcanBus):
    while True:
        bus.serialPortOrig.write(b"f")
        time.sleep(2.0)


if __name__ == '__main__':
    bus = slcanBus(channel="loop://")
    thread = Thread(target=send_thread, args=(bus,))
    thread.start()
    while True:
        t0 = time.perf_counter()
        bus.recv(3.0)
        print(time.perf_counter() - t0)

It should time out every 3 seconds, but it blocks forever.

@mikisama
Copy link
Contributor Author

mikisama commented Jan 31, 2023

But how can you ensure the timeout? Try this example:

import time
from threading import Thread

from can.interfaces.slcan import slcanBus


def send_thread(_bus: slcanBus):
    while True:
        bus.serialPortOrig.write(b"f")
        time.sleep(2.0)


if __name__ == '__main__':
    bus = slcanBus(channel="loop://")
    thread = Thread(target=send_thread, args=(bus,))
    thread.start()
    while True:
        t0 = time.perf_counter()
        bus.recv(3.0)
        print(time.perf_counter() - t0)

It should time out every 3 seconds, but it blocks forever.

Thanks for the example code, I finally get your point.

I noticed that there are two types of SLCAN devices categorized by how data is transmitted to the PC.

  1. Serial based. The MCU sends the SLCAN data byte by byte to FT232 through the UART, then the FT232 sends the SLCAN data to PC through the USB.
CAN <--> MCU <--> FT232 <--> PC
  1. USB CDC VCOM based. The MCU sends the whole SLCAN data to the PC via one USB transfer.
CAN <--> MCU <--> PC

Since my SLCAN device is CDC VCOM based. Before seeing your example code, I don't understand why there is an add-up effect.😂

@mikisama
Copy link
Contributor Author

mikisama commented Jan 31, 2023

What if we call in_waiting only once?

    def _read(self, timeout: Optional[float]) -> Optional[str]:
        _timeout = serial.Timeout(timeout)
        self.serialPortOrig.timeout = timeout

        with error_check("Could not read from serial device"):
            while True:
                for _ in range(max(1, self.serialPortOrig.in_waiting)):
                    new_byte = self.serialPortOrig.read(size=1)
                    if new_byte:
                        self._buffer.extend(new_byte)
					else:
					    break
				    
                    if new_byte in (self._ERROR, self._OK):
                        string = self._buffer.decode()
                        del self._buffer[:]
                        return string

                if _timeout.expired():
                    break

            return None

Edit: i added max, otherwise we'll cause a hot loop and high CPU usage again.

@zariiii9003
I'm sorry. This code works fine. I don't know why the test result was not very good yesterday.
This code is currently the best solution.

But it still can't handle timeout accurately.
image

@mikisama
Copy link
Contributor Author

I change self.serialPortOrig.timeout=timeout to self.serialPortOrig.timeout=0.001
It can now handle timeout with relative accuracy.

image

@@ -287,7 +287,9 @@ def get_version(

string = self._read(timeout)

if len(string) == 6 and string[0] == cmd:
if not string:
Copy link
Contributor Author

@mikisama mikisama Jan 31, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Re-added the None checking.
Due to the unit test using the loop:// parameter, self._read will read back the content sent by self._write(cmd). It can not catch the None error.

image

the data in the input buffer.
@mikisama
Copy link
Contributor Author

@zariiii9003
Do you know what's wrong with pypy?
Some github CI tests failed, and they were all pypy based.

@mikisama mikisama requested review from zariiii9003 and Tbruno25 and removed request for zariiii9003 and Tbruno25 February 1, 2023 01:29
Copy link
Collaborator

@zariiii9003 zariiii9003 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM. I will merge if you are happy with the performance.

@mikisama
Copy link
Contributor Author

mikisama commented Feb 4, 2023

LGTM. I will merge if you are happy with the performance.

Thanks for your review. The performance seems to be good so far.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants