NSLog() producing interleaved output in Xcode console in a multithreaded context

I'm using Xcode 11.2.1 and macOS 10.15.1. Using the following self-contained example code (this replaces the contents of 'ViewController.swift' in Xcode's 'Single View App' template):


import UIKit

class CustomThread: Thread {
    override func main() {
        while true {
            NSLog("test")
        }
    }
}

class ViewController: UIViewController {
    private let thread0 = CustomThread()
    private let thread1 = CustomThread()

    override func viewDidLoad() {
        super.viewDidLoad()

        thread0.start()
        thread1.start()
    }
}


I occasionally get output like this in the Xcode console:


20192019-12-08 14:39:42.525873-0600 my_app[80118:12471303] test
-12-08 14:39:42.525186-0600 my_app[80118:12471302] test


Wherein messages logged from different threads are interleaved with one another. This is on the simulator. I also tried it with a device running iPadOS 13.2.3, but wasn't able to reproduce the behavior there.


If I use print() instead of NSLog(), I don't see any interleaving.


The documentation for print() doesn't appear to address thread safety. In the Thread Programming Guide, NSLog() is listed as being 'generally considered to be thread-safe'. In the documentation for NSLogv(), it says:


"Output from NSLogv is serialized, in that only one thread in a process can be doing the writing/logging described above at a time. All attempts at writing/logging a message complete before the next thread can begin its attempts.


The effects of NSLogv are not serialized with subsystems other than those discussed above (such as the standard I/O package) and do not produce side effects on those subsystems (such as causing buffered output to be flushed, which may be undesirable)."


I'm not entirely clear as to what the second paragraph quoted above means, but I'm wondering if NSLog() being serialized and thread safe doesn't necessarily mean its output is guaranteed to be atomic in the Xcode console.


Is the interleaving in the Xcode console expected behavior? If so, what's the recommended way to log atomically to the Xcode console? Should I use a lock? Or is print() guaranteed to be atomic and therefore preferable?

  • I'm seeing this too, and I'd love to know if it's expected.

Add a Comment