RLock doesn't work like I'd expect

[Erick Jones]

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

[ddorian43]

> From my understanding of normal mutex behavior, conventionally the other greenthread should've been ahead in the queue.

Where is this queue located? Can you link to it in the source code? (I couldn't find it)