[SR-761] dispatch_async is "not very concurrent" and has a 1s overhead on Linux

[drewcrawford]

Previous ID	SR-761
Radar	None
Original Reporter	@drewcrawford
Type	Bug
Status	Resolved
Resolution	Done

Attachment: Download

Environment

Linux x64
swift-DEVELOPMENT-SNAPSHOT-2016-02-08-a

Additional Detail from JIRA

Votes	0
Component/s	libdispatch
Labels	Bug, Linux
Assignee	frankeh (JIRA)
Priority	Medium

md5: b2ed8e5cf6e4eaac3f1ede31d47b998f

Issue Description:

The attached program enqueues 10 blocks of work on the default queue. On Darwin, all blocks run in parallel, and the program completes in 5 seconds:

0.0 block 0 enter
0.0 block 7 enter
0.0 block 1 enter
0.0 block 3 enter
0.0 block 2 enter
0.0 block 4 enter
0.0 block 5 enter
0.0 block 6 enter
0.0 block 8 enter
0.0 block 9 enter
5.0 block 1 leave
5.0 block 6 leave
5.0 block 9 leave
5.0 block 5 leave
5.0 block 3 leave
5.0 block 0 leave
5.0 block 8 leave
5.0 block 4 leave
5.0 block 2 leave
5.0 block 7 leave
5.0 finished

On Linux however, the blocks enter the queue staggered 1 at a time, 1 second apart. This doubles the runtime of the program:

0.0 block 1 enter
0.0 block 0 enter
1.0 block 2 enter
2.0 block 3 enter
3.0 block 4 enter
4.0 block 5 enter
5.0 block 1 leave
5.0 block 0 leave
5.0 block 6 enter
5.0 block 7 enter
5.0 block 8 enter
6.0 block 2 leave
6.0 block 9 enter
7.0 block 3 leave
8.0 block 4 leave
9.0 block 5 leave
10.0 block 6 leave
10.0 block 7 leave
10.0 block 8 leave
11.0 block 9 leave
11.0 finished

In addition to that (rather large) performance regression, the fact that dispatch_async and/or the default queue has in practice a constant-time overhead of 1 second on Linux breaks a lot of my Darwin code, which expects a Darwin-like overhead for this call.

[drewcrawford]

cc: dgrove-oss (JIRA User)

[swift-ci]

Comment by Hubertus Franke (JIRA)

Thanks Drew, this is clearly an issue, we see in other constellations as well, but this is a simple test case.
The root cause of this is as follows:

• libpwq starts with two worker threads

• as you can see from the test program and the output the program stalls.

• reason is the worker threads sleep and as a result are not draining other work that is in the queue.

• libpwq has a user level thread manager that examines the state of all threads and if 'S' (blocked sleeping, presumably for I/O) and there is additional work, it will start ONE new thread.

• The thread manager runs every second, that's why you see it pick up new work one by one.

I replicated the monitor code externally to the running program monitoring the process and system state wrt to running threads and waiting threads and you get exactly the behavior described above.
namely an increasing number of threads , only one running and rest sleeping.

monitoring process
==> numthreads=4 runprocs=1 S=4
==> numthreads=5 runprocs=1 S=5
==> numthreads=6 runprocs=1 S=6
==> numthreads=7 runprocs=1 S=7
==> numthreads=8 runprocs=1 S=8
==> numthreads=9 runprocs=1 S=9
==> numthreads=10 runprocs=1 S=10
==> numthreads=10 runprocs=1 S=10
==> numthreads=10 runprocs=1 S=10
==> numthreads=10 runprocs=1 S=10
==> numthreads=10 runprocs=1 S=10

So yes a solution to this dilemma must be found in the linux port. Apparently in OSX they have
tight this thread pool notion with I/O blocking in the kernel (not confirmed). So you see the instant behavior of threats picking up the work.

In Linux, since the threads are blocking on I/O they can not make further progress until the I/O (here sleep 5 ) completes. Hope this explains at least what your are seeing.

[swift-ci]

Comment by Hubertus Franke (JIRA)

