unreliable / unpredictable results using the API

[Human]

Firing off API commands like print() or setFastBacklight() can result in an OSError, number 121 or 5. The raw number of the exceptions is reduced by sleeping "enough" between commands, but not necessarily the frequency of exceptions per API call. Receiving an OSError number 121 almost always causes "glitching" of the display, where unexpected characters print it in unexpected places. A number 5 usually does not result in glitching, but it can still happen.

This issue appears to have old origins and is not unique to this python API: https://community.sparkfun.com/t/20x4-lcd-screen-troubles-with-speed/15438/3

A newer, more thorough discussion mirroring my experience is here: https://community.sparkfun.com/t/serlcd-i2c-timing-issue/39322

Quoting from TS Chris from 2020:

if you send a command before the LCD has completed the previous instruction, unpredictable things happen on the display.

I don’t think we take into account how long the various commands take to process, (by the LCD controller, not the ATmega on the LCD) but that might be a good addition to future firmware revisions.

It sure seems to be the case that this is not unique to the Python API, and it has been an issue for 5-15 years. I was building an application that would smartly update only changed data, but with all the error handling and sleep() statements to try to reduce the likelihood of exceptions, it was ironically much faster to just blindly update the entire display as fast as the API allows. I can achieve a 1Hz refresh rate with occasional glitching that lasts a maximum of 1s. When attempting to sleep() strategically to avoid exceptions, the "smart" refresh of only changed text was actually slower.

[sfe-SparkFro]

Thanks for the report! Can you please share some sample code that replicates the problem, and the exact output you're seeing?

Skimming through this and the links you sent, I agree that this seems to be an issue with firing commands too quickly. However just for completeness, could you please answer the following:

Which exact product are you using? Do you know the SKU or exact product name?

Based on conversation from #8, you're using a Raspberry Pi, correct? Just in case it helps us, which Pi are you using (3/4/5?), and which version of PiOS are you running? Also, have you changed your I2C config at all in /boot/config.txt? If so, please share what changes you have made.

How have you wired up the LCD to your Pi? Are you using a Qwiic cable that goes to headers? Or are you using the Qwiic Shim by chance? How long is the cable? Do you have any other devices on your I2C bus?

Thanks!

[Human]

I wrote a quick and dirty test to exercise the API and characterize the issue. Because it employs sleep() with increasing durations as the code runs, it will obviously take time to have results for longer sleep durations, but here is what I have so far:

import qwiic_serlcd
import time

lcd = qwiic_serlcd.QwiicSerlcd()
lcd.begin()
lcd.leftToRight()
lcd.noCursor()
lcd.disableSystemMessages()
lcd.setContrast(0)
lcd.clearScreen()

exception_max = 10

exception_count = 0
print_calls = 0
sleep_amount = 0.0

def maybe_sleep():
    if sleep_amount > 0:
        time.sleep(sleep_amount)

maybe_sleep()

started_at = time.time()

while True:
    try:
        print_calls += 1
        lcd.print(str(exception_count)[0])
    except OSError as e:
        exception_count += 1
        exceptions_per_second = exception_count / (time.time() - started_at)
        print("with sleep " + str(round(sleep_amount,2)) + " and " + str(print_calls) + " print() calls, exceptions per second: " + str(exceptions_per_second))
    maybe_sleep()
    if exception_count == exception_max:  # every N exceptions, try incrementing post-print() sleep a little
        print(str(exception_count) + " exceptions after " + str(print_calls) + " print() calls over " + str(time.time() - started_at) + "s")
        sleep_amount += 0.1
        exception_count = 0
        print_calls = 0
        started_at = time.time()

# nohup unbuffer python3 ./exception_demo.py > log &

Partial results:

