Skip to content

Performance regression - /admin/realms/{realm}/users 5-6x worse reponse time and throughtput after 26.3.0 #48480

Description

@zaenk

Warning

edit: The original benchmark run did not take the keycloak version - benchmark tool compatibility into account and runs on versions before 26.3 were silently failing creating the users, effectively running on an empty realm.

For the corrected measurements see #48480 (comment)

Before reporting an issue

  • I have read and understood the above terms for submitting issues, and I understand that my issue may be closed without action if I do not follow them.

Area

admin/api

Describe the bug

Context

After upgrading from 25.0.4 to 26.5.5 the admin api users endpoint reponse time on cold cache went from few seconds to 2+ mins with low number of users (1-2k)

Endpoint and params /admin/realms/{realm}/users?briefRepresentation=false&first=0&max=-1&q=

The setup uses fgap v1, 20+ custom user attributes, brute force detection with permanent lockout.

To identify the issue without the effects of that specific realm setup, I've ran the official benchmarks on the base keycloak images without any customisations.

Benchmarks

  • run the tests for the latest few minor versions
list of versions
  • 24.0.5
  • 25.0.6
  • 26.0.8
  • 26.1.5
  • 26.2.5
  • 26.3.5
  • 26.4.7
  • 26.5.7
  • 26.6.1
test run command
  java -Xmx1G \
    -Drealm-name=test-realm \
    -Dclient-secret=gatling-secret \
    -Dusers-per-realm=1000 \
    -Duser-page-size=1000 \
    -Duser-number-of-pages=1 \
    -Dusers-per-sec=10 \
    -Dmeasurement=30 \
    -cp "$FAT_JAR" \
    io.gatling.app.Gatling \
    -s "keycloak.scenario.admin.UserCrawl" 
  • run on local machine with a simple docker compose setup, no obsevability
docker compose
volumes:
  postgres_data:
    driver: local

services:
  postgres:
    image: postgres:16
    container_name: keycloak-postgres
    volumes:
      - postgres_data:/var/lib/postgresql/data
    environment:
      POSTGRES_DB: keycloak
      POSTGRES_USER: keycloak
      POSTGRES_PASSWORD: password
    ports:
      - "5432:5432"

  keycloak:
    image: ${KC_IMAGE:-quay.io/keycloak/keycloak:26.5.7}
    container_name: keycloak
    cpus: ${KC_CPUS:-4.0}
    command:
      - start-dev
    volumes:
      - ./providers:/opt/keycloak/providers:z
    environment:
      KC_DB_URL: jdbc:postgresql://postgres:5432/keycloak
      KC_DB_USERNAME: keycloak
      KC_DB_PASSWORD: password
      KC_DB: postgres
      KC_HOSTNAME: localhost
      KEYCLOAK_ADMIN: admin
      KEYCLOAK_ADMIN_PASSWORD: admin
    ports:
      - "8080:8080"
    depends_on:
      - postgres
    healthcheck:
      test: ["CMD-SHELL", "curl -sf http://localhost:8080/health/ready || exit 1"]
      interval: 5s
      timeout: 5s
      retries: 30
  • cleared the database after each version (docker compose down -v --remove-orphans)

Initial results

Warning

edit: The measurements for versions before 26.3 are not correct, see #48480 (comment)

Version 26.3.5 shows a 3-4x performance degradation

csv data

⚠️ edit: data points pre 26.3 are wrong due to an error in the benchmarking setup

kc_version,cpus,cache,requests,ok,ko,mean_ms,p50_ms,p75_ms,p95_ms,p99_ms,max_ms,req_per_sec,sla_pass
24.0.5,1,cold,8372,8372,0,3,3,3,5,28,58,279.07,true
24.0.5,1,warm,10506,10506,0,2,2,3,4,7,47,338.9,true
24.0.5,2,cold,7326,7326,0,3,3,4,6,8,56,236.32,true
24.0.5,2,warm,8746,8746,0,3,3,3,5,8,46,282.13,true
24.0.5,4,cold,7522,7522,0,3,3,4,6,8,37,242.65,true
24.0.5,4,warm,9398,9398,0,3,3,3,4,7,26,303.16,true
25.0.6,1,cold,6280,6280,0,4,3,4,7,28,54,202.58,true
25.0.6,1,warm,9234,9234,0,3,3,3,4,9,45,307.8,true
25.0.6,2,cold,9776,9776,0,3,3,3,5,6,31,325.87,true
25.0.6,2,warm,13190,13190,0,2,2,3,3,5,28,439.67,true
25.0.6,4,cold,9718,9718,0,3,3,3,5,6,50,323.93,true
25.0.6,4,warm,13462,13462,0,2,2,3,3,4,22,448.73,true
26.0.8,1,cold,7720,7720,0,3,3,4,5,29,68,257.33,true
26.0.8,1,warm,11932,11932,0,2,2,3,3,5,49,397.73,true
26.0.8,2,cold,9232,9232,0,3,3,3,5,7,36,297.81,true
26.0.8,2,warm,12764,12764,0,2,2,3,3,5,25,411.74,true
26.0.8,4,cold,8988,8988,0,3,3,3,5,7,37,289.94,true
26.0.8,4,warm,13082,13082,0,2,2,3,3,4,31,436.07,true
26.1.5,1,cold,7442,7442,0,4,3,4,5,31,77,240.06,true
26.1.5,1,warm,9988,9988,0,3,3,3,4,6,47,322.19,true
26.1.5,2,cold,9308,9308,0,3,3,3,5,6,43,300.26,true
26.1.5,2,warm,12900,12900,0,2,2,3,3,4,22,430,true
26.1.5,4,cold,9308,9308,0,3,3,3,5,7,41,310.27,true
26.1.5,4,warm,13062,13062,0,2,2,3,3,4,23,421.35,true
26.2.5,1,cold,7544,7544,0,4,3,4,5,30,86,243.35,true
26.2.5,1,warm,11768,11768,0,2,2,3,3,5,50,392.27,true
26.2.5,2,cold,9306,9306,0,3,3,3,5,7,35,300.19,true
26.2.5,2,warm,12788,12788,0,2,2,3,3,4,19,426.27,true
26.2.5,4,cold,9036,9036,0,3,3,3,5,7,52,291.48,true
26.2.5,4,warm,12722,12722,0,2,2,3,3,4,54,410.39,true
26.3.5,1,cold,482,482,0,61,53,66,116,300,6976,15.55,true
26.3.5,1,warm,804,804,0,36,42,63,80,102,168,25.94,true
26.3.5,2,cold,680,680,0,43,45,63,79,116,4165,21.94,true
26.3.5,2,warm,848,848,0,34,19,62,67,80,104,27.35,true
26.3.5,4,cold,656,656,0,44,50,65,85,118,4304,21.16,true
26.3.5,4,warm,842,842,0,34,30,62,68,82,115,27.16,true
26.4.7,1,cold,522,522,0,55,58,65,107,268,5410,16.84,true
26.4.7,1,warm,720,720,0,40,57,68,95,113,160,23.23,true
26.4.7,2,cold,626,626,0,46,55,68,90,119,3459,20.19,true
26.4.7,2,warm,748,748,0,38,36,67,77,113,129,24.13,true
26.4.7,4,cold,580,580,0,49,46,70,105,150,3880,18.71,true
26.4.7,4,warm,730,730,0,39,32,67,92,111,128,23.55,true
26.5.7,1,cold,484,484,0,60,59,68,126,295,5800,15.61,true
26.5.7,1,warm,720,720,0,40,56,67,93,111,129,23.23,true
26.5.7,2,cold,578,578,0,49,53,71,111,144,3393,19.27,true
26.5.7,2,warm,782,782,0,36,41,64,74,93,109,25.23,true
26.5.7,4,cold,678,678,0,43,42,65,83,123,3274,21.87,true
26.5.7,4,warm,796,796,0,36,33,64,76,84,102,25.68,true
26.6.1,1,cold,458,458,0,64,62,77,179,276,5468,14.77,true
26.6.1,1,warm,714,714,0,41,40,70,95,115,201,23.03,true
26.6.1,2,cold,578,578,0,50,53,73,104,142,3306,18.65,true
26.6.1,2,warm,704,704,0,41,52,71,94,115,159,22.71,true
26.6.1,4,cold,676,676,0,43,58,64,87,129,3220,21.81,true
26.6.1,4,warm,664,664,0,43,54,68,109,157,312,21.42,true

⚠️ edit: data points pre 26.3 are wrong due to an error in the benchmarking setup
Image

Something is clearly going on, claude checking the list of commits between the two versions flagged

Trace regression to FGAP partial evaluation — PR #38085 introduced in 26.3.0

as the possible culprit. Built a local image from a400057 but it turned out to be still good.

Bisect - 1st performance bump

Warning

edit: These findings are invalid, see #48480 (comment)

To find the offending commit, followed this workflow:

  • build keycloak quarkus
./mvnw -pl quarkus/deployment,quarkus/dist -am -DskipTests -DskipProtoLock=true clean install
  • build keycloak docker image
cd quarkus/container
cp ../dist/target/keycloak-999.0.0-SNAPSHOT.tar.gz .
docker build --build-arg KEYCLOAK_DIST=keycloak-999.0.0-SNAPSHOT.tar.gz -t keycloak-local:<COMMIT-HASH> .
  • run the same benchmark on the image
  • as cpu count effect showed no significance in the previous runs, i've only run these test with 1 cpu, 2 times per version - cold and warm cache
git bisect 26.3.5 a4000575a4
git bisect
# bad: [8d6ab96cc3f2d1060f96f0e4e5adf46854c30933] Set version to 26.3.5
# good: [a4000575a4b1960bab7b32f72b3c4956ae3f4f88] Initial support for partial evaluation
git bisect start '26.3.5' 'a4000575a4'
# bad: [5386b065d0743327d042b926ef0ed491f09d7989] Bump @types/node from 22.14.0 to 22.15.17 in /js (#39574)
git bisect bad 5386b065d0743327d042b926ef0ed491f09d7989
# good: [bc45788318b53f0b52665848d23bc6a7bf91ddd6] make mouse select clear filter (#38839)
git bisect good bc45788318b53f0b52665848d23bc6a7bf91ddd6
# good: [54499d94ab7ff19d7bfabdb3e74b91c28468a51d] Avoid automatic DB upgrades (#39275)
git bisect good 54499d94ab7ff19d7bfabdb3e74b91c28468a51d
# bad: [9ad0e1abfa25f3193c149a303a700c555d1d686f] Check if LDAP entry is still valid before validating duplicate emails
git bisect bad 9ad0e1abfa25f3193c149a303a700c555d1d686f
# bad: [9142978c70d7f72552a367b1045a3518cd5da36a] added missing await, increase test stability (#39381)
git bisect bad 9142978c70d7f72552a367b1045a3518cd5da36a
# good: [ba150ed0f93be857b23ae9841da357649b220624] Split GroupTest into multiple files
git bisect good ba150ed0f93be857b23ae9841da357649b220624
# bad: [24910d9e1c76a1e953936c558ab02a27eb91820e] addresses slow import/export performance by limiting persistence context size (#37926)
git bisect bad 24910d9e1c76a1e953936c558ab02a27eb91820e
# good: [d7966c0e2afcd556c8a884374350d7c687ecd2d1] Fix GrantTypeCondition config key mismatch
git bisect good d7966c0e2afcd556c8a884374350d7c687ecd2d1
# good: [71fbc0e57ed4fe8f4bd5a6e9fd3ccacbd196f69d] Uncaught server error during organization update when name already exists
git bisect good 71fbc0e57ed4fe8f4bd5a6e9fd3ccacbd196f69d
# first bad commit: [24910d9e1c76a1e953936c558ab02a27eb91820e] addresses slow import/export performance by limiting persistence context size (#37926)
csv data

⚠️ edit: data points pre 26.3 are wrong due to an error in the benchmarking setup