I hacked the libpwq library to start more threads and not wait for the one second one thread increase, but start with more threads.

frankeh@GCD:~/swiftbench/prog-lang-shootout/SwiftBench$ PWQ_WMIN=10 ./test1
manager_main: starting with 10 threads
0.0 block 3 enter
0.0 block 0 enter
0.0 block 2 enter
0.0 block 5 enter
0.0 block 4 enter
0.0 block 1 enter
0.0 block 7 enter
0.0 block 9 enter
0.0 block 8 enter
0.0 block 6 enter
5.0 block 3 leave
5.0 block 2 leave
5.0 block 4 leave
5.0 block 5 leave
5.0 block 0 leave
5.0 block 1 leave
5.0 block 7 leave
5.0 block 8 leave
5.0 block 6 leave
5.0 block 9 leave
5.0 finished

Which performs as expected. Of course this is not an acceptable hack, but just to demonstrate where the problems lies, namely i/O blocking the execution threads.

[drewcrawford]

Thanks for your work on this frankeh (JIRA User)! Do you have a link to the patch?

I struggle to see what is unacceptable about this, but I also don't understand the Darwin behavior, really. I understand that we need some throttling on threadspawn (to limit IO contention, basically) so perhaps my use of sleep here in the example was poor.

In the program that motivated me to file this bug, the real situation is something like:

dispatch_async(specialIOQueue) {
        //io
        dispatch_semaphore_signal(sema)
}
if dispatch_semaphore_wait(sema, timeout) != 0 { //where timeout is shorter than 1s
    throw DeadlineExceeded
}

On Linux, we always hit DeadlineExceeded, because the dispatch_async onto the specialIOQueue does not happen until the queue waiting for it has already given up.

Application logic could potentially be simplified by moving the timeout logic onto the specialIOQueue and using dispatch_sync, but the refactor in the application is non-trivial. I have not determined whether dispatch_sync would run into the same worker limit issue that async does here as you investigated, so it is not clear to me that is even a useful exercise.

[drewcrawford]

Just brainstorming about this, one mitigation for this (for my situation anyway, perhaps not the bug overall) would be to immediately launch/adjust the thread watchdog from the implementation of dispatch_semaphore_wait. Since the caller, by definition, is going to sleep at that point. Then we don't need to wait for the 1s tock to unlock a new thread for IO.

Perhaps that should also be done across the *sync functions as well, since they too are likely sleepers.

This obviously doesn't solve the problem for "actual" sleep but it does mitigate the vast majority of cases in my codebase. For the last 5%, we could introduce a user-function that one calls before entering the sleep state, although I don't know what the temperature is as far as increasing the API surface area.

[swift-ci]

Comment by Hubertus Franke (JIRA)

Here is the simple patch (note that was just to see whether the theory holds or not). Ignore the two last segments.
Set PWQ_WMIN=10 or some high value and you see it work.

diff --git a/src/posix/manager.c b/src/posix/manager.c
index 8ffbdbb..6b209d6 100755

• • • a/src/posix/manager.c
      +++ b/src/posix/manager.c
      @@ -171,7 +171,7 @@ manager_init(void)
      scoreboard.sb_suspend = 0;

/* Determine the initial thread pool constraints */

• worker_min = 2; // we can start with a small amount, worker_idle_threshold will be used as new dynamic low watermark
  + worker_min = getenv("PWQ_WMIN") ? atoi(getenv("PWQ_WMIN")) : 2; // we can start with a small amount, worker_idle_threshold will be used as new dynamic low watermark
  worker_idle_threshold = (PWQ_ACTIVE_CPU > 0) ? (PWQ_ACTIVE_CPU) : worker_idle_threshold_per_cpu();

/* FIXME: should test for symbol instead of for Android */
@@ -561,6 +561,7 @@ manager_main(void *unused attribute ((unused)))
pthread_sigmask(SIG_BLOCK, &sigmask, NULL);

/* Create the minimum number of workers */

• printf("%s: starting with %d threads\n", FUNCTION, worker_min);
  for (i = 0; i < worker_min; i++)
  worker_start();

