Open Closed

Slow Dynamic Principal Contributors #9852

User avatar
0
kfrancis@clinicalsupportsystems.com created

Using: Tiered, MVC+SQL/EF with OpenIddict, ABP 9.3.2

I have the following hooked up to try and identify what's causing large and/or frequent delays:

/// <summary>
/// A debug implementation of the AbpClaimsPrincipalFactory that logs the resolution and contribution of claims
/// principal contributors.
/// </summary>
[Dependency(ReplaceServices = true)]
[ExposeServices(typeof(IAbpClaimsPrincipalFactory))]
public class DebugAbpClaimsPrincipalFactory : AbpClaimsPrincipalFactory
{
    private const int SlowThresholdMs = 500; // Log anything slower than 500ms
    private const string SlowMarker = "PERFORMANCE_BOTTLENECK";
    private readonly ILogger<DebugAbpClaimsPrincipalFactory> _logger;

    public DebugAbpClaimsPrincipalFactory(
        IServiceProvider serviceProvider,
        IOptions<AbpClaimsPrincipalFactoryOptions> abpClaimOptions,
        ILogger<DebugAbpClaimsPrincipalFactory> logger)
        : base(serviceProvider, abpClaimOptions)
    {
        _logger = logger;
    }

    /// <summary>
    ///     Creates a ClaimsPrincipal by contributing claims from registered contributors.
    /// </summary>
    /// <param name="options">
    ///     The options that define how claims are contributed to the ClaimsPrincipal.
    /// </param>
    /// <param name="existsClaimsPrincipal">
    ///     An existing ClaimsPrincipal to contribute to, or null to create a new one.
    /// </param>
    /// <param name="isDynamic">
    ///     If true, only dynamic contributors will be processed. If false, all contributors will be processed.
    /// </param>
    /// <returns>
    ///     A Task that represents the asynchronous operation, containing the created ClaimsPrincipal.
    /// </returns>
    public override async Task<ClaimsPrincipal> InternalCreateAsync(
        AbpClaimsPrincipalFactoryOptions options,
        ClaimsPrincipal? existsClaimsPrincipal = null,
        bool isDynamic = false)
    {
        var claimsPrincipal = existsClaimsPrincipal ?? new ClaimsPrincipal(new ClaimsIdentity(
            AuthenticationType,
            AbpClaimTypes.UserName,
            AbpClaimTypes.Role));

        var context = new AbpClaimsPrincipalContributorContext(claimsPrincipal, ServiceProvider);

        if (!isDynamic)
        {
            foreach (var contributorType in options.Contributors)
            {
                var stopwatch = Stopwatch.StartNew();

                var contributor =
                    (IAbpClaimsPrincipalContributor)ServiceProvider.GetRequiredService(contributorType);
                stopwatch.Stop();

                if (stopwatch.ElapsedMilliseconds > SlowThresholdMs)
                {
                    _logger.LogError(
                        "{SlowMarker} SLOW RESOLUTION: {ContributorType} took {ElapsedMs}ms to resolve",
                        SlowMarker, contributorType.Name, stopwatch.ElapsedMilliseconds);
                }

                var contributeStopwatch = Stopwatch.StartNew();
                await contributor.ContributeAsync(context);
                contributeStopwatch.Stop();

                if (contributeStopwatch.ElapsedMilliseconds > SlowThresholdMs)
                {
                    _logger.LogError(
                        "{SlowMarker} SLOW CONTRIBUTION: {ContributorType} took {ElapsedMs}ms to contribute",
                        SlowMarker, contributorType.Name, contributeStopwatch.ElapsedMilliseconds);
                }
            }
        }
        else
        {
            _logger.LogInformation("DYNAMIC_CLAIMS_START: Processing dynamic contributors...");

            foreach (var contributorType in options.DynamicContributors)
            {
                var stopwatch = Stopwatch.StartNew();

                var contributor =
                    (IAbpDynamicClaimsPrincipalContributor)ServiceProvider.GetRequiredService(contributorType);
                stopwatch.Stop();

                if (stopwatch.ElapsedMilliseconds > SlowThresholdMs)
                {
                    _logger.LogError(
                        "{SlowMarker} SLOW DYNAMIC RESOLUTION: {ContributorType} took {ElapsedMs}ms to resolve",
                        SlowMarker, contributorType.Name, stopwatch.ElapsedMilliseconds);
                }
                else
                {
                    _logger.LogInformation(
                        "FAST DYNAMIC RESOLUTION: {ContributorType} took {ElapsedMs}ms to resolve",
                        contributorType.Name, stopwatch.ElapsedMilliseconds);
                }

                var contributeStopwatch = Stopwatch.StartNew();
                await contributor.ContributeAsync(context);
                contributeStopwatch.Stop();

                if (contributeStopwatch.ElapsedMilliseconds > SlowThresholdMs)
                {
                    _logger.LogError(
                        "{SlowMarker} SLOW DYNAMIC CONTRIBUTION: {ContributorType} took {ElapsedMs}ms to contribute",
                        SlowMarker, contributorType.Name, contributeStopwatch.ElapsedMilliseconds);
                }
                else
                {
                    _logger.LogInformation(
                        "FAST DYNAMIC CONTRIBUTION: {ContributorType} took {ElapsedMs}ms to contribute",
                        contributorType.Name, contributeStopwatch.ElapsedMilliseconds);
                }
            }

            _logger.LogInformation("DYNAMIC_CLAIMS_END: Finished processing dynamic contributors");
        }

        return context.ClaimsPrincipal;
    }
}

