grouper_ddl is slow due to selecting * from every table/view

On Wed, May 25, 2016 at 05:32:15AM +0000, Hyzer, Chris wrote:
>Can you run jstack on the process id and see where it is hung (after waiting a bit so it makes progress)? Send the output along. It should generate a script, not sure why it isnt. What database / version are you using? How many groups/memberships do you have?
>
>Thanks
>Chris

Hi Chris,

We're using MySQL, with a version that reports as:
"5.5.49-enterprise-commercial-advanced-log"

I ran counts on the grouper_groups and grouper_memberships:
select count from grouper_groups;
312137
select count from grouper_memberships;
2618119

I let the the gsh -registry -check run for a few hrs, and ran jstack on it.
This was the output:

=====
2016-05-25 15:22:57
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.92-b14 mixed mode):

"Attach Listener" #24 daemon prio=9 os_prio=0 tid=0x00007ff03c00c800 nid=0x62c3 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"net.sf.hibernate.cache.UpdateTimestampsCache.data" #23 daemon prio=5 os_prio=0 tid=0x00007ff064ae9000 nid=0x5ee5 waiting on condition [0x00007ff041867000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)

• parking to wait for <0x00000000e2077558> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  at java.lang.Thread.run(Thread.java:745)

"org.hibernate.cache.UpdateTimestampsCache.data" #22 daemon prio=5 os_prio=0 tid=0x00007ff064b15000 nid=0x5ee4 waiting on condition [0x00007ff041968000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)

• parking to wait for <0x00000000e20777b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  at java.lang.Thread.run(Thread.java:745)

"net.sf.ehcache.CacheManager@328cf0e1" #21 daemon prio=5 os_prio=0 tid=0x00007ff064aeb000 nid=0x5ee3 in Object.wait() [0x00007ff041a69000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

• waiting on <0x00000000e2077a20> (a java.util.TaskQueue)
  at java.lang.Object.wait(Object.java:502)
  at java.util.TimerThread.mainLoop(Timer.java:526)
• locked <0x00000000e2077a20> (a java.util.TaskQueue)
  at java.util.TimerThread.run(Timer.java:505)

"MySQL Statement Cancellation Timer" #20 daemon prio=5 os_prio=0 tid=0x00007ff034074000 nid=0x5ee2 in Object.wait() [0x00007ff041d6a000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

• waiting on <0x00000000e1d99930> (a java.util.TaskQueue)
  at java.lang.Object.wait(Object.java:502)
  at java.util.TimerThread.mainLoop(Timer.java:526)
• locked <0x00000000e1d99930> (a java.util.TaskQueue)
  at java.util.TimerThread.run(Timer.java:505)

"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2" #19 daemon prio=5 os_prio=0 tid=0x00007ff064a90000 nid=0x5ee1 in Object.wait() [0x00007ff041e6b000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:534)

• locked <0x00000000e1d99ad8> (a com.mchange.v2.async.ThreadPoolAsynchronousRunner)

"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1" #18 daemon prio=5 os_prio=0 tid=0x00007ff064a93800 nid=0x5ee0 in Object.wait() [0x00007ff041f6c000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:534)

• locked <0x00000000e1d99ad8> (a com.mchange.v2.async.ThreadPoolAsynchronousRunner)

"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0" #17 daemon prio=5 os_prio=0 tid=0x00007ff064aa9000 nid=0x5edf in Object.wait() [0x00007ff04206d000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:534)

• locked <0x00000000e1d99ad8> (a com.mchange.v2.async.ThreadPoolAsynchronousRunner)

"Timer-1" #16 daemon prio=5 os_prio=0 tid=0x00007ff064aa6000 nid=0x5ede in Object.wait() [0x00007ff04216e000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.util.TimerThread.mainLoop(Timer.java:552)

• locked <0x00000000e1d99fb8> (a java.util.TaskQueue)
  at java.util.TimerThread.run(Timer.java:505)

"net.sf.hibernate.cache.UpdateTimestampsCache.data" #14 daemon prio=5 os_prio=0 tid=0x00007ff064674000 nid=0x5edd waiting on condition [0x00007ff054ffe000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)

• parking to wait for <0x00000000e15aef40> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  at java.lang.Thread.run(Thread.java:745)

"org.hibernate.cache.UpdateTimestampsCache.data" #13 daemon prio=5 os_prio=0 tid=0x00007ff064677000 nid=0x5edc waiting on condition [0x00007ff068181000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)

• parking to wait for <0x00000000e15af1a0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
  at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  at java.lang.Thread.run(Thread.java:745)

"net.sf.ehcache.CacheManager@64cd705f" #12 daemon prio=5 os_prio=0 tid=0x00007ff0646a7000 nid=0x5edb in Object.wait() [0x00007ff068282000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

• waiting on <0x00000000e15af408> (a java.util.TaskQueue)
  at java.lang.Object.wait(Object.java:502)
  at java.util.TimerThread.mainLoop(Timer.java:526)
• locked <0x00000000e15af408> (a java.util.TaskQueue)
  at java.util.TimerThread.run(Timer.java:505)

"Timer-0" #8 daemon prio=5 os_prio=0 tid=0x00007ff064597800 nid=0x5ed4 in Object.wait() [0x00007ff068a9b000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.util.TimerThread.mainLoop(Timer.java:552)

• locked <0x00000000e11ff4c8> (a java.util.TaskQueue)
  at java.util.TimerThread.run(Timer.java:505)

"Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007ff0640bd000 nid=0x5ed2 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007ff0640b2000 nid=0x5ed1 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007ff0640af800 nid=0x5ed0 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007ff0640ae000 nid=0x5ecf runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007ff06407b000 nid=0x5ece in Object.wait() [0x00007ff069bbc000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

• waiting on <0x00000000e0e67000> (a java.lang.ref.ReferenceQueue$Lock)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
• locked <0x00000000e0e67000> (a java.lang.ref.ReferenceQueue$Lock)
  at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
  at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007ff064076800 nid=0x5ecd in Object.wait() [0x00007ff069cbd000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

• waiting on <0x00000000e0e671b8> (a java.lang.ref.Reference$Lock)
  at java.lang.Object.wait(Object.java:502)
  at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
• locked <0x00000000e0e671b8> (a java.lang.ref.Reference$Lock)
  at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=0 tid=0x00007ff06400a800 nid=0x5ecb runnable [0x00007ff06d73d000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)

• locked <0x00000000d12f1360> (a com.mysql.jdbc.util.ReadAheadInputStream)
  at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1994)
  at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2411)
  at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2916)
  at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1631)
  at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1723)
  at com.mysql.jdbc.Connection.execSQL(Connection.java:3283)
• locked <0x00000000d12edbe8> (a java.lang.Object)
  at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1332)
  at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1467)
• locked <0x00000000d12edbe8> (a java.lang.Object)
  at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
  at edu.internet2.middleware.grouper.hibernate.BySqlStatic$2.callback(BySqlStatic.java:158)
  at edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:687)
  at edu.internet2.middleware.grouper.hibernate.BySqlStatic.select(BySqlStatic.java:141)
  at edu.internet2.middleware.grouper.hibernate.BySqlStatic.select(BySqlStatic.java:126)
  at edu.internet2.middleware.grouper.ddl.GrouperDdlUtils.assertTablesThere(GrouperDdlUtils.java:2543)
  at edu.internet2.middleware.grouper.ddl.GrouperDdlUtils.ddlutilsDropViewIfExists(GrouperDdlUtils.java:1524)
  at edu.internet2.middleware.grouper.ddl.GrouperDdl.dropAllViews(GrouperDdl.java:2720)
  at edu.internet2.middleware.grouper.ddl.GrouperDdlUtils.bootstrapHelper(GrouperDdlUtils.java:554)
  at edu.internet2.middleware.grouper.registry.RegistryInitializeSchema.main(RegistryInitializeSchema.java:172)
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:498)
  at edu.internet2.middleware.grouper.app.gsh.GrouperShell.handleSpecialCase(GrouperShell.java:204)
  at edu.internet2.middleware.grouper.app.gsh.GrouperShell.main(GrouperShell.java:144)
  at edu.internet2.middleware.grouper.app.gsh.GrouperShellWrapper.main(GrouperShellWrapper.java:31)

"VM Thread" os_prio=0 tid=0x00007ff06406f000 nid=0x5ecc runnable

"VM Periodic Task Thread" os_prio=0 tid=0x00007ff0640c0800 nid=0x5ed3 waiting on condition

JNI global references: 278
=====

>----Original Message----
>From: grouper-users-request On Behalf Of Baron Fujimoto
>Sent: Tuesday, May 24, 2016 11:01 PM
>To: Grouper Users
>Subject: [grouper-users] grouper registry upgrade 2.1.5 -> 2.2.2 problems
>
>I'm trying to upgrade a grouper 2.1.5 registry to 2.2.2
>using the procedure described on this wiki page:
>
><https://spaces.internet2.edu/display/Grouper/v2.2+Upgrade+Instructions+from+v2.1>
>
>When I point an configure a 2.2.2 api to use the 2.1.5 registry and run
>"gsh -registry -check". It just hangs after confirming that I want to
>schemaexport all tables. The api error log contains the following errors:
>
>2016-05-24 16:37:31,350: [main] WARN GrouperStartup.printConfigOnce(167) - - Grouper starting up: version: 2.2.2, build date: null, env: grouper-test
>[...]
>2016-05-24 16:37:37,260: [main] ERROR JDBCExceptionReporter.logExceptions(234) - - Unknown column 'stem0_.id_index' in 'field list'
>2016-05-24 16:37:37,645: [main] ERROR JDBCExceptionReporter.logExceptions(234) - - Field 'grouptype_uuid' doesn't have a default value
>2016-05-24 16:37:37,645: [main] ERROR Field$1.callback(1063) - - unable to add field: groupAttrReaders: Problem in HibernateSession: HibernateSession (2e52fb3e): notNew, notReadonly, READ_WRITE_NEW, activeTransaction, session (d176a31),
>2016-05-24 16:37:37,726: [main] ERROR JDBCExceptionReporter.logExceptions(234) - - Unknown column 'stem0_.id_index' in 'field list'
>2016-05-24 16:37:37,726: [main] ERROR GroupType$5.callback(873) - - unable to add type: grouperLoader: Problem find stem by name: 'etc:legacy:attribute', Problem in HibernateSession: HibernateSession (67dba613): notNew, notReadonly, READ_WRITE_NEW, activeTransaction, session (ecfbe91),
>2016-05-24 16:37:46,699: [main] ERROR GrouperDdlUtils.bootstrapHelper(474) - - Grouper ddl object type 'Grouper' has dbVersion: 26 and java version: 29
>
>Any suggestions?
>--
>Baron Fujimoto :: UH Information Technology Services
>minutas cantorum, minutas balorum, minutas carboratum desendus pantorum

–
Baron Fujimoto :: UH Information Technology Services
minutas cantorum, minutas balorum, minutas carboratum desendus pantorum