@@ -790,7 +791,10 @@ manager_workqueue_additem(struct _pthread_workqueue *workq, struct work *witem)
// and no other thread have managed to race us and empty the wqlist on our behalf already
if (scoreboard.idle > 0) // && ((wqlist_mask & wqlist_index_bit) != 0)) // disabling this fringe optimization for now
{
+// printf("%s: %d\n", FUNCTION, LINE);
+// pthread_mutex_lock(&wqlist_mtx);
pthread_cond_signal(&wqlist_has_work); // don't need to hold the mutex to signal
+// pthread_mutex_unlock(&wqlist_mtx);
}
}
}

[swift-ci]

Comment by Hubertus Franke (JIRA)

Now to your other comments. There are multiple options here and it depends on how wide the net is cast.
Your sleep example is a good, because where does it say I can't do this in Swift ? Is it truely considered bad programming style?
So there are two options, but regardless, we need to spawn new threads (because we need the stack which is "occupied" while blocked).

Option 1) User space option:
as you say grab it at the location where you are and call libpwq to start another thread.
Running the "thread inspection logic" is to expensive as it hits the /proc/<process>/<all-tasks> filesystem
which at high thread count will have some overhead. So just start a thread.
The problem we have is that all blocking system calls ( I/O (read,write) and sleep ) will not be covered.
Certainly we can transfer blocking calls into nonblocking but then we have to track that , but
it gives us the option to hook for thread expansion and we don't know whether the call indeed blocked (think about read calls that get data from the filecache (no blocking)), so I don't like this solution.

Option 2) Kernel options:
We let the thread block in the kernel and pick up that even with some kernel change (event handler).
The event will be sent to the libpwq through a channel to allow manager thread to be woken up (currently
its timeout every second) and create a new thread (preferably bypassing the count logic).
Thread reduction can be done in a leisure way. This will catch all "true thread blocking events", however
requires some overhead as well. This seems more elaborate, requires the participation of the linux community
and potentially will take significant time to find its way to distributions.

I don't have enough SWIFT experience to judge whether "using blocking system calls as bad programming style"
will fly, but I do think we might need a solution that does not depend at t

[swift-ci]

Comment by Hubertus Franke (JIRA)

Good news .. hooking into dispatch_semaphore_wait and just calling worker_start from libpwq works.
You want a patch and see how far that will get us ?

Its not good solution, but proofs the point.

[drewcrawford]

Thanks for your remarks. Let me take this one at a time.

Running the "thread inspection logic" is to expensive as it hits the /proc/<process>/<all-tasks> filesystem
which at high thread count will have some overhead. So just start a thread.

I agree we should just start threads without checking the FS in this case.

Certainly we can transfer blocking calls into nonblocking but then we have to track that , but

I don't understand what you mean here. Do you mean the software developer can rewrite their code to be nonblocking? That is true. But if you mean libdispatch can do this, I would object to libdispatch trying to take automatic steps here. I deliberately write blocking code sometimes, I would like to be in control of that decision.

we don't know whether the call indeed blocked (think about read calls that get data from the filecache (no blocking)), so I don't like this solution.

I agree that this is an issue. I think it is not completely out of the question to solve it at the API layer (as explained below), but I agree a kernel-event approach would be better if we can actually make it work.

This seems more elaborate, requires the participation of the linux community
and potentially will take significant time to find its way to distributions.

There's the rub. The lead time is basically "forever" here, because it just takes a long time for kernel features to trickle down to distributions. RHEL for example, won't get it until RHEL 8, which will be years. So maybe we should look into this, but I don't think it is viable in the near future.

There are some existing ideas here, for example, libkqueue has a Linux port that does something. However, AFAIK the performance on Linux is not excellent, as it's not native.

I don't have enough SWIFT experience to judge whether "using blocking system calls as bad programming style"
will fly,

