Why is my dbxquery command running so slowly?

[billycote]

I'm running just a very simple query to test out my connection to a database. I'm using Splunk Enterprise Version 6.6.2 with version 3.1 of splunk DB Connect. I can't get the simplest of queries to return in a timely manner from the search bar.

my query string looks like this :

|| dbxquery query="select 1 from DUAL;" connection="dipit_snow" and my timeframe is last 15 minutes though I'm not sure why that would matter

pretty simple. but it's taking
This search has completed and has returned 1 results by scanning 0 events in 31.798 seconds
to complete with the majority of the time (29.65 seconds in command.dbxquery according to the logs)

I can provide the detailed logs as well. I'm using ojdbc7 driver but I've also tried 6 and 8 with the same results.

I'm getting worse results with any larger queries.

From the log

08-16-2017 16:22:23.063 ERROR ChunkedExternProcessor - stderr: 16:22:23.062 603@vc2coma1275125n.fmr.com [main] WARN com.splunk.dbx.message.MessageEnum - action=initialize_resource_bundle_files error=Can't find bundle for base name Messages, locale en_US
08-16-2017 16:22:23.658 ERROR ChunkedExternProcessor - stderr: 16:22:23.656 603@vc2coma1275125n.fmr.com [main] INFO c.s.d.s.driver.DriverServiceImpl - action=register_driver driver=oracle.jdbc.OracleDriver 12.1 succeeded
08-16-2017 16:22:23.658 ERROR ChunkedExternProcessor - stderr: 16:22:23.656 603@vc2coma1275125n.fmr.com [main] INFO c.s.d.s.driver.DriverServiceImpl - action=load_drivers spent 91 ms to rescan all jdbc drivers
08-16-2017 16:22:23.668 ERROR ChunkedExternProcessor - stderr: 16:22:23.667 603@vc2coma1275125n.fmr.com [main] INFO c.s.dbx.connector.ConnectorFactory - action=collect_connection_pool_metrics interval_in_seconds=60

[RasmusToelhoej]

Hi we have the same issue with all queries, for example: '| dbxquery query="select 1;" connection="mysql_test"'.
It affects all databases, have tried against MySQL and MSSQL, all queries takes 6-8 seconds minimum, making the dbxquery unusable for real-time queries against the database.

The time is spend in the following when we select Inspect Job:
Total: 8.656 seconds
1.68s command.dbxquery
0.78s dispatch.optimize.FinalEval
2.12 dispatch.optimize.matchReportAcceleration
1.58 dispatch.optimize.toJson

All the dispatch.optimize steps where introduced in Splunk 6.5 and can be removed with "| noop search_optimization=false | dbxquery ..." before your search.

But there still is a 1.6 - 2.0 second delay in the dbxquery which we will investigate, the SQL only takes 0.02 seconds to execute.
Hope the '| noop search_optimization=false' can help with your queries, if not, try to Inspect the Job and send where the time is spend.

Will try to create a bug report with Splunk, looks like the dbxquery got slow after 6.5 and after DB Connect changed to a Java backend that processes the SQL queries.

[justinatpnnl]

This one is a little old, but wanted to add my +1. We noticed that DBXQuery commands that had a subsearch were much faster than those that used the normal syntax. Apparently having the subsearch disables the search optimization steps. Using the command @RasmusToelhoej provided to disable search optimization shaved three seconds off of our query and took it from 4.7 seconds to 1.7. Thanks!

| noop search_optimization=false
| dbxquery connection="test" query="select * from table"

[billycote]

I will certainly give it a try! Thanks for the suggestion and I'll let you know what comes of it

[RasmusToelhoej]

Hi billycote I think I found the reason.

Time spend in command.dbxquery and dispatch.evaluate.dbxquery is time where Splunk waits for a Java process to launch and return the data. (Defined in Splunk\etc\apps\splunk_app_db_connect\default\commands.conf)

Each dbxquery search spawns an Java process which has to load .jar files and 80MB memory heap, it's very heavy, I have seen 1 customer where it took 12 seconds to launch the Java process. (Application monitoring tools that does Java byte-code instrumentation during Java process launch can also slow it down, like Instana, dynaTrace, New Relic, AppDynamics, so check if they are installed on the Splunk server)

You can test how fast the process launches by running: (Windows)
cd C:\Program Files\Splunk\etc\apps\splunk_app_db_connect\bin
"C:\Program Files\Splunk\etc\apps\splunk_app_db_connect\windows_x86_64\bin\command.bat" -Dlogback.configurationFile=../config/command_logback.xml -DDBX_COMMAND_LOG_LEVEL=INFO -cp ../jars/command.jar com.splunk.dbx.command.DbxQueryCommand

It should output something immediately, and process monitor should show java.exe with 80MB memory loaded.

A simple dashboard with 4x dbxquery queries results in 4x Java processes being spawned, which consumes 300~400 MB memory. This happens everytime the dashboard is loaded.

I will try to create my own MSSQL app that runs the queries via Python, should be much faster, without all the overhead of Java processes launching. Looks to me like DB Connect isn't usefull for doing live queries, where you want the results in under 2-5 seconds.

[billycote]

Hi Rasmus. Thank you for taking the time to respond. That could very well be part of the problem. I don't have any other java instrumentation on the system. I'm running on LINUX so i can't run that command but I'll see if I can find the LINUX equivalent.

It seems that db connect might not be useful at all if it can't do relatively quick queries of the database.