Re: [Mono-dev] High threadpool CPU usage

[Chris Swiedler]

Thanks. I’ll try to use the profiler, but this problem doesn’t happen at 
startup, and running the application under profiling for eight hours is 
probably infeasible.

I see that at one point mono support signal-based enabling/disabling of the 
profiler, like how SIGUSR2 toggles the trace mechanism on and off. Is that sort 
of functionality ever going to be re-added? Currently there’s the heapshot 
option via the TCP listener, perhaps there could be enable/disable commands via 
that mechanism?

chris

From: Ludovic Henry [mailto:ludo...@xamarin.com]
Sent: Friday, May 27, 2016 1:27 AM
To: Chris Swiedler ; mono-devel-list 

Subject: Re: [Mono-dev] High threadpool CPU usage

Hi Chris,

The signal handler you are seeing is the GC signalling every thread to suspend 
them. So yes you are right, that's the sgen collector stopping the world.

To track down the large number of allocation, I would encourage you to try the 
log profiler (documentation: 
http://www.mono-project.com/docs/debug+profile/profile/profiler/ ). That should 
give you some more insights in where the allocations are coming from.

Thank you,
Ludovic

On Thu, May 26, 2016 at 8:20 PM Chris Swiedler 
> wrote:
Thanks, Ludovic. I’m using mono-4.2.3. The ‘massive amounts of GC’ idea makes 
sense based on what I’m seeing. When I run pstack, I get a number of threadpool 
threads in stacks with:

#0  0x7fdff1c6a952 in do_sigsuspend (set=0x954220 ) at 
../sysdeps/unix/sysv/linux/sigsuspend.c:32
#1  __GI___sigsuspend (set=set@entry=0x954220 ) at 
../sysdeps/unix/sysv/linux/sigsuspend.c:46
#2  0x005c7534 in suspend_thread (info=0x7fdf480008c0, 
context=context@entry=0x7fde997ea1c0) at sgen-os-posix.c:126
#3  0x005c771f in suspend_handler (_dummy=, 
_info=, context=0x7fde997ea1c0) at sgen-os-posix.c:153
#4  

I thought this was related to GDB / pstack attaching, but it’s actually the 
suspend handling for the sgen collector, right?

Is a thread suspending itself CPU-intensive? I see lots of threads with high 
CPU at any point, which seems to indicate that this wouldn’t just be the CPU 
usage of the collector thread itself.

Do you have any suggestions for how to track down the large numbers of 
allocations? This isn’t very easy to reproduce, but now that I know what to 
look for, I might be able to get it to happen in a test environment.

chris

From: Ludovic Henry [mailto:ludo...@xamarin.com]
Sent: Thursday, May 26, 2016 8:43 AM
To: Chris Swiedler 
>; mono-devel-list 
>
Subject: Re: [Mono-dev] High threadpool CPU usage

Hi Chris,

The first stacktrace you are observing is for threadpool thread parking. We use 
this technique for threads that are currently not doing anything, to keep them 
around for a little while (5-60 seconds) so if we have burst of usage, we do 
not end up destroying and creating threads all the time.

The second stacktrace you are observing is, as you noted, when performing a 
garbage collection, when the GC thread is suspending all the running threads. 
So if you are witnessing this trace very often, it means a thread is allocating 
memory very quickly triggering GC collection very often.

So I would need more information to tell you exactly why it would use 100% CPU. 
Also which version of Mono are you running?

Thank you very much,
Ludovic
On Wed, May 25, 2016 at 8:30 PM Chris Swiedler 
> wrote:
We have a server app which is periodically going into a mode where all 
threadpool threads start running at very high CPU. I've run pstack when it's in 
this mode, and every time I do it, nearly all the threadpool threads have this 
stack:

#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at 
../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00618817 in mono_cond_timedwait_ms 
(cond=cond@entry=0x7fe7ee1fddc0, mutex=0x241eb78, timeout_ms=) 
at mono-mutex.c:181
#2  0x00586f28 in worker_park () at threadpool-ms.c:509
#3  worker_thread (data=) at threadpool-ms.c:607
#4  0x005841e9 in start_wrapper_internal (data=) at 
threads.c:725
#5  start_wrapper (data=) at threads.c:772
#6  0x00621026 in inner_start_thread (arg=0x7fe831df4650) at 
mono-threads-posix.c:97
#7  0x7fe88a55edf5 in start_thread (arg=0x7fe7ee1fe700) at 
pthread_create.c:308
#8  0x7fe88a28c1ad in clone () at 
../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Usually one thread will have a stack like this:

