Search code examples
c#nservicebusdotnet-httpclient

Serious delay using HttpClient in combination with NServiceBus

I'm doing an integration POC using NServiceBus. This integration fires notifications to an API when something happens.

It all works, but serious performance issues rise when concurrent http requests are executed.

I have an endpoint configured that does one thing: sending a json request (notification) to a REST API.

My Setup:

The endpoint (framework 4.6.1) has 1 static HttpClient that is initialized just once on the start of the program:

internal static void Intitialize()
        {
            ServicePointManager.DefaultConnectionLimit = 100;
            var apiSettings = NotificationEngineManager.GetInterfaceSettings()?.API;
            NotificationClient = new HttpClient();
            NotificationClient.Timeout = TimeSpan.FromSeconds(45);
            if (!string.IsNullOrEmpty(apiSettings.UserName))
            {
                var byteArray = Encoding.ASCII.GetBytes($"{apiSettings.UserName}:{apiSettings.Password}");
                NotificationClient.DefaultRequestHeaders.Authorization = new AuthenticationHeaderValue("Basic", Convert.ToBase64String(byteArray));
            }
        }

        internal static HttpClient NotificationClient { get; set; }

My handler responsible for posting the requests:

   public async Task Handle(EventRegistered message, IMessageHandlerContext context)
            {
                var apiSettings = NotificationEngineManager.GetInterfaceSettings()?.API;
                if (apiSettings == null)
                {
                    throw new BusinessException("No valid API settings found");
                }

                JsonSerializerSettings settings = new JsonSerializerSettings();
                settings.NullValueHandling = NullValueHandling.Ignore;
                settings.DateFormatString = "s";
                settings.Converters.Add(new StringEnumConverter { });


                try
                {
                    var jsonRequest = JsonConvert.SerializeObject(message.Notification, settings);
                    var response = await HttpClients.NotificationClient.PostAsync(apiSettings.Endpoint, new StringContent(jsonRequest, Encoding.UTF8, "application/json"));
                    response.EnsureSuccessStatusCode();
                }
                catch (TaskCanceledException)
                {
                    throw new Exception("Notifiaction Request timed out.");
                }

                await context.Publish(new NotificationSent(message, DateTime.Now)).ConfigureAwait(false);

}

The problem:

The NServiceBus endpoint handles 10 messages concurrently, meaning 10 http post requests at the same time.

The Rest API takes about 0.2s to respond to 1 message. But firing 10 http post requests simultaneously takes about 35 seconds. The requests all start at the same time, but also all end at the same time, which is about 35 seconds later.

enter image description here

Using netstat command I can see 10 open tcp connections to the API. So the HttpClient does handle the concurrent requests.

The strange thing is, if I set my endpoint concurrency to just 1, meaning http requests are handled 1 by 1, all 10 requests have been processed within 2 seconds.

If I set my endpoint concurrency level to 20 or more, almost all requests timeout (timeout = 45s).

Same can be reproduced using HttpWebRequest instead of HttpClient.

I'm at a loss here. What do I miss? It looks like all the requests are waiting on each other, either on the client or the server. Any help is very much appreciated.

The Rest API is a basic .NET Core API running on ISS (not express).

// POST api/notification
        [HttpPost]
        [Authorize]
        public async Task<IActionResult> Post([FromBody] Notification notification)
        {
            try
            {
                return Accepted();
            }
            catch (Exception ex)
            {

                return BadRequest(ex);
            }

        }

UPDATE: Both Client side (nservicebus) and server side (api) log. Both running in debug mode on local host and easily to reproduce.

client side

    log.Info($"Start request {message.Event.Id.ToString()}");
                    var response = await HttpClients.NotificationClient.PostAsync(apiSettings.Endpoint, new StringContent(jsonRequest, Encoding.UTF8, "application/json"));              
                    response.EnsureSuccessStatusCode();
                    log.Info($"Stop request {message.Event.Id.ToString()}");