kc_version,cpus,cache,requests,ok,ko,mean_ms,p50_ms,p75_ms,p95_ms,p99_ms,max_ms,req_per_sec,sla_pass
26.2.5,1,cold,7212,7212,0,4,3,4,6,34,70,240.4,true
26.2.5,1,warm,11248,11248,0,2,2,3,3,6,46,362.84,true
a4000575a4,1,cold,7176,7176,0,4,3,4,6,28,71,231.48,true
a4000575a4,1,warm,11746,11746,0,2,2,3,3,5,46,378.9,true
2ea6b8a222,1,cold,7648,7648,0,3,3,4,5,30,60,246.71,true
2ea6b8a222,1,warm,11696,11696,0,2,2,3,3,5,47,377.29,true
bc45788318,1,cold,7226,7226,0,4,3,4,6,30,56,233.1,true
bc45788318,1,warm,11332,11332,0,2,2,3,3,6,48,365.55,true
54499d94ab,1,cold,7568,7568,0,4,3,4,5,30,56,252.27,true
54499d94ab,1,warm,11268,11268,0,2,2,3,3,6,48,363.48,true
ba150ed0f9,1,cold,7158,7158,0,4,3,4,6,34,62,230.9,true
ba150ed0f9,1,warm,10976,10976,0,2,2,3,4,6,48,354.06,true
d7966c0e2a,1,cold,7334,7334,0,4,3,4,6,29,55,236.58,true
d7966c0e2a,1,warm,10860,10860,0,2,2,3,4,6,45,362,true
71fbc0e57e,1,cold,6312,6312,0,4,3,4,7,27,57,210.4,true
71fbc0e57e,1,warm,9728,9728,0,3,2,3,4,8,47,313.81,true
24910d9e1c,1,cold,1130,1130,0,25,23,26,55,101,6289,36.45,true
24910d9e1c,1,warm,1800,1800,0,16,21,25,30,56,83,58.06,true
9142978c70,1,cold,1148,1148,0,25,23,26,52,94,6032,37.03,true
9142978c70,1,warm,1868,1868,0,15,21,23,27,59,81,60.26,true
9ad0e1abfa,1,cold,1196,1196,0,24,22,25,50,99,5945,38.58,true
9ad0e1abfa,1,warm,1910,1910,0,15,21,24,26,49,84,61.61,true
5386b065d0,1,cold,1160,1160,0,25,23,26,55,88,5744,37.42,true
5386b065d0,1,warm,1854,1854,0,15,21,23,31,55,77,59.81,true
26.3.5,1,cold,486,486,0,60,60,65,122,303,6891,15.68,true
26.3.5,1,warm,804,804,0,36,39,63,76,99,119,25.94,true

⚠️ edit: data points pre 26.3 are wrong due to an error in the benchmarking setup
Image