#0  sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:85
#1  0x0061aa37 in mono_sem_wait (sem=0x9542c0 , 
alertable=alertable@entry=0) at mono-semaphore.c:107
#2  0x005c77bd in sgen_wait_for_suspend_ack (count=count@entry=18) at 

Re: [Mono-dev] High threadpool CPU usage

[Ludovic Henry]

Hi Chris,

The signal handler you are seeing is the GC signalling every thread to
suspend them. So yes you are right, that's the sgen collector stopping the
world.

To track down the large number of allocation, I would encourage you to try
the log profiler (documentation:
http://www.mono-project.com/docs/debug+profile/profile/profiler/ ). That
should give you some more insights in where the allocations are coming from.

Thank you,
Ludovic

On Thu, May 26, 2016 at 8:20 PM Chris Swiedler 
wrote:

> Thanks, Ludovic. I’m using mono-4.2.3. The ‘massive amounts of GC’ idea
> makes sense based on what I’m seeing. When I run pstack, I get a number of
> threadpool threads in stacks with:
>
>
>
> #0  0x7fdff1c6a952 in do_sigsuspend (set=0x954220
> ) at ../sysdeps/unix/sysv/linux/sigsuspend.c:32
>
> #1  __GI___sigsuspend (set=set@entry=0x954220 ) at
> ../sysdeps/unix/sysv/linux/sigsuspend.c:46
>
> #2  0x005c7534 in suspend_thread (info=0x7fdf480008c0,
> context=context@entry=0x7fde997ea1c0) at sgen-os-posix.c:126
>
> #3  0x005c771f in suspend_handler (_dummy=,
> _info=, context=0x7fde997ea1c0) at sgen-os-posix.c:153
>
> #4  
>
>
>
> I thought this was related to GDB / pstack attaching, but it’s actually
> the suspend handling for the sgen collector, right?
>
>
>
> Is a thread suspending itself CPU-intensive? I see lots of threads with
> high CPU at any point, which seems to indicate that this wouldn’t just be
> the CPU usage of the collector thread itself.
>
>
>
> Do you have any suggestions for how to track down the large numbers of
> allocations? This isn’t very easy to reproduce, but now that I know what to
> look for, I might be able to get it to happen in a test environment.
>
>
>
> chris
>
>
>
> *From:* Ludovic Henry [mailto:ludo...@xamarin.com]
> *Sent:* Thursday, May 26, 2016 8:43 AM
> *To:* Chris Swiedler ; mono-devel-list <
> mono-devel-list@lists.ximian.com>
> *Subject:* Re: [Mono-dev] High threadpool CPU usage
>
>
>
> Hi Chris,
>
>
>
> The first stacktrace you are observing is for threadpool thread parking.
> We use this technique for threads that are currently not doing anything, to
> keep them around for a little while (5-60 seconds) so if we have burst of
> usage, we do not end up destroying and creating threads all the time.
>
>
>
> The second stacktrace you are observing is, as you noted, when performing
> a garbage collection, when the GC thread is suspending all the running
> threads. So if you are witnessing this trace very often, it means a thread
> is allocating memory very quickly triggering GC collection very often.
>
>
>
> So I would need more information to tell you exactly why it would use 100%
> CPU. Also which version of Mono are you running?
>
>
>
> Thank you very much,
>
> Ludovic
>
> On Wed, May 25, 2016 at 8:30 PM Chris Swiedler 
> wrote:
>
> We have a server app which is periodically going into a mode where all
> threadpool threads start running at very high CPU. I've run pstack when
> it's in this mode, and every time I do it, nearly all the threadpool
> threads have this stack:
>
> #0  pthread_cond_timedwait@@GLIBC_2.3.2 () at
> ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
> #1  0x00618817 in mono_cond_timedwait_ms 
> (cond=cond@entry=0x7fe7ee1fddc0,
> mutex=0x241eb78, timeout_ms=) at mono-mutex.c:181
> #2  0x00586f28 in worker_park () at threadpool-ms.c:509
> #3  worker_thread (data=) at threadpool-ms.c:607
> #4  0x005841e9 in start_wrapper_internal (data=) at
> threads.c:725
> #5  start_wrapper (data=) at threads.c:772
> #6  0x00621026 in inner_start_thread (arg=0x7fe831df4650) at
> mono-threads-posix.c:97
> #7  0x7fe88a55edf5 in start_thread (arg=0x7fe7ee1fe700) at
> pthread_create.c:308
> #8  0x7fe88a28c1ad in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
>
> Usually one thread will have a stack like this:
>
> #0  sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:85
> #1  0x0061aa37 in mono_sem_wait (sem=0x9542c0
> , alertable=alertable@entry=0) at
> mono-semaphore.c:107
> #2  0x005c77bd in sgen_wait_for_suspend_ack (count=count@entry=18)
> at sgen-os-posix.c:188
> #3  0x005c78f9 in sgen_thread_handshake (suspend=suspend@entry=1)
> at sgen-os-posix.c:224
> #4  0x005c7e92 in sgen_client_stop_world
> (generation=generation@entry=0) at sgen-stw.c:234
> #5  0x005e6aca in sgen_stop_world (generation=0) at sgen-gc.c:3389
> #6  0x005e6c29 in sgen_perform_collection (requested_size=4096,
> generation_to_collect=0, reason=0x6d9595 "Nursery full", wait_to_finish=0)
> at sgen-gc.c:2322#7  0x005da62a in sgen_alloc_obj_nolock
> (vtable=vtable@entry=0x7fe85c0343c0, size=size@entry=128) at
> sgen-alloc.c:291
> #8  0x005da913 in sgen_alloc_obj (vtable=vtable@entry=0x7fe85c0343c0,
> size=128) at sgen-alloc.c:457
> #9  0x005c86e9 in 

