When I read ServiceStack channel on Google+ I found an benchmark which said that ServiceStack serialization under mono is very slow. That is discouraged me because I thought that SS demonstrated very good json serialization performance versus other .net json serialization frameworks. Maybe testers used wrong configuration or bad test case? The questions were opened for me and I decided to check it by myself.

Preparing environment and measurement metrics

My environment:
CPU: Intel(R) Core(TM)2 Duo CPU E4600 @ 2.40GHz
OS: Ubuntu 12.04 32 bit
Mono Runtime Engine version 3.2.5 (master/6a9c585 Fri Oct 25 01:56:00 NOVT 2013)

I have built mono from the github sources as described here. As measurement tool I am going to use ab from apache2-utils package. If you want to install ab, you can write apt-get install apache2-utils. I am going to run ab 5 times, performing 100000 url gets each time and get the result mean. Every run I will use 10 threads to run request in parallel.

The command looks like this: ab -n 100000 -c 10 http://host:port/url

ServiceStack was compiled from github v3 branch in mono release build for Mono/.NET 4.0 platform

As soon as environment is prepared I have to create test case. I choose to create very simple ServiceStack service similar to benchmarks which returns "Hello, world!" message. You can find source code at github. Also I would like to get some metrics for comparison. I choose to create simple ASP.NET application with "Hello, world" .aspx and .html files and benchmark them.

Start benchmarking

All tests I made from localhost. This reduces overhead for network traffic, but takes processor resources what penalties to absolute results. But difference is not so much for mono benchmarks, so I decide to choose more stable results rather than higher absolute values (which could be more higher when run at faster processor unit)

Url	Web server	requests/sec	Standart deviation	std dev %
hello.aspx	xsp4	1659.238	79.39	4.78
hello.html	xsp4	1004.428	34.47	3.43
hello.html	apache2	7129.956	76.80	1.08
Servicestack	xsp4	1913.746	34.84	1.82

Amazing results. You can see, that serving static html page in apache2 has the better performance than do it with xsp4, what was predictable, but not seven-times difference! Also, apsx page serves 1.6x faster than static html. Do you expect this? I did not.

Also, when I ran these benchmarks, I found that xsp4 grew in memory very fast when serving apsx pages, and after some limit (~265m) killed threads and produced deny of service error. Seems there is some memory leak in mono web server

But our goal is ServiceStack. You can see, that ServiceStack runs faster than aspx page or static html page in xsp4, but not so fast as apache2 static html. Why is so slow? Can we improve the performance? Answers to these questions you will find in next chapters

Looking inside ServiceStack runs

Why ServiceStack runs on mono not so fast as we can expect? To find answers to the question I turned up profile mode for xsp4 and look into generated profiles. To do it, before running xsp4 execute following command in shell:

export MONO_OPTIONS="--profile=log:noalloc,output=../output.mlpd"

log:noalloc means that we don't want to gather info about allocated objects. We are interested only in method calls timing
output=../output.mlpd sets the name of file for profiling information be gathered. Please note that we set parent directory instead of current for output file. Web server watches for changes in current directory and if we set it web server will get a lot of notification messages that the directory has changed and it draws back on the performance.

After that run the commands:

ab -n 500 -c 10 http://host:port/url
mprof-report output.mlpd > profile.txt

500 method calls is enough for getting profiling information, mprof-report produces human-readable form for the info.

