search

hudl / Mjolnir

Isolation and fail-fast fault tolerance library, modeled after https://github.com/Netflix/Hystrix.
Apache License 2.0
78 stars 10 forks source link

Bulkhead don't take effect immediately #56

Open RongieZeng opened 8 years ago

RongieZeng commented 8 years ago

Context: 1、I use jemeter to load test one api which is hosted in IIS, and the api dependency on a remote service which is wrappered up with the SyncCommand class. 2、The load is 100 Thread/Request per second, the remote service calling will take at least 60s(just for test), the maxConcurrent of Hudl.Mjolnir is 30.

Problem: Because every requests take very long time, so i think when 100 requests are comming, just 30 requests will be accepted, and other 70 ones will be rejected immediately. But the real test don't work like this, before the 70 ones and the follow-up requests are rejected, the requests are still blocked about 1 minute. And why is this?

robhruska commented 8 years ago

Thanks for the report @RongieZeng, I'll have a look. The semaphore bulkhead is new in 1.6.0, so it could be a bug. I'll try and get to it this weekend. I've been a bit behind on Mjolnir work and been meaning to catch up on getting 2.6.0 out the door officially.

RongieZeng commented 8 years ago

OK. Thank you for your work, expect for it.

RongieZeng commented 8 years ago

Hi, @robhruska . Is there any progress?

robhruska commented 8 years ago

I've been running some tests to try and reproduce this, but the bulkhead seems to be applying immediately for me. I'm running a test with a sync command that Thread.Sleeps for 60 seconds with a maxConcurrency of 30, and as soon as the 31st request comes in (while the other 30 are sleeping) it and subsequent requests are all rejected within a couple milliseconds of being received.

The test is just run by hitting a .NET MVC controller action that creates a new command and invokes it using CommandInvoker.Instance.InvokeReturn().

Any chance you could share the code for your command and anything else that might be relevant? Does anything in the source code for the bulkhead or semaphore stick out to you as a possible cause?

RongieZeng commented 8 years ago

The command:

public class UserInfoCommand : SyncCommand<UserInfoResp>
        {
        private IUserService _userService;
        private UserInfoReq _userInfoReq;
        public UserInfoCommand(IUserService userService, UserInfoReq userInfoReq) : base("UserService", "UserServiceUserInfo", new TimeSpan(0, 0, 5))
        {
            _userService = userService;
            _userInfoReq = userInfoReq;
        }
        public override UserInfoResp Execute(CancellationToken cancellationToken)
        {
            return _userService.UserInfo(_userInfoReq);
        }
    }

CommandHelper:

 public class CommandHelper
        {
        public static T Excute<T>(SyncCommand<T> command)
        {
            var commandInvoker = new CommandInvoker();
            return commandInvoker.InvokeThrow(command);
        }
    }

The place use the command:

[HttpGet]
            public ActionResult CustomerInfoTest(string regNumber)
            {
            var userInfoResp = CommandHelper.Excute(new UserInfoCommand(_userService, new UserInfoReq { RegNumber = regNumber }));
            return new JsonResult()
            {
                Data = new { Success = userInfoResp.Success, RegNumber = regNumber },
                JsonRequestBehavior = JsonRequestBehavior.AllowGet
            };
        }      
       public ActionResult Test()
      {
          return Content("Hello word");
      }

More information: I recyle the AppPool which host the MVC application before the test, which will make sure every object in the Hudl.Mjonir is not initialized. I know that if the first time an asp.net application is started up, it will take some time to compile the application, so i have visited the 'Test' action first. Once the bulkhead has take effect, everything is ok.

RongieZeng commented 8 years ago

Mjolnir's log :

