[keycloak-user] High Utilization with Keycloak Spring Boot adapter

[Alan Gibson]

Hello all,

During load testing the REST API of a Spring Boot based microservice, we
noticed that Keycloak was forming a huge bottleneck. We had 3 instances of
Keycloak (running in clustered mode), each of which was consuming 100% of 8
Xeon CPUs, while only hitting about 80 API calls per second. The load test
itself used 800 concurrent users, each doing 1 HTTP request every 100
milliseconds.

It looks like every time a POST is made to the REST API, Spring Boot makes
a call to Keycloak to (re)authenticate the user. The Keycloak logs are
filled with:

2016-11-06 11:48:07,819 DEBUG [org.jboss.resteasy.resteasy_jaxrs.i18n]
(default task-74) RESTEASY002315: PathInfo: /realms/proxy/protocol/openid-
connect/token
2016-11-06 11:48:07,820 DEBUG [org.keycloak.services] (default task-74)
AUTHENTICATE CLIENT
2016-11-06 11:48:07,820 DEBUG [org.keycloak.services] (default task-74)
client authenticator: client-secret
2016-11-06 11:48:07,820 DEBUG [org.keycloak.services] (default task-74)
client authenticator SUCCESS: client-secret
2016-11-06 11:48:07,820 DEBUG [org.keycloak.services] (default task-74)
Client devicereportreceiver authenticated by client-secret
2016-11-06 11:48:07,820 DEBUG [org.keycloak.services] (default task-74)
AUTHENTICATE ONLY
2016-11-06 11:48:07,820 DEBUG [org.keycloak.services] (default task-74)
processFlow
2016-11-06 11:48:07,820 DEBUG [org.keycloak.services] (default task-74)
check execution: direct-grant-validate-username requirement: REQUIRED
2016-11-06 11:48:07,820 DEBUG [org.keycloak.services] (default task-74)
authenticator: direct-grant-validate-username
2016-11-06 11:48:07,820 DEBUG [org.keycloak.services] (default task-74)
invoke authenticator.authenticate
2016-11-06 11:48:07,821 DEBUG [org.keycloak.services] (default task-74)
authenticator SUCCESS: direct-grant-validate-username
2016-11-06 11:48:07,821 DEBUG [org.keycloak.services] (default task-74)
check execution: direct-grant-validate-password requirement: REQUIRED
2016-11-06 11:48:07,821 DEBUG [org.keycloak.services] (default task-74)
authenticator: direct-grant-validate-password
2016-11-06 11:48:07,821 DEBUG [org.keycloak.services] (default task-74)
invoke authenticator.authenticate
2016-11-06 11:48:07,821 DEBUG
[org.hibernate.engine.transaction.internal.TransactionImpl]
(default task-74) begin
2016-11-06 11:48:07,821 DEBUG
[org.jboss.jca.core.connectionmanager.pool.strategy.OnePool]
(default task-74) KeycloakDS: getConnection(null,
WrappedConnectionRequestInfo at 25df8309[userName=postgres]) [0/20]
2016-11-06 11:48:09,560 DEBUG [org.keycloak.services] (default task-74)
authenticator SUCCESS: direct-grant-validate-password
2016-11-06 11:48:09,560 DEBUG [org.keycloak.services] (default task-74)
check execution: direct-grant-validate-otp requirement: OPTIONAL
2016-11-06 11:48:09,560 DEBUG [org.keycloak.services] (default task-74)
authenticator: direct-grant-validate-otp
2016-11-06 11:48:09,569 DEBUG [org.keycloak.services] (default task-74)
invoke authenticator.authenticate
2016-11-06 11:48:09,569 DEBUG [org.keycloak.services] (default task-74)
authenticator ATTEMPTED: direct-grant-validate-otp
2016-11-06 11:48:09,569 DEBUG [org.keycloak.services] (default task-74)
Using full scope for client
2016-11-06 11:48:09,569 DEBUG [org.keycloak.services] (default task-74)
Using full scope for client
2016-11-06 11:48:09,739 DEBUG [org.keycloak.events] (default task-74)
type=LOGIN, realmId=REMOVED, clientId=REMOVED, userId=REMOVED,
ipAddress=REMOVED, auth_method=openid-connect, token_id=REMOVED,
grant_type=password, refresh_token_type=Refresh, refresh_token_id=REMOVED,
client_auth_method=client-secret, username=REMOVED
2016-11-06 11:48:09,739 DEBUG
[org.hibernate.engine.transaction.internal.TransactionImpl]
(default task-74) committing
2016-11-06 11:48:09,751 DEBUG
[org.jboss.jca.core.connectionmanager.pool.strategy.OnePool]
(default task-74) KeycloakDS: returnConnection(2aab4b06, false) [0/20]

The Spring Boot application.properties looks like

keycloak.realm=REMOVED
keycloak.realmKey=REMOVED
keycloak.auth-server-url=${KEYCLOAK_AUTHENTICATION_SERVER}
keycloak.ssl-required=none
keycloak.resource=REMOVED
#keycloak.use-resource-role-mappings=true
keycloak.enable-basic-auth=true
keycloak.credentials.secret=${KEYCLOAK_CLIENT_SECRET}
keycloak.cors=true
keycloak.cors-allowed-headers=x-requested-with,origin,content-type,accept,
authorization
keycloak.cors-allowed-methods=GET,POST,DELETE,PUT,OPTIONS
keycloak.cors-max-age=3600
keycloak.expose-token=true
keycloak.bearer-only=true
keycloak.securityConstraints[0].securityCollections[0].name=REMOVED
keycloak.securityConstraints[0].securityCollections[0].authRoles[0]=user
keycloak.securityConstraints[0].securityCollections[0].patterns[0]=/REMOVED
keycloak.securityConstraints[1].securityCollections[0].name=REMOVED
keycloak.securityConstraints[1].securityCollections[0].authRoles[0]=DEVICE
keycloak.securityConstraints[1].securityCollections[0].
patterns[0]=/REMOVED/*

So my questions are:

1. Would you expect to see this kind of high utilization with my test
scenario?

2. Should the Keycloak Spring Boot adapter be reauthenticating with every
request, as opposed to caching the authentication results for a short
period of time, or just relying on normal HTTP sessions?

Br,
Alan