Grouper Users - Open Discussion List

["Hyzer, Chris" <>]

Have you analyzed your tables and rebuilt your indexes?  Do you do this automatically periodically?  I think its not the cache that is taking a long time, its the query to the group subject source

Thanks,

Chris

---

From: <> on behalf of Jim Fox <>
Sent: Monday, August 27, 2018 4:50:04 PM
To:
Subject: [grouper-users] cache does not respond for 20 seconds

 

I'm having cache issues with grouper 2.3
This is version 2.3 with patches to 100 or so.  I haven't edited the cache properties files.

I put a group, with admin info and etc

I try to read the group and get lookup the admins: by
SubjectFinder.findByIdentifier('some_id')

The log shows we get to here quickly:

    2018-08-27 13:30:56,673: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG SourcesXmlResolver$LogLabelCallable.call(174) -  - findByIdentifier on source: g:gsa, 'gws.cac.washington.edu', time in millis: 10
    2018-08-27 13:30:56,674: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG SourcesXmlResolver$LogLabelCallable.call(174) -  - findByIdentifier on source: uwpds, 'gws.cac.washington.edu', time in millis: 1
    2018-08-27 13:30:56,675: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG Hib3MemberDAO.membersFlashCacheRetrieveBySubjectId(1029) -  - retrieving from member flash cache by subjectId: uwpds, d9459cae21d011d4abd00004ac494ffe

Then this right away:

    2018-08-27 13:30:56,675: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG HibernateSession.<init>(288) -  - HibernateSession.<init>() line 288, HibernateSession._internal_hibernateSession() line 468, HibernateSession.callbackHibernateSession() line 660, ByHqlStatic.list() line 407, ByHqlStatic.listSet() line 458, Hib3GroupDAO.findAllGroupsSecureHelper() line 3351, Hib3GroupDAO.getAllGroupsSecure() line 3895, GroupFinder.findGroups() line 1180, GrouperSourceAdapter.callback() line 288, GrouperSession.callbackGrouperSession() line 974, GrouperSourceAdapter.getSubjectsByIdentifiers() line 272, GrouperSourceAdapter.getSubjectByIdentifier() line 378, SourcesXmlResolver.callLogic() line 387, SourcesXmlResolver.callLogic() line 384, SourcesXmlResolver.call() line 169, SourcesXmlResolver.executeCallables() line 230, SourcesXmlResolver.findByIdentifier() line 393, CachingResolver.findByIdentifier() line 191, ValidatingResolver.findByIdentifier() line 160, SubjectFinder.findByIdentifier() li!
 ne 1088, SubjectFinder.findByIdentifier() line 697

and

    2018-08-27 13:30:56,676: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG HibernateSession.<init>(289) -  - grouperTransactionType: READONLY_OR_USE_EXISTING, okToUseHibernate: true, readonlyMode: false, parentSessionExists: false, newHibernateSession: true, immediateGrouperTransactionTypeUsed: READONLY_NEW, immediateGrouperTransactionTypeReadonly: true, hibernateSession: HibernateSession (1e4e29ae): new, readonly, READONLY_NEW, notActiveTransaction, session (4fa2c92c)


Then, a full 20 seconds later:

    2018-08-27 13:31:16,608: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG ByHql.list(446) -  - returnType: Group, hibernateSession: HibernateSession (1e4e29ae): new, readonly, READONLY_NEW, notActiveTransaction, session (4fa2c92c), foundSize: 0
    2018-08-27 13:31:16,610: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG HibernateSession.callbackHibernateSession(716) -  - HibernateSession.callbackHibernateSession() line 716, ByHqlStatic.list() line 407, ByHqlStatic.listSet() line 458, Hib3GroupDAO.findAllGroupsSecureHelper() line 3351, Hib3GroupDAO.getAllGroupsSecure() line 3895, GroupFinder.findGroups() line 1180, GrouperSourceAdapter.callback() line 288, GrouperSession.callbackGrouperSession() line 974, GrouperSourceAdapter.getSubjectsByIdentifiers() line 272, GrouperSourceAdapter.getSubjectByIdentifier() line 378, SourcesXmlResolver.callLogic() line 387, SourcesXmlResolver.callLogic() line 384, SourcesXmlResolver.call() line 169, SourcesXmlResolver.executeCallables() line 230, SourcesXmlResolver.findByIdentifier() line 393, CachingResolver.findByIdentifier() line 191, ValidatingResolver.findByIdentifier() line 160, SubjectFinder.findByIdentifier() line 1088, SubjectFinder.findByIdentifier() line 697
    2018-08-27 13:31:16,611: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG HibernateSession.callbackHibernateSession(717) -  - grouperTransactionType: READONLY_OR_USE_EXISTING, auditControl: WILL_NOT_AUDIT, hibernateSession: HibernateSession (1e4e29ae): new, readonly, READONLY_NEW, notActiveTransaction, session (4fa2c92c), hibernateSessionsInThreadLocal: 1e4e29ae, willCreateAudit: false, createdContext: false, closedSession: true
    2018-08-27 13:31:16,611: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG GrouperSession.callbackGrouperSession(986) -  - Stack: GrouperSession.callbackGrouperSession() line 986, GrouperSourceAdapter.getSubjectsByIdentifiers() line 272, GrouperSourceAdapter.getSubjectByIdentifier() line 378, SourcesXmlResolver.callLogic() line 387, SourcesXmlResolver.callLogic() line 384, SourcesXmlResolver.call() line 169, SourcesXmlResolver.executeCallables() line 230, SourcesXmlResolver.findByIdentifier() line 393, CachingResolver.findByIdentifier() line 191, ValidatingResolver.findByIdentifier() line 160, SubjectFinder.findByIdentifier() line 1088, SubjectFinder.findByIdentifier() line 697
    2018-08-27 13:31:16,612: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG GrouperSession.callbackGrouperSession(987) -  - {method=callbackGrouperSession(), hash=821691446, subject=d9459cae21d011d4abd00004ac494ffe, start_staticSession=d9459cae21d011d4abd00004ac494ffe, start_staticSessions=0, needsToBeRemoved=true, postAdd_staticSession=d9459cae21d011d4abd00004ac494ffe, postAdd_staticSessions_0=d9459cae21d011d4abd00004ac494ffe, end_staticSession=d9459cae21d011d4abd00004ac494ffe, end_staticSessions=0}
    2018-08-27 13:31:16,612: [ajp-nio-127.0.0.1-8009-exec-7] DEBUG SourcesXmlResolver$LogLabelCallable.call(174) -  - findByIdentifier on source: grouperEntities, 'gws.cac.washington.edu', time in millis: 19937

Note the 19937 milliseconds.

How can I stop this?
Can I disable cache while I'm trying to fix it?

Thanks,
Jim