2016-06-08 10:52:59,795 [DEBUG] [1] Added Key=mjolnir.pools.default.threadCount, Value='20' 
2016-06-08 10:52:59,810 [DEBUG] [1] Added Key=mjolnir.pools.default.queueLength, Value='20' 
2016-06-08 10:52:59,810 [DEBUG] [1] Added Key=mjolnir.bulkhead.UserServiceUserInfo.maxConcurrent, Value='20' 
2016-06-08 10:52:59,810 [DEBUG] [1] Added Key=mjolnir.breaker.default.minimumOperations, Value='10' 
2016-06-08 10:52:59,810 [DEBUG] [1] Added Key=mjolnir.breaker.default.thresholdPercentage, Value='50' 
2016-06-08 10:52:59,810 [DEBUG] [1] Added Key=mjolnir.breaker.default.trippedDurationMillis, Value='10000' 
2016-06-08 10:52:59,810 [DEBUG] [1] Added Key=mjolnir.metrics.default.windowMillis, Value='45000' 
2016-06-08 10:53:04,303 [INFO ] [10] DotNetOpenAuth.Core, Version=4.3.4.13329, Culture=neutral, PublicKeyToken=2780ccd10d57b246 (official) 
2016-06-08 10:53:04,319 [INFO ] [10] Reporting will use isolated storage with scope: Domain, Assembly, Machine 
2016-06-08 10:53:50,916 [INFO ] [12] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:50,916 [INFO ] [7] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:50,916 [INFO ] [10] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:50,916 [INFO ] [8] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:50,916 [INFO ] [12] Begin getting bulkhead 
2016-06-08 10:53:50,916 [INFO ] [7] Begin getting bulkhead 
2016-06-08 10:53:50,916 [INFO ] [10] Begin getting bulkhead 
2016-06-08 10:53:50,916 [INFO ] [8] Begin getting bulkhead 
2016-06-08 10:53:50,947 [INFO ] [12] End getting bulkhead 
2016-06-08 10:53:50,947 [INFO ] [7] End getting bulkhead 
2016-06-08 10:53:50,947 [INFO ] [10] End getting bulkhead 
2016-06-08 10:53:50,947 [INFO ] [8] End getting bulkhead 
2016-06-08 10:53:51,571 [INFO ] [9] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:51,571 [INFO ] [9] Begin getting bulkhead 
2016-06-08 10:53:51,571 [INFO ] [9] End getting bulkhead 
2016-06-08 10:53:52,102 [INFO ] [15] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:52,102 [INFO ] [15] Begin getting bulkhead 
2016-06-08 10:53:52,102 [INFO ] [15] End getting bulkhead 
2016-06-08 10:53:52,648 [INFO ] [16] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:52,648 [INFO ] [16] Begin getting bulkhead 
2016-06-08 10:53:52,648 [INFO ] [16] End getting bulkhead 
2016-06-08 10:53:53,163 [INFO ] [17] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:53,163 [INFO ] [17] Begin getting bulkhead 
2016-06-08 10:53:53,163 [INFO ] [17] End getting bulkhead 
2016-06-08 10:53:53,693 [INFO ] [18] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:53,693 [INFO ] [18] Begin getting bulkhead 
2016-06-08 10:53:53,693 [INFO ] [18] End getting bulkhead 
2016-06-08 10:53:54,223 [INFO ] [20] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:54,223 [INFO ] [20] Begin getting bulkhead 
2016-06-08 10:53:54,223 [INFO ] [20] End getting bulkhead 
2016-06-08 10:53:54,754 [INFO ] [21] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:54,754 [INFO ] [21] Begin getting bulkhead 
2016-06-08 10:53:54,754 [INFO ] [21] End getting bulkhead 
2016-06-08 10:53:55,284 [INFO ] [22] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:55,284 [INFO ] [22] Begin getting bulkhead 
2016-06-08 10:53:55,284 [INFO ] [22] End getting bulkhead 
2016-06-08 10:53:55,830 [INFO ] [23] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:55,830 [INFO ] [23] Begin getting bulkhead 
2016-06-08 10:53:55,830 [INFO ] [23] End getting bulkhead 
2016-06-08 10:53:56,361 [INFO ] [24] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:56,361 [INFO ] [24] Begin getting bulkhead 
2016-06-08 10:53:56,361 [INFO ] [24] End getting bulkhead 
2016-06-08 10:53:57,359 [INFO ] [25] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:57,359 [INFO ] [25] Begin getting bulkhead 
2016-06-08 10:53:57,359 [INFO ] [25] End getting bulkhead 
2016-06-08 10:53:58,373 [INFO ] [26] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:58,373 [INFO ] [26] Begin getting bulkhead 
2016-06-08 10:53:58,373 [INFO ] [26] End getting bulkhead 
2016-06-08 10:53:59,371 [INFO ] [27] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:53:59,371 [INFO ] [27] Begin getting bulkhead 
2016-06-08 10:53:59,371 [INFO ] [27] End getting bulkhead 
2016-06-08 10:54:00,370 [INFO ] [28] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:54:00,370 [INFO ] [28] Begin getting bulkhead 
2016-06-08 10:54:00,370 [INFO ] [28] End getting bulkhead 
2016-06-08 10:54:01,368 [INFO ] [29] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:54:01,368 [INFO ] [29] Begin getting bulkhead 
2016-06-08 10:54:01,368 [INFO ] [29] End getting bulkhead 
2016-06-08 10:54:02,367 [INFO ] [30] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:54:02,367 [INFO ] [30] Begin getting bulkhead 
2016-06-08 10:54:02,367 [INFO ] [30] End getting bulkhead 
2016-06-08 10:54:03,427 [INFO ] [31] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 10:54:03,427 [INFO ] [31] Begin getting bulkhead 
2016-06-08 10:54:03,427 [INFO ] [31] End getting bulkhead 
2016-06-08 10:54:04,192 [ERROR] [31] Error。 
Hudl.Mjolnir.Bulkhead.BulkheadRejectedException: “Hudl.Mjolnir.Bulkhead.BulkheadRejectedException”。
   At Hudl.Mjolnir.Command.BulkheadInvoker.ExecuteWithBulkhead[TResult](SyncCommand`1 command, CancellationToken ct)
   At Hudl.Mjolnir.Command.CommandInvoker.Invoke[TResult](SyncCommand`1 command, OnFailure failureAction, InformativeCancellationToken ct)
   At Hudl.Mjolnir.Command.CommandInvoker.InvokeThrow[TResult](SyncCommand`1 command)
   At WHTR.VipCenter.Services.Commands.CommandHelper.Excute[T](SyncCommand`1 command)
   At WHTR.VipCenter.Web.Controllers.HomeController.CustomerInfoTest(String regNumber)
   At lambda_method(Closure , ControllerBase , Object[] )
   At System.Web.Mvc.ReflectedActionDescriptor.Execute(ControllerContext controllerContext, IDictionary`2 parameters)
   At System.Web.Mvc.ControllerActionInvoker.InvokeActionMethod(ControllerContext controllerContext, ActionDescriptor actionDescriptor, IDictionary`2 parameters)
   At System.Web.Mvc.Async.AsyncControllerActionInvoker.<BeginInvokeSynchronousActionMethod>b__39(IAsyncResult asyncResult, ActionInvocation innerInvokeState)
   At System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult`2.CallEndDelegate(IAsyncResult asyncResult)
   At System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<InvokeActionMethodFilterAsynchronouslyRecursive>b__3f()
   At System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass48.<InvokeActionMethodFilterAsynchronouslyRecursive>b__41()
   At System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass33.<BeginInvokeActionMethodWithFilters>b__32(IAsyncResult asyncResult)
   At System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<>c__DisplayClass2b.<BeginInvokeAction>b__1c()
   At System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<BeginInvokeAction>b__1e(IAsyncResult asyncResult)
   At System.Web.Mvc.Controller.<BeginExecuteCore>b__1d(IAsyncResult asyncResult, ExecuteCoreState innerState)
   At System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult)
   At System.Web.Mvc.Controller.EndExecuteCore(IAsyncResult asyncResult)
   At System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult)
   At System.Web.Mvc.MvcHandler.<BeginProcessRequest>b__5(IAsyncResult asyncResult, ProcessRequestState innerState)
   At System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult)
   At System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
   At System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

'Begin getting bulkhead' and 'End getting bulkhead' is added before and after '_context.GetBulkhead(command.BulkheadKey)'. And the request's datetime is '10:53:50,916'(100 requests is comming at the same time), while the first reject time is '10:54:04,192'

robhruska commented 8 years ago

That behavior looks correct to me. The logs show mjolnir.bulkhead.UserServiceUserInfo.maxConcurrent=20, and I see 20 CommandInvoke logs, with the 21st attempt being rejected.

From your original post:

the requests are still blocked about 1 minute. And why is this?

Is part of the differing expectation here due to timeout behavior and not necessarily the bulkhead itself?

Though you've defined the 5-second timeout in the Command constructor, you haven't passed the CancellationToken through to the call to your user service in your Execute method, so there's likely no timeout being applied. Mjolnir's timeout/cancellation behavior assumes you're using cooperative cancellation there (like we chatted about in #54).

RongieZeng commented 8 years ago

Sorry. Maybe this is not the problem of Mjolnir. I add a log at the begging of the action:

 [HttpGet]
        public ActionResult CustomerInfoTest(string regNumber)
        {
            logger.Info("Request is comming");
            var userInfoResp = CommandHelper.Excute(new UserInfoCommand(_userService, new UserInfoReq { RegNumber = regNumber }));
            return new JsonResult()
            {
                Data = new { Success = userInfoResp.Success, RegNumber = regNumber },
                JsonRequestBehavior = JsonRequestBehavior.AllowGet
            };
        }

And the log is like this:


2016-06-08 12:05:12,983 [INFO ] [55] Request is comming 
2016-06-08 12:05:12,983 [INFO ] [53] Request is comming 
2016-06-08 12:05:12,983 [INFO ] [52] Request is comming 
2016-06-08 12:05:12,983 [INFO ] [57] Request is comming 
2016-06-08 12:05:12,983 [INFO ] [56] Request is comming 
2016-06-08 12:05:12,983 [INFO ] [54] Request is comming 
2016-06-08 12:05:13,092 [INFO ] [52] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:13,092 [INFO ] [53] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:13,092 [INFO ] [57] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:13,092 [INFO ] [55] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:13,092 [INFO ] [56] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:13,092 [INFO ] [54] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:13,108 [INFO ] [52] Begin getting bulkhead 
2016-06-08 12:05:13,108 [INFO ] [54] Begin getting bulkhead 
2016-06-08 12:05:13,108 [INFO ] [55] Begin getting bulkhead 
2016-06-08 12:05:13,108 [INFO ] [53] Begin getting bulkhead 
2016-06-08 12:05:13,108 [INFO ] [57] Begin getting bulkhead 
2016-06-08 12:05:13,108 [INFO ] [56] Begin getting bulkhead 
2016-06-08 12:05:13,139 [INFO ] [52] End getting bulkhead 
2016-06-08 12:05:13,139 [INFO ] [56] End getting bulkhead 
2016-06-08 12:05:13,139 [INFO ] [53] End getting bulkhead 
2016-06-08 12:05:13,139 [INFO ] [55] End getting bulkhead 
2016-06-08 12:05:13,139 [INFO ] [54] End getting bulkhead 
2016-06-08 12:05:13,139 [INFO ] [57] End getting bulkhead 
2016-06-08 12:05:13,810 [INFO ] [36] Request is comming 
2016-06-08 12:05:13,810 [INFO ] [36] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:13,810 [INFO ] [36] Begin getting bulkhead 
2016-06-08 12:05:13,810 [INFO ] [36] End getting bulkhead 
2016-06-08 12:05:14,340 [INFO ] [58] Request is comming 
2016-06-08 12:05:14,340 [INFO ] [58] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:14,340 [INFO ] [58] Begin getting bulkhead 
2016-06-08 12:05:14,340 [INFO ] [58] End getting bulkhead 
2016-06-08 12:05:14,918 [INFO ] [59] Request is comming 
2016-06-08 12:05:14,918 [INFO ] [59] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:14,918 [INFO ] [59] Begin getting bulkhead 
2016-06-08 12:05:14,918 [INFO ] [59] End getting bulkhead 
2016-06-08 12:05:15,869 [INFO ] [51] Request is comming 
2016-06-08 12:05:15,869 [INFO ] [51] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:15,869 [INFO ] [51] Begin getting bulkhead 
2016-06-08 12:05:15,869 [INFO ] [51] End getting bulkhead 
2016-06-08 12:05:16,868 [INFO ] [49] Request is comming 
2016-06-08 12:05:16,868 [INFO ] [49] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:16,868 [INFO ] [49] Begin getting bulkhead 
2016-06-08 12:05:16,868 [INFO ] [49] End getting bulkhead 
2016-06-08 12:05:17,850 [INFO ] [48] Request is comming 
2016-06-08 12:05:17,850 [INFO ] [48] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:17,866 [INFO ] [48] Begin getting bulkhead 
2016-06-08 12:05:17,866 [INFO ] [48] End getting bulkhead 
2016-06-08 12:05:18,849 [INFO ] [15] Request is comming 
2016-06-08 12:05:18,864 [INFO ] [15] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:18,864 [INFO ] [15] Begin getting bulkhead 
2016-06-08 12:05:18,864 [INFO ] [15] End getting bulkhead 
2016-06-08 12:05:19,863 [INFO ] [47] Request is comming 
2016-06-08 12:05:19,863 [INFO ] [47] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:19,863 [INFO ] [47] Begin getting bulkhead 
2016-06-08 12:05:19,863 [INFO ] [47] End getting bulkhead 
2016-06-08 12:05:20,861 [INFO ] [46] Request is comming 
2016-06-08 12:05:20,861 [INFO ] [46] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:20,861 [INFO ] [46] Begin getting bulkhead 
2016-06-08 12:05:20,861 [INFO ] [46] End getting bulkhead 
2016-06-08 12:05:21,860 [INFO ] [44] Request is comming 
2016-06-08 12:05:21,860 [INFO ] [44] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:21,860 [INFO ] [44] Begin getting bulkhead 
2016-06-08 12:05:21,860 [INFO ] [44] End getting bulkhead 
2016-06-08 12:05:22,874 [INFO ] [43] Request is comming 
2016-06-08 12:05:22,874 [INFO ] [43] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:22,874 [INFO ] [43] Begin getting bulkhead 
2016-06-08 12:05:22,874 [INFO ] [43] End getting bulkhead 
2016-06-08 12:05:23,872 [INFO ] [42] Request is comming 
2016-06-08 12:05:23,872 [INFO ] [42] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:23,872 [INFO ] [42] Begin getting bulkhead 
2016-06-08 12:05:23,872 [INFO ] [42] End getting bulkhead 
2016-06-08 12:05:24,870 [INFO ] [41] Request is comming 
2016-06-08 12:05:24,870 [INFO ] [41] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:24,870 [INFO ] [41] Begin getting bulkhead 
2016-06-08 12:05:24,870 [INFO ] [41] End getting bulkhead 
2016-06-08 12:05:25,869 [INFO ] [40] Request is comming 
2016-06-08 12:05:25,869 [INFO ] [40] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:25,869 [INFO ] [40] Begin getting bulkhead 
2016-06-08 12:05:25,869 [INFO ] [40] End getting bulkhead 
2016-06-08 12:05:26,867 [INFO ] [39] Request is comming 
2016-06-08 12:05:26,867 [INFO ] [39] Invoke Command=UserService.UserInfo Breaker=UserServiceUserInfo Bulkhead=UserServiceUserInfo Timeout=5000 
2016-06-08 12:05:26,867 [INFO ] [39] Begin getting bulkhead 
2016-06-08 12:05:26,867 [INFO ] [39] End getting bulkhead 
2016-06-08 12:05:27,616 [ERROR] [39] Rrror。 
Hudl.Mjolnir.Bulkhead.BulkheadRejectedException: “Hudl.Mjolnir.Bulkhead.BulkheadRejectedException”。
   At Hudl.Mjolnir.Command.BulkheadInvoker.ExecuteWithBulkhead[TResult](SyncCommand`1 command, CancellationToken ct)
   At Hudl.Mjolnir.Command.CommandInvoker.Invoke[TResult](SyncCommand`1 command, OnFailure failureAction, InformativeCancellationToken ct)
   At Hudl.Mjolnir.Command.CommandInvoker.InvokeThrow[TResult](SyncCommand`1 command)
   At WHTR.VipCenter.Services.Commands.CommandHelper.Excute[T](SyncCommand`1 command)
   At WHTR.VipCenter.Web.Controllers.HomeController.CustomerInfoTest(String regNumber)
   At lambda_method(Closure , ControllerBase , Object[] )
   At System.Web.Mvc.ReflectedActionDescriptor.Execute(ControllerContext controllerContext, IDictionary`2 parameters)
   At System.Web.Mvc.ControllerActionInvoker.InvokeActionMethod(ControllerContext controllerContext, ActionDescriptor actionDescriptor, IDictionary`2 parameters)
   At System.Web.Mvc.Async.AsyncControllerActionInvoker.<BeginInvokeSynchronousActionMethod>b__39(IAsyncResult asyncResult, ActionInvocation innerInvokeState)
   At System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult`2.CallEndDelegate(IAsyncResult asyncResult)
   At System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<InvokeActionMethodFilterAsynchronouslyRecursive>b__3f()
   At System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass48.<InvokeActionMethodFilterAsynchronouslyRecursive>b__41()
   At System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass33.<BeginInvokeActionMethodWithFilters>b__32(IAsyncResult asyncResult)
   At System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<>c__DisplayClass2b.<BeginInvokeAction>b__1c()
   At System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<BeginInvokeAction>b__1e(IAsyncResult asyncResult)
   At System.Web.Mvc.Controller.<BeginExecuteCore>b__1d(IAsyncResult asyncResult, ExecuteCoreState innerState)
   At System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult)
   At System.Web.Mvc.Controller.EndExecuteCore(IAsyncResult asyncResult)
   At System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult)
   At System.Web.Mvc.MvcHandler.<BeginProcessRequest>b__5(IAsyncResult asyncResult, ProcessRequestState innerState)
   At System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult)
   At System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()

Still don't know where the requests are blocked, i'll have some more tests

RongieZeng commented 8 years ago

Yes, i know the timeout will not work here. What i expect is the cost time between the first requst coming and the first request is rejected is 1s, but now it is about 14s(the original post is about 1 minute, don't know why).