with sleep 0.0 and 1487 print() calls, exceptions per second: 0.06321613383076233
with sleep 0.0 and 1514 print() calls, exceptions per second: 0.12424038612321846
with sleep 0.0 and 1976 print() calls, exceptions per second: 0.14267480078595396
with sleep 0.0 and 6799 print() calls, exceptions per second: 0.055120106009018885
with sleep 0.0 and 6808 print() calls, exceptions per second: 0.06881825122271357
with sleep 0.0 and 7203 print() calls, exceptions per second: 0.07805577371237842
with sleep 0.0 and 7424 print() calls, exceptions per second: 0.08836072572105227
with sleep 0.0 and 7555 print() calls, exceptions per second: 0.09924187624132452
with sleep 0.0 and 7617 print() calls, exceptions per second: 0.11074980787712219
with sleep 0.0 and 13567 print() calls, exceptions per second: 0.06904271271339822
10 exceptions after 13567 print() calls over 144.8380434513092s
with sleep 0.1 and 1172 print() calls, exceptions per second: 0.0077097910296984
with sleep 0.1 and 2816 print() calls, exceptions per second: 0.006414040775282841
with sleep 0.1 and 3489 print() calls, exceptions per second: 0.007764763262819661
with sleep 0.1 and 3909 print() calls, exceptions per second: 0.009240472209644508
with sleep 0.1 and 5799 print() calls, exceptions per second: 0.007785252289723893
with sleep 0.1 and 7337 print() calls, exceptions per second: 0.007383619169579452
with sleep 0.1 and 8406 print() calls, exceptions per second: 0.007518587186597376
with sleep 0.1 and 9739 print() calls, exceptions per second: 0.007416427796495289
with sleep 0.1 and 9961 print() calls, exceptions per second: 0.008157564775244512
with sleep 0.1 and 11248 print() calls, exceptions per second: 0.008026750261945558
10 exceptions after 11248 print() calls over 1245.934531211853s
with sleep 0.2 and 670 print() calls, exceptions per second: 0.0070918259289542524
with sleep 0.2 and 1240 print() calls, exceptions per second: 0.007658804536581528
with sleep 0.2 and 2014 print() calls, exceptions per second: 0.007071038901564199
with sleep 0.2 and 3617 print() calls, exceptions per second: 0.005248438406258121
with sleep 0.2 and 3865 print() calls, exceptions per second: 0.006139536160899171
with sleep 0.2 and 7983 print() calls, exceptions per second: 0.0035664525440419217
with sleep 0.2 and 8690 print() calls, exceptions per second: 0.003822308069429095
with sleep 0.2 and 8980 print() calls, exceptions per second: 0.004227285074182265
with sleep 0.2 and 9267 print() calls, exceptions per second: 0.004608413919052429
with sleep 0.2 and 9268 print() calls, exceptions per second: 0.005119933591486357
10 exceptions after 9268 print() calls over 1953.3505952358246s
with sleep 0.3 and 730 print() calls, exceptions per second: 0.004413843801674778
with sleep 0.3 and 2781 print() calls, exceptions per second: 0.002314936937576378
with sleep 0.3 and 6823 print() calls, exceptions per second: 0.0014150246724586209
with sleep 0.3 and 13115 print() calls, exceptions per second: 0.0009814745349473644
with sleep 0.3 and 15049 print() calls, exceptions per second: 0.0010691682181579443
with sleep 0.3 and 16439 print() calls, exceptions per second: 0.0011745134699011701
with sleep 0.3 and 17280 print() calls, exceptions per second: 0.0013035741705828986
with sleep 0.3 and 20423 print() calls, exceptions per second: 0.0012605148917629338
with sleep 0.3 and 23309 print() calls, exceptions per second: 0.0012424917804218715
with sleep 0.3 and 25762 print() calls, exceptions per second: 0.00124908842793967
10 exceptions after 25762 print() calls over 8006.13858795166s
with sleep 0.4 and 4539 print() calls, exceptions per second: 0.0005364488887407087
with sleep 0.4 and 5246 print() calls, exceptions per second: 0.000928280940307991
with sleep 0.4 and 5650 print() calls, exceptions per second: 0.0012928427975247004
with sleep 0.4 and 6461 print() calls, exceptions per second: 0.0015073828821149321
with sleep 0.4 and 6911 print() calls, exceptions per second: 0.001761527090967029
with sleep 0.4 and 7842 print() calls, exceptions per second: 0.0018628473699845325
with sleep 0.4 and 10670 print() calls, exceptions per second: 0.0015972417194580167
with sleep 0.4 and 11454 print() calls, exceptions per second: 0.001700464579662426
with sleep 0.4 and 11616 print() calls, exceptions per second: 0.0018863442544019117
with sleep 0.4 and 11793 print() calls, exceptions per second: 0.0020644813175541834
10 exceptions after 11793 print() calls over 4844.231974363327s
with sleep 0.5 and 884 print() calls, exceptions per second: 0.0022172212077801855
with sleep 0.5 and 1444 print() calls, exceptions per second: 0.002713550262051358
with sleep 0.5 and 3665 print() calls, exceptions per second: 0.0016030164664190345
with sleep 0.5 and 4170 print() calls, exceptions per second: 0.001878455033846892
with sleep 0.5 and 4693 print() calls, exceptions per second: 0.002086337034269355
with sleep 0.5 and 5036 print() calls, exceptions per second: 0.002333058216231401
with sleep 0.5 and 6296 print() calls, exceptions per second: 0.0021770896722765583
with sleep 0.5 and 8443 print() calls, exceptions per second: 0.0018553188592517228
with sleep 0.5 and 8569 print() calls, exceptions per second: 0.0020565434166879538
with sleep 0.5 and 10025 print() calls, exceptions per second: 0.0019531403958657724
10 exceptions after 10025 print() calls over 5120.459891319275s
with sleep 0.6 and 298 print() calls, exceptions per second: 0.005512614856531368
with sleep 0.6 and 303 print() calls, exceptions per second: 0.010843270811779753
with sleep 0.6 and 1116 print() calls, exceptions per second: 0.004405259825571539
with sleep 0.6 and 1213 print() calls, exceptions per second: 0.005403643725099416
with sleep 0.6 and 1433 print() calls, exceptions per second: 0.005716863831052716
with sleep 0.6 and 1815 print() calls, exceptions per second: 0.005415566989016103
with sleep 0.6 and 1822 print() calls, exceptions per second: 0.00629392801350661
with sleep 0.6 and 2020 print() calls, exceptions per second: 0.006487665064199869
with sleep 0.6 and 2352 print() calls, exceptions per second: 0.006267925907372588
with sleep 0.6 and 2671 print() calls, exceptions per second: 0.006132286770840074
10 exceptions after 2671 print() calls over 1631.3133091926575s
with sleep 0.7 and 97 print() calls, exceptions per second: 0.01465491357438665
with sleep 0.7 and 448 print() calls, exceptions per second: 0.006294980819428757
with sleep 0.7 and 2332 print() calls, exceptions per second: 0.0018106938017379045
with sleep 0.7 and 2484 print() calls, exceptions per second: 0.0022664767734913984
with sleep 0.7 and 3881 print() calls, exceptions per second: 0.0018130331169669753
with sleep 0.7 and 4356 print() calls, exceptions per second: 0.0019383471060490055
with sleep 0.7 and 4368 print() calls, exceptions per second: 0.002255197848362106
with sleep 0.7 and 5089 print() calls, exceptions per second: 0.0022121417273608156
with sleep 0.7 and 5623 print() calls, exceptions per second: 0.0022522795331473694
with sleep 0.7 and 7550 print() calls, exceptions per second: 0.0018637184105948792
10 exceptions after 7550 print() calls over 5366.31769990921s
with sleep 0.8 and 330 print() calls, exceptions per second: 0.003748809516366629
with sleep 0.8 and 1408 print() calls, exceptions per second: 0.001753207626937887
with sleep 0.8 and 3808 print() calls, exceptions per second: 0.0009719317278914516
with sleep 0.8 and 4567 print() calls, exceptions per second: 0.0010804938256985424
with sleep 0.8 and 5006 print() calls, exceptions per second: 0.0012321530236336308
with sleep 0.8 and 5097 print() calls, exceptions per second: 0.0014521835010165055
with sleep 0.8 and 7312 print() calls, exceptions per second: 0.0011809158531701702
with sleep 0.8 and 8858 print() calls, exceptions per second: 0.00111403820373335
with sleep 0.8 and 9769 print() calls, exceptions per second: 0.001136406284567551
with sleep 0.8 and 9868 print() calls, exceptions per second: 0.0012500059315843717
10 exceptions after 9868 print() calls over 8000.7623081207275s
with sleep 0.9 and 117 print() calls, exceptions per second: 0.009464935026226768
with sleep 0.9 and 1526 print() calls, exceptions per second: 0.0014399326264738974
with sleep 0.9 and 1770 print() calls, exceptions per second: 0.0018619912907495476
with sleep 0.9 and 1911 print() calls, exceptions per second: 0.0022993910674373513
with sleep 0.9 and 2539 print() calls, exceptions per second: 0.0021630400131587794
with sleep 0.9 and 2877 print() calls, exceptions per second: 0.002290600533524881
with sleep 0.9 and 4094 print() calls, exceptions per second: 0.0018777683375489635
with sleep 0.9 and 8005 print() calls, exceptions per second: 0.0010974070616271018
with sleep 0.9 and 9190 print() calls, exceptions per second: 0.0010753739363783428
with sleep 0.9 and 9445 print() calls, exceptions per second: 0.001162598442690873
10 exceptions after 9445 print() calls over 8602.322418928146s
with sleep 1.0 and 319 print() calls, exceptions per second: 0.0031110814646025647
with sleep 1.0 and 1236 print() calls, exceptions per second: 0.0016021621114865583
with sleep 1.0 and 1627 print() calls, exceptions per second: 0.0018253505877930754
with sleep 1.0 and 2373 print() calls, exceptions per second: 0.001668362744507108
with sleep 1.0 and 2815 print() calls, exceptions per second: 0.001757890246720035
with sleep 1.0 and 3151 print() calls, exceptions per second: 0.001884462344518776
with sleep 1.0 and 3459 print() calls, exceptions per second: 0.002002719113036603
with sleep 1.0 and 6257 print() calls, exceptions per second: 0.0012651344183718931
with sleep 1.0 and 6864 print() calls, exceptions per second: 0.0012973946151447183
with sleep 1.0 and 7701 print() calls, exceptions per second: 0.0012848517297617016
10 exceptions after 7701 print() calls over 7783.999480009079s

