Idea Details

Enhancement Request: Wildfly Datasources - Enable Share Prepared Statement

Last activity 27 days ago
Alan Baugher's profile image
07-22-2019 11:49 AM

OBSERVATION(S):

1- OOTB Wildfly datasource configurations for the CA Identity Manager r14.1 do NOT leverage the two (2) configurations for SQL pre-prepared statements.   
2- Use of the JDBC SPY feature we can observe the use of these SQL statements.
3 - Enable Wildfly parameter(s): share-prepared-statements has a markable improvement on performance.
4.  Use of the Wildfly parameter  track-statement shows that CA Identity Manager has "unclosed statements"  - Per RHEL tech note, this is a possible impact to performance.  

REF:   

https://access.redhat.com/solutions/492513

https://access.redhat.com/solutions/2464751



REQUEST(2):     

1- Create/Update Tech Note on the use of prepared statement parameter in Wildfly data sources.   

2-  Request follow up on the "unclosed statements" challenge per RHEL tech note.

3- Enable the prepared statement with new installations/virtual appliance.


Example to enable Wildfly feature:

/subsystem=datasources/data-source=iam_im-imtaskpersistencedb-ds:write-attribute(name=prepared-statements-cache-size,value=25)
/subsystem=datasources/data-source=iam_im-imtaskpersistencedb-ds:write-attribute(name=share-prepared-statements, value=true)
/subsystem=datasources/data-source=iam_im-imobjectstoredb-ds:write-attribute(name=prepared-statements-cache-size,value=25)
/subsystem=datasources/data-source=iam_im-imobjectstoredb-ds:write-attribute(name=share-prepared-statements, value=true)


Example to monitor the CA Identity Manager JDBC calls including prepared-statements.


connect
:take-snapshot
batch
/subsystem=logging/periodic-rotating-file-handler=im_jdbc_debug:add(file={"path"=>"im_jdbc_debug.log", "relative-to"=>"jboss.server.log.dir"}, suffix=".yyyy.MM.dd", level=DEBUG, append=true, autoflush=fals
e, suffix=".yyyy-MM-dd-HH", formatter="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n")
/subsystem=datasources/data-source=iam_im-imobjectstoredb-ds/:write-attribute(name=spy,value=true)
/subsystem=datasources/data-source=iam_im-imtaskpersistencedb-ds/:write-attribute(name=spy,value=true)
/subsystem=logging/logger=jboss.jdbc.spy/:add(handlers=["im_jdbc_debug"], level=TRACE, use-parent-handlers=false)
run-batch
:reload





Cheers,

Alan Baugher



Comments

28 days ago

Per RHEL community note:

<track-statements/> is a debugging feature: it checks that all statements are closed when the connection is returned to the pool: remember to disable it in production environment.

This statement may be interpreted for both "true" and "NOWARN" values

28 days ago

Follow-up:   

https://access.redhat.com/solutions/40841

Use of the following:

/subsystem=datasources/data-source=iam_im-imtaskpersistencedb-ds/:write-attribute(name=track-statements,value=true)

/subsystem=datasources/data-source=iam_im-imobjectstoredb-ds/:write-attribute(name=track-statements,value=true)


Allows Wildfly to report the following WARNING message(s):

16:10:56,407 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE

These "unclosed connection" appear to have a performance impact.


During the startup of the CA Identity Manager, monitor of the OS (object store) and TP (task persistence) shows over 1100 connections with this warning message.






16:10:54,738 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:54,745 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:54,754 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:54,758 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:54,812 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:54,818 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:55,117 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:55,121 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:55,127 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:55,132 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:55,138 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:55,142 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:55,146 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:56,177 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:56,207 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:56,273 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:56,386 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
16:10:56,407 WARN [org.jboss.jca.adapters.jdbc.WrappedConnection] (MSC service thread 1-8) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE
root@vapp0001 VAPP-14.1.0 (192.168.242.146):/opt/CA/wildfly-idm/standalone/log > grep -i "Closing a statement you left open," wildfly-console.log | wc -l
1192


