CODEWITHSUNDEEP
objective-cgrand-central-dispatch
onTheWay
onTheWay

Reputation: 128

Why weird behavior of barrier on concurrent queue?

I am trying to verify the functionality of dispatch_barrier_async, and use "points of interest" to check what happened.

The code is as below:

_syncQueue = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0);

for (int index = 0; index < 3; ++index) {
    kdebug_signpost_start(0, 0, 0, 0, 0);
    dispatch_sync(_syncQueue, ^{
        NSLog(@"sync@@@@@@ >>>>    %d ",index);
        sleep(1);
        NSLog(@"sync@@@@@@ <<<<    %d ",index);

    });
    kdebug_signpost_end(0, 0, 0, 0, 0);
}

for (int index = 3; index < 6; ++index) {
    kdebug_signpost_start(1, 0, 0, 0, 1);
    dispatch_barrier_async(_syncQueue, ^{
        NSLog(@"sync===== >>>>    %d ",index);
        sleep(1);
        NSLog(@"sync===== <<<<    %d ",index);

    });
    kdebug_signpost_end(1, 0, 0, 0, 1);
}

for (int index = 6; index < 9; ++index) {
    kdebug_signpost_start(2, 0, 0, 0, 2);
    dispatch_sync(_syncQueue, ^{
        NSLog(@"sync***** >>>>    %d ",index);
        sleep(1);
        NSLog(@"sync***** <<<<    %d ",index);
    });
    kdebug_signpost_end(2, 0, 0, 0, 2);
}

I expect that

But the result is as below:

sync@@@@@@ >>>>    0
sync@@@@@@ <<<<    0
sync@@@@@@ >>>>    1
sync@@@@@@ <<<<    1
sync@@@@@@ >>>>    2
sync@@@@@@ <<<<    2
sync***** >>>>    6
sync===== >>>>    3
sync===== >>>>    4
sync===== >>>>    5
sync***** <<<<    6
sync***** >>>>    7
sync===== <<<<    3
sync===== <<<<    4
sync===== <<<<    5
sync***** <<<<    7
sync***** >>>>    8

My confusion as below:

  1. since task 6 is already started before task 3, and task 3 is dispatch_barrier_async dispatched task, why taks 3 does not wait task 6 finish and then start ? which violates my expectation a);

  2. after dispatch_barrier_async dispatched task 5 start to work, another task 7 is started before task 5 finished, which violates my expectation b)

I use "points of interest" tool to debug it, but seems, the 2nd loop does not shows on the graphic generated by intrument. it's my first time to use this tool, Could someone help to point out what's the issue here ?

enter image description here

[04/02] Thanks Rob. Here are some update after following your suggestion.

Update1: After change the queue creation method of 2nd loop to dispatch_queue_create, it works well. the tasks dispatched by dispatch_barrier_async will wait for the tasks before them to finish. and the tasks after them will start util they(tasks dispatched by dispatch_barrier_async) finished.

enter image description here

update2: Then I used the code you provided, and change the queue creation of 2nd loop back to dispatch_async, they also works as expection. But, the "points of interest" graphic has some problem. some task in 2nd loop cannot be displayed correctly.

  1. Xcode indicate some error for (0x4 0x0 0x0 0x1) and (0x5 0x0 0x0 0x1), as "The interval can not be logged as an interval because the start could not be determined."

  2. the (0x3 0x0 0x0 0x1) is not listed, but (0x5 0x0 0x0 0x1) is listed twice. and only one (0x5 0x0 0x0 0x1) displayed on the graphic

  3. I never see an indicator Ⓢ in the "points of interest" tool.

That yields the following messages:

00:00.000.000 2ndLoop (KDebug Interval Signpost) ended by test.app (pid: 64903, tid: 0x1619027), with arguments: (0x4 0x0 0x0 0x1). The interval can not be logged as an interval because the start could not be determined. __kdebug_trace64 ← (8 other frames)

00:00.000.000 2ndLoop (KDebug Interval Signpost) ended by test.app (pid: 64903, tid: 0x1619028), with arguments: (0x5 0x0 0x0 0x1). The interval can not be logged as an interval because the start could not be determined. __kdebug_trace64 ← (8 other frames)

00:04.134.364 2ndLoop (KDebug Interval Signpost), started by test.app (pid: 64903, tid: 0x1619028), with arguments: (0x5 0x0 0x0 0x1), ended 1.00 s later by test.app (pid: 64903, tid: 0x1619026), with arguments: (0x3 0x0 0x0 0x1) __kdebug_trace64 ← (9 other frames)

enter image description here

Upvotes: 1

Views: 261

Answers (1)

Rob
Rob

Reputation: 437442

