uwsgi and mono - thread concurrency is absent?

[Evengard]

Hello!

I've stumbled upon a weird problem.

My config is this:

[uwsgi]
plugins = mono,logfile
enable-threads = true
socket = %dtmp/uwsgi.sock
stats = %dtmp/stats.sock
modifier1 = 15
uid=www-data
gid=www-data
mono-key = MONO_APP
route-run = addvar:MONO_APP=${UWSGI_APPID}
mono-index = Default.aspx
master = true
processes = 1
threads = 10
threads-stack-size = 10000000 # Welp, without this it didn't started at all

With this config I'm trying to start an application (which is passed via nginx uwsgi_param UWSGI_APPID /srv/http/mydomain.com/main/webapp;), and it basically works... Except that it works single threaded only!

The threads get spawned (checked with top -H -p pid), but only one thread is ACTUALLY used. No matter how I changed the parameters, it never really used second or third thread for concurrent requests! No matter how much threads I spawn.

Using process = 10 instead of threads basically works, but the app itself is legacy and contains an in-process cache, which can't be synchronized across application instances.

What am I missing here?

[unbit]

Hi, i suppose you are noticing it from the stats server or uwsgitop ? have you tried putting a Thread.Sleep in one handler and try sending another request to the server ?

[Evengard]

@unbit , well, I'm monitoring the request logs, also using top -H -p pid to see the load.

As you advised, I added a Thread.Sleep(10000) and opened 5 pages (after making sure it compiled). I've made sure that they don't share any session lock or whatsoever. Still all the pages were loaded one after another, with 10 seconds between each of them (total 50 seconds of waiting).

I'm using hyperfastcgi for now but wanted to migrate to uwsgi. hyperfastcgi handles this test without issues, all the pages loaded simultaneously (after 10 seconds after sending the requests, as expected).

[unbit]

Hi, use curl for testing, as browsers limits the number of concurrent connection to the same host

[Evengard]

Same test with curl:

$ time curl https://uwsgitest.$DOMAIN > /dev/null 2>&1 & \
> time curl https://uwsgitest.$DOMAIN > /dev/null 2>&1 & \
> time curl https://uwsgitest.$DOMAIN > /dev/null 2>&1 & \
> time curl https://uwsgitest.$DOMAIN > /dev/null 2>&1 & \
> time curl https://uwsgitest.$DOMAIN > /dev/null 2>&1 & \
>
[1] 16992
[2] 16993
[3] 16994
[4] 16995
[5] 16996
$
real    0m14.887s
user    0m0.048s
sys     0m0.020s

real    0m24.933s
user    0m0.044s
sys     0m0.020s

real    0m34.991s
user    0m0.048s
sys     0m0.028s

real    0m45.044s
user    0m0.052s
sys     0m0.020s

real    0m55.062s
user    0m0.032s
sys     0m0.028s

Also hyperfastcgi4 which passes the test:

$ time curl https://linuxtest.$DOMAIN > /dev/null 2>&1 & \
> time curl https://linuxtest.$DOMAIN > /dev/null 2>&1 & \
> time curl https://linuxtest.$DOMAIN > /dev/null 2>&1 & \
> time curl https://linuxtest.$DOMAIN > /dev/null 2>&1 & \
> time curl https://linuxtest.$DOMAIN > /dev/null 2>&1 & \
>
[1] 17098
[2] 17099
[3] 17100
[4] 17101
[5] 17102
$
real    0m10.326s
user    0m0.044s
sys     0m0.012s

real    0m10.326s
user    0m0.028s
sys     0m0.020s

real    0m10.320s
user    0m0.036s
sys     0m0.016s

real    0m10.338s
user    0m0.032s
sys     0m0.008s

real    0m10.380s
user    0m0.032s
sys     0m0.012s

[Evengard]

uwsgi/plugins/mono/mono_plugin.c

Line 592 in 3c0bf08

umono.process_request(app->callable, &exc);

