HyperFastCgi Performace Degradation about hyperfastcgi

[xplicit]

What is the HelloWorld application you used to check the performance?

500 reqs/second is very low throughput for HelloWorld.app with native listener. Accordingly to your nginx static file tests you should get 1.2-1.3K rps for ASP.NET WebForms app and 2.3-2.5K if you use servicestack for REST.

For benchmarking you should disable logging in nginx (disable access log) and in hyperfastcgi (set the logging levels to error only and please check that hyperfastcgi logs don't contain errors). And please check that the app returns the page you've expected (if the page returns an ASP.NET error message instead, the performance could be very low).

Also it would be interesting to see benchmarking results for Raw Host https://github.com/xplicit/HyperFastCgi/blob/master/samples/hello-world.config

I've made the tests before for ServiceStack helloworld app and WebForms helloworld app, running 100 millions requests without degrading performance, so I think the issue possible in the exceptions were throwed during the benchmarking or in the specific application code.

[matsaleh13]

Thanks for your quick reply!

I agree that 500 reqs/sec is very low; thanks for confirming that. The expected performance you suggest is what I also had expected, between 1K - 2.5K depending on various other factors.

We have a custom ASP.NET framework upon which we are building a suite of web "micro" services. It is similar in nature to ServiceStack as far as I know. Our HelloWorld is a reference implementation of one such service.

The request being tested is a trivial "echo". The service responds with a raw string, the contents of the last segment of the request's URL. In all my tests, this is simply the string "test". I have verified during testing that the app returns the expected string "test".

I will try adjusting the log output as you suggest in both nginx and hyperfastcgi.

I have not found any evidence of exceptions being thrown in our service code. If they are, they are being silently ignored (obviously horrible if so, I'll verify).

As part of my performance analysis, I profiled our HelloWorld service running under HyperFastCgi while running one of our ab tests. Perhaps you could gain some insight from it, and make some suggestions. Please see the mprof report below, where I have marked lines of interest with asterisks (**):

Method call summary
Total(ms) Self(ms)      Calls Method name
 1225084      180      69274 (wrapper runtime-invoke) <Module>:runtime_invoke_void__this___object (object,intptr,intptr,intptr)
**887436   887436      92455 (wrapper managed-to-native) System.Threading.WaitHandle:WaitOne_internal (System.Threading.WaitHandle,intptr,int,bool)
  850860      131      47376 System.Threading.WaitHandle:WaitOne (int,bool)
  845852       23      23856 (wrapper runtime-invoke) object:runtime_invoke_void__this__ (object,intptr,intptr,intptr)
  845605        4          2 System.Threading.Thread:StartInternal ()
  845600      222          2 System.Threading.Timer/Scheduler:SchedulerThread ()
  844845       20      45041 System.Threading.WaitHandle:WaitOne (int)
  644640       49      22546 HyperFastCgi.Transports.BaseAppHostTransport/<AddBodyPart>c__AnonStorey0:<>m__1 (object)
  644591       45      22546 HyperFastCgi.AppHosts.AspNet.AspNetNativeWebRequest:Process (HyperFastCgi.Interfaces.IWebResponse)
  644545       36      22546 HyperFastCgi.AppHosts.AspNet.MonoWorkerRequest:ProcessRequest ()
  644484       59      22546 System.Web.HttpRuntime:ProcessRequest (System.Web.HttpWorkerRequest)
  643917       89      22546 System.Web.HttpRuntime:RealProcessRequest (object)
**643365      151      22546 System.Web.HttpRuntime:Process (System.Web.HttpWorkerRequest)
**558696      112      22546 System.Web.HttpApplication:System.Web.IHttpHandler.ProcessRequest (System.Web.HttpContext)
  557503        0          1 (wrapper runtime-invoke) <Module>:runtime_invoke_int_object (object,intptr,intptr,intptr)
  557503        9          1 HyperFastCgi.MainClass:Main (string[])
  556055        0          1 HyperFastCgi.Listeners.NativeListener:<Listen>m__0 (object)
  556055   548848          1 (wrapper managed-to-native) HyperFastCgi.Listeners.NativeListener:ProcessLoop ()
  556046        0          1 Mono.Unix.UnixSignal:WaitAny (Mono.Unix.UnixSignal[])
  556046        0          1 Mono.Unix.UnixSignal:WaitAny (Mono.Unix.UnixSignal[],int)
  556046   556044          1 (wrapper managed-to-native) Mono.Unix.UnixSignal:WaitAny (intptr[],int,int,Mono.Unix.UnixSignal/Mono_Posix_RuntimeIsShuttingDown)
  521490       80      22546 System.Web.HttpApplication:Start (object)
**511079     1340      39825 System.Web.HttpApplication:Tick ()
**509734     1081      39825 System.Web.HttpApplication/<Pipeline>c__Iterator1:MoveNext ()
**467888      126      22546 MyCompany.RpcServer.Web.RpcAsyncHandler:BeginProcessRequest (System.Web.HttpContext,System.AsyncCallback,object)
**467613     1116      35328 MyCompany.RpcServer.Web.RpcAsyncHandler/<ProcessRequestAsync>c__async0:MoveNext ()
  465738       35      22546 MyCompany.RpcServer.Web.RpcAsyncHandler:ProcessRequestAsync (System.Web.HttpContext)
  465530       52      22546 System.Runtime.CompilerServices.AsyncTaskMethodBuilder:Start<MyCompany.RpcServer.Web.RpcAsyncHandler/<ProcessRequestAsync>c__async0> (MyCompany.RpcServer.Web.RpcAsyncHandler/<ProcessRequestAsync>c__async0&)
  338794      133     157944 System.Collections.Specialized.NameValueCollection:get_Item (string)
  335142       30      22546 System.Web.HttpParamsCollection:Get (string)
  332980       66      22546 System.Web.HttpParamsCollection:MergeCollections ()
**332878     1827      67663 System.Collections.Specialized.NameValueCollection:Add (System.Collections.Specialized.NameValueCollection)
**253109     5170    2299694 System.Collections.Specialized.NameValueCollection:Add (string,string)
**214610     6754    8169150 System.Collections.Hashtable:GetHash (object)
**201955    37328    6786215 System.Web.Util.SecureHashCodeProvider:GetHashCode (object)
  191292      945    2119262 System.Web.BaseParamsCollection:LoadInfo ()
  182019       46      22546 System.Web.BaseParamsCollection:get_Count ()
  181926       33      22546 System.Web.ServerVariablesCollection:InsertInfo ()
  181893     1016      22546 System.Web.ServerVariablesCollection:loadServerVariablesCollection ()
**164644   106191   83410743 char:ToLower (char,System.Globalization.CultureInfo)
**161323     6469    2324869 System.Collections.Specialized.NameObjectCollectionBase:BaseAdd (string,object)
  151755     5203    5785464 System.Collections.Hashtable:get_Item (object)

I have not yet tried printing traces from this report, but I think I'll take a stab at that for some of these calls.

Thanks again for your help, and best regards.

[matsaleh13]

Sergey,

I want to thank you again very much for your time.

After reading your comments about HelloWorld, I decided to write a truly trivial implementation that does not use our service framework at all to use as a baseline. I reran my test suite against the new trivial service running under HyperFastCgi, and this time I got the expected results: approximately 2400 requests/second at concurrency 20 with no degradation over time.

I apologize for wasting your time, but thank you very much for helping me scope my investigation more precisely.

Kind regards, Matt

[xplicit]

Glad to hear that! By the way from your profiling traces I suspect that you've run into threadpool strarving when threads don't return to the threadpool after assigning by asynchronous task. This is just an idea I can't be sure 100% in it. You can proof or overturn my suspection by watching number of threads in threadpool (via performance counter, for example). Also if I am right about threadpool starving, increasing min-threads value in hyperfastcgi config should decrease degradation.

[matsaleh13]

Thanks very much for that observation and suggestion! For the near term we've got a non-async implementation that provides reliable behavior and acceptable results for now. We'll want to revisit async soon enough, however, so I'll be sure to keep your suggestion in mind when I come back to that.

Thanks and regards, Matt