Method call summary
Total(ms) Self(ms)      Calls Method name
   56244        8       1581 (wrapper runtime-invoke) :runtime_invoke_void__this___object (object,intptr,intptr,intptr)
   54344        3        500 Mono.WebServer.XSPWorker:RunInternal (object)
   54240        3        500 (wrapper remoting-invoke-with-check) Mono.WebServer.XSPApplicationHost:ProcessRequest (int,System.Net.IPEndPoint,System.Net.IPEndPoint,string,string,string,string,byte[],string,intptr,Mono.WebServer.SslInformation)
   54237        5        500 Mono.WebServer.XSPApplicationHost:ProcessRequest (int,System.Net.IPEndPoint,System.Net.IPEndPoint,string,string,string,string,byte[],string,intptr,Mono.WebServer.SslInformation)
   53513        4        500 Mono.WebServer.BaseApplicationHost:ProcessRequest (Mono.WebServer.MonoWorkerRequest)
   53390        1        500 Mono.WebServer.MonoWorkerRequest:ProcessRequest ()
   53226        5        500 System.Web.HttpRuntime:ProcessRequest (System.Web.HttpWorkerRequest)
   53173        4        500 System.Web.HttpRuntime:RealProcessRequest (object)
   53157       14        500 System.Web.HttpRuntime:Process (System.Web.HttpWorkerRequest)
   44442       14        500 System.Web.HttpApplication:System.Web.IHttpHandler.ProcessRequest (System.Web.HttpContext)
   44403       18        500 System.Web.HttpApplication:Start (object)
   41356      416        500 System.Web.HttpApplication:Tick ()
   40940      148        500 System.Web.HttpApplication/c__Iterator1:MoveNext ()
   17158       10        500 ServiceStack.WebHost.Endpoints.Support.EndpointHandlerBase:ProcessRequest (System.Web.HttpContext)
   17136       39        500 ServiceStack.WebHost.Endpoints.RestHandler:ProcessRequest (ServiceStack.ServiceHost.IHttpRequest,ServiceStack.ServiceHost.IHttpResponse,string)
   11422       25        500 System.Web.HttpApplication:PipelineDone ()
   11047       12        500 System.Web.HttpApplication:OutputPage ()
   11033       53        500 System.Web.HttpResponse:Flush (bool)
   10996      74       2108 System.Web.Configuration.WebConfigurationManager:GetSection (string,string,System.Web.HttpContext)
   10646       5       1004 System.Configuration.Configuration:GetSectionInstance (System.Configuration.SectionInfo,bool)
    9401     569     130811 System.Collections.Hashtable:GetHash (object)
    9252     596     106531 System.Collections.Hashtable:get_Item (object)
    8405       11        500 System.Web.HttpApplicationFactory:GetApplication (System.Web.HttpContext)
    8082        1        500 System.Web.HttpApplication:GetHandler (System.Web.HttpContext,string)
    8081        9        500 System.Web.HttpApplication:GetHandler (System.Web.HttpContext,string,bool)
    6861    1760      25111 Mono.Globalization.Unicode.SimpleCollator:CompareInternal (string,int,int,string,int,int,bool&,bool&,bool,bool,Mono.Globalization.Unicode.SimpleCollator/Context&)
    6707        8      2500 ServiceStack.WebHost.Endpoints.Extensions.HttpRequestWrapper:get_HttpMethod ()
    6699       13       500 ServiceStack.WebHost.Endpoints.Extensions.HttpRequestWrapper:Param (string)

I bold suspicious methods with both long execution time and large number of calls. As you can see only one is from ServiceStack code it is a property HttpRequestWrapper.HttpMethod. So what can we do, how can we increase performance, when most of long executing calls are related to mono and mono web server?

Lets have a look what methods call long-executing methods. To get info about backtraces, you should run command

mprof-report --traces ../output.mlpd > profile-traces.txt

   10996       74       2108 System.Web.Configuration.WebConfigurationManager:GetSection (string,string,System.Web.HttpContext)
 500 calls from:
  System.Web.HttpApplication:Start (object)
  System.Web.HttpApplication:Tick ()
  System.Web.HttpApplication/c__Iterator1:MoveNext ()
  System.Web.HttpApplication:GetHandler (System.Web.HttpContext,string)
  System.Web.HttpApplication:GetHandler (System.Web.HttpContext,string,bool)
  System.Web.HttpApplication:LocateHandler (System.Web.HttpRequest,string,string)
 500 calls from:
  System.Web.HttpRuntime:RealProcessRequest (object)
  System.Web.HttpRuntime:Process (System.Web.HttpWorkerRequest)
  System.Web.HttpApplication:System.Web.IHttpHandler.ProcessRequest (System.Web.HttpContext)
  System.Web.HttpApplication:Start (object)
  System.Web.HttpApplication:PreStart ()
  System.Web.Configuration.WebConfigurationManager:GetSection (string)
 500 calls from:
  Mono.WebServer.XSPWorkerRequest:SendHeaders ()
  Mono.WebServer.XSPWorkerRequest:GetHeaders ()
  Mono.WebServer.MonoWorkerRequest:get_HeaderEncoding ()
  System.Web.HttpResponse:get_HeaderEncoding ()
  System.Web.Configuration.WebConfigurationManager:SafeGetSection (string,System.Type)
  System.Web.Configuration.WebConfigurationManager:GetSection (string)
 500 calls from:
  System.Web.HttpApplication:System.Web.IHttpHandler.ProcessRequest (System.Web.HttpContext)
  System.Web.HttpApplication:Start (object)
  System.Web.HttpApplication:Tick ()
  System.Web.HttpApplication/c__Iterator1:MoveNext ()
  System.Web.HttpApplication/c__Iterator0:MoveNext ()
  System.Web.Security.UrlAuthorizationModule:OnAuthorizeRequest (object,System.EventArgs)

