abp icon indicating copy to clipboard operation
abp copied to clipboard

Performance issue: PermissionAppService.GetAsync spends most time in server-side localization (8–10s → 220ms when disabled)

Open imanov2013 opened this issue 3 months ago • 3 comments

Repository / Area: https://github.com/abpframework/abp — Permission Management (Volo.Abp.PermissionManagement), localization (Volo.Abp.Localization), Angular UI (@abp/permission-management)


Summary

On our integration environment, the API:

GET /api/permission-management/permissions?providerName=R&providerKey=admin

took ~8–10 seconds with the native ABP implementation. After instrumenting the code (no behavior changes, just timers), we found the bottleneck is server-side localization of groups and permissions via:

DisplayName?.Localize(StringLocalizerFactory)

When we disable server-side localization (leave DisplayName = null and rely on the already-present displayNameResource + displayNameKey for the client), the same call drops to ~220 ms.

This suggests the per-item localization loop is doing repeated resource lookups and allocations that do not benefit from caching when there are 400+ permission names.

We propose ABP either caches these lookups within the request (or globally per culture), or exposes an official toggle to skip server-side localization and encourage client-side localization (which the ABP UI already supports).


Environment

  • ABP version: TODO (e.g., 8.x.x)
  • .NET: TODO (e.g., .NET 8)
  • DB: SQL Server (audit logs used for timings)
  • Frontend: Angular template (@abp/permission-management)
  • Deployment: Integration (INT) behind APIM/Ingress (but delays confirmed server-side via Server-Timing headers)

Note: the delay is inside the AppService — not network. Server-Timing shows the method’s internal breakdown.


Scale of data

  • Groups: ~22
  • Permissions: ~419 names (flattened)
  • DB calls: 16 (native behavior: per group)
  • Providers: providerName=R, providerKey=admin

What we changed (for diagnostics only)

We kept the native logic but added timers and extra audit fields. We also added a toggle to disable server-side localization to confirm the hypothesis.

ExtraProperties we record on the audit action/log

Key Meaning
Perms.TraceId Per-call trace id
Perms.Groups Number of groups returned
Perms.Names Number of flattened permission names queried
Perms.DefsMs Time to fetch definition groups
Perms.StateMs Time in ISimpleStateCheckerManager.IsEnabledAsync loop
Perms.DbMs Time in IPermissionManager.GetAsync(names, providerName, providerKey)
Perms.DbCalls Number of DB calls (groups)
Perms.TopDb Top 3 groups by DB time
Perms.LocMs Cumulative time in server‑side localization for groups & permissions
Perms.DtoMs Time to assemble DTOs (copy/add)
Perms.AllocBytes Allocated bytes during the method (where available)

Option (toggle)

// appsettings.json
{
  "PermissionDiagnostics": {
    "EnableServerTimingHeaders": true,
    "GroupWarnDbMs": 300,
    "GroupWarnStateMs": 150,
    "LocalizeServerSide": true  // set to false to disable server-side localization
  }
}

When LocalizeServerSide=false, we keep DisplayNameKey and DisplayNameResource so the UI can localize. ABP Angular UI already reads those.


Measured results (real requests)

Slow (server-side localization ON)

TotalMs ≈ 8887 ms
DefsMs = 4 ms
StateMs = 34 ms
DbMs = 171 ms (16 calls; ~8–12 ms each)
LocMs = 8580 ms    <-- bottleneck
DtoMs = 1 ms
Names = 419, Groups = 22
AllocBytes ≈ 50,174,320 B (~47.8 MB)
Server-Timing: defs;dur=4,state;dur=34,db;dur=171,tot;dur=8887
TraceId: 87c6b7252225495abe8149a4a649b592
TopDb: FileManagement:db=23ms,n=8|RMPDashboard:db=19ms,n=273|SettingManagement:db=16ms,n=1

Example ExtraProperties JSON for the slow call:

