Group 2.3 Function (UI button) --> View Audit Log SQL timeout

Chris,

 

I can inform you that for my search dropping the audit type id produced one more row being returned.

"Added attribute assignment"

 

So as long as the UI can display a row like that. ( or the other audit type id values) then I think that is a good solution. Seeing when attributes are assigned (and which was assigned) would seem like a good thing to see too.

–

Carey Matthew Black.123@osu.edu

 

(EDIT: I forgot to explicitly say: * The query performed well. ( < 1 second ) * )

 

----Original Message----

From: Hyzer, Chris <mchyzer@isc.upenn.edu>

Sent: Friday, April 20, 2018 4:27 PM

To: Black, Carey M. <black.123@osu.edu>; 

Subject: RE: Group 2.3 Function (UI button) --> View Audit Log SQL timeout

 

Add a jira please, when searching for uuids we don't need use audit_type_id at all, unless someone wants to debate that with me    This will be a quick fix...

 

Can you see if the query is fast without audit type id?

 

WHERE  (

this_.string04 = '3574b587e41b46f19c2787ade9ab09ca' OR

this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' OR

this_.string01 = '3574b587e41b46f19c2787ade9ab09ca' OR

this_.string06 = '3574b587e41b46f19c2787ade9ab09ca' OR

this_.string03 = '3574b587e41b46f19c2787ade9ab09ca')

 

Thanks!

Chris

 

----Original Message----

From: Black, Carey M.

Sent: Friday, April 20, 2018 4:01 PM

Subject: [grouper-core] Group 2.3 Function (UI button) --> View Audit Log SQL timeout

 

I think this is a bug / enchantment request. So let me describe what I see and what I think I know....

 

Env:  Grouper 2.3 on MariaDb ( Version: '10.2.14-MariaDB-log')

                Special note: " There is one other thing that might be of interest - it has a custom setting of optimizer_search_depth=0" REF: https://mariadb.com/resources/blog/setting-optimizer-search-depth-mysql

 However I don't think that setting is causing the issue.

