janson
janson

Reputation: 693

Grand Central Dispatches - execution out of order?

I'm trying to get a better understanding of GCD so I wrote the test code below (Bottom). Essentially two functions with waits inside sent on different queues and println on main thread waiting for particular tasks.

I expect the console output should be:

BEFORE FUNCTIONS
start 3 sec loop
start 5 sec loop
end 3 sec loop
BETWEEN FUNCTIONS WAIT ON LONG
AFTER FUNCTIONS WAIT ON LONG
end 5 sec loop
BETWEEN FUNCTIONS WAIT ON LONGER
AFTER FUNCTIONS WAIT ON LONGER

but what I get instead is:

BEFORE FUNCTIONS
start 3 sec loop
start 5 sec loop
BETWEEN FUNCTIONS WAIT ON LONGER
AFTER FUNCTIONS WAIT ON LONGER
end 3 sec loop
BETWEEN FUNCTIONS WAIT ON LONG
AFTER FUNCTIONS WAIT ON LONG
end 5 sec loop

a number of things don't make sense to me - 1. Why are the "Longer" ones printed before the "Long"? 2. Why are the "Longer" ones not printed after the END of the longer i.e. 5 second function?

CODE (ViewController.swift)

import UIKit

class ViewController: UIViewController {
  
  var longQueue = dispatch_group_create()
  var longerQueue = dispatch_group_create()
  var queueLow = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_LOW, 0)
  var queueHigh = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_HIGH, 0)
  
  override func didReceiveMemoryWarning() {
    super.didReceiveMemoryWarning()
  }
  
  override func viewDidLoad() {
    super.viewDidLoad()

    println("BEFORE FUNCTIONS")
    
    dispatch_async(queueHigh) {
      self.longFunc()
    }
    
    dispatch_group_notify(longQueue, dispatch_get_main_queue()) {
      println("BETWEEN FUNCTIONS WAIT ON LONG")
    }
    dispatch_group_notify(longerQueue, dispatch_get_main_queue()) {
      println("BETWEEN FUNCTIONS WAIT ON LONGER")
    }
    
    dispatch_async(queueLow) {
      self.longerFunc()
    }

    dispatch_group_notify(longQueue, dispatch_get_main_queue()) {
      println("AFTER FUNCTIONS WAIT ON LONG")
    }
    dispatch_group_notify(longerQueue, dispatch_get_main_queue()) {
      println("AFTER FUNCTIONS WAIT ON LONGER")
    }
  }
  
  func longFunc () {
    dispatch_group_enter(self.longQueue)
      println("start 3 sec loop")
      sleep(3)
      println("end 3 sec loop")
    dispatch_group_leave(self.longQueue)
  }
  
  func longerFunc() {
    dispatch_group_enter(self.longerQueue)
      println("start 5 sec loop")
      sleep(5)
      println("end 5 sec loop")
    dispatch_group_leave(self.longerQueue)
  }

}

Upvotes: 1

Views: 240

Answers (2)

rob mayoff
rob mayoff

Reputation: 385620

When you queue a block using dispatch_async, there may be some time before that block begins running, during which the queueing thread (the main thread, in your case) continues to run. Then again, the queued block may begin running right away, before the next statement in the queueing thread runs.

When you call dispatch_group_notify, if the group's entry count is zero at that moment, dispatch_group_notify will immediately queue the notification block for execution. But queuing a block for execution is different than running the block! If the dispatch queue is busy, it won't run the notification block right away.