{
  "Perms.TraceId":"87c6b7252225495abe8149a4a649b592",
  "Perms.Groups":22,
  "Perms.DefsMs":4,
  "Perms.StateMs":31,
  "Perms.DbMs":131,
  "Perms.DbCalls":16,
  "Perms.Names":419,
  "Perms.TopDb":"FileManagement:db=18ms,n=8|RMPDashboard:db=15ms,n=273|SettingManagement:db=14ms,n=1",
  "Perms.LocMs":8580,
  "Perms.DtoMs":1,
  "Perms.AllocBytes":50174320
}

We also have a second slow sample:

TotalMs ≈ 9549 ms, DbMs ≈ 149 ms, LocMs high
TraceId: c1fe8f47c60f4eea92f18d6a18d0b5c6

Fast (server-side localization OFF — client localizes)

TotalMs ≈ 220 ms
DefsMs = 2 ms
StateMs = 35 ms
DbMs = 118 ms (16 calls)
LocMs = 0 ms
DtoMs = 0–1 ms
Names = 419, Groups = 22
AllocBytes ≈ 3,619,968 B (~3.46 MB)
Server-Timing: defs;dur=2,state;dur=35,db;dur=118,tot;dur=220
TraceId: 084ab2821fa74467987d18bf5fe2b99e
TopDb: FileManagement:db=19ms,n=8|RMPDashboard:db=12ms,n=273|LanguageManagement:db=11ms,n=4

Repro steps

  1. Prepare a solution with ~20‑25 permission groups and ~400–500 permissions total (typical enterprise setup with multiple modules).
  2. Use the native PermissionAppService.GetAsync logic (no filtering). The only change we made for diagnostics is adding timers and audit extra properties — the selection/DB logic is identical.
  3. Call:
    GET /api/permission-management/permissions?providerName=R&providerKey=admin
    
  4. Observe total time and internal breakdown via Server-Timing and/or audit (sample SQL below).
  5. Toggle LocalizeServerSide=false and repeat to confirm the shift.

Why we believe it’s localization

  • DB time is consistently ≤ 150–170 ms for 16 calls (1 per group).
  • StateMs is ≤ 45 ms.
  • With the native method, LocMs plainly accounts for ~8.5 seconds.
  • Disabling Localize(...) moves TotalMs to ~220 ms — the remainder lines up with DB and state checks.

This points to repeated per-item resource lookups and/or lack of a cache for LocalizableString.Localize(...) in this path.


Proposed fixes / enhancements

We’d be happy with any of the following (in order of impact):

  1. In-request caching: cache LocalizableString.Localize(factory) results for {resourceName, key, culture} during the call (simple Dictionary), so each permission/group key is resolved once.
  2. Global per-culture cache (e.g., IMemoryCache) with invalidation on culture switch / resource changes.
  3. Official toggle to skip server-side localization (mirror what we did), relying on displayNameResource + displayNameKey. The Angular UI already supports this.
  4. Localize groups only server-side (small N), and leave permissions (large N) for the client.
  5. Batch localization (if feasible) instead of N * Localize(...) calls.

Any of the above should cut LocMs to near zero under load.


Workaround we use (no package changes)

We keep LocalizeServerSide=false and add a tiny Angular HttpInterceptor that targets only the permissions endpoint and fills displayName on the fly from {displayNameResource, displayNameKey} using ABP’s LocalizationService. This keeps node_modules intact and keeps UI behavior the same.

Pseudocode

if (req.url.includes('/api/permission-management/permissions')) {
  const body = res.body;
  for (const g of body.groups) {
    g.displayName ||= loc.instant({ key: g.displayNameKey, sourceName: g.displayNameResource });
    for (const p of g.permissions) {
      p.displayName ||= loc.instant({ key: p.displayNameKey, sourceName: p.displayNameResource });
    }
  }
}

SQL we used to extract the timings from ABP audit

This query prefers AbpAuditLogActions.ExtraProperties (where we write Perms.*) and falls back to AbpAuditLogs.ExtraProperties. It also computes daily p95 to give context:

DECLARE @SinceDays int = 14;
DECLARE @Top       int = 200;

