Hi,
Just and update.I rand another test, where i created tenants from scratch in keycloak 4.7
, in that case, the startup time is pretty good, for about 900 tenants with 6 to 7 clients
, 3 user groups, 3 to 4 custom mappers and 50 users in each tenants takes less than 30
seconds ( this was taking about 40 to 50 min) in keycloak 4.5...This is really awesome..
But, i upgrade from 4.5 to 4.7, the system does not even start up after 2 hours :(
On Thursday, 6 December, 2018, 7:42:48 PM IST, Madhu <kkcmadhu(a)yahoo.com> wrote:
Thanks Marek,
I tried with Keycloak 4.1.7, unfortunately, the start up time in my case has increased
tremendously for my 621 tenants, the start up time for keycloak node was about 40 mins,
and after moving to 4.1.7 i see this increased to 1 hours 30 min + (still not
starting)...
I also see that the cpu usage for the keycloak process is constatnly 100% .i tried with
c4.xlarge (4 core) .upgraded to c4.x2large( 8 core), still the cpu usage is 100% and
there is no big difference in start up time ( comes down by max 2 mins)i.e 40 mins to 38
mins.
The connection pool size is set adequately lareage 60 +,but i don't see many session
in my database instance (not more than1 or 2 sessions).
The cpu usage in database (my sql is almost less than 1% and occassionly spikes to 2%)..
upon enabling hibernate stats in keycloak, i keep seeing messages like this :
2:21:53,612 INFO [org.keycloak.connections.jpa.HibernateStatsReporter]
(Timer-2)Statistics[start time=1544098883667,sessions opened=1,sessions
closed=0,transactions=0,successful transactions=0,optimistic lock
failures=0,flushes=0,connections obtained=11728,statements prepared=11728,statements
closed=0,second level cache puts=0,second level cache hits=0,second level cache
misses=0,entities loaded=15688,entities updated=0,entities inserted=0,entities
deleted=0,entities fetched=91,collections loaded=10187,collections updated=0,collections
removed=0,collections recreated=0,collections fetched=10187,naturalId queries executed to
database=0,naturalId cache puts=0,naturalId cache hits=0,naturalId cache
misses=0,naturalId max query time=0,queries executed to database=1263,query cache
puts=0,query cache hits=0,query cache misses=0,update timestamps cache puts=0,update
timestamps cache hits=0,update timestamps cache misses=0,max query time=13]
Important entities statistics:org.keycloak.models.jpa.entities.AuthenticationFlowEntity -
inserted: 0, updated: 0, removed: 0, loaded: 1081, fetched:
0org.keycloak.models.jpa.entities.RealmAttributeEntity - inserted: 0, updated: 0, removed:
0, loaded: 1909, fetched: 0org.keycloak.models.jpa.entities.ComponentEntity - inserted: 0,
updated: 0, removed: 0, loaded: 1079, fetched:
0org.keycloak.models.jpa.entities.ProtocolMapperEntity - inserted: 0, updated: 0, removed:
0, loaded: 3419, fetched: 0org.keycloak.models.jpa.entities.RoleEntity - inserted: 0,
updated: 0, removed: 0, loaded: 271, fetched:
0org.keycloak.models.jpa.entities.ClientScopeEntity - inserted: 0, updated: 0, removed: 0,
loaded: 906, fetched: 0org.keycloak.models.jpa.entities.RequiredActionProviderEntity -
inserted: 0, updated: 0, removed: 0, loaded: 450, fetched:
0org.keycloak.models.jpa.entities.AuthenticationExecutionEntity - inserted: 0, updated: 0,
removed: 0, loaded: 2795, fetched: 0org.keycloak.models.jpa.entities.ComponentConfigEntity
- inserted: 0, updated: 0, removed: 0, loaded: 3235, fetched:
0org.keycloak.models.jpa.entities.AuthenticatorConfigEntity - inserted: 0, updated: 0,
removed: 0, loaded: 180, fetched: 0
Important collections
statistics:org.keycloak.models.jpa.entities.ClientScopeEntity.protocolMappers - recreated:
0, updated: 0, removed: 0, loaded: 901, fetched:
901org.keycloak.models.jpa.entities.ClientScopeEntity.attributes - recreated: 0, updated:
0, removed: 0, loaded: 900, fetched:
900org.keycloak.models.jpa.entities.ProtocolMapperEntity.config - recreated: 0, updated:
0, removed: 0, loaded: 3419, fetched:
3419org.keycloak.models.jpa.entities.AuthenticatorConfigEntity.config - recreated: 0,
updated: 0, removed: 0, loaded: 180, fetched:
180org.keycloak.models.jpa.entities.AuthenticationFlowEntity.executions - recreated: 0,
updated: 0, removed: 0, loaded: 1081, fetched:
1081org.keycloak.models.jpa.entities.ComponentEntity.componentConfigs - recreated: 0,
updated: 0, removed: 0, loaded: 1079, fetched:
1079org.keycloak.models.jpa.entities.RequiredActionProviderEntity.config - recreated: 0,
updated: 0, removed: 0, loaded: 450, fetched: 450
Important queries statistics:.....................................select m.role.id from
ClientScopeRoleMappingEntity m where m.clientScope =
:clientScopeexecutionCount=900executionAvgTime=0 ms
14:03:23,646 INFO [org.keycloak.connections.jpa.HibernateStatsReporter]
(Timer-2)Statistics[start time=1544104973645,sessions opened=0,sessions
closed=0,transactions=0,successful transactions=0,optimistic lock
failures=0,flushes=28,connections obtained=272,statements prepared=294,statements
closed=0,second level cache puts=0,second level cache hits=0,second level cache
misses=0,entities loaded=23,entities updated=2,entities inserted=30,entities
deleted=0,entities fetched=0,collections loaded=154,collections updated=6,collections
removed=0,collections recreated=8,collections fetched=154,naturalId queries executed to
database=0,naturalId cache puts=0,naturalId cache hits=0,naturalId cache
misses=0,naturalId max query time=0,queries executed to database=73,query cache
puts=0,query cache hits=0,query cache misses=0,update timestamps cache puts=0,update
timestamps cache hits=0,update timestamps cache misses=0,max query time=0]
Important entities statistics:
Important collections statistics:
Important queries statistics:
14:03:53,647 INFO [org.keycloak.connections.jpa.HibernateStatsReporter]
(Timer-2)Statistics[start time=1544105003646,sessions opened=0,sessions
closed=0,transactions=0,successful transactions=0,optimistic lock
failures=0,flushes=37,connections obtained=189,statements prepared=211,statements
closed=0,second level cache puts=0,second level cache hits=0,second level cache
misses=0,entities loaded=13,entities updated=2,entities inserted=39,entities
deleted=0,entities fetched=0,collections loaded=81,collections updated=6,collections
removed=0,collections recreated=8,collections fetched=81,naturalId queries executed to
database=0,naturalId cache puts=0,naturalId cache hits=0,naturalId cache
misses=0,naturalId max query time=0,queries executed to database=63,query cache
puts=0,query cache hits=0,query cache misses=0,update timestamps cache puts=0,update
timestamps cache hits=0,update timestamps cache misses=0,max query time=0]
Important entities statistics:
Important collections statistics:
Important queries statistics:
14:04:23,647 INFO [org.keycloak.connections.jpa.HibernateStatsReporter]
(Timer-2)Statistics[start time=1544105033647,sessions opened=0,sessions
closed=0,transactions=0,successful transactions=0,optimistic lock
failures=0,flushes=31,connections obtained=232,statements prepared=276,statements
closed=0,second level cache puts=0,second level cache hits=0,second level cache
misses=0,entities loaded=20,entities updated=4,entities inserted=35,entities
deleted=0,entities fetched=0,collections loaded=121,collections updated=12,collections
removed=0,collections recreated=16,collections fetched=121,naturalId queries executed to
database=0,naturalId cache puts=0,naturalId cache hits=0,naturalId cache
misses=0,naturalId max query time=0,queries executed to database=69,query cache
puts=0,query cache hits=0,query cache misses=0,update timestamps cache puts=0,update
timestamps cache hits=0,update timestamps cache misses=0,max query time=1]
Important entities statistics:
Important collections statistics:
Important queries statistics:
14:04:53,646 INFO [org.keycloak.connections.jpa.HibernateStatsReporter]
(Timer-2)Statistics[start time=1544105063647,sessions opened=0,sessions
closed=0,transactions=0,successful transactions=0,optimistic lock
failures=0,flushes=32,connections obtained=235,statements prepared=257,statements
closed=0,second level cache puts=0,second level cache hits=0,second level cache
misses=0,entities loaded=19,entities updated=2,entities inserted=34,entities
deleted=0,entities fetched=0,collections loaded=122,collections updated=6,collections
removed=0,collections recreated=8,collections fetched=122,naturalId queries executed to
database=0,naturalId cache puts=0,naturalId cache hits=0,naturalId cache
misses=0,naturalId max query time=0,queries executed to database=68,query cache
puts=0,query cache hits=0,query cache misses=0,update timestamps cache puts=0,update
timestamps cache hits=0,update timestamps cache misses=0,max query time=0]
Important entities statistics:
Important collections statistics:
Important queries statistics:
On Wednesday, 5 December, 2018, 2:09:55 PM IST, Marek Posolda
<mposolda(a)redhat.com> wrote:
Hi,
I suggest to upgrade to latest 4.7.0.Final. I know there were some
improvements in recent version regarding this.
However you will still probably see some issues as we did not yet try to
test with so big amount of realms. We plan to improve on this use-case.
Marek
On 27/11/2018 12:46, Madhu wrote:
Hi I am using keycloak 4.5. i created about 600+ tenants with 50
users each for a performance testing.
Upon creating tenants the start up time of keycloak increases drastically. This seems to
be due to pretty much all entities at start up..
I tried disabling realm cache, user cache and did not help.. can you suggest how to bring
down the start up time?
Is it absolutely necessary for keycloak to load every thing at start up??
This is an extract from hibernate stat i got on a c4 xlarge ec2 instance ( 4 core 8 gig),
keycloak configured with xms=xmx=5g.
018-11-24 10:33:19,998 INFO [org.hibernate.envers.boot.internal.EnversServiceImpl]
(ServerService Thread Pool – 61) Envers integration enabled? : true
2018-11-24 10:33:20,499 INFO [org.hibernate.validator.internal.util.Version]
(ServerService Thread Pool – 61) HV000001: Hibernate Validator 5.3.6.Final
2018-11-24 10:33:21,296 INFO [org.hibernate.hql.internal.QueryTranslatorFactoryInitiator]
(ServerService Thread Pool – 61) HHH000397: Using ASTQueryTranslatorFactory
^C
[centos@ip-172-31-45-199 log]$ 11:10:45,750 INFO [org.hibernate.engi
ne.internal.StatisticalLoggingSessionEventListener] (ServerService Th read Pool – 61)
Session Metrics {
669457663 nanoseconds spent acquiring 92974 JDBC connections;
148185664 nanoseconds spent releasing 92974 JDBC connections;
1852958902 nanoseconds spent preparing 92974 JDBC statements;
35866600579 nanoseconds spent executing 92974 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
0 nanoseconds spent performing 0 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
543461113 nanoseconds spent executing 2 flushes (flushing a total of 227216 entities and
158902 collections);
2197548626817 nanoseconds spent executing 14139 partial-flushes ( flushing a total of*
1042012050 entities and 1042012050 collections*)
}
11:10:45,780 INFO [org.hibernate.engine.internal.StatisticalLoggingS essionEventListener]
(ServerService Thread Pool – 61) Session Metric s
{ 7689387 nanoseconds spent acquiring 1 JDBC connections; 34263 nanoseconds spent
releasing 1 JDBC connections; 8025969 nanoseconds spent preparing 1 JDBC statements;
909784 nanoseconds spent executing 1 JDBC statements; 0 nanoseconds spent executing 0 JDBC
batches; 0 nanoseconds spent performing 0 L2C puts; 0 nanoseconds spent performing 0 L2C
hits; 0 nanoseconds spent performing 0 L2C misses; 3525215 nanoseconds spent executing 3
flushes (flushing a total o f 3 entities and 0 collections); 0 nanoseconds spent executing
0 partial-flushes (flushing a total of 0 entities and 0 collections)}
11:10:45,795 INFO [org.hibernate.engine.internal.StatisticalLoggingS essionEventListener]
(ServerService Thread Pool – 61) Session Metric s {
437680 nanoseconds spent acquiring 1 JDBC connections;
10539 nanoseconds spent releasing 1 JDBC connections;
465001 nanoseconds spent preparing 1 JDBC statements;
719260 nanoseconds spent executing 1 JDBC statements;
0 nanoseconds spent executing 0 JDBC batches;
0 nanoseconds spent performing 0 L2C puts;
0 nanoseconds spent performing 0 L2C hits;
0 nanoseconds spent performing 0 L2C misses;
0 nanoseconds spent executing 0 flushes (flushing a total of 0 en tities and 0
collections);
17455 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and
0 collections)
All My 600 +realms are pretty much same i.e. each realm has a client scope, a java script
mapper (to get all the realm roles into resouce role),couple of attribute mappers, 2 users
groups ( 1 for admins) and 1 for other users. i have about 50 users in each realm and all
the user belongs to one of the 2 user groups ( no custom roles though)..
Also, I bench marked the start up time after creating 50 or 100 realms and the start up
time increases as the number of realms increases .
I am able to manage as i have disabled the admin console and use rest endpoints.. but
still the start up time and loading pretty much every thing seems little wiered.
Please correct my understanding if i am wrong here..
| No of Realms | Start up time in mins |
| 0 realms | 0.22 mins |
| 100 realms | 2.34 mins |
| 200 realms | 2.53 mins |
| 300 realms | 5.34 mins |
| 400 realms | 9.42 mins |
| 500 realms | 14.6 mins |
| 650 realms | 37 mins |
Like wise the time taken to create tenants too gradually increases ( i use import to
create realms)
from about 3 seconds for first few realms to about 30 sec for 600th realm..
Any advise /help will be appreciated.
_______________________________________________
keycloak-user mailing list
keycloak-user(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/keycloak-user