Interpreting execution costs on the Job Inspector page: Query update

koshyk — Fri, 27 Sep 2019 09:45:18 GMT

Could see an old question in 2010 , but just getting confused on the timings/duration vs execution cost

I've a search which finishes in This search has completed in 87.776 seconds

Below is snapshot of job inspector. As per the documentation, the command.search.index (which took 102.39) tells how long it took to look into the .TSIDX files for the location to read in the raw data. I assume this is in seconds?

So the confusion is, the entire search has taken only 87.776 seconds, but a component took more than that? Different components are much higher than the total duration. (NOTE this is a SHC & IDX cluster environment). Do we need to divide the duration (seconds) value with the cluster SHC count to get the real value in seconds?

Duration (seconds)      Component   Invocations Input count Output count
    0.96     command.eval   960 14,440  14,440
    0.10     command.fields 240 3,606   3,606
    0.48     command.pretransaction 478 10,818  10,818
    0.00     command.rename 1   -   -
    275.92   command.search 718 7,361   11,100
    102.39   command.search.index   326 -   -
    24.10    command.search.filter  435 -   -
    4.37     command.search.fieldalias  195 737,809 737,809
    3.88     command.search.calcfields  195 737,809 737,809
    1.66     command.search.expand_search   1   -   -
    0.00     command.search.index.usec_1_8  83,018,230  -   -
    0.00     command.search.index.usec_512_4096 1   -   -
    0.00     command.search.index.usec_64_512   14  -   -
    0.00     command.search.index.usec_8_64 125,952 -   -
         .........  
        ..........

There are more entries to this.

Re: Interpreting execution costs on the Job Inspector page: Query update

wmyersas — Fri, 27 Sep 2019 15:10:24 GMT

You've got a couple different times in play here.

The 87.776 seconds is total elapsed human time (ie, form when it started searching towhen it completed, was just under a miunte and a half on the wall clock - you experienced less than 90 seconds for it to run).

The other times are total elapsed system time - across all Search Heads, Indexers, etc.

Splunk's summing the runtimes of every server involved for those values (eg the 275.92 & 102.39 seconds) so that you can see how hard your search actually worked behind the scenes to get you a sub-90-second perceived (ie, real-world) run time.

Another way to think about it: if you had an all-in-one Splunk instance that could handle the workload, this search would've taken a few minutes to complete.

This is a good way to analyze a few things (at least):

Splunk's horizontal scalability (ie, how more Indexers cut perceived run time)
How much data you're really looking at to get your results
What part(s) of the search are least time-efficient
Perhaps where you can look to improve your search's performance

From personal experience, I can say that you can see (on a large enough search) the difference in doing something like index=ndx field1=value1 field2=value3 and index=ndx sourcetype=srctp field1=value1 field2=value2.

The first form tries to look in all sourcetypes you have access to (even if there's only 1 sourcetype in the index) in index=ndx for all the fields you've asked for. First time I started investigating this for myself, I saw searches trying to look for field=value1 field2=value2 in over 200 sourcetypes!

Maybe that's what you meant. But if you know which sourcetype(s) you want to look at, you're going to be able to accelerate your searches by limiting your search to just the sourcetype(s) you care about.

topic Interpreting execution costs on the Job Inspector page: Query update in Splunk Search

Interpreting execution costs on the Job Inspector page: Query update

Re: Interpreting execution costs on the Job Inspector page: Query update