WITH base AS (
  SELECT
    al.Id,
    al.ExecutionTime,
    al.ExecutionDuration AS TotalMs,
    al.TenantId,
    al.UserId,
    al.UserName,
    al.ClientIpAddress,
    al.HttpMethod,
    al.Url,
    ala.ServiceName,
    ala.MethodName,
    ala.Parameters,
    CAST(al.ExecutionTime AT TIME ZONE 'UTC' AS date) AS DayUtc,
    COALESCE(ala.ExtraProperties, al.ExtraProperties) AS EP
  FROM dbo.AbpAuditLogs al
  JOIN dbo.AbpAuditLogActions ala ON ala.AuditLogId = al.Id
  WHERE ala.ServiceName = 'MyFleetManager.Permissions.LoggedPermissionAppService'
    AND ala.MethodName IN ('GetAsync','UpdateAsync')
    AND al.ExecutionTime >= DATEADD(DAY, -@SinceDays, SYSUTCDATETIME())
),
picked AS (
  SELECT TOP (100000)
    b.*, 
    CASE WHEN JSON_VALUE(b.EP, '$."Perms.TraceId"') IS NOT NULL THEN 1 ELSE 0 END AS HasPerms
  FROM base b
),
best AS (
  SELECT *
  FROM (
    SELECT p.*,
           ROW_NUMBER() OVER (
             PARTITION BY p.Id, p.MethodName
             ORDER BY p.HasPerms DESC, p.ExecutionTime DESC
           ) AS rn
    FROM picked p
  ) s
  WHERE s.rn = 1
),
calls AS (
  SELECT
    b.*,
    j.PermsTraceId,
    j.GroupsCount,
    j.DefsMs,
    j.StateMs,
    j.DbMs,
    j.DbCalls,
    j.NamesCount,
    j.TopDbRaw,
    j.LocMs,
    j.DtoMs,
    j.AllocBytes
  FROM best b
  OUTER APPLY OPENJSON(b.EP)
    WITH (
      [PermsTraceId] nvarchar(100) '$."Perms.TraceId"',
      [GroupsCount]  int           '$."Perms.Groups"',
      [DefsMs]       int           '$."Perms.DefsMs"',
      [StateMs]      int           '$."Perms.StateMs"',
      [DbMs]         int           '$."Perms.DbMs"',
      [DbCalls]      int           '$."Perms.DbCalls"',
      [NamesCount]   int           '$."Perms.Names"',
      [TopDbRaw]     nvarchar(max) '$."Perms.TopDb"',
      [LocMs]        int           '$."Perms.LocMs"',
      [DtoMs]        int           '$."Perms.DtoMs"',
      [AllocBytes]   bigint        '$."Perms.AllocBytes"'
    ) AS j
),
with_p95 AS (
  SELECT
    c.*,
    PERCENTILE_CONT(0.95) WITHIN GROUP (ORDER BY c.TotalMs) OVER (PARTITION BY c.DayUtc) AS P95TotalMs_Day,
    PERCENTILE_CONT(0.95) WITHIN GROUP (ORDER BY c.DbMs)   OVER (PARTITION BY c.DayUtc) AS P95DbMs_Day,
    PERCENTILE_CONT(0.95) WITHIN GROUP (ORDER BY c.StateMs)OVER (PARTITION BY c.DayUtc) AS P95StateMs_Day
  FROM calls c
)
SELECT TOP (@Top)
  wp.ExecutionTime,
  wp.MethodName,
  wp.TotalMs,
  wp.DefsMs,
  wp.StateMs,
  wp.DbMs,
  wp.DbCalls,
  wp.GroupsCount,
  wp.NamesCount,
  wp.LocMs,
  wp.DtoMs,
  wp.AllocBytes,
  wp.PermsTraceId,
  wp.TopDbRaw,
  wp.P95TotalMs_Day,
  wp.P95DbMs_Day,
  wp.P95StateMs_Day,
  wp.UserName,
  wp.ClientIpAddress,
  wp.HttpMethod,
  wp.Url,
  wp.TenantId,
  wp.UserId
FROM with_p95 wp
ORDER BY wp.ExecutionTime DESC;

Request to ABP team

  • Confirm whether server-side localization for ~400–500 permission entries is expected to add seconds of CPU time.
  • Consider one or more of:
    • in-request caching for Localize(...) results,
    • an official toggle to skip server-side localization (use key+resource),
    • localize only group titles server-side,
    • or any other optimization that avoids per-item localization for the full tree.

We’re happy to provide a minimal repro or PR if helpful. Thanks for your time! 🙏


Contact / Trace IDs (samples)

  • Slow: 87c6b7252225495abe8149a4a649b592
  • Slow: c1fe8f47c60f4eea92f18d6a18d0b5c6
  • Fast: 084ab2821fa74467987d18bf5fe2b99e

imanov2013 avatar Oct 09 '25 06:10 imanov2013

hi @imanov2013

Prepare a solution with ~20‑25 permission groups and ~400–500 permissions total (typical enterprise setup with multiple modules).

I will check the PermissionAppService, Can you share your test project?

Thanks.

maliming avatar Oct 09 '25 06:10 maliming

Hi @maliming,

I’ve included the entire LoggedPermissionAppService used in our tests. Our integration environment uses ABP 8.3.3.0 on .NET 8 with a single shared SQL Server database for multiple teams (ABP supports single‑DB multi‑tenancy). We have ~22 permission groups and ~419 permissions.

When PermissionDiagnosticsOptions.LocalizeServerSide is true (the default), loading the permissions UI takes 8–10 seconds. Simply switching it to false reduces the page load to ~220 ms. This suggests the slowdown is tied to the volume of localization lookups. We suspect that the huge number of localization keys (one per permission/group) exacerbates the problem, since ABP’s localization mechanism performs a lookup per key.

Below is the full code we’re using to measure each stage. It logs timing for policy checks, group retrieval, state filtering, database calls and server‑side localization. The “CreatePermissionGroupDto” and “CreatePermissionGrantInfoDto” methods call .Localize() only when LocalizeServerSide is true:

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Authorization;
using Microsoft.AspNetCore.Http;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Options;
using Volo.Abp;
using Volo.Abp.Application.Services;
using Volo.Abp.Auditing;
using Volo.Abp.Authorization.Permissions;
using Volo.Abp.DependencyInjection;
using Volo.Abp.Localization;
using Volo.Abp.MultiTenancy;
using Volo.Abp.PermissionManagement;
using Volo.Abp.SimpleStateChecking;

namespace MyFleetManager.Permissions;

public sealed class PermissionDiagnosticsOptions
{
    public bool EnableServerTimingHeaders { get; set; } = true;
    public int GroupWarnDbMs { get; set; } = 300;
    public int GroupWarnStateMs { get; set; } = 150;

    /// <summary>
    /// When true (default), keep server-side localization (native behaviour).
    /// Set to false to measure the impact of server-side localization.
    /// </summary>
    public bool LocalizeServerSide { get; set; } = true;
}

[Authorize]
[Audited]
[Dependency(ReplaceServices = true)]
[ExposeServices(typeof(IPermissionAppService))]
public sealed class LoggedPermissionAppService : ApplicationService, IPermissionAppService
{
    private readonly PermissionManagementOptions _options;
    private readonly IPermissionManager _permissionManager;
    private readonly IPermissionDefinitionManager _definitionManager;
    private readonly ISimpleStateCheckerManager<PermissionDefinition> _stateChecker;
    private readonly IHttpContextAccessor _http;
    private readonly IAuditingManager _auditing;
    private readonly ILogger<LoggedPermissionAppService> _logger;
    private readonly PermissionDiagnosticsOptions _diag;

    public LoggedPermissionAppService(
        IPermissionManager permissionManager,
        IPermissionDefinitionManager permissionDefinitionManager,
        IOptions<PermissionManagementOptions> options,
        ISimpleStateCheckerManager<PermissionDefinition> simpleStateCheckerManager,
        IHttpContextAccessor http,
        IAuditingManager auditing,
        IOptions<PermissionDiagnosticsOptions> diagOptions,
        ILogger<LoggedPermissionAppService> logger)
    {
        _permissionManager = permissionManager;
        _definitionManager = permissionDefinitionManager;
        _options = options.Value;
        _stateChecker = simpleStateCheckerManager;
        _http = http;
        _auditing = auditing;
        _logger = logger;
        _diag = diagOptions?.Value ?? new PermissionDiagnosticsOptions();
    }