#############

Monitor the startup performance:

16:10:30,355 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 1 : Attempting to start ServiceLocator.
16:10:31,322 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 2 : Attempting to start PolicyServerService
16:10:31,355 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 3 : Attempting to start ServerCommandService
16:10:31,429 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 4 : Attempting to start EnvironmentService
16:10:53,339 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 5 : Attempting to start SecretKeyStore
16:10:53,441 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 6 : Attempting to start CacheManagerService
16:10:53,444 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 7 : Attempting to load global plugins.
16:10:53,444 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 8 : Attempting to start AdaptersConfigService
16:10:53,447 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 9 : Attempting to start EmailProviderService
16:10:53,451 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 10 : Attempting to start AuditProviderService
16:10:53,458 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 11 : Attempting to start RuntimeStatusDetailService
16:10:53,476 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 12 : Attempting to start PasswordService
16:10:53,476 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 13 : Attempting to start LogicalAttributeService
16:10:53,479 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 14 : Attempting to start BLTHService
16:10:53,479 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 15 : Attempting to start ParticipantResolverService
16:10:53,479 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 16 : Attempting to start NotificationRuleService
16:10:53,479 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 17 : Attempting to start EventAdapterService
16:10:53,479 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 18 : Attempting to start TaskService
16:10:53,487 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 19 : Attempting to start WorkflowCallbackService
16:10:53,490 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 20 : Attempting to start WorkflowService
16:10:53,494 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 21 : Attempting to start TaskStatusNotifyService
16:10:53,497 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 22 : Attempting to start EventService
16:10:53,542 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 23 : Attempting to start AdminService
16:10:53,543 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 24 : Attempting to start GeneralMonitorAdmin
16:10:53,544 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 25 : Attempting to start StatusNotificationService
16:10:53,558 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 26 : Attempting to start GlobalInitializer plug-ins
16:10:54,087 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 27 : Attempting to start SchedulerService
16:10:54,265 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 28 : Attempting to start NIMSMIntegrationService
16:10:54,275 INFO [ims.Main] (MSC service thread 1-8) * Startup Step 29 : Attempting to start environments


​With the value changed from NOWARN to false for OS/TP DB:

root@vapp0001 VAPP-14.1.0 (192.168.242.146):/opt/CA/wildfly-idm/standalone/log > grep -i step im_step4_debug.log
16:23:42,633 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 1 : Attempting to start ServiceLocator.
16:23:43,483 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 2 : Attempting to start PolicyServerService
16:23:43,515 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 3 : Attempting to start ServerCommandService
16:23:43,579 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 4 : Attempting to start EnvironmentService
16:23:59,245 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 5 : Attempting to start SecretKeyStore
16:23:59,327 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 6 : Attempting to start CacheManagerService
16:23:59,330 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 7 : Attempting to load global plugins.
16:23:59,330 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 8 : Attempting to start AdaptersConfigService
16:23:59,332 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 9 : Attempting to start EmailProviderService
16:23:59,336 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 10 : Attempting to start AuditProviderService
16:23:59,344 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 11 : Attempting to start RuntimeStatusDetailService
16:23:59,360 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 12 : Attempting to start PasswordService
16:23:59,360 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 13 : Attempting to start LogicalAttributeService
16:23:59,362 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 14 : Attempting to start BLTHService
16:23:59,362 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 15 : Attempting to start ParticipantResolverService
16:23:59,363 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 16 : Attempting to start NotificationRuleService
16:23:59,363 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 17 : Attempting to start EventAdapterService
16:23:59,363 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 18 : Attempting to start TaskService
16:23:59,369 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 19 : Attempting to start WorkflowCallbackService
16:23:59,372 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 20 : Attempting to start WorkflowService
16:23:59,376 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 21 : Attempting to start TaskStatusNotifyService
16:23:59,377 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 22 : Attempting to start EventService
16:23:59,423 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 23 : Attempting to start AdminService
16:23:59,425 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 24 : Attempting to start GeneralMonitorAdmin
16:23:59,426 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 25 : Attempting to start StatusNotificationService
16:23:59,439 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 26 : Attempting to start GlobalInitializer plug-ins
16:23:59,824 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 27 : Attempting to start SchedulerService
16:23:59,966 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 28 : Attempting to start NIMSMIntegrationService
16:23:59,978 INFO [ims.Main] (MSC service thread 1-9) * Startup Step 29 : Attempting to start environments