I will very very often see slow contributions from the following:

  • IdentitySessionDynamicClaimsPrincipalContributor
  • EditionDynamicClaimsPrincipalContributor
[2025-09-03 17:38:17.935] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 793ms to contribute
[2025-09-03 17:38:18.935] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 1783ms to contribute
[2025-09-03 17:39:06.501] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "IdentitySessionDynamicClaimsPrincipalContributor" took 798ms to contribute
[2025-09-03 17:40:23.994] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 1360ms to contribute
[2025-09-03 17:40:24.517] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 1878ms to contribute
[2025-09-03 17:40:41.697] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 585ms to contribute
[2025-09-03 17:40:42.651] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 1538ms to contribute
[2025-09-03 17:40:43.652] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 2537ms to contribute
[2025-09-03 17:40:44.170] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "IdentitySessionDynamicClaimsPrincipalContributor" took 3059ms to contribute
[2025-09-03 17:40:44.171] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "IdentitySessionDynamicClaimsPrincipalContributor" took 3059ms to contribute
[2025-09-03 17:40:45.169] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 998ms to contribute
[2025-09-03 17:43:14.784] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "IdentitySessionDynamicClaimsPrincipalContributor" took 892ms to contribute
[2025-09-03 17:43:14.784] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 883ms to contribute
[2025-09-03 17:43:15.799] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 1897ms to contribute
[2025-09-03 17:43:16.815] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "IdentityDynamicClaimsPrincipalContributor" took 2916ms to contribute
[2025-09-03 17:43:16.821] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "IdentitySessionDynamicClaimsPrincipalContributor" took 2927ms to contribute
[2025-09-03 17:43:16.822] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 2037ms to contribute
[2025-09-03 17:43:17.374] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 552ms to contribute
[2025-09-03 17:43:18.353] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "IdentitySessionDynamicClaimsPrincipalContributor" took 1537ms to contribute
[2025-09-03 17:44:31.660] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 650ms to contribute
[2025-09-03 17:44:31.660] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 651ms to contribute
[2025-09-03 17:44:31.660] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "EditionDynamicClaimsPrincipalContributor" took 651ms to contribute
[2025-09-03 17:44:31.661] [Error]  () <CabMD.Diagnostics.DebugAbpClaimsPrincipalFactory> "PERFORMANCE_BOTTLENECK" SLOW DYNAMIC CONTRIBUTION: "IdentityDynamicClaimsPrincipalContributor" took 642ms to contribute