    public async Task<GetPermissionListResultDto> GetAsync(string providerName, string providerKey)
    {
        var traceId = Guid.NewGuid().ToString("N");
        var swTotal = Stopwatch.StartNew();

        // Policy check
        await CheckProviderPolicy(providerName);

        // Fetch groups
        var swDefs = Stopwatch.StartNew();
        var groups = await _definitionManager.GetGroupsAsync();
        swDefs.Stop();

        var result = new GetPermissionListResultDto
        {
            EntityDisplayName = providerKey,
            Groups = new List<PermissionGroupDto>()
        };

        var side = CurrentTenant.GetMultiTenancySide();

        long msState = 0, msDb = 0, msLoc = 0, msDto = 0;
        int dbCalls = 0, namesTotal = 0;

        // Measure allocations for GC pressure
        long allocBefore = 0, allocAfter = 0, allocDelta = 0;
        try { allocBefore = GC.GetAllocatedBytesForCurrentThread(); } catch { }

        var groupDiag = new List<(string Group, int Candidates, int Needed, long StateMs, int Names, long DbMs)>();

        foreach (var group in groups)
        {
            // Create group DTO (optional localization)
            var swLocGroup = Stopwatch.StartNew();
            var groupDto = CreatePermissionGroupDto(group);
            swLocGroup.Stop();
            msLoc += swLocGroup.ElapsedMilliseconds;

            // Candidate permissions
            var permissions = group.GetPermissionsWithChildren()
                .Where(x => x.IsEnabled)
                .Where(x => !x.Providers.Any() || x.Providers.Contains(providerName))
                .Where(x => x.MultiTenancySide.HasFlag(side));

            var needed = new List<PermissionDefinition>();
            var neededNames = new HashSet<string>(StringComparer.Ordinal);
            int candidateCount = 0;

            var swState = Stopwatch.StartNew();
            foreach (var p in permissions)
            {
                candidateCount++;
                if (p.Parent != null && !neededNames.Contains(p.Parent.Name))
                    continue;

                if (await _stateChecker.IsEnabledAsync(p))
                {
                    needed.Add(p);
                    neededNames.Add(p.Name);
                }
            }
            swState.Stop();
            msState += swState.ElapsedMilliseconds;

            if (needed.Count == 0)
            {
                groupDiag.Add((group.Name, candidateCount, 0, swState.ElapsedMilliseconds, 0, 0));
                continue;
            }

            // Permission DTOs (optional localization)
            var swLocPerms = Stopwatch.StartNew();
            var grantInfoDtos = needed.Select(CreatePermissionGrantInfoDto).ToList();
            swLocPerms.Stop();
            msLoc += swLocPerms.ElapsedMilliseconds;

            var names = needed.Select(x => x.Name).ToArray();
            namesTotal += names.Length;

            // DB access
            var swDb = Stopwatch.StartNew();
            var multipleGrantInfo = await _permissionManager.GetAsync(names, providerName, providerKey);
            swDb.Stop();

            msDb += swDb.ElapsedMilliseconds;
            dbCalls++;

            // Assemble DTOs
            var swDto = Stopwatch.StartNew();
            foreach (var grantInfo in multipleGrantInfo.Result)
            {
                var dto = grantInfoDtos.First(x => x.Name == grantInfo.Name);
                dto.IsGranted = grantInfo.IsGranted;
                foreach (var provider in grantInfo.Providers)
                {
                    dto.GrantedProviders.Add(new ProviderInfoDto
                    {
                        ProviderName = provider.Name,
                        ProviderKey = provider.Key
                    });
                }
                groupDto.Permissions.Add(dto);
            }
            if (groupDto.Permissions.Count > 0)
                result.Groups.Add(groupDto);
            swDto.Stop();
            msDto += swDto.ElapsedMilliseconds;

            groupDiag.Add((group.Name, candidateCount, needed.Count, swState.ElapsedMilliseconds, names.Length, swDb.ElapsedMilliseconds));

            if (swDb.ElapsedMilliseconds > _diag.GroupWarnDbMs || swState.ElapsedMilliseconds > _diag.GroupWarnStateMs)
            {
                _logger.LogWarning(
                    "Perms.Get trace={Trace} {Prov}/{Key} GROUP={Group} candidates={Cand} needed={Need} state={State}ms db={Db}ms names={Names}",
                    traceId, providerName, providerKey,
                    group.Name, candidateCount, needed.Count, swState.ElapsedMilliseconds, swDb.ElapsedMilliseconds, names.Length);
            }
        }

        swTotal.Stop();
        try { allocAfter = GC.GetAllocatedBytesForCurrentThread(); allocDelta = allocAfter - allocBefore; } catch { }

        _logger.LogInformation(
            "Perms.Get trace={Trace} {Prov}/{Key} groups={Groups} defs={Defs}ms state={State}ms db={Db}ms calls={Calls} names={Names} loc={Loc}ms dto={Dto}ms alloc={Alloc}B total={Total}ms",
            traceId, providerName, providerKey, groups.Count,
            swDefs.ElapsedMilliseconds, msState, msDb, dbCalls, namesTotal, msLoc, msDto, allocDelta, swTotal.ElapsedMilliseconds);

        // Audit and response headers (omitted for brevity)

        return result;
    }

    public async Task UpdateAsync(string providerName, string providerKey, UpdatePermissionsDto input)
    {
        var traceId = Guid.NewGuid().ToString("N");
        var sw = Stopwatch.StartNew();

        await CheckProviderPolicy(providerName);

        int count = 0;
        foreach (var p in input.Permissions)
        {
            await _permissionManager.SetAsync(p.Name, providerName, providerKey, p.IsGranted);
            count++;
        }

        sw.Stop();
        _logger.LogInformation("Perms.Update trace={Trace} {Prov}/{Key} count={Count} ms={Ms}",
            traceId, providerName, providerKey, count, sw.ElapsedMilliseconds);

        // Add server‑timing headers if enabled
    }

    // ===== Helper methods =====

    private async Task CheckProviderPolicy(string providerName)
    {
        var policyName = _options.ProviderPolicies.GetOrDefault(providerName);
        if (policyName.IsNullOrEmpty())
            throw new AbpException($"No policy defined to get/set permissions for the provider '{providerName}'.");
        await AuthorizationService.CheckAsync(policyName);
    }

    private PermissionGrantInfoDto CreatePermissionGrantInfoDto(PermissionDefinition p)
    {
        string? display = null;
        if (_diag.LocalizeServerSide)
            display = p.DisplayName?.Localize(StringLocalizerFactory);

        return new PermissionGrantInfoDto
        {
            Name = p.Name,
            DisplayName = display,
            ParentName = p.Parent?.Name,
            AllowedProviders = p.Providers,
            GrantedProviders = new List<ProviderInfoDto>()
        };
    }

    private PermissionGroupDto CreatePermissionGroupDto(PermissionGroupDefinition g)
    {
        var loc = g.DisplayName as LocalizableString;

        string? display = null;
        if (_diag.LocalizeServerSide)
            display = g.DisplayName?.Localize(StringLocalizerFactory);

        return new PermissionGroupDto
        {
            Name = g.Name,
            DisplayName = display,
            DisplayNameKey = loc?.Name,
            DisplayNameResource = (loc?.ResourceType != null)
                ? LocalizationResourceNameAttribute.GetName(loc.ResourceType)
                : null,
            Permissions = new List<PermissionGrantInfoDto>()
        };
    }
}

We’d appreciate any guidance on mitigating the impact of localization in large permission sets. Could the large number of localization keys be causing the slowdown? Any best practices to cache or avoid repeated lookups would be helpful.


imanov2013 avatar Oct 09 '25 07:10 imanov2013

Could you share a test project to reproduce the Performance issue?

Thanks.

maliming avatar Oct 09 '25 07:10 maliming