Sakai 2.9.x > 12.x - Site Info egregiously slow - ideas for troubleshooting?

[Mike Osterman]

Hi all,

I'm a few days away from cutting over from Sakai 2.9.x to 12.x - FINALLY!

BUT, I could use some help troubleshooting a big performance issue I have:

I have a test site with 163 users (one of our biggest) but I'm having the exact same behavior with a site with 2 users.

On our 2.9 instance, loading the 163 user site takes no more than 4 seconds. On the 12.x instance, it takes 14 seconds. Again, it takes 14 seconds for the site with 2 users as well.

When running, mysqld is using about 75% of the CPU, then goes right back down to nearly idle when done.

Here's what I've checked so far:

• Slow query log - nothing
• Tuned memory allocation upwards in JAVA_OPTS - started with similar sizes to production (some changes in Java 8) - no change in behavior
• Brought over performance-related entries in my.cnf
• Reviewed sakai.properties

I would also expect that running the "Site Info" page a second time would be faster due to caching, but it is slow both times.

Production:

Sakai - 2.9.x

MySQL - 5.1.73

Tomcat - 7

OS - RHEL 6.9

Memory - 10GB

Java - 6

JAVA_OPTS (relevant memory args): -server -Xms4096m -Xmx4096m -XX:PermSize=512m -XX:MaxPermSize=512m -XX:NewSize=192m -XX:MaxNewSize=384m

New server:

Sakai - 12.x

MySQL - 5.5.60-log (Community Edition)

Tomcat - 8

OS - RHEL 7.5

Memory - 10GB

Java 8

JAVA_OPTS (relevant memory args): -server -Xms6144m -Xmx6144m -XX:NewSize=2048m -XX:MaxNewSize=2048m

So, thoughts of where I can look for root causes? Maybe some interesting log4j debug areas to add?

I did see one thread about problems MySQL performance, and 5.5 was mentioned, but no resolution was posted:

https://groups.google.com/a/apereo.org/forum/#!searchin/sakai-dev/mysql$205.5/sakai-dev/Fjm1PjG-QbU/SKKB_vxiCgAJ

Thanks for any and all pointers!

Mike

[Sam Ottenhoff]

Do you see orphaned users in the Site Info list when you are logged in as an admin and viewing that site's Site Info?

Are you using LDAP? Do you have LDAP debug enabled?

YourKit is an incredible tool that almost always provides a definitive answer to questions like this one.

MySQL 5.6 is definitely recommended. 5.5 has some optimization issues but those appear to be mostly centered around Forums.

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+...@apereo.org.
To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

[Mike Osterman]

Hi Sam,

Thanks for the ideas!

No orphaned users - in fact, one of them has only two users and still takes 14 seconds.

We are using LDAP, so I'll add some debug for that, and will also check out YourKit to see what might be going on. Great suggestions!

I'll report back what I find as I go, and welcome any additional pointers from the community.

Thanks,

Mike

[Mike Osterman]

Update: It turns out this a more targeted issue--it only happens when logged in as "admin."

