I'm sure it's working as designed, but it's still baffling to me. Maybe there's a way to make it work the way I want?
The issue is that if a greenthread releases and then re-acquires an RLock without doing any blocking operations in between, it will be able to immediately re-acquire that lock even if another greenthread was already waiting. From my understanding of normal mutex behavior, conventionally the other greenthread should've been ahead in the queue.
Below is some example code. In my original program, the io_loop is sending a lot of data over a slow link, and heartbeat_loop is supposed to send something once a second. For the sake of having a self-contained example, this just does gevent.sleep in lieu of actual I/O operations, but hopefully it conveys.
import logging
from datetime import datetime, timedelta
import gevent.pool
import gevent.lock
import sys
logger = logging.getLogger('rlock-test-1')
out_mtx = gevent.lock.RLock()
def init_log():
stream_fmt = '%(asctime)s [%(name)s] %(levelname)s - %(message)s'
logging.basicConfig(level='INFO', force=True, format=stream_fmt, stream=sys.stderr)
def main():
group = gevent.pool.Group()
group.spawn(heartbeat_loop)
group.spawn(io_loop)
group.join()
def io_loop():
counter = 0
for i in range(10):
with out_mtx:
gevent.sleep(0.7) # Imagine this is a slow I/O operation
counter += 1
logger.info('Sent packet %d', counter)
# gevent.sleep(0.1) # If we add this sleep here, it gives the heartbeats a chance to run
def heartbeat_loop():
counter = 0
t_start = datetime.utcnow().replace(microsecond=0)
ts = t_start + timedelta(seconds=1)
for i in range(8):
now = datetime.utcnow()
delay = (ts - now).total_seconds()
if delay > 0.1:
gevent.sleep(delay)
with out_mtx:
gevent.sleep(0.1) # Imagine this is a quick I/O operation
counter += 1
logger.info('Sent heartbeat %d', counter)
ts += timedelta(seconds=1)
if __name__ == '__main__':
init_log()
main()
Here's the output, note that the "heartbeats" are all sent after the "packets":
2023-11-29 14:03:19,941 [rlock-test-1] INFO - Sent packet 1
2023-11-29 14:03:20,643 [rlock-test-1] INFO - Sent packet 2
2023-11-29 14:03:21,344 [rlock-test-1] INFO - Sent packet 3
2023-11-29 14:03:22,045 [rlock-test-1] INFO - Sent packet 4
2023-11-29 14:03:22,746 [rlock-test-1] INFO - Sent packet 5
2023-11-29 14:03:23,448 [rlock-test-1] INFO - Sent packet 6
2023-11-29 14:03:24,149 [rlock-test-1] INFO - Sent packet 7
2023-11-29 14:03:24,850 [rlock-test-1] INFO - Sent packet 8
2023-11-29 14:03:25,552 [rlock-test-1] INFO - Sent packet 9
2023-11-29 14:03:26,253 [rlock-test-1] INFO - Sent packet 10
2023-11-29 14:03:26,354 [rlock-test-1] INFO - Sent heartbeat 1
2023-11-29 14:03:26,454 [rlock-test-1] INFO - Sent heartbeat 2
2023-11-29 14:03:26,555 [rlock-test-1] INFO - Sent heartbeat 3
2023-11-29 14:03:26,656 [rlock-test-1] INFO - Sent heartbeat 4
2023-11-29 14:03:26,757 [rlock-test-1] INFO - Sent heartbeat 5
2023-11-29 14:03:26,857 [rlock-test-1] INFO - Sent heartbeat 6
2023-11-29 14:03:26,958 [rlock-test-1] INFO - Sent heartbeat 7
2023-11-29 14:03:27,058 [rlock-test-1] INFO - Sent heartbeat 8