Re: [Mono-dev] TCP connects

[Greg Young]

OK I spent some more time looking through this. There is a ton of not
really async stuff happening in async methods also
cancellations/timeouts/etc don't work properly. Moral of the story for
people searching this in the future etc, use the PCL version which
seems to work thus far.



On Thu, May 26, 2016 at 5:36 PM, Greg Young  wrote:
> In looking through a recent issue, when a node disappears we end up with:
>
> "Threadpool worker" at  <0x>
> at (wrapper managed-to-native)
> System.Net.Sockets.Socket.Connect_internal
> (intptr,System.Net.SocketAddress,int&) <0x>
> at System.Net.Sockets.Socket.Connect (System.Net.EndPoint) <0x00135>
> at System.Net.WebConnection.Connect (System.Net.HttpWebRequest) <0x00615>
> at System.Net.WebConnection.InitConnection (object) <0x0031a>
> at System.Net.WebConnection.m__0 (object) <0x00024>
> at (wrapper runtime-invoke)
> .runtime_invoke_void__this___object
> (object,intptr,intptr,intptr) <0x>
>
> "Threadpool worker" at  <0x>
> at (wrapper managed-to-native)
> System.Net.Sockets.Socket.Connect_internal
> (intptr,System.Net.SocketAddress,int&) <0x>
> at System.Net.Sockets.Socket.Connect (System.Net.EndPoint) <0x00135>
> at System.Net.WebConnection.Connect (System.Net.HttpWebRequest) <0x00615>
> at System.Net.WebConnection.InitConnection (object) <0x0031a>
> at System.Net.WebConnection.m__0 (object) <0x00024>
> at (wrapper runtime-invoke)
> .runtime_invoke_void__this___object
> (object,intptr,intptr,intptr) <0x>
>
> On every thread from our async code. As the connection is timing out
> the entire ThreadPool very quickly blocks.
>
> https://github.com/mono/mono/blob/master/mcs/class/System/System.Net/WebConnection.cs#L195
>
> I am guessing the right fix here would be to use async connect?
>
> Cheers,
>
> Greg
>
>
> --
> Studying for the Turing test



-- 
Studying for the Turing test
___
Mono-devel-list mailing list
Mono-devel-list@lists.ximian.com
http://lists.ximian.com/mailman/listinfo/mono-devel-list