Swift pthread read/write lock taking a while to release the lock

Question

I am trying to implement a read/write lock in Swift with the pthread API's and I have come across a strange issue.

My implementation is largely based on the following with the addition of a timeout for attempted read locks.

http://swiftweb.johnholdsworth.com/Deferred/html/ReadWriteLock.html

Here is my implementation:

 public final class ReadWriteLock {

        private var lock = pthread_rwlock_t()

        public init() {
            let status = pthread_rwlock_init(&lock, nil)
            assert(status == 0)
        }

        deinit {
            let status = pthread_rwlock_destroy(&lock)
            assert(status == 0)
        }

        @discardableResult
        public func withReadLock<Result>(_ body: () throws -> Result) rethrows -> Result {
            pthread_rwlock_rdlock(&lock)
            defer { pthread_rwlock_unlock(&lock) }
            return try body()
        }

        @discardableResult
        public func withAttemptedReadLock<Result>(_ body: () throws -> Result) rethrows -> Result? {
            guard pthread_rwlock_tryrdlock(&lock) == 0 else { return nil }
            defer { pthread_rwlock_unlock(&lock) }
            return try body()
        }

        @discardableResult
        public func withAttemptedReadLock<Result>(_ timeout: Timeout = .now, body: () throws -> Result) rethrows -> Result? {
            guard timeout != .now else { return try withAttemptedReadLock(body) }

            let expiry = DispatchTime.now().uptimeNanoseconds + timeout.rawValue.uptimeNanoseconds
            var ts = Timeout.interval(1).timespec
            var result: Int32
            repeat {
                result = pthread_rwlock_tryrdlock(&lock)
                guard result != 0 else { break }
                nanosleep(&ts, nil)
            } while DispatchTime.now().uptimeNanoseconds < expiry

            // If the lock was not acquired
            if result != 0 {
                // Try to grab the lock once more
                result = pthread_rwlock_tryrdlock(&lock)
            }
            guard result == 0 else { return nil }
            defer { pthread_rwlock_unlock(&lock) }
            return try body()
        }

        @discardableResult
        public func withWriteLock<Return>(_ body: () throws -> Return) rethrows -> Return {
            pthread_rwlock_wrlock(&lock)
            defer { pthread_rwlock_unlock(&lock) }
            return try body()
        }
    }

/// An amount of time to wait for an event.
public enum Timeout {
    /// Do not wait at all.
    case now
    /// Wait indefinitely.
    case forever
    /// Wait for a given number of seconds.
    case interval(UInt64)
}

public extension Timeout {

    public var timespec: timespec {
        let nano = rawValue.uptimeNanoseconds
        return Darwin.timespec(tv_sec: Int(nano / NSEC_PER_SEC), tv_nsec: Int(nano % NSEC_PER_SEC))
    }

    public var rawValue: DispatchTime {
        switch self {
            case .now:
                return DispatchTime.now()
            case .forever:
                return DispatchTime.distantFuture
            case .interval(let milliseconds):
                return DispatchTime(uptimeNanoseconds: milliseconds * NSEC_PER_MSEC)
        }
    }
}

extension Timeout : Equatable { }

public func ==(lhs: Timeout, rhs: Timeout) -> Bool {
    switch (lhs, rhs) {
        case (.now, .now):
            return true
        case (.forever, .forever):
            return true
        case (let .interval(ms1), let .interval(ms2)):
            return ms1 == ms2
        default:
            return false
    }
}

Here is my unit test:

func testReadWrite() {
    let rwLock = PThreadReadWriteLock()
    let queue = OperationQueue()
    queue.maxConcurrentOperationCount = 2
    queue.qualityOfService = .userInteractive
    queue.isSuspended = true

    var enterWrite: Double = 0
    var exitWrite: Double = 0
    let writeWait: UInt64 = 500
    // Get write lock
    queue.addOperation {
        enterWrite = Double(Timeout.now.rawValue.uptimeNanoseconds) / Double(NSEC_PER_MSEC)
        rwLock.withWriteLock {
            // Sleep for 1 second
            var ts = Timeout.interval(writeWait).timespec
            var result: Int32
            repeat { result = nanosleep(&ts, &ts) } while result == -1
        }
        exitWrite = Double(Timeout.now.rawValue.uptimeNanoseconds) / Double(NSEC_PER_MSEC)
    }

    var entered = false
    var enterRead: Double = 0
    var exitRead: Double = 0
    let readWait = writeWait + 50
    // Get read lock
    queue.addOperation {
        enterRead = Double(Timeout.now.rawValue.uptimeNanoseconds) / Double(NSEC_PER_MSEC)
        rwLock.withAttemptedReadLock(.interval(readWait)) {
            print("**** Entered! ****")
            entered = true
        }
        exitRead = Double(Timeout.now.rawValue.uptimeNanoseconds) / Double(NSEC_PER_MSEC)
    }

    queue.isSuspended = false
    queue.waitUntilAllOperationsAreFinished()

    let startDifference = abs(enterWrite - enterRead)
    let totalWriteTime = abs(exitWrite - enterWrite)
    let totalReadTime = abs(exitRead - enterRead)
    print("Start Difference: \(startDifference)")
    print("Total Write Time: \(totalWriteTime)")
    print("Total Read Time: \(totalReadTime)")

    XCTAssert(totalWriteTime >= Double(writeWait))
    XCTAssert(totalReadTime >= Double(readWait))
    XCTAssert(totalReadTime >= totalWriteTime)
    XCTAssert(entered)
}

Finally, the output of my unit test is the following:

Start Difference: 0.00136399269104004
Total Write Time: 571.76081609726
Total Read Time: 554.105705976486

Of course, the test is failing because the write lock is not released in time. Given that my wait time is only half a second (500ms), why is it taking roughly 570ms for the write lock to execute and release?

I have tried executing with optimizations both on and off to no avail.

I was under the impression that nanosleep is high resolution sleep timer I would expect to have a resolution of at least 5-10 milliseconds here for the lock timeout.

Can anyone shed some light here?

Answer 1

Turns out foundation was performing some kind of optimization with the OperationQueue due to the long sleep in my unit test.

Replacing the sleep function with usleep and iterating with a 1ms sleep until the total time is exceed seems to have fixed the problem.

    // Get write lock
    queue.addOperation {
        enterWrite = Double(Timeout.now.rawValue.uptimeNanoseconds) / Double(NSEC_PER_MSEC)
        rwLock.withWriteLock {
            let expiry = DispatchTime.now().uptimeNanoseconds + Timeout.interval(writeWait).rawValue.uptimeNanoseconds
            let interval = Timeout.interval(1)
            repeat {
                interval.sleep()
            } while DispatchTime.now().uptimeNanoseconds < expiry
        }
        exitWrite = Double(Timeout.now.rawValue.uptimeNanoseconds) / Double(NSEC_PER_MSEC)
    }