#################     Same for all six (6) DB ###########
​​root@vapp0001 VAPP-14.1.0 (192.168.242.146):/opt/CA/wildfly-idm/standalone/log > start_im
Starting WildFly (IDM): [ OK ]
root@vapp0001 VAPP-14.1.0 (192.168.242.146):/opt/CA/wildfly-idm/standalone/log > grep -i step im_step4_debug.log
16:42:07,206 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 1 : Attempting to start ServiceLocator.
16:42:08,203 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 2 : Attempting to start PolicyServerService
16:42:08,235 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 3 : Attempting to start ServerCommandService
16:42:08,302 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 4 : Attempting to start EnvironmentService
16:42:25,539 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 5 : Attempting to start SecretKeyStore
16:42:25,651 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 6 : Attempting to start CacheManagerService
16:42:25,654 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 7 : Attempting to load global plugins.
16:42:25,654 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 8 : Attempting to start AdaptersConfigService
16:42:25,657 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 9 : Attempting to start EmailProviderService
16:42:25,661 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 10 : Attempting to start AuditProviderService
16:42:25,671 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 11 : Attempting to start RuntimeStatusDetailService
16:42:25,690 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 12 : Attempting to start PasswordService
16:42:25,690 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 13 : Attempting to start LogicalAttributeService
16:42:25,692 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 14 : Attempting to start BLTHService
16:42:25,693 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 15 : Attempting to start ParticipantResolverService
16:42:25,693 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 16 : Attempting to start NotificationRuleService
16:42:25,693 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 17 : Attempting to start EventAdapterService
16:42:25,693 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 18 : Attempting to start TaskService
16:42:25,699 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 19 : Attempting to start WorkflowCallbackService
16:42:25,701 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 20 : Attempting to start WorkflowService
16:42:25,705 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 21 : Attempting to start TaskStatusNotifyService
16:42:25,706 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 22 : Attempting to start EventService
16:42:25,750 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 23 : Attempting to start AdminService
16:42:25,752 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 24 : Attempting to start GeneralMonitorAdmin
16:42:25,753 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 25 : Attempting to start StatusNotificationService
16:42:25,766 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 26 : Attempting to start GlobalInitializer plug-ins
16:42:26,311 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 27 : Attempting to start SchedulerService
16:42:26,463 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 28 : Attempting to start NIMSMIntegrationService
16:42:26,474 INFO [ims.Main] (MSC service thread 1-12) * Startup Step 29 : Attempting to start environments


Testing for any errors with this new configuration:

config@vapp0001 VAPP-14.1.0 (192.168.242.146):~ > cat jdbc.cli
connect
:take-snapshot
batch
/subsystem=datasources/data-source=iam_im-imobjectstoredb-ds:write-attribute(name=prepared-statements-cache-size,value=25)
/subsystem=datasources/data-source=iam_im-imobjectstoredb-ds:write-attribute(name=share-prepared-statements, value=true)
/subsystem=datasources/data-source=iam_im-imobjectstoredb-ds/:write-attribute(name=idle-timeout-minutes,value=1)
/subsystem=datasources/data-source=iam_im-imobjectstoredb-ds/:write-attribute(name=flush-strategy,value=IdleConnections)
/subsystem=datasources/data-source=iam_im-imobjectstoredb-ds/:write-attribute(name=track-statements,value=false)

/subsystem=datasources/data-source=iam_im-imtaskpersistencedb-ds/:write-attribute(name=prepared-statements-cache-size,value=25)
/subsystem=datasources/data-source=iam_im-imtaskpersistencedb-ds/:write-attribute(name=share-prepared-statements,value=true)
/subsystem=datasources/data-source=iam_im-imtaskpersistencedb-ds/:write-attribute(name=idle-timeout-minutes,value=1)
/subsystem=datasources/data-source=iam_im-imtaskpersistencedb-ds/:write-attribute(name=flush-strategy,value=IdleConnections)
/subsystem=datasources/data-source=iam_im-imtaskpersistencedb-ds/:write-attribute(name=track-statements,value=false)

/subsystem=datasources/data-source=iam_im-imworkflowdb-ds/:write-attribute(name=prepared-statements-cache-size,value=25)
/subsystem=datasources/data-source=iam_im-imworkflowdb-ds/:write-attribute(name=share-prepared-statements,value=true)
/subsystem=datasources/data-source=iam_im-imworkflowdb-ds/:write-attribute(name=idle-timeout-minutes,value=1)
/subsystem=datasources/data-source=iam_im-imworkflowdb-ds/:write-attribute(name=flush-strategy,value=IdleConnections)
/subsystem=datasources/data-source=iam_im-imworkflowdb-ds/:write-attribute(name=track-statements,value=false)

/subsystem=datasources/data-source=iam_im-imarchivedb-ds/:write-attribute(name=prepared-statements-cache-size,value=25)
/subsystem=datasources/data-source=iam_im-imarchivedb-ds/:write-attribute(name=share-prepared-statements,value=true)
/subsystem=datasources/data-source=iam_im-imarchivedb-ds/:write-attribute(name=idle-timeout-minutes,value=1)
/subsystem=datasources/data-source=iam_im-imarchivedb-ds/:write-attribute(name=flush-strategy,value=IdleConnections)
/subsystem=datasources/data-source=iam_im-imarchivedb-ds/:write-attribute(name=track-statements,value=false)

/subsystem=datasources/data-source=iam_im-imauditdb-ds:write-attribute(name=prepared-statements-cache-size,value=25)
/subsystem=datasources/data-source=iam_im-imauditdb-ds:write-attribute(name=share-prepared-statements,value=true)
/subsystem=datasources/data-source=iam_im-imauditdb-ds:write-attribute(name=idle-timeout-minutes,value=1)
/subsystem=datasources/data-source=iam_im-imauditdb-ds:write-attribute(name=flush-strategy,value=IdleConnections)
/subsystem=datasources/data-source=iam_im-imauditdb-ds:write-attribute(name=track-statements,value=false)

/subsystem=datasources/data-source=iam_im-imreportsnapshotdb-ds/:write-attribute(name=prepared-statements-cache-size,value=25)
/subsystem=datasources/data-source=iam_im-imreportsnapshotdb-ds/:write-attribute(name=share-prepared-statements,value=true)
/subsystem=datasources/data-source=iam_im-imreportsnapshotdb-ds/:write-attribute(name=idle-timeout-minutes,value=1)
/subsystem=datasources/data-source=iam_im-imreportsnapshotdb-ds/:write-attribute(name=flush-strategy,value=IdleConnections)
/subsystem=datasources/data-source=iam_im-imreportsnapshotdb-ds/:write-attribute(name=track-statements,value=false)
run-batch
:reload


/opt/CA/wildfly-idm/bin/jboss-cli.sh --connect --user=jboss-admin --password=Password01! --file=jdbc.cli


########   IMPORTANT NOTE  ###########
If jdbc connections are NOT closed correctly, and the token​​ 

track-statements,value=false

will cause memory issues with the database, e.g. ORA-01034 ORACLE Not Available &  ORA-27102 out of memory

and the server

Linux-x86_64  Error: 12:  Cannot allocate memory.