grouper_audit_entry ( table) has 48 M rows right now. ( not even a full years' worth of an audit.)

  

When I use the UI, view a group and use the Function (UI button) --> View Audit Log

  The UI "hangs"... and eventually "times out".

 

I dropped down to the DB and watched the "process list" and was able to capture the SQL that was running.

 When I run that SQL "by hand" ... it takes... forever... ( I have not actually waited long enough for it to finish... But I have waited for an hour...)

 

However, I spoke with a more knowledgeable "not a DBA" person about the query and they suggested something interesting to try... and the query dropped to less than a second to finish!

 

 

Grouper generated SQL (formatted for readability instead of a single very long line...) "

SELECT this_.id                       AS id1_10_0_,

       this_.hibernate_version_number AS hibernat2_10_0_,

       this_.act_as_member_id         AS act_as_m3_10_0_,

       this_.audit_type_id            AS audit_ty4_10_0_,

       this_.context_id               AS context_5_10_0_,

       this_.created_on               AS created_6_10_0_,

       this_.description              AS descript7_10_0_,

       this_.env_name                 AS env_name8_10_0_,

       this_.grouper_engine           AS grouper_9_10_0_,

       this_.grouper_version          AS grouper10_10_0_,

       this_.int01                    AS int11_10_0_,

       this_.int02                    AS int12_10_0_,

       this_.int03                    AS int13_10_0_,

       this_.int04                    AS int14_10_0_,

       this_.int05                    AS int15_10_0_,

       this_.last_updated             AS last_up16_10_0_,

       this_.logged_in_member_id      AS logged_17_10_0_,

       this_.server_host              AS server_18_10_0_,

       this_.string01                 AS string19_10_0_,

       this_.string02                 AS string20_10_0_,

       this_.string03                 AS string21_10_0_,

       this_.string04                 AS string22_10_0_,

       this_.string05                 AS string23_10_0_,

       this_.string06                 AS string24_10_0_,

       this_.string07                 AS string25_10_0_,

       this_.string08                 AS string26_10_0_,

       this_.duration_microseconds    AS duratio27_10_0_,

       this_.query_count              AS query_c28_10_0_,

       this_.user_ip_address          AS user_ip29_10_0_,

       this_.server_user_name         AS server_30_10_0_

FROM   grouper_audit_entry this_

WHERE  (

        ( this_.audit_type_id = 'b51cc1fa35e74e9c91042c2b77951695' AND this_.string04 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = '43c9e640be604bfcbe3501a094329381' AND this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'd743e9e2cf484f909707f45e692a7143' AND this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'c84718a7d6ed486a8ec729119a414e48' AND this_.string01 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = '6850d73f0cdc4b769e738df4321c1c7c' AND this_.string04 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = '7d1806d5d17f46ecb222901ad6f2bcde' AND this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'c9d6606c5cc34e93aca63c7673bf3db7' AND this_.string04 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'b68b2c7742a34acebc5216b29605da56' AND this_.string04 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = '78d1dc004f624e1cb2e3b000d55fb739' AND this_.string04 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'c5ed9cd3208a487187c22e788c5d252f' AND this_.string01 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = '78d1dc004f624e1cb2e3b000d55fb739' AND this_.string06 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'b51cc1fa35e74e9c91042c2b77951695' AND this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = '43c9e640be604bfcbe3501a094329381' AND this_.string04 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = '6850d73f0cdc4b769e738df4321c1c7c' AND this_.string06 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'c6169fb1308547a6b23bd8f83429e934' AND this_.string01 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'b68b2c7742a34acebc5216b29605da56' AND this_.string06 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'c9d6606c5cc34e93aca63c7673bf3db7' AND this_.string06 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = '7c90939f260a4c4ba13b521ac456f3cb' AND this_.string01 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = '7d1806d5d17f46ecb222901ad6f2bcde' AND this_.string06 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'cf7260265907443bbdb02314d9ce2ffc' AND this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'c5ed9cd3208a487187c22e788c5d252f' AND this_.string03 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = '4432fe9a76b74d818595e60c7d17a3b8' AND this_.string01 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'cd273399dd9944e09d132b5bb3f9e0e9' AND this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'b3812b8c15b5421db52cfd4af1ee5817' AND this_.string04 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'f487688c07ee40f7beee911d51ead17c' AND this_.string01 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'b68b2c7742a34acebc5216b29605da56' AND this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'cf7260265907443bbdb02314d9ce2ffc' AND this_.string04 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'f33ae045bd284dbc9a7e965dba1dccf5' AND this_.string01 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'b3812b8c15b5421db52cfd4af1ee5817' AND this_.string06 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = '6f5a24dee4c34f8e8b4a77dddf814f0c' AND this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'c9d6606c5cc34e93aca63c7673bf3db7' AND this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'a0ec507ee6f14cf587e3a513c4217c43' AND this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = 'bbec1c063df04e949fbffbd1fc5f2f39' AND this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' )

          OR ( this_.audit_type_id = '7d1806d5d17f46ecb222901ad6f2bcde' AND this_.string04 = '3574b587e41b46f19c2787ade9ab09ca' )

        )

ORDER  BY this_.last_updated DESC

LIMIT  50

"

 

 

 

However, if that where clause is rearranged to ( our improved version ) :

"

WHERE  (

this_.string04 = '3574b587e41b46f19c2787ade9ab09ca' OR

this_.string02 = '3574b587e41b46f19c2787ade9ab09ca' OR

this_.string01 = '3574b587e41b46f19c2787ade9ab09ca' OR

this_.string06 = '3574b587e41b46f19c2787ade9ab09ca' OR

this_.string03 = '3574b587e41b46f19c2787ade9ab09ca')

AND

       ( ( this_.audit_type_id = 'b51cc1fa35e74e9c91042c2b77951695'  )

          OR ( this_.audit_type_id = '43c9e640be604bfcbe3501a094329381'   )

          OR ( this_.audit_type_id = 'd743e9e2cf484f909707f45e692a7143'   )

          OR ( this_.audit_type_id = 'c84718a7d6ed486a8ec729119a414e48'   )

          OR ( this_.audit_type_id = '6850d73f0cdc4b769e738df4321c1c7c'   )

          OR ( this_.audit_type_id = '7d1806d5d17f46ecb222901ad6f2bcde'   )

          OR ( this_.audit_type_id = 'c9d6606c5cc34e93aca63c7673bf3db7'   )

          OR ( this_.audit_type_id = 'b68b2c7742a34acebc5216b29605da56'   )

          OR ( this_.audit_type_id = '78d1dc004f624e1cb2e3b000d55fb739'   )

          OR ( this_.audit_type_id = 'c5ed9cd3208a487187c22e788c5d252f'   )

          OR ( this_.audit_type_id = '78d1dc004f624e1cb2e3b000d55fb739'   )

          OR ( this_.audit_type_id = 'b51cc1fa35e74e9c91042c2b77951695'   )

          OR ( this_.audit_type_id = '43c9e640be604bfcbe3501a094329381'   )

          OR ( this_.audit_type_id = '6850d73f0cdc4b769e738df4321c1c7c'   )

          OR ( this_.audit_type_id = 'c6169fb1308547a6b23bd8f83429e934'   )

          OR ( this_.audit_type_id = 'b68b2c7742a34acebc5216b29605da56'   )

          OR ( this_.audit_type_id = 'c9d6606c5cc34e93aca63c7673bf3db7'   )

          OR ( this_.audit_type_id = '7c90939f260a4c4ba13b521ac456f3cb'   )

          OR ( this_.audit_type_id = '7d1806d5d17f46ecb222901ad6f2bcde'   )

          OR ( this_.audit_type_id = 'cf7260265907443bbdb02314d9ce2ffc'   )

          OR ( this_.audit_type_id = 'c5ed9cd3208a487187c22e788c5d252f'   )

          OR ( this_.audit_type_id = '4432fe9a76b74d818595e60c7d17a3b8'   )

          OR ( this_.audit_type_id = 'cd273399dd9944e09d132b5bb3f9e0e9'   )

          OR ( this_.audit_type_id = 'b3812b8c15b5421db52cfd4af1ee5817'   )

          OR ( this_.audit_type_id = 'f487688c07ee40f7beee911d51ead17c'   )

          OR ( this_.audit_type_id = 'b68b2c7742a34acebc5216b29605da56'   )

          OR ( this_.audit_type_id = 'cf7260265907443bbdb02314d9ce2ffc'   )

          OR ( this_.audit_type_id = 'f33ae045bd284dbc9a7e965dba1dccf5'   )

          OR ( this_.audit_type_id = 'b3812b8c15b5421db52cfd4af1ee5817'   )

          OR ( this_.audit_type_id = '6f5a24dee4c34f8e8b4a77dddf814f0c'   )

          OR ( this_.audit_type_id = 'c9d6606c5cc34e93aca63c7673bf3db7'  )

          OR ( this_.audit_type_id = 'a0ec507ee6f14cf587e3a513c4217c43'   )

          OR ( this_.audit_type_id = 'bbec1c063df04e949fbffbd1fc5f2f39'  )

          OR ( this_.audit_type_id = '7d1806d5d17f46ecb222901ad6f2bcde'  )

        )

"

NOTE: The " this_.audit_type_id " part does have some dups in it. So it could be even shorter...

NOTE: I understand that the select is not strictly "identical". ( technically) However, the audit_type_id  value appears to be a foreign  key from grouper_audit_type.

                I think the general idea of the select is to show all of the  audit_type_id (values of interest) for the (in this case) "Group ID" that gets stuffed into the various String* columns.

( Why the groupID ends up in various columns... I don't know.. but I will assume there is a good reason for that .... variety.)

 

With this where clause the query returned in less than 100 ms !

 

So I am not sure where that query is constructed, or how to start to track it down... but I think it should be "reordered" so that it can work at scale. 

–

Carey Matthew Black.123@osu.edu