Use-dependent write timeouts

[chelsell]

Hello again,

I'm working with an Arduino Mega in Windows 10. Recently, my application crashes with a pyserial write timeout after about 10 minutes of working perfectly. I don't know what has changed that is causing this issue, I've tried rolling back both pymata and my application to a date where everything seemed stable, but no luck. I can confirm from my serial port monitor that there is a write timeout right before the crash happens. Setting writeTimeout = 0 in pymata_serial.py definitely seems to fix this problem--is there anything I should be worried about using that setting?

It seems like this crash is associated with writing to the Arduino again after a period of inactivity where audio is played over the line out using pyaudio. I don't see how audio could possibly affect the existing pyserial connection though.

Any insight you may have into this problem would be greatly appreciated!

-CH

[MrYsLab]

A write_timeout value of 0 means "non-blocking". If it is working for you it should not be an issue. Looking at the pyserial issues list, there seems to be several reported issues involving Windows 10 and the pyserial timeouts. However if you are combining pyaudio and pymata-aio within the same process, most likely pyaudio is blocking the asyncio event loop of pymata-aio, causing the issue, and not a Windows 10/pyserial issue. Mixing asyncio and non-asyncio libraries is tricky and should be avoided. If it is possible to run the pyaudio portion in a separate thread, o better yet, a separate process, this may solve the problem.

[chelsell]

@MrYsLab thanks, I'll have to test out a different implementation of the audio. It's still a little vexing because we never had this problem before, but it seems like the cause must be beyond the scope of your package. I'll post here if I find something that might help people in the future.

[MrYsLab]

Thanks for the info. PyAudio looks like it calls time.sleep() which is a blocking call. I am not sure why things suddenly started giving you problems, but if I can help, please feel free to ask.

[chelsell]

@MrYsLab I think I'm still encountering stability issues related to this problem. I'm not sure if I can make the ~PyAudio~ simpleaudio portion run in a separate process since my application needs to schedule both arduino writes and ~PyAudio~ simpleaudio* playback in the same timeframe. Maybe this is too broad a question, but how would you do that in order to maximize stability? Right now, the schedule is a single loop that either writes to the arduino or plays audio, like so:

*the way we're using simpleaudio doesn't block or call time.sleep(), so maybe that's not the problem?

class Schedule:
    """
    This class is itself a queue: It will drop elements out of Schedule.queue as they are taken.
    """

    stimulus_list = None  # type: List[Tuple[int, Stimulus]]
    queue = None  # type: LifoQueue
    time_range = None  # type: Iterable[float]
    n_ms_total = None

    def __init__(self, stimulus_list: List[Tuple[int, Stimulus]], n_ms_total: int) -> None:
        """Stimulus_list is in MILLISECONDS."""

        self.stimulus_list = stimulus_list
        self.queue = LifoQueue()
        self.time_range = range(0, len(self.stimulus_list))
        self.n_ms_total = n_ms_total

        # sorting on tuples apparently sorts by the first index first
        for index_ms, stimulus in sorted(stimulus_list, key=lambda x: x[0], reverse=True):

            seconds = index_ms / 1000

            if stimulus.is_digital():
                pin = config.stimuli['digital_pins'][stimulus.name]
                self.queue.put_nowait(ScheduledStimulus(seconds, stimulus, pin))
                #logging.debug("Scheduling digital pin {} = {} for frame {}ms and stimulus {}".format(pin, bool(stimulus.intensity != 0), index_ms, stimulus.name))

            elif stimulus.is_analog():
                pin = config.stimuli['analog_pins'][stimulus.name]
                self.queue.put_nowait(ScheduledStimulus(seconds, stimulus, pin))
                #logging.debug("Scheduling digital pin {} = {} for frame {}ms and ".format(pin, stimulus.intensity, index_ms, stimulus.name))

            elif stimulus.is_audio():
                self.queue.put_nowait(ScheduledStimulus(seconds, stimulus, None))
                #logging.debug("Scheduling wav file {} playing at {} dB for frame {}ms".format(stimulus.name, stimulus.intensity, index_ms))

            else:
                raise ValueError("No stimulus type {}".format(stimulus.name))

    def get_nowait(self) -> ScheduledStimulus:
        return self.queue.get_nowait()

    def run_scheduled_and_wait(self, board: Board, audio: SauronxAudio) -> StimulusTimeLog:
        """Runs the stimulus schedule immediately.
        This runs the scheduled stimuli and blocks. Does not sleep.
        """

        stimulus_time_log = StimulusTimeLog()
        stimulus_time_log.start()  # This is totally fine: It happens at time 0 in the stimulus_list AND the full battery.

        t0 = monotonic()
        for _ in self.time_range:
            stimulus = self.get_nowait()
            while monotonic() - t0 < stimulus.scheduled_seconds: pass

            # Use self._board.digital_write and analog_write because we don't want to perform checks (for performance)
            if stimulus.is_digital():
                board._board.digital_write(stimulus.pin, stimulus.intensity)
            elif stimulus.is_analog():
                board._board.analog_write(stimulus.pin, stimulus.intensity)
            elif stimulus.is_audio():
                try:
                    audio.play(stimulus.audio_obj)  # volume is handled internally
                except BaseException as e:
                    logging.error("Failed to play audio stimulus {} at {}".format(stimulus, monotonic()-t0))
                    logging.error(e)
            else:
                raise ValueError("Invalid stimulus type %s!" % stimulus.stim_type)

            stimulus_time_log.append(StimulusTimeRecord(stimulus, datetime.datetime.now()))

        # This is critical. Otherwise, the StimulusTimeLog will finish() at the time the last stimulus is applied, not the time the battery ends
        # TODO simplify StimulusTimeLog so that we don't need this wait: It's just start + length
        while monotonic() - t0 < self.n_ms_total / 1000: pass
        stimulus_time_log.finish()
        return stimulus_time_log  # for trimming camera frames

I'm not sure if this changes anything, but elsewhere we're also setting callbacks for arduino sensors (for logging only, those callbacks don't send any new commands to the board) and spawning a thread that uses PyAudio to record from a microphone. My intuition is that we probably need to switch to pymata_core and wrap this all in asyncio, but I'm curious to hear what you think.

EDIT: based on your remarks in other issues, I figured that spawning the recording as a new thread rather than a new process might be contributing to the instability. It wasn't hard to make the recording its own process, so hopefully that helps.

[MrYsLab]

@chelsell Normally, file manipulation, like streaming a file a file, or reading or writing a file, is a blocking call. Trying to wrap simpleaudio in asyncio is probably going to be very difficult to do. I think the simplest option is to go from pymata-aio to PyMata, assuming it has all the functionality you need. Its API is very simliar to pymata-aio, but slightly different. It has the callback facility, so I think it will work for your application. Using PyMata will allow you to run the Arduino/PyMata code in one thread and allow you to create a separate thread for the simpleaudio functionality. I hope this helps.