The offending commit was 24910d9 (#37926), based on the changes EntityManagerProxy wrapper seemed as something that would affect database operations.

For testing the hypotesis, I've asked claude to revert the EntityManagerProxy related change only (see zaenk@14cb345), and run the test one more time.

⚠️ edit: data points pre 26.3 are wrong due to an error in the benchmarking setup
Image

Removing the EntityManagerProxy restored the performance for this test.

The linked commit zaenk@14cb345 is not a proposed fix, it was just testing the effect of EntityManagerProxy on the perfomrance of the admin api users endpoint.

The reports also show another degradation step between 5386b06 and 26.3.5, but I have not investigated that yet (maybe #46681 related?) see below.

Claude's original tip, FGAP partial evaluation, has a slight effect on the number, but not that dramatic - it was introduced sometimes after d7966c0.

Bisect - 2nd performance bump

Warning

edit: This finding is valid, though, less dramatic then what was initially implied by the issue, see #48480 (comment)

The issue identified does not reach the level of slowdown that was measured in 26.3.5, so in another session ran the same load tests for the remaining part of the git history

git bisect 26.3.5 5386b065d0
csv data
kc_version,cpus,cache,requests,ok,ko,mean_ms,p50_ms,p75_ms,p95_ms,p99_ms,max_ms,req_per_sec,sla_pass
26.2.5,1,cold,7212,7212,0,4,3,4,6,34,70,240.4,true
26.2.5,1,warm,11248,11248,0,2,2,3,3,6,46,362.84,true
71fbc0e57e,1,cold,6312,6312,0,4,3,4,7,27,57,210.4,true
71fbc0e57e,1,warm,9728,9728,0,3,2,3,4,8,47,313.81,true
24910d9e1c,1,cold,1130,1130,0,25,23,26,55,101,6289,36.45,true
24910d9e1c,1,warm,1800,1800,0,16,21,25,30,56,83,58.06,true
5386b065d0,1,cold,1160,1160,0,25,23,26,55,88,5744,37.42,true
5386b065d0,1,warm,1854,1854,0,15,21,23,31,55,77,59.81,true
34ad280665,1,cold,474,474,0,62,58,67,129,353,7308,15.29,true
34ad280665,1,warm,816,816,0,36,56,62,79,108,123,27.2,true
7776e8c587,1,cold,492,492,0,60,55,67,126,311,7061,15.87,true
7776e8c587,1,warm,842,842,0,35,36,61,74,101,137,27.16,true
cbd0d18f6a,1,cold,512,512,0,58,52,60,108,284,7596,16.52,true
cbd0d18f6a,1,warm,904,904,0,32,38,55,72,98,115,29.16,true
39699e7d3a,1,cold,524,524,0,56,58,66,100,285,6850,16.9,true
39699e7d3a,1,warm,812,812,0,36,36,63,83,104,160,26.19,true
ec4d104188,1,cold,490,490,0,60,59,68,116,282,7204,15.81,true
ec4d104188,1,warm,806,806,0,36,57,64,80,100,142,26.0,true
864dbf8824,1,cold,494,494,0,60,57,67,106,297,7206,15.94,true
864dbf8824,1,warm,810,810,0,36,35,63,81,108,147,26.13,true
06bd292534,1,cold,522,522,0,56,57,66,103,284,6752,16.84,true
06bd292534,1,warm,820,820,0,36,40,62,78,113,139,26.45,true
4f488bc9a0,1,cold,484,484,0,61,57,66,130,288,7320,15.61,true
4f488bc9a0,1,warm,808,808,0,36,29,62,82,111,172,26.06,true
ad511cbc53,1,cold,458,458,0,64,57,69,104,347,7726,14.77,true
ad511cbc53,1,warm,810,810,0,36,35,63,78,105,123,26.13,true
26.3.5,1,cold,486,486,0,60,60,65,122,303,6891,15.68,true
26.3.5,1,warm,804,804,0,36,39,63,76,99,119,25.94,true
Image

Commit 34ad280 (#39598) introduced a refactor to use user profile provider when mapping user representation on admin api endpoints.

Reverting to user model based only based mapping in the code path (zaenk@add978f) of the benchmark restores the performance to the previous level.

csv data
kc_version,cpus,cache,requests,ok,ko,mean_ms,p50_ms,p75_ms,p95_ms,p99_ms,max_ms,req_per_sec,sla_pass
26.2.5,1,cold,7212,7212,0,4,3,4,6,34,70,240.4,true
26.2.5,1,warm,11248,11248,0,2,2,3,3,6,46,362.84,true
71fbc0e57e,1,cold,6312,6312,0,4,3,4,7,27,57,210.4,true
71fbc0e57e,1,warm,9728,9728,0,3,2,3,4,8,47,313.81,true
24910d9e1c,1,cold,1130,1130,0,25,23,26,55,101,6289,36.45,true
24910d9e1c,1,warm,1800,1800,0,16,21,25,30,56,83,58.06,true
5386b065d0,1,cold,1160,1160,0,25,23,26,55,88,5744,37.42,true
5386b065d0,1,warm,1854,1854,0,15,21,23,31,55,77,59.81,true
34ad280665,1,cold,474,474,0,62,58,67,129,353,7308,15.29,true
34ad280665,1,warm,816,816,0,36,56,62,79,108,123,27.2,true
34ad280665-fix,1,cold,1200,1200,0,24,22,25,50,104,6079,38.71,true
34ad280665-fix,1,warm,1876,1876,0,15,21,24,28,68,90,60.52,true
26.3.5,1,cold,486,486,0,60,60,65,122,303,6891,15.68,true
26.3.5,1,warm,804,804,0,36,39,63,76,99,119,25.94,true
Image

Version

26.5.5

Regression

  • The issue is a regression

Expected behavior

maintained req/sec and response time performance of admin api between releases

Actual behavior

⚠️ edit: data points pre 26.3 are wrong due to an error in the benchmarking setup

Commit req/sec mean ms note
26.2.5 363 2 baseline
71fbc0e 314 3 FGAP (#38085) — minor overhead
24910d9 58 16 EntityManagerProxy (#37926)
34ad280 27 36 UserProfileProvider per-user (#39595)
26.3.5 26 36 release tag

for some my setup, admin api users single page can take more than 60s-120s

  • 1-2k
  • 20+ user attributes
  • fine grained admin auth v1
  • brute force protection - permanent lockout
  • 1 CPU, 4G RAM

if the api call took 10-20 sec previously (which would be still fine) now it takes 60+ sec with this rate of degradation.

How to Reproduce?

I don't have a reproducer yet for the extreme low response rate, but I provided the description with load test results, git bisect investigation that pinpoints an issue that caused a performance degradation in keycloak admin api.

Anything else?

After looking into 34ad280, noticed @BatchSize(20) for UserEntity.attributes - as I have 20+ attributes per user I speculate this also have a multiplier effect in my setup, but I still need to look into it with jfr/cryostat....

edit: added bisect 2 section, added 'anything else' answer
edit2: summary table, and making clear that the attribute fetch is a speculation
edit3: turns out the initial benchmark setup had an error. the data here is misleading, see #48480 (comment) for the corrected measurements_

Metadata

Metadata

Assignees

Type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions