DBConnect errors and performance

[damucka]

Hello,

I am suffering massively from the performance of the DBConnect, it has a severe impact on our dashboards as they rely on the SQL accesses. I tried to analyze it, shooting the simplest possible SQL against the database:

select now() from dummy

I created the java program using the same jDBC driver the Splunk does and executing the above SQL 100 times against the link textdatabase. The results were:

Number of repetitions: 100
Average Time to establish jDBC connection (ms): 165
Average Time to execute the SQL Query over jDBC (ms): 19

This means I am getting the response back on average in 165 + 19 = 184 ms.
Now, when I get with the same SQL over dbxquery, it consistently takes 2.2 seconds. I understand Splunk has to do more, authorizations, roles check and so on, but this is here a disaster for me ... I have many tiny SQLs and Splunk adds per default a lead time of 2 sec to each of them.

I checked the search.log of the dbxquery and there are some error entries there and they seem to cost quite some time:

...
01-27-2020 16:05:50.624 INFO  ChunkedExternProcessor - Running process: /opt/splunk/etc/apps/splunk_app_db_connect/linux_x86_64/bin/command.sh -Dlogback.configurationFile\=../config/command_logback.xml -DDBX_COMMAND_LOG_LEVEL\=TRACE -cp ../jars/command.jar com.splunk.dbx.command.DbxQueryCommand
01-27-2020 16:05:51.091 ERROR ChunkedExternProcessor - stderr: 16:05:51.089 48877@mo-7ee963859.zone1.mo.sap.corp [main] DEBUG c.splunk.dbx.command.DbxQueryCommand - action=exec_dbxquery_command args={}
01-27-2020 16:05:51.466 ERROR ChunkedExternProcessor - stderr: 16:05:51.465 48877@mo-7ee963859.zone1.mo.sap.corp [main] INFO  c.splunk.dbx.utils.TrustManagerUtil - action=load_key_manager_succeed
01-27-2020 16:05:51.636 INFO  ChunkedExternProcessor - Custom search command is a generating command.
...

and then

