[keycloak-user] start up of keycloak nodes roughly increases two folds for every 100 tenants.
Marek Posolda
mposolda at redhat.com
Wed Dec 12 04:08:26 EST 2018
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 <mailto: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 <mailto:keycloak-user at lists.jboss.org>
> > https://lists.jboss.org/mailman/listinfo/keycloak-user
>
>
>
More information about the keycloak-user
mailing list