I'm not sure but I think it's here that we need to patch to allow multiple threads, although I'm not sure as I'm not familiar with uwsgi codebase. I think we need to switch the thread here and only then process the request via mono?

[Evengard]

After seeing how other plugins works, it seems that at this exact place we need to indeed pass it to the thread here and return UWSGI_AGAIN. I can't see anywhere in the mono plugin code any UWSGI_AGAIN, so it really seems like it just actually blocks here until the request in mono is complete. I also can't see any thread management at this point too. I guess the support for multithreading is absent at this point. I think I can try to implement it, but I guess I will need some guidance about the employed methods of how it all works. I think I'll base it making it kinda analoguous to the lua plugin (I'm familiar a bit with the C lua interface, so I guess I can understand the basic flow of how such plugin should work), but I am not familiar with the internal uwsgi structures, what should I set and how.

[unbit]

Threading support is here: https://github.com/unbit/uwsgi/blob/master/plugins/mono/mono_plugin.c#L609

the code is pretty old but i clearly remember that i invested in threading as it is the preferred concurrency approach in .net. Maybe something changed in the mono api ?

[Evengard]

It seems that mono_thread_attach do not make any request to be split across different threads. It just makes possible to use a thread for accessing mono itself. But you still need to manage the threads manually.

Either way, it seems for me that the uwsgi_mono_request call is done from the main thread (the one accepting new requests), so it is not distributed across threads at this point. And umono.process_request blocks it either way, even if it does somehow (which I doubt) it ends up in a different thread. We want this call to be asynchronous I think.

[unbit]

this is how the uwsgi internal api works. Basically that "attaching" is managed for each thread (the ones you spawn with threads = n). Can you check with strace if the additional threads are deadlocked ?

[Evengard]

So basically uwsgi_mono_request should already be distributed across threads? That's weird then. I'm not used to strace though, will try to see it but I'm not familiar with it at all, so I'm not sure if I'll be able to understand from the output if it is deadlocked or not, and what exactly should I look at. Anyway, as a side note, it didn't even wanted to start until I put

threads-stack-size = 10000000

With anything smaller it just got stuck. Only with this value or above it was fine (I even tried 999999999) but I never got the threads to actually handle requests.

[Evengard]

I've run an strace on an idling thread, and got repeating the folowing:

