JDBC driver query takes too long due to MapHandler process

Hi all,

 

IDM 4.8.6 with JDBC 4.2.1.0 connector.

 

This is a triggered driver receiving events from three different tables throughout the same direct_process table. Connector does a lot of back searches (using token-query or token-src-attr command). Sometimes the query executes in close to 50ms, that I think is fine:

[09/23/24 22:04:14.215]:IDDB2IDC PT:                BEGIN Handle QUERY.
[09/23/24 22:04:14.215]:IDDB2IDC PT:                BEGIN Interpret initial query.
[09/23/24 22:04:14.216]:IDDB2IDC PT:                Have association.
[09/23/24 22:04:14.217]:IDDB2IDC PT:                Scope:  entry
[09/23/24 22:04:14.217]:IDDB2IDC PT:                END   Interpret initial query.
[09/23/24 22:04:14.218]:IDDB2IDC PT:                select column1, column2 from database.tablewhere column1 = ?
[09/23/24 22:04:14.219]:IDDB2IDC PT:                BEGIN Instantiate prepared statement.
[09/23/24 22:04:14.220]:IDDB2IDC PT:                	Allocating statement from connection 6a5afe2c.
[09/23/24 22:04:14.221]:IDDB2IDC PT:                	Allocated  statement SELECT COLUMN1, COLUMN2 FROM DATABASE.TABLEWHERE COLUMN1 = ?.
[09/23/24 22:04:14.222]:IDDB2IDC PT:                END   Instantiate prepared statement.
[09/23/24 22:04:14.223]:IDDB2IDC PT:                	IN  @ index  1, field 'COLUMN1', value = 38047
[09/23/24 22:04:14.224]:IDDB2IDC PT:                	Allocated result set 5b4473e4 from statement select column1, column2from database.tablewhere column1 = ?.
[09/23/24 22:04:14.226]:IDDB2IDC PT:                	RS  field ‘tablekey’, length: 11, value = '012345678901'
[09/23/24 22:04:14.227]:IDDB2IDC PT:                	Closed    result set 5b4473e4.
[09/23/24 22:04:14.227]:IDDB2IDC PT:                Closed     statement select column1, column2 from database.table where column1 = ?.
[09/23/24 22:04:14.229]:IDDB2IDC PT:                END   Handle QUERY.
[09/23/24 22:04:14.229]:IDDB2IDC PT:                Number of statements allocated on connection 'dedicated1':  1.
[09/23/24 22:04:14.230]:IDDB2IDC PT:                Publisher shim returned:

But, most frequently, the process took 5, 10 or more seconds due a MapImpl process (not database query itself):

[09/23/24 22:03:07.681]:IDDB2IDC PT:                        BEGIN Handle QUERY.
[09/23/24 22:03:07.682]:IDDB2IDC PT:                        BEGIN Interpret initial query.
[09/23/24 22:03:07.683]:IDDB2IDC PT:                        Base object:  schema
[09/23/24 22:03:07.683]:IDDB2IDC PT:                        Scope:  subtree
[09/23/24 22:03:07.684]:IDDB2IDC PT:                        END   Interpret initial query.
[09/23/24 22:03:07.684]:IDDB2IDC PT:                        select column1 from database.table where column2= ? order by column1
[09/23/24 22:03:07.686]:IDDB2IDC PT:                        BEGIN Instantiate prepared statement.
[09/23/24 22:03:07.686]:IDDB2IDC PT:                        	Allocating statement from connection 6a5afe2c.
[09/23/24 22:03:07.687]:IDDB2IDC PT:                        	Allocated  statement SELECT COLUMN1 FROM DATABASE.TABLE WHERE COLUMN2= ? ORDER BY COLUMN1.
[09/23/24 22:03:07.688]:IDDB2IDC PT:                        END   Instantiate prepared statement.
[09/23/24 22:03:07.689]:IDDB2IDC PT:                        	IN  @ index  1, field ‘tablekey’, length: 11, value = '012345678901'
[09/23/24 22:03:07.696]:IDDB2IDC PT:                        	Allocated result set 38cced83 from statement select column1 from database.table where column2= ? order by column1.
[09/23/24 22:03:07.697]:IDDB2IDC PT:                        Query 1727139787684 will expire at 2024-09-23 22:03:07.684.
[09/23/24 22:03:07.699]:IDDB2IDC PT:                        MapHandler: Instance of MapImpl not found. Instantiating...
[09/23/24 22:03:07.699]:IDDB2IDC PT:                        MapHandler: Instantiated MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1727139787684$0'.
[09/23/24 22:03:07.701]:IDDB2IDC PT:                        MapImpl: Opening MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1727139787684$0'.
[09/23/24 22:03:07.705]:IDDB2IDC PT:                        MapImpl: Opened MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1727139787684$0' with handle '3447353616'.
[09/23/24 22:03:10.320]:IDDB2IDC PT:                        MapHandler: Instance of MapImpl not found. Instantiating...
[09/23/24 22:03:10.321]:IDDB2IDC PT:                        MapHandler: Instantiated MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1727139787684$1'.
[09/23/24 22:03:10.322]:IDDB2IDC PT:                        MapImpl: Opening MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1727139787684$1'.
[09/23/24 22:03:10.327]:IDDB2IDC PT:                        MapImpl: Opened MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1727139787684$1' with handle '4064463920'.
[09/23/24 22:03:12.795]:IDDB2IDC PT:                        	RS  @ index  1, field 'COLUMN1', value = 31040
[09/23/24 22:03:12.797]:IDDB2IDC PT:                        	Closed    result set 38cced83.
[09/23/24 22:03:12.797]:IDDB2IDC PT:                        Closed     statement select column1 from database.table where column2= ? order by column1.
[09/23/24 22:03:12.800]:IDDB2IDC PT:                        Have no more query results.
[09/23/24 22:03:12.801]:IDDB2IDC PT:                        BEGIN query cleanup
[09/23/24 22:03:12.802]:IDDB2IDC PT:                        	Removed query state for query 1727139787684.
[09/23/24 22:03:12.803]:IDDB2IDC PT:                        	Did NOT delete persistent structures for query 1727139787684.
[09/23/24 22:03:12.804]:IDDB2IDC PT:                        END   query cleanup
[09/23/24 22:03:12.805]:IDDB2IDC PT:                        END   Handle QUERY.
[09/23/24 22:03:12.806]:IDDB2IDC PT:                        Number of statements allocated on connection 'dedicated1':  1.
[09/23/24 22:03:12.807]:IDDB2IDC PT:                        Publisher shim returned:

Is there a way to disable this process or better solution? I think this is related to the zoomDB (Am I right?) that is useless in this case.

Best wishes,

Alexandre

  • 0  

    Hello,

    To my understanding, ZoomDB is used a middle layer to "speed" things up - so that you are not forced to query the database directly - as you see, the "speed up" does not always work.

    You do have the option to use embedded SQL instead of nouns: https://www.netiq.com/documentation/identity-manager-49-drivers/jdbc/data/embed-sql-statements-in-xds-events-for-jdbc-driver.html and https://www.netiq.com/documentation/identity-manager-49-drivers/jdbc/data/how-sql-queries-work-in-jdbc-driver.html

    But time wise, I do not think it would be helping you much.

    This is interesting:

    [09/23/24 22:03:07.705]:IDDB2IDC PT:                        MapImpl: Opened MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1727139787684$0' with handle '3447353616'.
    [09/23/24 22:03:10.320]:IDDB2IDC PT:                        MapHandler: Instance of MapImpl not found. Instantiating...

    Here it looks to me that it thinks that MapImpl has been opened, and then discover (3 seconds later) that this is not the case. And then spends another 2 seconds on opening it (instantiate the interface).

    Why it closes the connection to ZoomDB I do not know, but it could be a timing issue or a memory issue. Memory could be tight, and therefor the garbage collector causes this. I really do not know.

  • 0 in reply to   

    Hi cpedersen,

     

    Thanks for your answer. Embedded SQL is not a option due to this note:

     

    The queries on the Publisher channel with srcCommandProcessor are scheduled for execution on the Subscriber channel and the script processing does not wait for the result to become available.

     

    Updating driver shim to version 4.2.2.0400 apparently resolves some bugs related to performance issues. We are monitoring and return in a couple of weeks

  • 0 in reply to 

    Hi, the issue apparently was solved after patch application. But still having some delay (close to 200ms) on zoomdb activities. Is this expected?

    [10/23/24 09:07:26.771]:IDDB2IDC PT: MapImpl: Deleting MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1729685246624$1'.
    [10/23/24 09:07:26.964]:IDDB2IDC PT: MapImpl: Deleted MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1729685246624$1' with handle '2569927040'.
    [10/23/24 09:07:26.965]:IDDB2IDC PT: MapHandler: Closing MapHandler 'com.microfocus.database.zoomdb.hashmap.HashMapHandler@1729685246624$1'.
    [10/23/24 09:07:26.966]:IDDB2IDC PT: MapImpl: MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1729685246624$1' is already in closed state. Nothing to do.
    [10/23/24 09:07:26.967]:IDDB2IDC PT: MapImpl: Deleting MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1729685246624$0'.
    [10/23/24 09:07:27.160]:IDDB2IDC PT: MapImpl: Deleted MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1729685246624$0' with handle '2535202160'.
    [10/23/24 09:07:27.162]:IDDB2IDC PT: MapHandler: Closing MapHandler 'com.microfocus.database.zoomdb.hashmap.HashMapHandler@1729685246624$0'.
    [10/23/24 09:07:27.163]:IDDB2IDC PT: MapImpl: MapImpl 'com.microfocus.database.zoomdb.hashmap.HashMapImpl@1729685246624$0' is already in closed state. Nothing to do.
    [10/23/24 09:07:27.164]:IDDB2IDC PT: END Handle QUERY.
    [10/23/24 09:07:27.165]:IDDB2IDC PT: Number of statements allocated on connection 'dedicated1': 1.