...
01-27-2020 16:05:51.654 ERROR ChunkedExternProcessor - stderr: 16:05:51.653 48877@mo-7ee963859.zone1.mo.sap.corp [main] WARN  com.splunk.dbx.message.MessageEnum - action=initialize_resource_bundle_files error=Can't find bundle for base name Messages, locale en_US
01-27-2020 16:05:51.707 ERROR ChunkedExternProcessor - stderr: 16:05:51.707 48877@mo-7ee963859.zone1.mo.sap.corp [main] DEBUG c.splunk.dbx.command.DbxQueryCommand - action=retrieve_connection_information search_info={args: [query=select now() from dummy, connection=HANA_MLBSO], rawArgs: [query="select now() from dummy", connection="HANA_MLBSO"], dispatchDir: /opt/splunk/var/run/splunk/dispatch/1580137550.796828, sid: 1580137550.796828, app: mlbso, owner: d038423, username: d038423, sessionKey: s0pV3CBFKvMS2krzSV74eeT3ZPX8dVbrQKFcisalfv6xdFOKGZeZHycnc6ZFlIiriflU1MB_qHYelAg0rD340BiBpBU2tTJqfmXGpjU^t5tY8vpk6Jq^nX7i4io^Ni2E, splunkdUri: https://127.0.0.1:8089, splunkVersion: 7.0.0, search: %7C%20noop%20search_optimization%3Dfalse%7C%20dbxquery%20query%3D%22select%20now%28%29%20from%20dummy%22%20connection%3D%22HANA_MLBSO%22, command: dbxquery, earliestTime: 1579532400, latestTime: 1580137550, maxResultRows: 50000}
01-27-2020 16:05:52.380 ERROR ChunkedExternProcessor - stderr: 16:05:52.380 48877@mo-7ee963859.zone1.mo.sap.corp [main] DEBUG com.splunk.dbx.crypto.Credentials - action=decrypt_data secret_path=/opt/splunk/etc/apps/splunk_app_db_connect/certs/identity.dat
01-27-2020 16:05:52.395 ERROR ChunkedExternProcessor - stderr: 16:05:52.394 48877@mo-7ee963859.zone1.mo.sap.corp [main] DEBUG c.splunk.dbx.command.DbxQueryCommand - action=connection_loaded connection=ConnectionConf{connectionType='hana', defaultDatabase='123', host='10.67.50.9', jdbcUrlFormat='jdbc:sap://:/', jdbcUrlSSLFormat='null', jdbcUseSSL=false, port=30241, serviceClass='null', jdbcDriverClass='com.sap.db.jdbc.Driver', testQuery='null', isolationLevel='null', readonly=false, identityName='HANA_MLBSO', identity=DotConfBase{title='HANA_MLBSO', disabled=false}, useConnectionPool=true, fetchSize=5000, maxConnLifetimeMillis=1800000, maxWaitMillis=30000, minIdle=1, maxTotalConn=8, idleTimeout=600000, timezone=CET, connectionProperties='null'}
01-27-2020 16:05:52.456 ERROR ChunkedExternProcessor - stderr: 16:05:52.456 48877@mo-7ee963859.zone1.mo.sap.corp [main] INFO  c.s.d.s.driver.DriverServiceImpl - action=register_driver driver=com.sap.db.jdbc.Driver 2.3 succeeded
01-27-2020 16:05:52.456 ERROR ChunkedExternProcessor - stderr: 16:05:52.456 48877@mo-7ee963859.zone1.mo.sap.corp [main] INFO  c.s.d.s.driver.DriverServiceImpl - action=load_drivers spent 51 ms to rescan all jdbc drivers
01-27-2020 16:05:52.503 ERROR ChunkedExternProcessor - stderr: 16:05:52.502 48877@mo-7ee963859.zone1.mo.sap.corp [main] INFO  c.s.dbx.connector.ConnectorFactory - action=collect_connection_pool_metrics interval_in_seconds=60
01-27-2020 16:05:52.510 ERROR ChunkedExternProcessor - stderr: 16:05:52.510 48877@mo-7ee963859.zone1.mo.sap.corp [main] DEBUG c.s.dbx.connector.ConnectorFactory - action=database_connection_established connection=HANA_MLBSO jdbc_url=jdbc:sap://10.67.50.9:30241/ user=ITOA_ADMIN is_pooled=false number_of_connection_pools=0
01-27-2020 16:05:52.757 ERROR ChunkedExternProcessor - stderr: 16:05:52.757 48877@mo-7ee963859.zone1.mo.sap.corp [main] DEBUG c.s.d.c.utils.JdbcConnectorFactory - action=create_connector_by_name class=com.splunk.dbx.connector.connector.impl.JdbcConnectorImpl
01-27-2020 16:05:52.760 ERROR ChunkedExternProcessor - stderr: 16:05:52.759 48877@mo-7ee963859.zone1.mo.sap.corp [main] DEBUG c.splunk.dbx.command.DbxQueryCommand - action=exec_common_query_without_paramtype connection=HANA_MLBSO query=select now() from dummy max_rows=100000 fetch_size=5000 time_out=600 params=null
01-27-2020 16:05:52.760 ERROR ChunkedExternProcessor - stderr: 16:05:52.760 48877@mo-7ee963859.zone1.mo.sap.corp [main] DEBUG c.s.d.c.c.impl.JdbcConnectorImpl - action=connector_executes_query sql='select now() from dummy' args=null limit=100000 fetch_size=5000
01-27-2020 16:05:52.812 INFO  UserManager - Unwound user context: d038423 -> NULL
...

Please find a full search log in the attachment.

Is there a chance that I configured anything wrongly there (java, DBConnect) and this is the reason for the above errors and the bad performance?
The SQL results from several databases are coming correctly though and also the health check for the dbconnect are green.

Please advise.

[SinghK]

Ok it seems like some misconfiguration but let's check it. 

Are you able to run the query form th hf where you have installed dbconnect from UI? Or dbconnect ui from anywhere else and can get an output without errors? There is an option ui under inputs to run the query and it should run succesfully from there itself.

[bknumb]

Hi @SinghK 

Thank you for your reply. I've figured it out. We upgraded openjdk on splunk servers and the old driver is not compatible with new version. After downgraded the openjdk it seems to work now.

However, sometimes the query return non-zero error code 9. Do you know what that error code mean? I can't find the document about DBX's error code

Thanks!

[SinghK]

I dont think there is any error code list for that.

But if  I can the logs with error code may be i can help. 

[SinghK]

I dont think this is from Db connect you should check with DBA if they have some return codes defined in DB.

[bknumb]

@damucka 

I used splunk db connect 3.2.0 and faced same your problem.

Is there any update on this issue?