So I turned on LDAP debugging, and all of the info came back from the LDAP servers near-instantaneously. The last log entry before The Great Pause (~14 seconds regardless of # of site members) was:

14-Aug-2018 22:58:46.617 DEBUG [http-nio-8443-exec-10] edu.amc.sakai.user.JLDAPDirectoryProvider.mapUserDataOntoUserEdit mapUserDataOntoUserEdit() [userData = edu.amc.sakai.user.LdapUserData@446bc511[

I then turned on All The Debug in log4j.properties:

log4j.rootLogger=DEBUG, Sakai

That was more text flying by than I ever care to look at again, but I think I found where the trouble is, though could still use help in resolving it if possible.

During The Great Pause, these messages flew by non-stop:

14-Aug-2018 23:04:50.454 DEBUG [http-nio-8443-exec-1] net.sf.ehcache.Cache.searchInStoreWithStats org.sakaiproject.db.BaseDbFlatStorage.SAKAI_SITE_PAGE_PROPERTY cache - Miss

14-Aug-2018 23:04:50.454 DEBUG [http-nio-8443-exec-1] com.zaxxer.hikari.pool.ProxyConnection.close sakai - Executed rollback on connection com.mysql.jdbc.JDBC4Connection@6d28039a due to dirty commit state on close().

14-Aug-2018 23:04:50.455 DEBUG [http-nio-8443-exec-1] com.zaxxer.hikari.pool.ProxyConnection.close sakai - Executed rollback on connection com.mysql.jdbc.JDBC4Connection@1ec7d62e due to dirty commit state on close().

All those rollbacks happening multiple times a second would explain why MySQL CPU was through the roof.

This doesn't happen at all when I'm logged in as a standard user, or Become User on another user. That said, it makes admin work on sites near untenable.

Any suggestions on how to stop this from happening?

Thanks!

Mike

On Tuesday, August 14, 2018 at 11:49:18 AM UTC-7, Mike Osterman wrote:

Hi Sam,

Thanks for the ideas!

No orphaned users - in fact, one of them has only two users and still takes 14 seconds.

We are using LDAP, so I'll add some debug for that, and will also check out YourKit to see what might be going on. Great suggestions!

I'll report back what I find as I go, and welcome any additional pointers from the community.

Thanks,

Mike

On Tue, Aug 14, 2018 at 11:34 AM Sam Ottenhoff wrote:

Do you see orphaned users in the Site Info list when you are logged in as an admin and viewing that site's Site Info?

Are you using LDAP? Do you have LDAP debug enabled?

YourKit is an incredible tool that almost always provides a definitive answer to questions like this one.

MySQL 5.6 is definitely recommended. 5.5 has some optimization issues but those appear to be mostly centered around Forums.

[Sam Ottenhoff]

Dirty commit state just means that a DB connection is being returned to the pool and HikariCP is cleaning it up. 

You would need to use YourKit or SQL logging (like p6spy) to figure out what DB calls are being made during that time.

How are your cache stats? Are any of the caches maxed out? 

[Kenneth Aragon]

Hi Mike,

How many sites is the admin user a member of.  I've seen really slow navigation if a user is a member of a lot of sites.  If they are a member of a ton of sites, I would recommend removing the admin user from those sites and taking another look.

Thanks,

Kenny Aragon

Technical Services Manager

P: (740) 599-5005 Ex. 803

 

--

[Mike Osterman]

Hi Kenny,

Every single site (hundreds, if not thousands). We’ve always been under the impression that the administrator had to be a member of the site to be able to work with them. If we could remove admin from all sites, that would be AMAZING for many reasons. 

Thanks!

Mike 

[Kenneth Aragon]

Hi Mike,

This is most likely the cause of the slowness.  Admin does not need to be and should not be enrolled in every site.  As an admin, you can access any site without actually being enrolled via Administration Workspace > Site Info.  The only thing you will notice is that these sites will no longer appear in the Sites drop down and you will need to use the Site Info tool to access them.

Thanks,

Kenny Aragon

Technical Services Manager

P: (740) 599-5005 Ex. 803

 

[Mike Osterman]

"The only thing you will notice is that these sites will no longer appear in the Sites drop down" - which slows it down login anyway. I'll drop admin from all and report back. Thank you!

-Mike

[Mike Osterman]

Thank you, Sam and Kenny for your help in tracking that down! I ran the following SQL, cleared the memory cache, and now it's super fast:

delete from sakai_site_user

where USER_ID = 'admin'

and site_ID not in ('~admin','!admin')

I must admit, it's a bit embarrassing that we've been adding "admin" to sites for 13 years, but I'm glad that we eventually figured it out.

Here's a last oddity: I ran the above delete, emptied the cache, but as soon as I restart and log in again, sakai_site_user gets repopulated, and I'm back to where I started with membership in 7,217 sites. :/

Do I need to remove myself via an API to make this stop? Or are there some cache files somewhere on the filesystem I need to reinit that are causing this db repopulation?

Thanks again!

Mike

On Wednesday, August 15, 2018 at 11:34:36 AM UTC-7, Mike Osterman wrote:

"The only thing you will notice is that these sites will no longer appear in the Sites drop down" - which slows it down login anyway. I'll drop admin from all and report back. Thank you!

-Mike

On Wed, Aug 15, 2018 at 11:24 AM Kenneth Aragon wrote:

Hi Mike,

This is most likely the cause of the slowness.  Admin does not need to be and should not be enrolled in every site.  As an admin, you can access any site without actually being enrolled via Administration Workspace > Site Info.  The only thing you will notice is that these sites will no longer appear in the Sites drop down and you will need to use the Site Info tool to access them.

Thanks,

Kenny Aragon

Technical Services Manager

P: (740) 599-5005 Ex. 803

 

On Wed, Aug 15, 2018 at 11:10 AM Mike Osterman  wrote:

Hi Kenny,

Every single site (hundreds, if not thousands). We’ve always been under the impression that the administrator had to be a member of the site to be able to work with them. If we could remove admin from all sites, that would be AMAZING for many reasons. 

Thanks!

Mike 

[Sam Ottenhoff]

SAKAI_REALM_RL_GR 

[Mike Osterman]

That did it - thanks!

[Sanghyun Jeon]

Dumb question. Do you remove all admin rows from  SAKAI_REALM_RL_GR table?

S

--

You received this message because you are subscribed to the Google Groups "Sakai Development" group.

To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+unsubscribe@apereo.org.

[Kenneth Aragon]

No.  You will need to avoid removing the rows with the realm realm_key associated with the !admin and !admin sites. 

Thanks,

Kenny Aragon

Technical Services Manager

P: (740) 599-5005 Ex. 803

 

To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+...@apereo.org.

[Mike Osterman]

Here's the SQL I used on MySQL:

delete from SAKAI_SITE_USER

where USER_ID = 'admin'

and site_ID not in ('~admin','!admin')

delete from SAKAI_REALM_RL_GR

where USER_ID = 'admin'

and REALM_KEY not in (

select REALM_KEY from sakai_realm

where REALM_ID in ('/site/~admin','/site/!admin')

)

[Gregory Guthrie]

Is there a site/document which describes required ongoing maintenance operations and processes like this, and the scripts to do them?

 

Other tables that need regular maintenance or cleanup…?

 

 

Dr. Gregory Guthrie

----------------------------------------------------------------

[Mike Osterman]

+1

It’s looking like this is not a one time deal (removing admin), but ongoing maintenance. Every new site I’ve created since has admin (maybe because my web service call is run by admin?) I suppose I could remove admin after adding the instructor(s), but it’s quite odd.

-Mike

[Sanghyun Jeon]

Thank you for sharing your queries, Mike.

That's bummer for ongoing maintenance, but at least now I know how to improve my performance.

Thank you again.

S

To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+unsubscribe@apereo.org.

To post to this group, send email to saka...@apereo.org.

[Mike Osterman]

Hello,

If you use web services to create sites, you can add a call to removeMemberFromSite() in the sakai site WSDL to remove the 'admin' account. I just tested that last night, and it works well.

-Mike

[Reinier Post]

On Wed, Aug 15, 2018 at 08:17:10PM -0700, Mike Osterman wrote:
> Here's the SQL I used on MySQL:
>
> delete from SAKAI_SITE_USER
> where USER_ID = 'admin'
> and site_ID not in ('~admin','!admin')
>
> delete from SAKAI_REALM_RL_GR
> where USER_ID = 'admin'
> and REALM_KEY not in (
> select REALM_KEY from sakai_realm
> where REALM_ID in ('/site/~admin','/site/!admin')
> )

We ran into the same issue and did essentially the same thing
with SOAP and Perl; I avoid updating the database directly when possible.
I can post the script if you like.

--
Reinier Post
TU Eindhoven