Look at the first backtrace. Don't you think that locating handler in web.config for every request looking strange? I think, all info about handlers should be loaded only once at application start and then reused for each request. If you look into mono code you will see that handlers are cached by mono, but why is ServiceStack handler is not cached?

The answer in these lines of code:

HttpHandlersSection httpHandlersSection = WebConfigurationManager.GetSection ("system.web/httpHandlers", req.Path, req.Context) as HttpHandlersSection;
ret = httpHandlersSection.LocateHandler (verb, url, out allowCache);

IHttpHandler handler = ret as IHttpHandler;
if (allowCache && handler != null && handler.IsReusable)
        cache [id] = ret;

To be cachable ServiceStack factory handler must implement IHttpHandler interface has IsReusable property set to 'true' and be allowed to cache. In mono source code you can find that allowCache means handler path in configuration section must not be "*" but it allowed to be "servicestack*" for example. So I changed httpHandlers section in web.config by changing attribute path="*" to path="servicestack*" and added implementation of IHttpHandler interface to ServiceStackHttpHandlerFactory

  #region IHttpHandler implementation

  void IHttpHandler.ProcessRequest(HttpContext context)
  {
   throw new NotImplementedException();
  }

  bool IHttpHandler.IsReusable
  {
   get
   {
    return true;
   }
  }

  #endregion

Then I recompiled ServiceStack and performed new benchmarks

Url	Web server	requests/sec	Standart deviation	std dev %
Servicestack	xsp4	1913.746	34.84	1.82
Servicestack reusable handler factory	xsp4	2003.238	35.39	1.77

Performance is increased by 4.68%. Not so much, but this just a start

In profiler we see that GetSection now called 1624 times instead of 2108

   14158       33       1624 System.Web.Configuration.WebConfigurationManager:GetSection (string,string,System.Web.HttpContext)

Now we will try to remove another overheads of GetSection calling. We can see that this method is called from HttpApplication.PreStart method and HttpResponse.HeaderEncoding property. Looking into source code brings a solution: get globalization section only once and than reuse it. This can be done only by changing mono sources. I did it and get results:

Url	Web server	requests/sec	Standart deviation	std dev %
Servicestack (mono 9eda1b4)	xsp4	1958.37	21.54	1.10
Servicestack (patched mono 9eda1b4)	xsp4	2025.316	21.56	1.06

Performance additionally gained 3.46%. Unfortunately before the patch I have had to update mono to revision 9eda1b4 and this dropped performance by 50 points from previous results

Now profiler shows 611 calls of GetSection and 7500ms what is much better

    7516       13        611 System.Web.Configuration.WebConfigurationManager:GetSection (string,string,System.Web.HttpContext)

Please note that this hack will work only if you don't use different globalization sections in web.config files are located in subdirectories of your site. If you site requires to use own globalizations for each path, don't use this hack

Now lets look to the HashTable:GetHash method. This method is fast, but it called too much times. It is not simply to reduce number of calls, but some hints could help. For example: add key in appSetting section of web.config file and you will reduce several thousands of GetHash calls but you should know this does not boost performance to any significant value

  <add key="MonoAspnetInhibitSettingsMap" value="true"/>

This key is used by mono to map some config sections to another one. If you do not use RoleMembership functionality or SqlServerCache you can disable mappings by adding the key. For more information you can read an article http://www.mono-project.com/ASP.NET_Settings_Mapping

..To be continued

Playing with mono

среда, 6 ноября 2013 г.

Servicestack performance in mono

Preparing environment and measurement metrics

Start benchmarking

Looking inside ServiceStack runs

2 комментария:

Обо мне

среда, 6 ноября 2013 г.

Servicestack performance in mono

Preparing environment and measurement metrics

Start benchmarking

Looking inside ServiceStack runs

2 комментария:

среда, 6 ноября 2013 г.