[keycloak-user] start up of keycloak nodes roughly increases two folds for every 100 tenants.

Thu Dec 6 09:12:48 EST 2018

 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 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.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 at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/keycloak-user