There are two separate issues:

  1. You cannot use barriers with global queues. A barrier says "don't run anything on this queue while this dispatched task is running", so the OS obviously doesn't like it when you try to do that on a global queue. As the documentation says, it will only honor barriers on custom concurrent queues, not global queues:

    The queue you specify should be a concurrent queue that you create yourself using the dispatch_queue_create function. If the queue you pass to this function is a serial queue or one of the global concurrent queues, this function behaves like the dispatch_async function

    Create your own concurrent queue, and it should work as expected.

    dispatch_queue_t queue = dispatch_queue_create("com.domain.app.test", DISPATCH_QUEUE_CONCURRENT);

    Yielding:

    enter image description here

  2. Your "Points of Interest" graph is showing the dispatching process (i.e. how much time is being taken up on the main thread), not the running of the tasks, themselves. So in your 2nd loop iterations, the asynchronous dispatching of them only took 25.54, 5.17, and 4.72 μs (microseconds) each. That's why you don't see your second iterations graphically in the "Points of Interest" tool. They're happening too quickly to be graphically represented. (By the way, this is a very good thing, and is why we never dispatch slow tasks synchronously; we never want to block the main thread.)

    Generally, when diagnosing GCD behavior, I find it more useful to the "points of interest" regions to represent the running of the tasks, not the dispatching of the tasks.

    To achieve this, it's probably more useful to put the os_signpost statements (formerly kdebug) inside the blocks, yielding the above diagram. Thus:

    dispatch_queue_t queue = dispatch_queue_create("com.domain.app.test", DISPATCH_QUEUE_CONCURRENT);

os_log_t log = os_log_create("ViewController", OS_LOG_CATEGORY_POINTS_OF_INTEREST);

for (int index = 0; index < 3; ++index) {
    os_signpost_event_emit(log, OS_SIGNPOST_ID_EXCLUSIVE, "first loop", "dispatching iteration %d", index);
    dispatch_sync(queue, ^{
        os_signpost_id_t identifier = os_signpost_id_generate(log);
        os_signpost_interval_begin(log, identifier, "first loop", "Iteration %d", index);
        sleep(1);
        os_signpost_interval_end(log, identifier, "first loop", "Iteration %d", index);
    });
}

for (int index = 3; index < 6; ++index) {
    os_signpost_event_emit(log, OS_SIGNPOST_ID_EXCLUSIVE, "second loop", "dispatching iteration %d", index);
    dispatch_barrier_async(queue, ^{
        os_signpost_id_t identifier = os_signpost_id_generate(log);
        os_signpost_interval_begin(log, identifier, "second loop", "Iteration %d", index);
        sleep(1);
        os_signpost_interval_end(log, identifier, "second loop", "Iteration %d", index);
    });
}

for (int index = 6; index < 9; ++index) {
    os_signpost_event_emit(log, OS_SIGNPOST_ID_EXCLUSIVE, "third loop", "dispatching iteration %d", index);
    dispatch_sync(queue, ^{
        os_signpost_id_t identifier = os_signpost_id_generate(log);
        os_signpost_interval_begin(log, identifier, "third loop", "Iteration %d", index);
        sleep(1);
        os_signpost_interval_end(log, identifier, "third loop", "Iteration %d", index);
    });
}

In your revised question, you ask:

Then I used the code you provided, and change the queue creation of 2nd loop back to dispatch_async, they also works as expection. But, the "points of interest" graphic has some problem. some task in 2nd loop cannot be displayed correctly.

  1. Xcode indicate some error for (0x4 0x0 0x0 0x1) and (0x5 0x0 0x0 0x1), as "The interval can not be logged as an interval because the start could not be determined."

  2. the (0x3 0x0 0x0 0x1) is not listed, but (0x5 0x0 0x0 0x1) is listed twice. and only one (0x5 0x0 0x0 0x1) displayed on the graphic

The trick with "Points of Interest" is that when doing GCD, it will reuse the worker threads, so it presents confusion as to how to match the start and end kdebug calls (which is what we used to use prior to os_signpost API).

If you are using the old kdebug API, you can pass the loop number as the “code” parameter to the kdebug calls and the iteration number as the first parameter after that. You can then go to “Recording Options” in Instruments and tell it to match start/end calls by both (a) the code; and (b) the first parameter after the code:

enter image description here

In the newer os_signpost API, you can call os_signpost_id_generate, as shown above, to generate an identifier, and points of interest will use that to match up the signpost calls for you.

You go on to ask:

  1. I never see an indicator Ⓢ in the "points of interest" tool.

Well, if you want to see those, you have to post them via os_signpost_event_emit (or os_log) to the points of interest log, as shown in the code snippet above.

Note, again, the Ⓢ signposts indicate when I did the dispatch calls from from the main thread, and the colored regions indicate the timing of the tasks on that concurrent queue.

I'd suggest you watch WWDC 2016 video System Trace in Depth for detailed information about how to use "Points of Interest" tool.

This has been updated for macOS 10.14 and iOS 12.0. For earlier OS versions, using the kdebug API, see previous revision of this answer.

Upvotes: 2

Related Questions