Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Bulkhead don't take effect immediately #56

Open
RongieZeng opened this issue Jun 3, 2016 · 9 comments
Open

Bulkhead don't take effect immediately #56

RongieZeng opened this issue Jun 3, 2016 · 9 comments

Comments

@RongieZeng
Copy link

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?
@RongieZeng RongieZeng changed the title Bulkhead isn't effective immediately Bulkhead don't take effect immediately Jun 3, 2016
@robhruska
Copy link
Member

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
Copy link
Author

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

@RongieZeng
Copy link
Author

Hi, @robhruska . Is there any progress?

@robhruska
Copy link
Member

robhruska commented Jun 7, 2016 •
edited
Loading

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
Copy link
Author

RongieZeng commented Jun 8, 2016 •
edited
Loading

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
Copy link
Author

RongieZeng commented Jun 8, 2016 •
edited
Loading

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
Copy link
Member

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
Copy link
Author

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](SyncCommand1 command, CancellationToken ct) At Hudl.Mjolnir.Command.CommandInvoker.Invoke[TResult](SyncCommand1 command, OnFailure failureAction, InformativeCancellationToken ct)
At Hudl.Mjolnir.Command.CommandInvoker.InvokeThrow[TResult](SyncCommand1 command) At WHTR.VipCenter.Services.Commands.CommandHelper.Excute[T](SyncCommand1 command)
At WHTR.VipCenter.Web.Controllers.HomeController.CustomerInfoTest(String regNumber)
At lambda_method(Closure , ControllerBase , Object[] )
At System.Web.Mvc.ReflectedActionDescriptor.Execute(ControllerContext controllerContext, IDictionary2 parameters) At System.Web.Mvc.ControllerActionInvoker.InvokeActionMethod(ControllerContext controllerContext, ActionDescriptor actionDescriptor, IDictionary2 parameters)
At System.Web.Mvc.Async.AsyncControllerActionInvoker.b__39(IAsyncResult asyncResult, ActionInvocation innerInvokeState)
At System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult2.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.WrappedAsyncVoid1.CallEndDelegate(IAsyncResult asyncResult)
At System.Web.Mvc.Controller.EndExecuteCore(IAsyncResult asyncResult)
At System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid1.CallEndDelegate(IAsyncResult asyncResult) At System.Web.Mvc.MvcHandler.<BeginProcessRequest>b__5(IAsyncResult asyncResult, ProcessRequestState innerState) At System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid1.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
Copy link
Author

RongieZeng commented Jun 8, 2016 •
edited
Loading

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).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@robhruska @RongieZeng