Warm tip: This article is reproduced from stackoverflow.com, please click
api c# duration request wpf

Wpf Desktop Api call duration more longer than actual api response time about 8-10 seconds

发布于 2020-03-29 20:59:34

Here is case: I have wpf application on about 80 clients and they communicate single .net framework api for data process. I have stopwatch tracker some places for tracking durations on Wpf and api apps. Code samples :

My api attribute :

public class DurationControlLoggerAttribute : ActionFilterAttribute
{
    public override void OnActionExecuting(HttpActionContext actionContext)
    {
        var controller = actionContext.ActionDescriptor.ControllerDescriptor.ControllerName;
        var action = actionContext.ActionDescriptor.ActionName;

        actionContext.ActionArguments.Add("_stopwatch_", Stopwatch.StartNew());
    }

    public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        if (ConfigurationManager.AppSettings["ApiLogger"].ToLower().Trim() != "true")
            return;

        var controller = actionExecutedContext.ActionContext.ActionDescriptor.ControllerDescriptor.ControllerName;
        var action = actionExecutedContext.ActionContext.ActionDescriptor.ActionName;

        var stopWatch = (Stopwatch)actionExecutedContext.ActionContext.ActionArguments["_stopwatch_"];

        stopWatch.Stop();

        var scope = actionExecutedContext.ActionContext.Request.GetDependencyScope();
        var commonService = (ICommonService)scope.GetService(typeof(ICommonService));
        commonService.InsertLog(new Model.Common.LogModel
        {
            InsertDate = DateTime.Now.ToString(),
            LogLevel = "API",
            MachineName = "API",
            Message = $"Controller : {controller} - Action : {action} - TotalSeconds : {stopWatch.Elapsed.TotalSeconds}",
            StackTrace = string.Empty
        });
    }
}

Action sample :

    [HttpPost]
    [DurationControlLogger]
    public bool InsertProduct(ProductModel model)
    {
        return _mainService.TracingService.InsertProduct(model);
    }

This action process duration is about 0,03 seconds. On the other hand, wpf api call duration is about 10 seconds. Wpf code blocks are down below:

            var Stopwatch = Stopwatch.StartNew();
            var isSuccess = DataHelper.InsertProduct(Product);
            Stopwatch.Stop();
            if (Stopwatch.Elapsed.TotalSeconds > 2)
                DataHelper.InsertTraceLog($"ProducrtBusiness - InsertProduct TotalSecond : {Stopwatch.Elapsed.TotalSeconds}");

DataHelper.InsertProduct method does basic http post request. Code is here :

public static class HttpClientHelper
{
    public static T Post<T>(object model, string url)
    {
        var resultStatus = false;
        T resultData = default(T);

        using (var client = new HttpClient())
        {

            client.DefaultRequestHeaders.Accept.Clear();
            client.DefaultRequestHeaders.Accept.Add(new MediaTypeWithQualityHeaderValue("application/json"));


            var content = new StringContent(JsonConvert.SerializeObject(model), Encoding.UTF8, "application/json");

            HttpResponseMessage response = client.PostAsync(url, content).Result;

            if (response.IsSuccessStatusCode)
            {
                string data = response.Content.ReadAsStringAsync().Result;
                var result = JsonConvert.DeserializeObject<T>(data);
                resultStatus = response.StatusCode == System.Net.HttpStatusCode.OK;
                resultData = result;
            }
        }
        return resultStatus ? resultData : default(T);
    }
    .....

Does anyone has any idea about that situation?

EDIT

I add one last log code. Here is code: ` var stopwatch = Stopwatch.StartNew();

            HttpResponseMessage response = client.PostAsync(url, content).Result;

            stopwatch.Stop();
            if (stopwatch.Elapsed.TotalSeconds > 2)
            {
                AppendToFile($"{DateTime.Now.ToString()} - {model.ToString()} - {stopwatch.Elapsed.TotalSeconds} - Content: {jsonData}");
            }

`

This log duration still sometimes is 8-10 sec.

Questioner
Aydin Ayaydin
Viewed
81
Dean Chalk 2020-02-01 02:34

Well, it is likely (from what Ive seen) that you are running this code on the main message pump, (UI thread). During this method call you are performing an asynchronous call (PostAsync) and calling the 'Result' - making it run synchronously. However, while your UI thread was waiting, some other messages (UI updates?) where queued on the message pump, and were processed before your call to end the stopwatch (higher DispatcherPriority?) - delaying the timer end. This is pure speculation, but I would recommend that you use some async/await in your asynchronous code, and try and perform these data access tasks on a separate thread