Hi Marek,
Thanks for quick response and you are right.
i see migrate to 4_6 all over my logs...
name: keycloak-default ...]2018-12-12 11:28:00,787 INFO
[org.hibernate.Version] (ServerService Thread Pool -- 64) HHH000412: Hibernate Core
{5.3.6.Final}2018-12-12 11:28:00,789 INFO [org.hibernate.cfg.Environment] (ServerService
Thread Pool -- 64) HHH000206: hibernate.properties not found2018-12-12 11:28:00,968 INFO
[org.hibernate.annotations.common.Version] (ServerService Thread Pool -- 64) HCANN000001:
Hibernate Commons Annotations {5.0.4.Final}2018-12-12 11:28:01,167 INFO
[org.hibernate.dialect.Dialect] (ServerService Thread Pool -- 64) HHH000400: Using
dialect: org.hibernate.dialect.MySQL57Dialect2018-12-12 11:28:01,216 INFO
[org.hibernate.envers.boot.internal.EnversServiceImpl] (ServerService Thread Pool -- 64)
Envers integration enabled? : true2018-12-12 11:28:01,830 INFO [org.hibernate.orm.beans]
(ServerService Thread Pool -- 64) HHH10005002: No explicit CDI BeanManager reference was
passed to Hibernate, but CDI is available on the Hibernate ClassLoader.2018-12-12
11:28:01,903 INFO [org.hibernate.validator.internal.util.Version] (ServerService Thread
Pool -- 64) HV000001: Hibernate Validator 6.0.13.Final2018-12-12 11:28:03,601 INFO
[org.hibernate.hql.internal.QueryTranslatorFactoryInitiator] (ServerService Thread Pool --
64) HHH000397: Using ASTQueryTranslatorFactory2018-12-12 11:28:04,097 DEBUG
[org.keycloak.migration.MigrationModelManager] (ServerService Thread Pool -- 64) Migrating
older model to 4.6.02018-12-12 11:47:56,674 DEBUG
[org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64) Added
'roles' and 'web-origins' default client scopes2018-12-12 11:48:12,272
DEBUG [org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64)
Client scope 'roles' assigned to all the clients2018-12-12 11:48:14,004 DEBUG
[org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64) Added
'roles' and 'web-origins' default client scopes2018-12-12 11:48:29,549
DEBUG [org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64)
Client scope 'roles' assigned to all the clients2018-12-12 11:48:31,292 DEBUG
[org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64) Added
'roles' and 'web-origins' default client scopes2018-12-12 11:48:46,667
DEBUG [org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64)
Client scope 'roles' assigned to all the clients2018-12-12 11:48:48,383 DEBUG
[org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64) Added
'roles' and 'web-origins' default client scopes2018-12-12 11:49:03,859
DEBUG [org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64)
Client scope 'roles' assigned to all the clients2018-12-12 11:49:05,558 DEBUG
[org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64) Added
'roles' and 'web-origins' default client scopes2018-12-12 11:49:21,108
DEBUG [org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64)
Client scope 'roles' assigned to all the clients2018-12-12 11:49:22,869 DEBUG
[org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64) Added
'roles' and 'web-origins' default client scopes2018-12-12 11:49:38,398
DEBUG [org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64)
Client scope 'roles' assigned to all the clients2018-12-12 11:49:40,154 DEBUG
[org.keycloak.migration.migrators.MigrateTo4_6_0] (ServerService Thread Pool -- 64) Added
'roles' and 'web-origins' default client scopes
On Wednesday, 12 December, 2018, 2:38:32 PM IST, Marek Posolda
<mposolda(a)redhat.com> wrote:
On 12/12/2018 09:26, Madhu wrote:
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 :(
Thanks for the update.
If you want to know the cuase, maybe you can try to enable debug logging in standalone.xml
for category "org.keycloak.migration" and
"org.keycloak.connections.jpa" ? I have some suspicion that the issue can be in
the MigrateTo4_6_0 class, but not 100% sure.
Anyway, my previous statement still applies - Keycloak has currently known limitations
with big number of realms. The few use-cases (startup time) were fixed in 4.7, but there
are probably plenty of others, which are not. And even if the migration issue is fixed,
there will be still some others shown later... We generally want to improve performance
with big number of realms. Hopefully there is a time to do more work in Keycloak 5.x.
Marek
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: 0
org.keycloak.models.jpa.entities.RealmAttributeEntity - inserted: 0, updated: 0, removed:
0, loaded: 1909, fetched: 0 org.keycloak.models.jpa.entities.ComponentEntity - inserted:
0, updated: 0, removed: 0, loaded: 1079, fetched: 0
org.keycloak.models.jpa.entities.ProtocolMapperEntity - inserted: 0, updated: 0, removed:
0, loaded: 3419, fetched: 0 org.keycloak.models.jpa.entities.RoleEntity - inserted: 0,
updated: 0, removed: 0, loaded: 271, fetched: 0
org.keycloak.models.jpa.entities.ClientScopeEntity - inserted: 0, updated: 0, removed: 0,
loaded: 906, fetched: 0 org.keycloak.models.jpa.entities.RequiredActionProviderEntity -
inserted: 0, updated: 0, removed: 0, loaded: 450, fetched: 0
org.keycloak.models.jpa.entities.AuthenticationExecutionEntity - inserted: 0, updated: 0,
removed: 0, loaded: 2795, fetched: 0
org.keycloak.models.jpa.entities.ComponentConfigEntity - inserted: 0, updated: 0, removed:
0, loaded: 3235, fetched: 0 org.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: 901
org.keycloak.models.jpa.entities.ClientScopeEntity.attributes - recreated: 0, updated: 0,
removed: 0, loaded: 900, fetched: 900
org.keycloak.models.jpa.entities.ProtocolMapperEntity.config - recreated: 0, updated: 0,
removed: 0, loaded: 3419, fetched: 3419
org.keycloak.models.jpa.entities.AuthenticatorConfigEntity.config - recreated: 0, updated:
0, removed: 0, loaded: 180, fetched: 180
org.keycloak.models.jpa.entities.AuthenticationFlowEntity.executions - recreated: 0,
updated: 0, removed: 0, loaded: 1081, fetched: 1081
org.keycloak.models.jpa.entities.ComponentEntity.componentConfigs - recreated: 0, updated:
0, removed: 0, loaded: 1079, fetched: 1079
org.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 = :clientScope executionCount=900
executionAvgTime=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.engine.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