[keycloak-user] start up of keycloak nodes roughly increases two folds for every 100 tenants.
Madhu
kkcmadhu at yahoo.com
Wed Dec 12 07:30:48 EST 2018
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 at 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 at 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 at 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 at 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 at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/keycloak-user
More information about the keycloak-user
mailing list