To troubleshoot a Splunk DB Connect 3 performance issue, I have a Splunk free instance installed on my local PC, with DB connect 3 installed as well.
running search | dbxquery connection=BPM_devcert query="select 1 from DUAL;"
and it took about 7 seconds. Do not know what will cause the query to be so slow?
Duration (seconds) Component Invocations Input count Output count
0.59 command.dbxquery 1 - 1
0.00 dispatch.createdSearchResultInfrastructure 1 - -
1.34 dispatch.evaluate.dbxquery 2 - -
0.00 dispatch.finalWriteToDisk 1 - -
0.00 dispatch.preview.snapshot 1 - -
0.08 dispatch.writeStatus 3 - -
0.16 startup.configuration 2 - -
1.03 startup.handoff 2 - -
canSummarize None
createTime 2018-12-11T14:44:03.000-06:00
cursorTime 1969-12-31T18:00:00.000-06:00
custom
{ [-]
dispatch.earliest_time: -24h@h
dispatch.latest_time: now
dispatch.sample_ratio: 1
display.general.type: statistics
display.page.search.mode: smart
display.page.search.tab: statistics
search: | dbxquery connection=BPM_devcert query="select 1 from DUAL;"
workload_pool:
}
defaultSaveTTL 604800
defaultTTL 600
delegate None
diskUsage 69632
dispatchState DONE
doneProgress 1
dropCount None
eai:acl
{ [-]
app: search
can_write: true
modifiable: true
owner: admin
perms: { [+]
}
sharing: global
ttl: 600
}
earliestTime 2018-12-10T14:00:00.000-06:00
eventAvailableCount None
eventCount None
eventFieldCount None
eventIsStreaming true
eventIsTruncated None
eventSearch None
eventSorting none
isBatchModeSearch None
isDone true
isEventsPreviewEnabled None
isFailed None
isFinalized None
isPaused None
isPreviewEnabled true
isRealTimeSearch None
isRemoteTimeline None
isSaved None
isSavedSearch None
isTimeCursored None
isZombie None
keywords None
label None
latestTime 2018-12-11T14:44:02.000-06:00
modifiedTime 2018-12-11T15:09:40.586-06:00
normalizedSearch None
numPreviews 1
optimizedSearch | dbxquery connection=BPM_devcert query="select 1 from DUAL;"
phase0 None
phase1 dbxquery connection=BPM_devcert query="select 1 from DUAL;"
pid 28836
priority 5
provenance UI:Search
remoteSearch None
reportSearch dbxquery connection=BPM_devcert query="select 1 from DUAL;"
request
{ [-]
adhoc_search_level: smart
auto_cancel: 30
check_risky_command: false
custom.dispatch.earliest_time: -24h@h
custom.dispatch.latest_time: now
custom.dispatch.sample_ratio: 1
custom.display.general.type: statistics
custom.display.page.search.mode: smart
custom.display.page.search.tab: statistics
custom.search: | dbxquery connection=BPM_devcert query="select 1 from DUAL;"
custom.workload_pool:
earliest_time: -24h@h
indexedRealtime:
latest_time: now
preview: 1
provenance: UI:Search
rf: *
sample_ratio: 1
search: | dbxquery connection=BPM_devcert query="select 1 from DUAL;"
status_buckets: 300
ui_dispatch_app: search
workload_pool:
}
resultCount 1
resultIsStreaming None
resultPreviewCount 1
runDuration 6.969
runtime
{ [-]
auto_cancel: 30
auto_pause: 0
}
sampleRatio 1
sampleSeed 0
scanCount None
search | dbxquery connection=BPM_devcert query="select 1 from DUAL;"
searchCanBeEventType None
searchEarliestTime 1544472000
searchLatestTime 1544561042
searchProviders
[
]
searchTotalBucketsCount None
searchTotalEliminatedBucketsCount None
sid 1544561042.707
statusBuckets 300
ttl 599
workload_pool None
Additional info
timeline
search.log
I removed ojdbc6.jar and it cleaned the log little bit without much performance impact.
12-13-2018 14:59:01.786 INFO dispatchRunner - search context: user="thunder_wu", app="search", bs-pathname="C:\Program Files\Splunk\etc"
12-13-2018 14:59:01.789 INFO SearchParser - PARSING: | dbxquery connection=Realtime query="select 1 from DUAL;"
12-13-2018 14:59:01.792 INFO SearchParser - PARSING: | dbxquery connection=Realtime query="select 1 from DUAL;"
12-13-2018 14:59:01.792 INFO SearchParser - PARSING: | dbxquery connection=Realtime query="select 1 from DUAL;"
12-13-2018 14:59:01.792 INFO dispatchRunner - Executing the Search orchestrator and iterator model (dfs=0).
12-13-2018 14:59:01.793 INFO SearchOrchestrator - SearchOrchestrator getting constructed
12-13-2018 14:59:01.793 INFO SearchOrchestrator - Initialized the SRI
12-13-2018 14:59:01.793 INFO ISplunkDispatch - Not running in splunkd. Bundle replication not triggered.
12-13-2018 14:59:01.793 INFO SearchOrchestrator - Initialzing the run time settings for the orchestrator.
12-13-2018 14:59:01.793 INFO UserManager - Setting user context: thunder_wu
12-13-2018 14:59:01.793 INFO UserManager - Done setting user context: NULL -> thunder_wu
12-13-2018 14:59:01.793 INFO SearchOrchestrator - Creating the search DAG.
12-13-2018 14:59:01.793 INFO SearchParser - PARSING: | dbxquery connection=Realtime query="select 1 from DUAL;"
12-13-2018 14:59:01.806 INFO ChunkedExternProcessor - Running process: "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
12-13-2018 14:59:01.825 ERROR ChunkedExternProcessor - stderr: The system cannot find the file specified.
12-13-2018 14:59:02.344 ERROR ChunkedExternProcessor - stderr: 14:59:02.341 14048@W1835906 [main] INFO c.splunk.dbx.utils.TrustManagerUtil - action=load_key_manager_succeed
12-13-2018 14:59:02.431 INFO ChunkedExternProcessor - Custom search command is a generating command.
12-13-2018 14:59:02.431 INFO DispatchThread - BatchMode: allowBatchMode: 1, conf(1): 1, timeline/Status buckets(0):0, realtime(0):0, report pipe empty(0):0, reqTimeOrder(0):0, summarize(0):0, statefulStreaming(0):0
12-13-2018 14:59:02.431 INFO DispatchThread - required fields list to add to remote search =
12-13-2018 14:59:02.431 INFO DispatchCommandProcessor - summaryHash=NS3d9d854163f8f07a summaryId=92AEC8C6-1713-4938-B895-2A465856DC0D_search_thunder_wu_NS3d9d854163f8f07a remoteSearch=
12-13-2018 14:59:02.477 ERROR ChunkedExternProcessor - stderr: 14:59:02.438 14048@W1835906 [main] WARN com.splunk.dbx.message.MessageEnum - action=initialize_resource_bundle_files error=Can't find bundle for base name Messages, locale en_US
12-13-2018 14:59:03.497 ERROR ChunkedExternProcessor - stderr: 14:59:03.094 14048@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=register_driver driver=oracle.jdbc.OracleDriver 12.2 succeeded
12-13-2018 14:59:03.497 ERROR ChunkedExternProcessor - stderr: 14:59:03.094 14048@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=load_drivers spent 72 ms to rescan all jdbc drivers
studying above log I have some observation:
This is the search log. Looks like it detects more than one version of jdbc driver, and caused some re-scan attempt. Also got some error like "stderr: The system cannot find the file specified."
12-12-2018 20:42:20.286 INFO SearchOrchestrator - Creating the search DAG.
12-12-2018 20:42:20.286 INFO SearchParser - PARSING: | dbxquery connection=Realtime query="select 1 from DUAL;"
12-12-2018 20:42:20.299 INFO ChunkedExternProcessor - Running process: "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
12-12-2018 20:42:20.319 ERROR ChunkedExternProcessor - stderr: The system cannot find the file specified.
12-12-2018 20:42:20.837 ERROR ChunkedExternProcessor - stderr: 20:42:20.829 10636@W1835906 [main] INFO c.splunk.dbx.utils.TrustManagerUtil - action=load_key_manager_succeed
12-12-2018 20:42:20.916 INFO ChunkedExternProcessor - Custom search command is a generating command.
12-12-2018 20:42:20.917 INFO DispatchThread - BatchMode: allowBatchMode: 1, conf(1): 1, timeline/Status buckets(0):0, realtime(0):0, report pipe empty(0):0, reqTimeOrder(0):0, summarize(0):0, statefulStreaming(0):0
12-12-2018 20:42:20.917 INFO DispatchThread - required fields list to add to remote search =
12-12-2018 20:42:20.917 INFO DispatchCommandProcessor - summaryHash=NS3d9d854163f8f07a summaryId=92AEC8C6-1713-4938-B895-2A465856DC0D_search_thunder_wu_NS3d9d854163f8f07a remoteSearch=
12-12-2018 20:42:20.971 ERROR ChunkedExternProcessor - stderr: 20:42:20.924 10636@W1835906 [main] WARN com.splunk.dbx.message.MessageEnum - action=initialize_resource_bundle_files error=Can't find bundle for base name Messages, locale en_US
12-12-2018 20:42:21.990 ERROR ChunkedExternProcessor - stderr: 20:42:21.593 10636@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=load_drivers multiple version drivers exist, 2 drivers found.
12-12-2018 20:42:21.990 ERROR ChunkedExternProcessor - stderr: 20:42:21.593 10636@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - driver name is com.splunk.dbx.service.driver.DelegatingDriver, select version 12.2, loaded from file ojdbc8.jar
12-12-2018 20:42:21.990 ERROR ChunkedExternProcessor - stderr: 20:42:21.595 10636@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=register_driver driver=oracle.jdbc.OracleDriver 12.2 succeeded
12-12-2018 20:42:21.990 ERROR ChunkedExternProcessor - stderr: 20:42:21.595 10636@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=load_drivers spent 93 ms to rescan all jdbc drivers
12-12-2018 20:42:21.990 ERROR ChunkedExternProcessor - stderr: 20:42:21.660 10636@W1835906 [main] INFO c.s.dbx.connector.ConnectorFactory - action=collect_connection_pool_metrics interval_in_seconds=60
12-12-2018 20:42:23.010 INFO SearchParser - PARSING: | dbxquery connection=Realtime query="select 1 from DUAL;"
12-12-2018 20:42:23.011 INFO ChunkedExternProcessor - Running process: "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
12-12-2018 20:42:23.030 ERROR ChunkedExternProcessor - stderr: The system cannot find the file specified.
12-12-2018 20:42:23.549 ERROR ChunkedExternProcessor - stderr: 20:42:23.516 11756@W1835906 [main] INFO c.splunk.dbx.utils.TrustManagerUtil - action=load_key_manager_succeed
12-12-2018 20:42:23.603 INFO ChunkedExternProcessor - Custom search command is a generating command.
12-12-2018 20:42:23.604 INFO AstOptimizer - SrchOptMetrics optimize_toJson=0.594
12-12-2018 20:42:23.618 ERROR ChunkedExternProcessor - stderr: 20:42:23.611 11756@W1835906 [main] WARN com.splunk.dbx.message.MessageEnum - action=initialize_resource_bundle_files error=Can't find bundle for base name Messages, locale en_US
12-12-2018 20:42:24.637 ERROR ChunkedExternProcessor - stderr: 20:42:24.241 11756@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=load_drivers multiple version drivers exist, 2 drivers found.
12-12-2018 20:42:24.637 ERROR ChunkedExternProcessor - stderr: 20:42:24.241 11756@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - driver name is com.splunk.dbx.service.driver.DelegatingDriver, select version 12.2, loaded from file ojdbc8.jar
12-12-2018 20:42:24.637 ERROR ChunkedExternProcessor - stderr: 20:42:24.242 11756@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=register_driver driver=oracle.jdbc.OracleDriver 12.2 succeeded
12-12-2018 20:42:24.637 ERROR ChunkedExternProcessor - stderr: 20:42:24.242 11756@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=load_drivers spent 78 ms to rescan all jdbc drivers
12-12-2018 20:42:24.637 ERROR ChunkedExternProcessor - stderr: 20:42:24.300 11756@W1835906 [main] INFO c.s.dbx.connector.ConnectorFactory - action=collect_connection_pool_metrics interval_in_seconds=60
12-12-2018 20:42:25.656 INFO SearchParser - PARSING: | dbxquery connection=Realtime query="select 1 from DUAL;"
12-12-2018 20:42:25.656 INFO ProjElim - Black listed processors=[addinfo]
12-12-2018 20:42:25.663 INFO AstOptimizer - SrchOptMetrics optimization=0.000
12-12-2018 20:42:25.663 INFO SearchPhaseGenerator - Optimized Search =| dbxquery connection=Realtime query="select 1 from DUAL;"
12-12-2018 20:42:25.663 INFO ParallelReducePolicy - Current Search Head doesn't have any usable peers to use.
12-12-2018 20:42:25.664 INFO PhaseNodeGenerationVisitor - User lacking run_multi_phased_searches, rolling back to 2-phase mode.
12-12-2018 20:42:25.664 INFO PhaseToPipelineVisitor - Phase Search = | dbxquery connection=Realtime query="select 1 from DUAL;"
12-12-2018 20:42:25.664 INFO SearchParser - PARSING: | dbxquery connection=Realtime query="select 1 from DUAL;"
12-12-2018 20:42:25.664 INFO ChunkedExternProcessor - Running process: "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
12-12-2018 20:42:25.684 ERROR ChunkedExternProcessor - stderr: The system cannot find the file specified.
12-12-2018 20:42:26.203 ERROR ChunkedExternProcessor - stderr: 20:42:26.199 15800@W1835906 [main] INFO c.splunk.dbx.utils.TrustManagerUtil - action=load_key_manager_succeed
12-12-2018 20:42:26.295 INFO ChunkedExternProcessor - Custom search command is a generating command.
12-12-2018 20:42:26.295 INFO SearchPipeline - ReportSearch=1 AllowBatchMode=0
12-12-2018 20:42:26.295 INFO SearchPhaseGenerator - Disabling timeliner since source is not an event index
12-12-2018 20:42:26.295 INFO SearchPhaseGenerator - Disabling timeliner since event search is empty
12-12-2018 20:42:26.295 INFO SearchPhaseGenerator - No need for RTWindowProcessor
12-12-2018 20:42:26.295 INFO SearchPhaseGenerator - Timeliner will not be executed
12-12-2018 20:42:26.295 INFO SearchPhaseGenerator - required fields list to add to different pipelines =
12-12-2018 20:42:26.295 INFO SearchPhaseGenerator - Search Phases created.
12-12-2018 20:42:26.311 INFO UserManager - Setting user context: splunk-system-user
12-12-2018 20:42:26.311 INFO UserManager - Done setting user context: thunder_wu -> splunk-system-user
12-12-2018 20:42:26.311 INFO UserManager - Unwound user context: splunk-system-user -> thunder_wu
12-12-2018 20:42:26.311 INFO UserManager - Setting user context: thunder_wu
12-12-2018 20:42:26.311 INFO UserManager - Done setting user context: thunder_wu -> thunder_wu
12-12-2018 20:42:26.311 INFO UserManager - Unwound user context: thunder_wu -> thunder_wu
12-12-2018 20:42:26.311 INFO DistributedSearchResultCollectionManager - Stream search:
12-12-2018 20:42:26.312 INFO UserManager - Setting user context: thunder_wu
12-12-2018 20:42:26.312 INFO UserManager - Setting user context: thunder_wu
12-12-2018 20:42:26.312 INFO UserManager - Done setting user context: NULL -> thunder_wu
12-12-2018 20:42:26.312 INFO UserManager - Done setting user context: NULL -> thunder_wu
12-12-2018 20:42:26.312 INFO SearchPhaseGenerator - Result collation will occur at proc=dbxquery
12-12-2018 20:42:26.312 INFO UserManager - Setting user context: thunder_wu
12-12-2018 20:42:26.312 INFO UserManager - Done setting user context: NULL -> thunder_wu
12-12-2018 20:42:26.312 INFO UserManager - Setting user context: thunder_wu
12-12-2018 20:42:26.312 INFO UserManager - Setting user context: thunder_wu
12-12-2018 20:42:26.312 INFO UserManager - Done setting user context: NULL -> thunder_wu
12-12-2018 20:42:26.312 INFO UserManager - Done setting user context: NULL -> thunder_wu
12-12-2018 20:42:26.312 INFO SearchParser - PARSING: | streamnoop
12-12-2018 20:42:26.312 INFO SearchParser - PARSING: streamnoop | dbxquery connection=Realtime query="select 1 from DUAL;"
12-12-2018 20:42:26.313 INFO ChunkedExternProcessor - Running process: "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
12-12-2018 20:42:26.333 ERROR ChunkedExternProcessor - stderr: The system cannot find the file specified.
12-12-2018 20:42:26.336 ERROR ChunkedExternProcessor - stderr: 20:42:26.302 15800@W1835906 [main] WARN com.splunk.dbx.message.MessageEnum - action=initialize_resource_bundle_files error=Can't find bundle for base name Messages, locale en_US
12-12-2018 20:42:27.032 INFO ChunkedExternProcessor - Custom search command is a generating command.
12-12-2018 20:42:27.032 INFO SearchOrchestrator - Starting the status control thread.
12-12-2018 20:42:27.032 INFO SearchOrchestrator - Starting phase=1
12-12-2018 20:42:27.032 INFO UserManager - Setting user context: thunder_wu
12-12-2018 20:42:27.032 INFO UserManager - Setting user context: thunder_wu
12-12-2018 20:42:27.032 INFO UserManager - Done setting user context: NULL -> thunder_wu
12-12-2018 20:42:27.032 INFO UserManager - Done setting user context: NULL -> thunder_wu
12-12-2018 20:42:27.032 INFO ReducePhaseExecutor - Stating phase_1
12-12-2018 20:42:27.032 INFO SearchStatusEnforcer - Enforcing disk quota = 10485760000
12-12-2018 20:42:27.032 INFO DispatchExecutor - BEGIN OPEN: Processor=dbxquery
12-12-2018 20:42:27.032 INFO DispatchExecutor - END OPEN: Processor=dbxquery
12-12-2018 20:42:27.033 INFO PreviewExecutor - Preview Enforcing initialization done
12-12-2018 20:42:27.331 INFO ReducePhaseExecutor - ReducePhaseExecutor=1 action=PREVIEW
12-12-2018 20:42:27.352 ERROR ChunkedExternProcessor - stderr: 20:42:26.930 11508@W1835906 [main] INFO c.splunk.dbx.utils.TrustManagerUtil - action=load_key_manager_succeed
12-12-2018 20:42:27.352 ERROR ChunkedExternProcessor - stderr: 20:42:27.041 11508@W1835906 [main] WARN com.splunk.dbx.message.MessageEnum - action=initialize_resource_bundle_files error=Can't find bundle for base name Messages, locale en_US
12-12-2018 20:42:27.355 ERROR ChunkedExternProcessor - stderr: 20:42:27.046 15800@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=load_drivers multiple version drivers exist, 2 drivers found.
12-12-2018 20:42:27.355 ERROR ChunkedExternProcessor - stderr: 20:42:27.046 15800@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - driver name is com.splunk.dbx.service.driver.DelegatingDriver, select version 12.2, loaded from file ojdbc8.jar
12-12-2018 20:42:27.355 ERROR ChunkedExternProcessor - stderr: 20:42:27.048 15800@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=register_driver driver=oracle.jdbc.OracleDriver 12.2 succeeded
12-12-2018 20:42:27.355 ERROR ChunkedExternProcessor - stderr: 20:42:27.048 15800@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=load_drivers spent 101 ms to rescan all jdbc drivers
12-12-2018 20:42:27.355 ERROR ChunkedExternProcessor - stderr: 20:42:27.121 15800@W1835906 [main] INFO c.s.dbx.connector.ConnectorFactory - action=collect_connection_pool_metrics interval_in_seconds=60
12-12-2018 20:42:27.871 ERROR ChunkedExternProcessor - stderr: 20:42:27.750 11508@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=load_drivers multiple version drivers exist, 2 drivers found.
12-12-2018 20:42:27.871 ERROR ChunkedExternProcessor - stderr: 20:42:27.750 11508@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - driver name is com.splunk.dbx.service.driver.DelegatingDriver, select version 12.2, loaded from file ojdbc8.jar
12-12-2018 20:42:27.871 ERROR ChunkedExternProcessor - stderr: 20:42:27.752 11508@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=register_driver driver=oracle.jdbc.OracleDriver 12.2 succeeded
12-12-2018 20:42:27.871 ERROR ChunkedExternProcessor - stderr: 20:42:27.752 11508@W1835906 [main] INFO c.s.d.s.driver.DriverServiceImpl - action=load_drivers spent 102 ms to rescan all jdbc drivers
12-12-2018 20:42:27.871 ERROR ChunkedExternProcessor - stderr: 20:42:27.823 11508@W1835906 [main] INFO c.s.dbx.connector.ConnectorFactory - action=collect_connection_pool_metrics interval_in_seconds=60
12-12-2018 20:42:28.296 INFO PreviewExecutor - Stopping preview triggers since search almost finished
12-12-2018 20:42:28.317 INFO ReducePhaseExecutor - Ending phase_1
What is your question?
questions is why it will take so long to run "select 1 from DUAL;" in dbxquery, thanks!
From the Job Inspector output, it looks like things are pretty quick on the Splunk side. Can you ask your DBA to look at the logs on the database side to see if anything might explain the duration?
The database itself is fast. Our PROD splunk instance 6.3 with db connect 2 returns query within 2 second. Locally I have splunk 7 free version with db connect 3 and "select 1 from DUAL" takes about 7 second. Both connects to the same database.