Product specs:

SparkFun 20x4 SerLCD - RGB Backlight (Qwiic)

SKU: LCD-16398

Yes, I'm using a Raspberry Pi 4B running 2024-11-19-raspios-bookworm-arm64-lite. In order to enable i2c, I had to alter /boot/firmware/config.txt to uncomment dtparam=i2c_arm=on

The hardware is connected to the Pi via a short qwiic cable, maybe 5", wired to the SDA, SCL, 3.3V, and GND pins. It's the only thing attached to the Pi other than the combo PoE and screw terminal hat.

[Human]

I'll have more sleep time increments available tomorrow, but I have already spotted an odd trend. Outliers aside, it tends to be the case that we accumulate an OSError every 1000 calls to print(), regardless of sleep() time. It's entirely possible that sleeping up to and including 1s is insufficient, though. In a POC project I have, I have seen OSError thrown even after sleeping 8s between API calls. (It will obviously take a long time to more formally test this case.)

[sfe-SparkFro]

Thank you, we'll take a look and see if we can replicate!

[sfe-SparkFro]

Firing off API commands like print() or setFastBacklight() can result in an OSError, number 121 or 5.

Looks like numbers 5 and 121 correspond to EIO and EREMOTEIO respectively. I can't find clear documentation on what exactly those mean, but I do know that EIO in MicroPython typically happens when a device fails to send an ACK.

@malcolm-sparkfun was able to replicate both with a Raspberry Pi and in MicroPython (edit: MicroPython actually seems stable, looking into it more now). He captured this trace with a logic analyzer showed a failed ACK:

So it seems the reason for the exceptions is that the Serial LCD fails to send an ACK. But why would it fail to send an ACK?

This issue appears to have old origins and is not unique to this python API: https://community.sparkfun.com/t/20x4-lcd-screen-troubles-with-speed/15438/3

The second comment in this thread mentioned that the LCD driver (HD44780) has a busy flag that should be checked before sending instructions. We went down that rabbit hole for a bit, but even if that is a problem, I don't see how that would explain exceptions being thrown. It could explain the graphics failing to render, but not a failed ACK.

The I2C interface doesn't actually go to the HD44780, it goes to an ATmega328P running this firmware which then interfaces with the HD44780. The I2C receive handler ISR simply copies the data into a buffer; nothing in there gives me any indication of what might cause the ACK, it's not like it's blocking or anything. So I think it should be able to handle data being sent to it at any rate. Which brings me back to your test results:

Partial results:

I've summarized your results in the table below:

Sleep time (s)	Number of print() calls before 10 exceptions
0.0	13567
0.1	11248
0.2	9268
0.3	25762
0.4	11793
0.5	10025
0.6	2671
0.7	7550
0.8	9868
0.9	9445
1.0	7701

Also decided to plot it and get an R² value:

Obviously there's some randomness here. Out of 118898 total calls to print(), there were 100 exceptions, so a roughly 1 in 1000 chance.

But more importantly, there doesn't seem to be an overwhelmingly clear trend here (R²=0.181 is not at all statistically significant). These kinds of systems operate on the order of milliseconds and microseconds, so if adding a full second of delay doesn't make a substantial improvement, then I don't think adding delays to your code will help much, if at all.

However, when a function like print() is called, it actually sends multiple bytes in rapid succession. So it's possible that adding delays to this driver between those bytes might help. But that feels like a poor workaround, and still doesn't explain why it's failing to ACK in the first place. Nor does that explain why your display would glitch out sometimes.

Edit:

Never mind, it only sends one byte at a time with a delay. Though maybe this delay isn't long enough? Or something? Idk, grasping at straws here.

qwiic_serlcd_py/qwiic_serlcd.py

Lines 213 to 225 in 5aa62c6

	def print(self, string):
	"""!
	Print a string of characters to the LCD
	@param string string: The string you would like to print. Aka ASCII characters. example: "Hello"
	@return **bool** Returns True if the I2C writes were successful, otherwise False.
	"""
	for c in string:
	if self._i2c.writeCommand(self.address, ord(c)) == False:
	return False
	time.sleep(0.01)
	return True