I work entirely in Swift these days. Most Swift developers are not using system calls at all, whether blocking or any other kind. They are using e.g. Foundation, which abstracts that away. The few people who do use system calls (like me) are generally clever enough to take basic steps to solve their own problems, so I don't believe it is a great burden for me to help libdispatch understand the code I am writing. To give some context here, compare the occurrence of [fopen|https://github.com/search?p=1&q=fopen+language%3Aswift&ref=searchresults&type=Code&utf8=✓] (150 incidences) against Foundation's [contentsOfFile|https://github.com/search?utf8=✓&q=contentsOfFile+language%3Aswift&type=Code&ref=searchresults] (23k incidences). People who read files with fopen are mostly Apple/IBM employees implementing Swift projects themselves, plus a very tiny number of folk like me who have very unusual problems. It would be nice if we didn't have to help libdispatch understand our blocking calls, but I don't think it's critical.

The only time ordinary people make blocking syscalls is sleep, but in that case I think they actually want their program to be slow, so I don't think sleeping "more efficiently" matters.

For the "read may or may not block case", I think it is as simple as increasing our API surface area:

dispatch_might_block() //dispatch should check "shortly" to see if thread is blocked
read(...)
dispatch_stopped_blocking() //cancel pending check, if any

Again, it is not ideal, but given the low incidence of developers making raw syscalls, I believe it is non-critical.

Perhaps to assist with awareness, we could provide some information in the console. For example, if the 1s tock detects a thread entering the sleep state "unannounced", we could print something like

Thread 23 entered the sleep state without informing libdispatch, which may impact performance. Call dispatch_will_sleep() before sleeping. Break on __dispatch_didnt_sleep to debug. For more information, see https://bugs.swift.org/browse/SR-761

That is probably all the kick we need for the tiny number of developers who will find themselves in this situation, they will read through the bug and figure out what is going on.

Good news .. hooking into dispatch_semaphore_wait and just calling worker_start from libpwq works.
You want a patch and see how far that will get us ?

Yes, that would be a good next step.

[swift-ci]

Comment by Hubertus Franke (JIRA)

OK .. coded the semwait interception up in libdispatch, which requires changes in libpwq as well.
Apply the following patch to libdispatch:
semwait_thread.diff
Apply the following to libpwq:
threadmgr_signal.diff
Use the following test program to highlight behavior:
test2.swift
Use the following program to execute by side to show you thread statistics
as it the libpwq internally computes (found it very helpful). Note that during
the sleeps between iterations the thread count goes down again only to be raised
again when another iterations starts. Run with <showpid test2>
No more need to use PWQ_WMIN environment variable:
showpid

Let me know whether that fixes much of your problems.

[drewcrawford]

So I attempted to apply the libdispatch patch, however it did not apply cleanly to master. Instead, I re-rolled it (0001-Rerolling-Hubertus-s-SR-761-patch-against-a650657.patch ) against 33b5d8b010a8f78ae80bab17cf440a157d9c02a9, and it can be applied via git am. (My reroll may have some problem which produces the bug below.) I also applied the provided libpwq patch.

Next, I attempted to run test2.swift. You can reproduce my exact environment with

docker run --privileged=true -it drewcrawford/swift:swift-DEVELOPMENT-SNAPSHOT-2016-02-25-a
# create test2.swift, such as with a text editor
swift -Xcc -fblocks test2.swift

Note that, I am not familiar with such a thing as DispatchWrapper, so I used Dispatch in test2.swift instead.

This produces the output RAMP-UP.log, which makes some progress. However, it still demonstrates the erroneous ramp-up behavior in the first trial for blocks 1-6, although puzzlingly, the behavior is correct for blocks 7-9 in that trial, and it remains correct for the 2nd trial onwards.

When re-running as

PWQ_WMIN=10 swift -Xcc -fblocks test2.swift

it correctly does not rampup for the whole program execution NO-RAMPUP.log .

So we are making some progress here, but still not totally sorted.

I am moving the above-styled environment into my development environment to test against more realistic workloads.

[drewcrawford]

Unfortunately, further testing in my development environment finds a new behavior that is also incorrect. (Please let me know if this is a separate bug I should file separately, or if it is part of this issue, but since it involves semaphore, and I reproduce with these patches, I suspect it is related.) dispatch_semaphore_wait now waits indefinitely regardless of the provided timeout.

deadlock.swift

This test program deadlocks on Linux (corelibs-dispatch):

0.0 waiting...

But not on Darwin:

0.0 waiting...
0.0 waited.
0.0 waiting...
0.0 waited.
0.0 waiting...
0.0 waited.
0.0 waiting...
0.0 waited.
0.0 waiting...
0.0 waited.
0.0 waiting...
0.0 waited.
0.0 waiting...
0.0 waited.
0.0 waiting...
0.0 waited.
0.0 waiting...
1.0 waited.

[swift-ci]

Comment by Hubertus Franke (JIRA)

The first few rampups implies to me that the patch did not cleanly apply.
I absolutely do not see this problem for test2.swift.
You can do a clean checkout of @ #54
The libpwq was accepted: https://github.com/mheily/libpwq ( just do a git pull if its under libdispatch)

DispatchWrapper ::= Dispatch is the correct "fix". I am still on an intermediate level, once dgrove-oss (JIRA User)'s fixes for that are official they can be downloaded.
I get the following output which further suggests, something wrong with the patching.
frankeh@GCD:~/swiftbench/prog-lang-shootout/SwiftBench$ ./deadlock
0.0 waiting...
0.0 waited.
0.0 waiting...
0.0 waited.
0.0 waiting...
1.0 waited.
1.0 waiting...
1.0 waited.
1.0 waiting...
1.0 waited.
1.0 waiting...
1.0 waited.
1.0 waiting...
1.0 waited.
1.0 waiting...
1.0 waited.
1.0 waiting...
1.0 waited.
1.0 waiting...
1.0 waited.
1.0 waiting...
1.0 waited.
1.0 waiting...
1.0 waited.
1.0 waiting...
2.0 waited.
2.0 waiting...
2.0 waited.
2.0 waiting...
2.0 waited.
2.0 waiting...
2.0 waited.
2.0 waiting...
2.0 waited.
2.0 waiting...
2.0 waited.
2.0 waiting...
2.0 waited.
2.0 waiting...
2.0 waited.
2.0 waiting...
2.0 waited.
2.0 waiting...
2.0 waited.
2.0 waiting...
3.0 waited.
3.0 waiting...
3.0 waited.
3.0 waiting...
3.0 waited.
3.0 waiting...
3.0 waited.
3.0 waiting...
3.0 waited.
3.0 waiting...
3.0 waited.
3.0 waiting...
3.0 waited.
3.0 waiting...
3.0 waited.

Now I see only one thread active:
monitoring <deadlock>
monitoring process
==> numthreads=1 runprocs=1 S=1
==> numthreads=1 runprocs=1 S=1
==> numthreads=1 runprocs=1 S=1

Results seem exactly what you expect.
What level of the libdispatch are you on ?

[drewcrawford]

I rebuilt cleanly my environment with the following changes:

1. Using libpwq from upstream origin/master.
2. Applying the patch from the PR to libdispatch, which is simply a fast-forward merge.

For the avoidance of doubt, I am attaching the exact libdispatch sourcetree I built. libdispatch.tar.xz

I have also published the entire OS image with the binaries in question on Dockerhub at drewcrawford/swift:sr-761-a.

After taking these steps:

1. deadlock.swift continues to deadlock after "0.0 waiting..."
2. test2.swift continues to show rampup behavior.

[swift-ci]

Comment by Hubertus Franke (JIRA)

I can see that you have already picked up the FUTEX patches that I submitted and which were merged yesterday. That FUTEX does not have necessary calls in there.

Go to the following location, see whether there is a SEM_FUTEX statement and
mimic the call to _dispatch_threadmgr_inform_wait() just as its done under SEM_SEMA.
Then it should work again.

./semaphore.c:381: _dispatch_threadmgr_inform_wait();
./semaphore.c:436: _dispatch_threadmgr_inform_wait();
./semaphore.c:648: _dispatch_threadmgr_inform_wait();
./semaphore.c:704: _dispatch_threadmgr_inform_wait();