ASP.NET HTTP Response Time takes +30 seconds if lock is used

[okarpov]

Hello,

I have two ASP.NET Kestrel applications on Ubuntu 22.04.3 LTS dedicated server with two networks and two public IPs.
One ASP.NET application serves all request fine and whout any HTTP Response delays mostly.

For some reason the second ASP.NET application serves all HTTP requests with +30 seconds delay for no any observable reason.

Could you, please, help me to identify the issue if possible and in case this is really ASP.NET issue then it will help to improve ASP.NET itself.

Thank you for any ideas and assistance.

One of such HTTP method is:

        app.MapGet("/getpendingaction", handler: getpendingaction);

        public static async Task<IResult> getpendingaction(HttpContext context)
        {
            try
            {
                if (context.Request.Query.ContainsKey("ip") && allowedIPs.Contains(context.Request.Query["ip"] + ",", StringComparison.Ordinal))
                {
                    Stopwatch m_sw = Stopwatch.StartNew();

                    string vip = context.Request.Query["ip"];
                    string retres = string.Empty;

                    VPS vps = null;
                    if (!vpsData.TryGetValue(vip, out vps))
                    {
                        vps = new VPS();
                        vps.IP = vip;
                        if (!vpsData.TryAdd(vps.IP, vps))
                        {
                            vpsData.TryGetValue(vip, out vps);
                        }
                    }
                    if (vps != null)
                    {
                        vps.NotResponding = false;
                        vps.LastUpdate = DateTime.UtcNow;

                        if (blkftp != null)
                        {
                            Stopwatch m_2sw = Stopwatch.StartNew();
                            try
                            {
                                retres = await logic?.GetPendingAction((string)context.Request.Query["ip"]);
                            }
                            catch (Exception ex)
                            {
                                Console.WriteLine("logic: " + ex);
                            }
                            m_2sw.Stop();
                            m_sw.Stop();
                            if (string.IsNullOrEmpty(retres))
                            {
                                retres = $"-1:-1:::::logic time {m_2sw.Elapsed.TotalMilliseconds} ms:webmethod time: {m_sw.Elapsed.TotalMilliseconds} ms";
                            }
                            else
                            {
                                retres += $"::logic time {m_2sw.Elapsed.TotalMilliseconds} ms:webmethod time: {m_sw.Elapsed.TotalMilliseconds} ms";
                            }
                            Interlocked.Exchange(ref avg_getpendingaction, (m_sw.Elapsed.TotalSeconds + avg_getpendingaction) / 2.0);
                            Interlocked.Exchange(ref max_getpendingaction, Math.Max(m_sw.Elapsed.TotalSeconds, max_getpendingaction));
                        }
                        context.Response.Headers.CacheControl = "no-cache, no-store, must-revalidate, max-age=0";
                        context.Response.Headers.Pragma = "no-cache";
                        context.Response.Headers.Expires = "0";

                        return Results.Content(retres);
                    }
                }
                else
                {
                    if (context.Request.Query.ContainsKey("ip"))
                    {
                        unknownIPs.TryAdd(context.Request.Query["ip"], null);
                    }
                    return Results.Content("ok :)");
                }
            }
            catch (Exception ex)
            {
                Console.WriteLine(ex);
            }

            return Results.Content("ok :)");
        }

so for this method we have the following times:

logic time 2092.7627 ms
webmethod time: 2092.7643 ms

but HTTP Response time +30 seconds which is measuerd with Development Tool in Google Chrome

Where should i start looking into? What to measure more? Any tools or suggestions?

[martincostello]

You could try turning the logging level up to Trace and observing where things are taking the most time as basic way of finding the slowest part.

You could also do that by using the Visual Studio Profiler while debugging - Measure app performance in Visual Studio.

[okarpov]

what do you mean by "logging level up to Trace" - could you please point me out.

unfortunately i can not use Visual Studio on Linux server

[martincostello]

Logging in .NET Core and ASP.NET Core: Configure logging

[okarpov]

am I right that the Kestrel Connection consums 98% of time for some reason?

[martincostello]

That's the inclusive time, so includes everything in the HTTP pipeline.

You want to look at what's using the most exclusive time, which looks to be your GetPendingAction method.

[okarpov]

this guy talks about inclusion, hard to figure out anything ))

https://michaelscodingspot.com/dotnet-trace/

[okarpov]

That's the inclusive time, so includes everything in the HTTP pipeline.

You want to look at what's using the most exclusive time, which looks to be your GetPendingAction method.

but as you can see in my code snippet it has Stopwatches which measure everything inside the method up to 2.09 seconds
and returns the measures in every HTTP response.

also, when there are not a lot of incoming requests to this web app everything works as expected and this web requests take around 0.1-3 seconds in total.

[okarpov]

interesting, may lock produces such strange behaviour if there are a lot of HTTP requests and it is inside of an asyn method like this:

static object lock_object= new object();

public async Task<string> GetPendingAction()
{
    lock(lock_object)
    {
        ...
        SQLite reading logic
        ...
    }
    ...
}

[martincostello]

It depends on the scope of the lock compared to the lifetime of the object using it and how that feeds into the HTTP request pipeline. It's not possible to tell you definitively without more code.

If lock_object is shared across all HTTP requests, then yes it will block all but one thread being able to do anything while that thread has possession of it.

You can find the documentation for lock here: The lock statement - ensure exclusive access to a shared resource

[okarpov]

after removing the lock (which was static object shared between all HTTP requests) everything started working as expected without any unintended delays (and it definitely does not relate to being second web app).

however it is strange and unclear anyway why such lock caused such a huge delay per HTTP request when the logic inside the lock was a matter of 10-100 milliseconds or even less.

and unfortunately i can not reproduce it locally (on windows) so may be it somehow relates to Linux ?

[okarpov]

seems i was able to reproduce it locally.
preparing sources and description and then will submit.

[okarpov]

here are the source files and steps to run and reproduce it.

• single web async method with 10ms LOCK increases response time by ~ x80.
• multiple web async methods with 10ms LOCKs sharing the same LOCK object increase response time by ~ x239.

for me personaly it is not clear and not obvious why 10 ms LOCK increases response time so hard and may be someone may explain it and it will be useful for understanding for other devs as well.

and it has nothing to do with multiple asp.net web applications.

steps to reproduce:

1. build both projects in the solution
2. run web .exe under terminal/console
3. run the console .exe under terminal/console
4. see results

TestWebLock.zip