[sfe-SparkFro]

Update:

This was captured using code that first calls setCursor() immediately followed by print(), so there's no delay. It failed periodically on a Raspberry Pi 4B, but worked consistently in MicroPython. The trace with the MicroPython device showed a ~200us delay between transmissions, so I suspect this particular failure mode can be resolved by simply adding a delay to all I2C instructions. Doesn't explain the root problem, but might at least serve as a workaround.

These traces we captured using code that only calls print(). This shows a missing clock pulse between the device address byte and the data byte. This looks like a different failure mode, I suspect caused by clock stretching from the ATmega328P, and the Raspberry Pi failing to wait for the clock stretch to resolve. AFAIK this is an outstanding issue with the Raspberry Pi 4 (sounds like it might be resolved on the Pi 5?).

[sfe-SparkFro]

Ok, I'm going to diagnose this as 2 different problems:

1. Clock stretching
   • The ATmega328P can sometimes have a small amount of clock stretching between bytes within a single I2C transaction. The hardware I2C peripherals on the Broadcom chips used up through the Pi 4 do not handle this correctly, and this seems to be fairly well known. The Pi 5 uses the RP1 for hardware I2C, which does appear to handle clock stretching correctly (I just tested that). So you've got a couple options:
     1. Switch to a Pi 5. Obviously this is not feasible in many cases, but it's good to know that the newer board is better, at least as far as this issue goes.
     2. Use software I2C. There's some instructions here on how to do that, which is a little involved, but theoretically should work (I've not tested myself).
2. Delay between commands
   • For some reason, it seems the ATmega328P sometimes needs some extra delay between commands. I don't fully understand why this is, but if you send multiple commands immediately, it seems to fail to send an ACK sometimes. Maybe this can be fixed with a firmware update, maybe not. But at least for now, there is a workaround that seems to work, which is to put delays between all I2C commands (I tested 1ms between setCursor() and print() and it worked fine, other commands may need longer). This can be achieved in a couple ways:
     1. In your code, add delays after all LCD commands. 1ms may be sufficient, but some commands may need longer.
     2. Update this Python driver (and our Arduino library) to have appropriate delays after all commands. We'll take a crack at this, but you can at least use the solution above in the meantime.

@Human Hope this helps!

[Human]

Thanks for that great analysis!

Based on the silk screening on the board I have, it looks like it also has support for SPI. If I hook it up over SPI instead of I2C, I would avoid any clock stretching issues on the Pi 4, right? Then I could re-run my tests with varying amounts of sleep after commands to see if the OSError (and resulting screen corruption) every ~1000 API calls goes away.

FWIW, more tests completed overnight, and, as you predicted, longer sleep times (up to 4s) didn't help.

I can also flash experimental firmware upgrades if you think there's value in doing so. I have worked with Arduinos before, but I may need some pointers on how to flash the embedded ATmega328P on the LCD board.

[sfe-SparkFro]

If I hook it up over SPI instead of I2C, I would avoid any clock stretching issues on the Pi 4, right?

Good point! Yes, I expect SPI would be much more reliable. Though that would require modification of this driver to use SPI instead of I2C, which is not something that's on our roadmap at this time. I think the simpler solution would be to just use software I2C, since that's a relatively simple configuration change on your Pi, as opposed to rewriting this driver.

FWIW, more tests completed overnight, and, as you predicted, longer sleep times (up to 4s) didn't help.

Good to know, thank you for sharing!

I can also flash experimental firmware upgrades if you think there's value in doing so

Thanks for the offer! We would first need to identify what the root problem is, which could be difficult and time consuming. Though maybe sparkfun/OpenLCD#34 is related? TBH if just adding small delays to this driver resolves the problem, we're probably likely to just leave that as a workaround without a firmware change, because doing a firmware change is actually a really big pain for us.

[Human]

FYI, I tried this unmaintained but recent python port of Sparkfun's Arduino library: https://github.com/fourstix/Sparkfun_CircuitPython_SerLCD

If I sleep for 0.005s after each write() call, I get no visual glitching. The major advantage of the serial connection on the LCD board is its speed; I am refreshing the entire LCD at about 18Hz. The major disadvantage is that the serial connection to the LCD board is receive-only so even if the underlying chipset could provide feedback, there's no board wiring for it. However, this disadvantage is mitigated by the reliability of that small sleep.

Does this result make sense? If the I2C library is running into speed limits on the ATmega328P, shouldn't those same speed limits apply to the serial library? I'm assuming that each library is communicating with the ATmega328P, but maybe that's not so.