How can I either speed these up or otherwise resolve?

Editions don't change (or change very, very infrequently), so I imagine there should be caching. For identity session, we're likely still doing things far too often - likely related to the session features.

Go to accepted answer
3 Answer(s)
  • User Avatar
    0
    AI-Bot created
    Support Team ABP Agent

    • The slowness in dynamic claims contributors like EditionDynamicClaimsPrincipalContributor and IdentitySessionDynamicClaimsPrincipalContributor is typically due to expensive operations (such as database queries or remote service calls) being performed on every HTTP request, since dynamic claims are resolved for every request and user.

    • According to ABP documentation, it is strongly recommended to use caching inside your dynamic claims contributors to avoid performance bottlenecks. The ContributeAsync method is called very frequently, so any non-cached logic (such as fetching edition or session data from the database) will cause significant delays.

    • For contributors like EditionDynamicClaimsPrincipalContributor, you should cache the edition information per tenant, as editions rarely change. For session-related contributors, cache the session data per user/session as appropriate.

    Example (pseudo-code for caching inside a contributor):

    public class MyDynamicClaimsContributor : IAbpDynamicClaimsPrincipalContributor
{
    private readonly IDistributedCache<MyEditionInfo> _cache;
    private readonly IEditionRepository _editionRepository;

    public MyDynamicClaimsContributor(IDistributedCache<MyEditionInfo> cache, IEditionRepository editionRepository)
    {
        _cache = cache;
        _editionRepository = editionRepository;
    }

    public async Task ContributeAsync(AbpDynamicClaimsPrincipalContributorContext context)
    {
        var tenantId = context.Principal.FindFirstValue(AbpClaimTypes.TenantId);
        var cacheKey = $"edition-info:{tenantId}";

        var editionInfo = await _cache.GetOrAddAsync(
            cacheKey,
            async () => await _editionRepository.GetEditionInfoAsync(tenantId),
            () => new DistributedCacheEntryOptions { AbsoluteExpirationRelativeToNow = TimeSpan.FromHours(1) }
        );

        // Add claims using editionInfo...
    }
}

    • Review your dynamic claims contributors and ensure all expensive operations are cached. If you are using ABP's built-in contributors, check if you have disabled or misconfigured distributed cache (e.g., Redis) in your environment, as this will force contributors to hit the database every time.

    • For further optimization, profile your contributors to identify any unnecessary or repeated queries, and refactor to minimize work done per request.

    Sources:

    This response was generated by AI. If it didn’t solve your problem, feel free to post a new answer — our support team will jump in to help you soon.

  • User Avatar
    0
    kfrancis@clinicalsupportsystems.com created

    Yes, that's where I'm trying to get to - the problem is that I don't know what these implementations are actually doing, so I can't just go replacing them. I understand they are pro-related, which is why I can't find non-forked examples, but something seems to be unnecessarily delayed in production by that code.

  • User Avatar
    0
    maliming created
    Support Team Fullstack Developer

    hi

    The EditionDynamicClaimsPrincipalContributor and IdentitySessionDynamicClaimsPrincipalContributor use distributed cache internally.

    I guess Redis may be slow.

    I can share these DynamicClaimsPrincipalContributors source code. Then you can add a stopwatch to check the cache performance.

    Please send mail to liming.ma@volosoft.com

    Thanks.

Assignee
User avatar maliming
Question details
Labels
None yet
Boost Your Development
ABP Live Training
Packages
See Trainings
Mastering ABP Framework Book
The Official Guide
Mastering
ABP Framework
Learn More
Mastering ABP Framework Book
Made with ❤️ on ABP v10.0.0-preview. Updated on September 04, 2025, 16:11