Let's look at how (I deduce) things happened to produce your actual output. After each statement that had some important effect, I'll describe what it did. I'll also put the print actions in bold.

  override func viewDidLoad() {
    super.viewDidLoad()

    println("BEFORE FUNCTIONS")

That line printed BEFORE FUNCTIONS to standard output.

    dispatch_async(queueHigh) {
      self.longFunc()
    }

You queued longFunc to run on queueHigh. It began running immediately and called dispatch_group_enter on longQueue, raising longQueue's entry count to 1. It also printed start 3 sec loop. Then it went to sleep for 3 seconds. It's on a background thread, so this didn't block the main thread.

    dispatch_group_notify(longQueue, dispatch_get_main_queue()) {
      println("BETWEEN FUNCTIONS WAIT ON LONG")
    }

You submitted a notification block to print BETWEEN FUNCTIONS WAIT ON LONG when longQueue's entry count is zero. It's not zero right now, because longFunc entered but hasn't left yet, so the notification block is added to the group, not to the main queue.

    dispatch_group_notify(longerQueue, dispatch_get_main_queue()) {
      println("BETWEEN FUNCTIONS WAIT ON LONGER")
    }

You submitted a notification block to print BETWEEN FUNCTIONS WAIT ON LONGER when longerQueue's entry count is zero. It's zero now, because longerFunc hasn't even been queued yet, so the notification block is immediately added to the main queue. But the main thread is busy running this method (viewDidLoad) right now, so it can't drain the main queue yet.

    dispatch_async(queueLow) {
      self.longerFunc()
    }

You submitted longerFunc to queueLow. It doesn't start running right away.

    dispatch_group_notify(longQueue, dispatch_get_main_queue()) {
      println("AFTER FUNCTIONS WAIT ON LONG")
    }

You submitted a notification block to print AFTER FUNCTIONS WAIT ON LONG when longQueue's entry count is zero. It's not zero right now, because longFunc entered but hasn't left yet, so the notification block is added to the group, not the main queue.

    dispatch_group_notify(longerQueue, dispatch_get_main_queue()) {
      println("AFTER FUNCTIONS WAIT ON LONGER")
    }

You submitted a notification block to print AFTER FUNCTIONS WAIT ON LONGER when longerQueue's entry count is zero. It's zero now, because longerFunc hasn't started yet, so the notification block is immediately added to the main queue. But the main thread is busy running this method (viewDidLoad) right now, so it can't drain the main queue yet.

  }

You returned from viewDidLoad, which lets main thread continue execution of the main run loop. Here's what happened next:

  • longerFunc started running. It called dispatch_group_enter on longerQueue, raising longerQueue's entry count to 1. Note that this does not retroactively remove those notification blocks from the main queue! They were queue at a time when longerQueue's entry count was zero, and they will remain on the main queue until they run, regardless of what happens to longerQueue's entry count later.

  • longerFunc printed start 5 sec loop and then went to sleep for 5 seconds. This is on its own background thread, so it doesn't block the main thread or the thread running longFunc.

  • The main thread's run loop dequeued a block from the main queue and executed it. This was the first notification block you submitted for longerQueue. It printed BETWEEN FUNCTIONS WAIT ON LONGER.

  • The main thread's run loop dequeued another block from the main queue and executed it. This was the second notification block you submitted for longerQueue. It printed AFTER FUNCTIONS WAIT ON LONGER.

  • The main thread's run loop didn't find any more blocks waiting on the main queue. It went to sleep.

  • The longFunc function finished its 3 second sleep. It printed end 3 sec loop.

  • The longFunc function called dispatch_group_leave on longQueue. This lowered the entry count of longQueue to zero, so the group submitted all pending notification blocks to the main queue. This act woke up the main thread's run loop.

  • The main thread's run loop dequeued another block from the main queue and executed it. This was the first notification block you submitted for longQueue. It printed BETWEEN FUNCTIONS WAIT ON LONG.

  • The main thread's run loop dequeued another block from the main queue and executed it. This was the second notification block you submitted for longQueue. It printed AFTER FUNCTIONS WAIT ON LONG.

  • The main thread's run loop didn't find any more blocks waiting on the main queue. It went to sleep.

  • The longerFunc function finished its 5 second sleep. It printed end 5 sec loop.

  • The longerFunc function called dispatch_group_leave on longerQueue. This lowered the entry count of longerQueue to zero. The longerQueue group had no pending notification blocks, so it did nothing.

The end.

Upvotes: 0

Rob
Rob

Reputation: 437582

There are two categories of problems here:

  1. You are entering the dispatch groups inside the longFunc and longerFunc. But, because you're dispatching the calls to those functions to their respective queues, you have no assurances that you're going to reach dispatch_group_enter before you reach the dispatch_group_notify calls you perform in viewDidLoad on the main thread. Also remember that the code that is dispatched to the background queues runs asynchronously and we have no assurances when it runs versus the code that is continuing to execute on the main thread. The key is that if it encounters dispatch_group_notify before you've even entered the group, that notify closure will fire immediately.

    To avoid this race condition, you either want to perform the dispatch_group_enter in viewDidLoad before you dispatch the code to the background queues (and obviously, before you set up the notify closure), or you want to just retire the entering and leaving of the groups and then replace dispatch_async with dispatch_group_async. Either of those approaches ensure that you enter groups before you add the notify closures to those groups.

  2. The dispatch notify closure that reports "BETWEEN FUNCTIONS WAIT ON LONGER" is an even more egregious example, where there's not even a race condition. You are simply adding that notify closure before you even dispatch the function that will later enter the group. So this will almost certainly fire before you code is dispatched to that queue.

Upvotes: 2

Related Questions