read(12, 0x7f8bd165bd60, 4096)          = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGRT_3 {si_signo=SIGRT_3, si_code=SI_TKILL, si_pid=27047, si_uid=33} ---
rt_sigprocmask(SIG_BLOCK, [RT_4], NULL, 8) = 0
futex(0x7f8bd2243e00, FUTEX_WAKE_PRIVATE, 1) = 1
rt_sigsuspend(~[RTMIN RT_1 RT_4], 8)    = ? ERESTARTNOHAND (To be restarted if no handler)
--- SIGRT_4 {si_signo=SIGRT_4, si_code=SI_TKILL, si_pid=27047, si_uid=33} ---
rt_sigreturn({mask=~[KILL STOP RTMIN RT_1]}) = -1 EINTR (Interrupted system call)
rt_sigprocmask(SIG_UNBLOCK, [RT_4], NULL, 8) = 0
futex(0x7f8bd2243e00, FUTEX_WAKE_PRIVATE, 1) = 1
rt_sigreturn({mask=[]})                 = 0
read(12, 0x7f8bd165bd60, 4096)          = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGRT_3 {si_signo=SIGRT_3, si_code=SI_TKILL, si_pid=27047, si_uid=33} ---
rt_sigprocmask(SIG_BLOCK, [RT_4], NULL, 8) = 0
futex(0x7f8bd2243e00, FUTEX_WAKE_PRIVATE, 1) = 1
rt_sigsuspend(~[RTMIN RT_1 RT_4], 8)    = ? ERESTARTNOHAND (To be restarted if no handler)
--- SIGRT_4 {si_signo=SIGRT_4, si_code=SI_TKILL, si_pid=27047, si_uid=33} ---
rt_sigreturn({mask=~[KILL STOP RTMIN RT_1]}) = -1 EINTR (Interrupted system call)
rt_sigprocmask(SIG_UNBLOCK, [RT_4], NULL, 8) = 0
futex(0x7f8bd2243e00, FUTEX_WAKE_PRIVATE, 1) = 1
rt_sigreturn({mask=[]})                 = 0
read(12,

On each request it repeats, and the request goes through the main thread instead. I'm unsure if it is of any help.

When no requests are made, it just idles at read(12, line (the same as the last line above)

Also, the fd=12 seems to be related to inotify. No ideas what exactly it does watches for.

[Evengard]

I think I know where the trouble is.

uwsgi/plugins/mono/mono_plugin.c

Lines 612 to 618 in 3c0bf08

	sigset_t smask;
	sigemptyset(&smask);
	#if defined(__APPLE__) || defined(__OpenBSD__) || defined(__FreeBSD__) || defined(__GNU_kFreeBSD__)
	sigaddset(&smask, SIGXFSZ);
	#else
	sigaddset(&smask, SIGPWR);
	#endif

It seems we're not handling all the needed signals for mono here. According to the Debugging mono article, we need to handle (at least under linux) theese handles:

SIGXCPU SIG33 SIG35 SIG36 SIG37 SIG38 SIGPWR

While here we handle only SIGPWR.
After I added after the line 618 the following:

sigaddset(&smask, SIGXCPU); //unsure if we really need this one
sigaddset(&smask, SIGSEGV); // see the comment below for this one
sigaddset(&smask, 33);
sigaddset(&smask, 35);
sigaddset(&smask, 36);
sigaddset(&smask, 37);
sigaddset(&smask, 38);

It started to work flawlessly in multithreading mode, and even more WITHOUT the need to set something as absurd as threads-stack-size = 10000000. It seems that some signals weren't handled by mono as they should have been. I'm unsure though about should they go under a platform define (line 614, line 616).

[Evengard]

I think I was a bit early on the good info. I am still getting weird SIGSEGVs just after my app got compiled and should actually serve the request. Can't understand why though.

UPD: now it crashes at anything bigger than 6 threads. SIGSEGV. Really don't know why. Also, my machine have a 7 core setup, so maybe it is 7 - 1.

UPD2: and now it works... Maybe it was just my system buggying... 28 threads running.

UPD3: it's still kinda unstable, dunno why... Sometimes crashing and sometimes not.

UPD4: that's really weird. If I don't set the process uid, it works fine under root, if I do set it, it crashes with a SIGSEGV... Seems like it tries to access some file in the /root directory for whatever cause, fails and SIGSEGV-s. Or whatever else is happening... Still weird that in single thread or 6 thread mode it is fine.

UPD5: solved! It was the ulimit -n limit kicking in. Never thought it would be it. Probably my app is using a big deal of this limit, and each thread opens the same amount. Anyway, I'm happy now. Adding these signal handlers did help. Unsure about the SIGXCPU, it worked without it, with setting only the 33, 35, 36, 37 and 38)

UPD6: seems like it is not solved after all... Still, I think it is something about limits...

UPD7: really weird, I set the limit of open files to 1048576, and it works fine if I run it via su www-data -c "uwsgi uwsgi.ini" but crashes if I run it from root uwsgi uwsgi.ini with uid=www-data and gid=www-data it crashes with a SIGSEGV.

UPD8: after high load, it still crashes after a while with the same SIGSEGV even when running via su. I really don't know why.

UPD9: I went crazy and added sigaddset(&smask, SIGSEGV); to the code above... It seems like IT ACTUALLY WORKED! The app stopped crashing and is fine now! I guess the mono runtime uses SIGSEGV too for some internal processing.

[Evengard]

#1913
Adding a possible fix for this bug.