Base solution for your next web application
Open Closed

Token validation very long #10772

User avatar
0
Ricavir created
  • Abp 6.6.2
  • Angular
  • .NET 5

Hi,

As you know from my previous questions, I'm facing many performance issues while adding new users to the app. I'm dealing with multi instance on Azure, Redis cache, Azure SignalR...

The problem here is that some requests are very long to execute. Please look at following example :

As you can see, the request is blocked for 10s on token validation... On the left side of the screenshot you can see thaat the same request can be very fast. I suspect a lock somewhere in the app because all Azure resources are good (CPU, RAM...).

It is very hard to find the root cause from my side.

Can you please provide some help to find a solution ?

Go to accepted answer
23 Answer(s)
  • User Avatar
    0
    Ricavir created

    Here is more information from profiler. ValidateToken method is waiting most of the time from another thread :

  • User Avatar
    0
    Ricavir created

    The problem should came from AsyncHelper.RunSync. All user requests are blocked when applicaation is in waiting state... maybe when updating cache data. I saw on abp source code that some locks and semaphore are being done.

    I should not be the only customer facing that issues I guess.

    We are pushing this issue in our TOP priorities ; I will continue my findings with dump files and provide feedback.

    Your help will be much appreciated

  • User Avatar
    0
    ismcagdas created
    Support Team

    Hi @ricavir

    We tried to reduce usages of AsyncHelper and removed it from many places. However, for security token validation, we are waiting for https://github.com/AzureAD/azure-activedirectory-identitymodel-extensions-for-dotnet/issues/468.

    Could you create an issue on GitHub, we will try to find a different solution to this problem.

  • User Avatar
    0
    Ricavir created

    Hi @ismcagdas,

    Thank you for your suggestion. I will create an issue on Github.

    The problem is happening on a regular basis : many requests are delayed from 10s and more ! When that happens everything seems to be locked. Something else must be wrong in the project. I can't imagine that other abp apps are having the same issue without doing anything.

    We are actively working on this issue and analysing memory dumps right now.

    Don't you have a clue to guide us ? We need to find a workarround in a very short time.

  • User Avatar
    0
    ismcagdas created
    Support Team

    Hi @ricavir

    The problem is ValidateToken is not async in *JwtSecurityTokenHandler. I think using a custom ASP.NET Core middleware instead of this class would be an option. In a middleware, you can totally validate the token asynchronously.

  • User Avatar
    0
    Ricavir created

    Thank you for your feedback @ismcagdas. I saw that you planned to work on it for v11.1, this is great. While waiting, do you have an idea or workarround to improve this ?

    We mitigate this issue and we found some similar issues (request queued) due to azure app service thread pool mechanism. It seems that adding threads to the pool can take 500ms. Thus, some guys are using this code :

    ThreadPool.SetMinThreads(50, 50); // worker and IO threads

    This allows to define a minimum thread count for the instance... this seems to improve a lot performance but we also found a lot of warnings. We are going to test it anyway in our staging slot but we would like to have your advice about it.

  • User Avatar
    0
    Ricavir created

    Finally, we decided to implement ThreadPool.SetMinThreads on staging slot. The first results were very good ! It is now in production and we improved by 2 request performance. It is still under monitoring for the next days.

    Our finding is that a sync method that is in an hot path (like ValidateToken) can turn very bad on azure since the allocation of threads is also taking some time to be done (500ms per allocation). Then, with increasing requests incoming, we had lots of requests queued wainting for available threads.

    This has been misleading us for a while because we were just adding more Azure resources ; but this problem is not depending on the server CPU or RAM, it is depending on thread pool behavior. Therefore, the only workarround is to set a minimum thread count and carefuly tune the value (we started to a value of 100 minimun threads).

    Hope this can help other abp users.

    We are then waiting for an async implementation of JWT token validation by ABP team to avoid definitely these side effects :)

  • User Avatar
    0
    ismcagdas created
    Support Team

    @ricavir thank you for your feedback. We will try to provide a solution with v11.1. I hope Microsoft Team cna provide the async support before we release v11.1 because it would be the best solution :).

  • User Avatar
    0
    Ricavir created

    Hi @ismcagdas, I also hope that Microsoft will fix that quickly but the issue is opened since 2016... I'm not confident for a fix until some months ! We are still getting big waiting times (sometimes more than 20s) because of this. It would be welcome to have a work arround for the next version 11.1 as you plan it on the milestone https://github.com/aspnetzero/aspnet-zero-core/milestone/93

  • User Avatar
    0
    ismcagdas created
    Support Team

    Hi @ricavir

    Thanks, yes, even if Microsoft doesn't provide a fix, we will at least provide a workaround for this.

    1
  • User Avatar
    0
    sedulen created

    It looks like v11.1 was released 7 days ago ! https://docs.aspnetzero.com/en/common/latest/Change-Logs

    • Async JWT validation

    @ricavir - have you tried upgrading or back-porting this change to your application. I'm curious if it's improved things for you

    @ismcagdas - do you see any issues with trying to backport this to ANZ v9.3.1 and .net core 3.1?

    I'm going to get working on a back-port of this feature change today.

    Thank you ANZ for working on this for us! -Brian

  • User Avatar
    0
    sedulen created

    @ricavir & @ismcagdas,

    Hello again. I have back-ported the Async JWT validation to my ANZ v9.3.1 & .net core 3.1 application build, and unfortunately I'm still seeing pretty rough performance.

    I am using Azure's new Load Testing (Preview) feature to run a fairly simple endurance test. I run 40 concurrent users for 5 minutes, looping over Login and then a few of our main Get endpoints. To note, my endurance test does re-authenticate with every loop as the same user, so I don't know if that is a flaw in the endurance test design.

    The Token Authentication endpoint is taking way too long, like 48+ seconds.

    With the Azure Application Insights Profiler enabled, I'm seeing HUGE lag times in "AWAIT_TIME", which as Microsoft documentation states is the thread performing it's execution. And looking at the Azure end-to-end transaction details, I can see 25+ seconds of air gap between SQL statement executions

    SELECT [a].[Id], [a].[ExpireDate], [a].[LoginProvider], [a].[Name], [a].[TenantId], [a].[UserId], [a].[Value] FROM [AbpUserTokens] AS [a] WHERE ((@__ef_filter__p_0 = CAST(1 AS bit)) OR ([a].[TenantId] = @__ef_filter__CurrentTenantId_1)) AND ([a].[UserId] = @__p_0)

    and SET NOCOUNT ON; INSERT INTO [AbpUserTokens] ([ExpireDate], [LoginProvider], [Name], [TenantId], [UserId], [Value]) VALUES (@p0, @p1, @p2, @p3, @p4, @p5); SELECT [Id] FROM [AbpUserTokens] WHERE @@ROWCOUNT = 1 AND [Id] = scope_identity();

    these 2 sql statements themselves are lightning fast, but something is taking ~25+ seconds to execute in here?

    I'm struggling to get any deeper insights into what issue might be. Thanks, -Brian

  • User Avatar
    0
    Ricavir created

    Hi @sedulen

    Yes, I have implemented asynchronous JWT token validation. It is better from my side, the app is faster and I'm not having these AWAIT_TIME anymore.

    You are pointing out AbpUserTokens, try to reduce the refresh token expiration date et check if this table has not too many records, this can affect you performance.

    I also tuned the thread pool count as explained upper on this thread ; this has also improved the app performance.

    I don't have used a loading test tool as you did.... but I should :)

  • User Avatar
    0
    sedulen created

    Thanks @ricavir!

    jMeter is pretty awesome, and has been pretty straight forward to get into. I'd be happy to share a .jmx file that we created to load test the /AbpUserConfiguration/GetAll endpoint.

    The performance of the Token Authentication endpoint is really baffling to me, and it seems to be in this method:

    await _userManager.AddTokenValidityKeyAsync( user, tokenValidityKey, DateTime.UtcNow.Add(expiration.Value) ); which would be where those 2 sql queries are executed. Looking at the ABP v5.14.0 source code for that function, ultimately what is called is Abp.Authorization.Users.AbpUserStore.AddTokenValidityKeyAsync

    which is this: ` public virtual async Task AddTokenValidityKeyAsync([NotNull] TUser user, string tokenValidityKey, DateTime expireDate, CancellationToken cancellationToken = default(CancellationToken)) { cancellationToken.ThrowIfCancellationRequested();

            Check.NotNull(user, nameof(user));

        await UserRepository.EnsureCollectionLoadedAsync(user, u => u.Tokens, cancellationToken);

        user.Tokens.Add(new UserToken(user, TokenValidityKeyProvider, tokenValidityKey, null, expireDate));
    }

    `

    that .EnsureCollectionLoadedAsync method is a custom extension, so I'm wondering if there is a wait happening in there.

    I may pull the latest ABP source code and diff the 2 versions just to see if anything has changed in the latest version. Unfortunately upgrading to the latest version will not be possible.

    -Brian

  • User Avatar
    0
    sedulen created

    @ricavir,

    Per your comments here: https://support.aspnetzero.com/QA/Questions/10772/Token-validation-very-long#answer-0db55823-079f-4cd7-c86a-3a00ff97661b

    I have code in place that lets me tune ThreadPool.SetMinThreads So I'll work with adjusting that tuning next.

    I'm curious in your post where you state: "Our finding is that a sync method that is in an hot path (like ValidateToken) can turn very bad on azure since the allocation of threads is also taking some time to be done (500ms per allocation). Then, with increasing requests incoming, we had lots of requests queued wainting for available threads."

    If you are deploying to Azure, what are you using? Container Instances? Kubernetes? AppServices?

    Also curious what your operating system is, if you are running on Windows or Linux. I am running Linux (3.1-focal - Ubuntu 20.04)

    Looking at Azure ApplicationInsights and Azure AppService Metrics & Logs, I'm not able to see how the ThreadPool is being managed. I thought there were some built-in metrics or performance counters that we could observe. I'm curious what you did to see the ThreadPool behavior

    Thanks again for the assistance! -Brian

  • User Avatar
    0
    Ricavir created

    Hi @sedulen,

    I know this is not an easy task to do... be strong :) From our side, we are running on Azure App Service (Windows). App Insights has been very useful to find our main issues, but be careful with its usage, we found that it "costs" on app performance. We heard that it can consume 20 to 25% of performance down ! When we stoped AppInsights, we noticed a gain of more than 50 ms on request time average. Your AWAIT_TIMEs can be caused by the usage of sync calls instead of async. I know that the lastest ABP releases have fixed a lot of that issues. Try to have a look at it !

    Cheers

  • User Avatar
    0
    sedulen created

    Thanks @ricavir,

    I'm talking with @ismcagdas over here: https://support.aspnetzero.com/QA/Questions/10868/issue-upgrading-from-v691-to-v930#answer-64d56c62-ce2d-3396-2449-3a02915f8646

    So in your production environment, you don't run with Azure ApplicationInsights ? I'm also curious what your logging levels are for your production environment.

    And lastly, have you observed any performance isses around using NewtonSoft.Json for your AppService serialization? Comparing that to the System.Text.Json.

    Thanks again for the help, -Brian

  • User Avatar
    0
    Ricavir created

    Hi @sedulen,

    No, not using Appinsights anymore as the app is running well now. On prod environment, our logging level is set to WARN. I don't have any information to provide about serialization, I'm using default ANZ implementation. Didn't see any issue with it.

    Glad to help if I can :)

    1
  • User Avatar
    0
    sedulen created

    Thanks @ricavir,

    Ironically I'm struggling with disabling the native Microsoft.AspnetCore logging. It seems to disregard any of my log4net.config settings or my appsettings.json "Logging" tag.

    I'm curious if you were to use a load testing tool like Siege (https://github.com/JoeDog/siege) And aimed ~100 concurrent requests at the /AbpUserConfiguration/GetAll method, that the performance would be for you.

    I've reduced jMeter test load down to just 2 API endpoints, 1 ANZ standard and 1 custom, but neither hit the database. Both us InMemory cached data, and both should be lightning fast.

    Under a small load these 2 endpoints are lightning fast. But bumping the load up to 100-250 concurrent requests, performance completely falls apart. Using the dotnet-tools like dotnet-counters, dotnet-trace, and dotnet-dump, I'm seeing heavy thread wait times in ConsoleLogging, which is baffling to me. So I'm currently working to try and shut all logging off for my tests and to see what that produces.

    I realize I'm steering original topic of this thread in a different direction, so I'll probably stop posting here and switch to another thread https://support.aspnetzero.com/QA/Questions/10868/issue-upgrading-from-v691-to-v930

    Thanks again for all the help and support. -Brian

  • User Avatar
    0
    ismcagdas created
    Support Team

    Hi @sedulen

    Did you have a chance to upgradae your ABP NuGet packages to latest version and also use the fix for async token validation ? I tihnk those two items will improve the performance of your app.

  • User Avatar
    0
    sedulen created

    hi @ismcagdas ,

    Unfortunately I can't upgrade to the latest ABP NuGet packages as they depend upon .net 5+

    At the moment i need to stay on .net 3.1

  • User Avatar
    0
    sedulen created

    Hi @ricavir

    For your implementation of: ThreadPool.SetMinThreads

    where do you have this set? Is this in your Startup class? If so, where do you have it, in ConfigureServices or in Configure ?

    Thanks, -Brian

  • User Avatar
    0
    ismcagdas created
    Support Team

    @sedulen Thanks. But, you can at least copy latest changes about async token validation from v11.1 and use it in your project. I think it will not force you to change your .NET version.

Assignee
No one
Labels
Non yet