[Mono-dev] Performance Problems on Mono with F# (maybe C#) Asyncs / Tasks

Fri Apr 11 14:17:06 UTC 2014

Hello everybody,

I think I found "one" of the root causes of the problem (while it seems 
to be true that async code performs worse on mono it doesn't seem to be 
as catastrophic as I thought initially).

It seems that the profiler analysis results have to be watched very 
carefully for code with lots of asyncs.

I figured out that "Process.GetCurrentProcess().MainModule.ModuleName" 
performs not very well on mono as
some tests with the fsharp interactive show:
.NET 4.5.1:
 > for i in 1 .. 10 do ignore <| 
Process.GetCurrentProcess().MainModule.ModuleName;;
Real: 00:00:00.000, CPU: 00:00:00.000, GC Gen0: 0, Gen1: 0, Gen2: 0
val it : unit = ()
 > for i in 1 .. 100 do ignore <| 
Process.GetCurrentProcess().MainModule.ModuleName;;
Real: 00:00:00.005, CPU: 00:00:00.000, GC Gen0: 0, Gen1: 0, Gen2: 0
val it : unit = ()
 > for i in 1 .. 1000 do ignore <| 
Process.GetCurrentProcess().MainModule.ModuleName;;
Real: 00:00:00.056, CPU: 00:00:00.062, GC Gen0: 5, Gen1: 1, Gen2: 0
val it : unit = ()
 > for i in 1 .. 100000 do ignore <| 
Process.GetCurrentProcess().MainModule.ModuleName;;
Real: 00:00:04.059, CPU: 00:00:04.093, GC Gen0: 577, Gen1: 0, Gen2: 0
val it : unit = ()

MONO (pretty much latest master):
 > for i in 1 .. 10 do ignore <| 
Process.GetCurrentProcess().MainModule.ModuleName;;
Real: 00:00:01.348, CPU: 00:00:01.280, GC gen0: 0, gen1: 0
val it : unit = ()
 > for i in 1 .. 100 do ignore <| 
Process.GetCurrentProcess().MainModule.ModuleName;;
Real: 00:00:12.905, CPU: 00:00:12.420, GC gen0: 1, gen1: 0
val it : unit = ()
 > for i in 1 .. 1000 do ignore <| 
Process.GetCurrentProcess().MainModule.ModuleName;;
Real: 00:02:13.444, CPU: 00:02:08.200, GC gen0: 6, gen1: 0
val it : unit = ()

Is this a known issue?

  Matthias

Am 06.03.2014 14:14, schrieb Matthias Dittrich:
> Hello,
>
> Basically I noticed some performance problems on mono. I have a unit 
> test suite which requires some minutes to run on .net but several 
> hours on mono.
>
> Because this code is heavily using F# asyncs I tried to find existing 
> bug reports of the problem.
> I found the following entries:
> http://lists.ximian.com/pipermail/mono-devel-list/2005-April/011477.html
> http://lists.ximian.com/pipermail/mono-bugs/2010-May/100566.html
> http://lists.ximian.com/pipermail/mono-devel-list/2010-January/033814.html
> But they all don't seem to be directly related, because of this I 
> decided to use the mono profiler and check the results.
>
> I had problems with the self compiled mono profiler 
> (libmono-profiler-log.so.0.0.0) I had to copy the file from the binary 
> distribution (It seems like the build is broken somehow on mono master?).
> For reference: I got the mighty: "The 'log' profiler wasn't found in 
> the main executable nor could it be loaded from 'mono-profiler-log'."
>
> Afer running the profiler the top results are:
> Method call summary
> Total(ms) Self(ms)      Calls Method name
> 67733962   539203     229540 
> Microsoft.FSharp.Control.AsyncBuilderImpl/callA at 815:Invoke 
> (Microsoft.FSharp.Control.AsyncParams`1<b>)
> 49135479   197016     163464 
> Microsoft.FSharp.Control.AsyncBuilderImpl/resultA at 781:Invoke 
> (Microsoft.FSharp.Control.AsyncParams`1<a>)
> 48703438    33181     162414 
> Microsoft.FSharp.Control.AsyncBuilderImpl/args at 799-1:Invoke (a)
> 42976340 42976339       5318 (wrapper managed-to-native) 
> System.Threading.WaitHandle:WaitOne_internal 
> (System.Threading.WaitHandle,intptr,int,bool)
> 42600383   368321     164611 
> Microsoft.FSharp.Control.AsyncBuilderImpl/bindA at 793:Invoke 
> (Microsoft.FSharp.Control.AsyncParams`1<b>)
> 37193074     1632      99251 (wrapper runtime-invoke) 
> <Module>:runtime_invoke_void__this___object (object,intptr,intptr,intptr)
> 29263844        8      12264 (wrapper runtime-invoke) 
> object:runtime_invoke_void__this__ (object,intptr,intptr,intptr)
> 27579799      103       4772 System.Threading.WaitHandle:WaitOne 
> (int,bool)
> 25615463      185         12 System.Threading.Thread:StartInternal ()
> 19749208       19      10942 
> System.Threading.Tasks.TpScheduler:TaskExecuterCallback (object)
> 19749189       19      10942 System.Threading.Tasks.Task:Execute ()
> 19749169       33      10942 System.Threading.Tasks.Task:ThreadStart ()
> 19748752       47      10942 System.Threading.ExecutionContext:Run 
> (System.Threading.ExecutionContext,System.Threading.ContextCallback,object)
> 19748253       90      10942 System.Security.SecurityContext:Run 
> (System.Security.SecurityContext,System.Threading.ContextCallback,object)
> 19748012       62      10942 
> System.Threading.ExecutionContext/<Run>c__AnonStorey0:<>m__0 (object)
> 19746136       55      10942 
> System.Threading.Tasks.Task/<ThreadStart>c__AnonStorey0:<>m__0 (object)
> 19744958       34      10942 System.Threading.Tasks.Task:InnerInvoke ()
> 18306055       81          5 
> System.Threading.Timer/Scheduler:SchedulerThread ()
> 18305830        3       1896 System.Threading.WaitHandle:WaitOne (int)
> 16264445        1        836 
> System.Threading.Tasks.TaskActionInvoker/FuncInvoke`1<bool>:Invoke 
> (System.Threading.Tasks.Task,object,System.Threading.Tasks.Tas\
> k)
>
> And I don't really know what that means or where the problem is 
> sitting. Can anybody help in reading the results? I have also attached 
> the complete output of mprof-report. When the problem is identified I 
> would be happy in helping to solve it.
>
> Thank you,
>  Matthias
>
>
> _______________________________________________
> Mono-devel-list mailing list
> Mono-devel-list at lists.ximian.com
> http://lists.ximian.com/mailman/listinfo/mono-devel-list

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ximian.com/pipermail/mono-devel-list/attachments/20140411/79a852c2/attachment.html>