Uploaded image for project: 'Grouper'
  1. Grouper
  2. GRP-1308

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

    XMLWordPrintable

    Details

      Description

      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

        Smart Checklist

          Attachments

            Activity

              People

              Assignee:
              chris.hyzer@at.internet2.edu Chris Hyzer (upenn.edu)
              Reporter:
              chris.hyzer@at.internet2.edu Chris Hyzer (upenn.edu)
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: