What could cause different output for the same code?

106 Views Asked by At

Why does this piece of code produce different output when run in Xcode and Swift Playground?

for i in 0...10 {
    DispatchQueue.global().async {
        DispatchQueue.global().sync {
            print("Print1",i)
        }
        print("Print2",i)
    }
}

Swift Playground Output:

Print1 0
Print1 1
Print1 4
Print1 2
Print1 5
Print1 3
Print1 7
Print1 6
Print1 8
Print1 9
Print1 10
Print2 10
Print2 4
Print2 2
Print2 6
Print2 1
Print2 3
Print2 8
Print2 5
Print2 7
Print2 0
Print2 9

Xcode output:

Print1 0
Print2 0
Print1 2
Print1 3
Print1 4
Print2 4
Print1 6
Print2 6
Print1 8
Print2 8
Print1 10
Print2 10
Print2 2
Print2 3
Print1 5
Print2 5
Print1 9
Print2 9
Print1 7
Print2 7
Print1 1
Print2 1

I ran it on different platforms, and the result was the same.

1

There are 1 best solutions below

0
Rob On

Dispatches to a concurrent queue can introduce races. Unfortunately, Playgrounds introduce sufficient overhead to lead one to incorrect conclusions.

For example, try the following in a playground, where we fetch the queue only once, but otherwise follow the pattern of your original example:

let queue = DispatchQueue.global()
for i in 0...10 {
    queue.async {
        queue.sync {
            print("Print1",i)
        }
        print("Print2",i)
    }
}

In my Playground, I now see:

Print1 0
Print1 1
Print2 0
Print1 2
Print1 3
Print2 1
Print1 4
Print2 3
Print1 5
Print2 4
Print1 6
Print2 5
Print1 7
Print2 6
Print1 8
Print2 7
Print1 9
Print2 8
Print1 10
Print2 9
Print2 10
Print2 2

That more closely resembles the behavior we see in Xcode. (It leads me to believe, to my surprise, that fetching the global queue is sufficiently slow in a Playground to alter the results.) Your results may vary, but you can see that the behavior can vary as a result of the most minor changes, leading to very different conclusions.

Bottom line, avoid using Playgrounds to draw conclusions about specific performance related behaviors in parallel execution. Races (especially when dispatching work items that, themselves, execute so quickly) are hard to manifest consistently. The overhead in Playgrounds can artificially skew the results.


For what it is worth, I prefer to use Instruments (see How to identify key events in Xcode Instruments?) to visually illustrate what is really going on. I also replace the simple print statements with something that is slow enough to actually manifest parallel execution. In the below, I replaced the print statements with a loop that spins on the CPU for one second. As a result, we can see a timeline that shows what really happens in parallel, and what doesn’t. FWIW, I limited this to six iterations, as to not make it too confusing:

enter image description here

The green intervals are where “Print1” was (inside the sync call), the orange intervals are where “Print2” was (after the sync call), and the purple intervals are the async call (where we had both “Print1” and “Print2” for that respective iteration). Because “Print1” and “Print2” have been replaced with spinning loops, we can now clearly see where there is concurrency, and where there are dependencies.

There are really a limited number of conclusions that can be drawn:

  1. Because the simple print statements have been replaced with something that takes a little longer, we mitigate aspects of the races between the “Print1” of one iteration and the “Print2” of other iterations;

  2. The six individual iterations run in parallel with respect to each other (because we are using a global queue, which is a concurrent queue); and

  3. Each “Print2” does not start until its respective “Print1” finishes (because the latter was done synchronously).

Beyond that (e.g., in what order the six parallel iterations actually run), we cannot say much.