2018-04-18 09:05:23.2886 INFO NOTIFY_WO_OUT 8 Start request
2018-04-18 09:05:23.2886 INFO NOTIFY_WO_OUT 10 Start request
2018-04-18 09:05:23.2886 INFO NOTIFY_WO_OUT 5 Start request
2018-04-18 09:05:23.2886 INFO NOTIFY_WO_OUT 2 Start request
2018-04-18 09:05:23.2886 INFO NOTIFY_WO_OUT 4 Start request
2018-04-18 09:05:23.6336 INFO NOTIFY_WO_OUT 6 Start request
2018-04-18 09:05:24.6329 INFO NOTIFY_WO_OUT 9 Start request
2018-04-18 09:05:25.6142 INFO NOTIFY_WO_OUT 1 Start request
2018-04-18 09:05:26.6544 INFO NOTIFY_WO_OUT 7 Start request
2018-04-18 09:05:27.6545 INFO NOTIFY_WO_OUT 3 Start request
2018-04-18 09:05:47.2034 INFO NOTIFY_WO_OUT 5 Stop request
2018-04-18 09:05:47.6285 INFO NOTIFY_WO_OUT 3 Stop request
2018-04-18 09:05:47.9855 INFO NOTIFY_WO_OUT 6 Stop request
2018-04-18 09:05:48.0550 INFO NOTIFY_WO_OUT 9 Stop request
2018-04-18 09:05:48.5226 INFO NOTIFY_WO_OUT 4 Stop request
2018-04-18 09:05:48.5526 INFO NOTIFY_WO_OUT 10 Stop request
2018-04-18 09:05:48.9987 INFO NOTIFY_WO_OUT 8 Stop request
2018-04-18 09:05:49.0347 INFO NOTIFY_WO_OUT 1 Stop request
2018-04-18 09:05:49.0647 INFO NOTIFY_WO_OUT 7 Stop request
2018-04-18 09:05:49.3017 INFO NOTIFY_WO_OUT 2 Stop request

server side logging. Logging middleware added to the beginning of the pipeline.

2018-04-18 09:05:38.7660 INFO Begin Request 6
2018-04-18 09:05:38.7850 INFO message 6 received
2018-04-18 09:05:38.8150 INFO End Request 6
2018-04-18 09:05:39.4036 INFO Begin Request 9
2018-04-18 09:05:39.4231 INFO message 9 received
2018-04-18 09:05:39.4551 INFO End Request 9
2018-04-18 09:05:39.7172 INFO Begin Request 10
2018-04-18 09:05:39.7512 INFO message 10 received
2018-04-18 09:05:39.7512 INFO Begin Request 8
2018-04-18 09:05:39.7812 INFO End Request 10
2018-04-18 09:05:39.8132 INFO message 8 received
2018-04-18 09:05:39.8302 INFO End Request 8
2018-04-18 09:05:40.0722 INFO Begin Request 1
2018-04-18 09:05:40.1097 INFO message 1 received
2018-04-18 09:05:40.1097 INFO Begin Request 5
2018-04-18 09:05:40.1413 INFO message 5 received
2018-04-18 09:05:40.1703 INFO End Request 1
2018-04-18 09:05:40.1913 INFO End Request 5
2018-04-18 09:05:40.4033 INFO Begin Request 3
2018-04-18 09:05:40.4403 INFO message 3 received
2018-04-18 09:05:40.4563 INFO End Request 3
2018-04-18 09:05:40.5173 INFO Begin Request 7
2018-04-18 09:05:40.5508 INFO message 7 received
2018-04-18 09:05:40.5663 INFO End Request 7
2018-04-18 09:05:41.0100 INFO Begin Request 4
2018-04-18 09:05:41.0470 INFO message 4 received
2018-04-18 09:05:41.0630 INFO End Request 4
2018-04-18 09:05:41.3535 INFO Begin Request 2
2018-04-18 09:05:41.3740 INFO message 2 received
2018-04-18 09:05:41.4080 INFO End Request 2

Looking at request 8. Request was initiated in code at .23. Server received request at .39. So there is a gap of 16 seconds.

Solution

  • I was logging the network trace using System.Diagnostics and NLog. This was causing the serious performance drop.

    Disabling System.Diagnostics solved my issue.