Where does a search process consume its run time?

rettops — Fri, 16 Aug 2013 21:21:58 GMT

We have performance problems. Looking at one of the search logs, I see that it ends with

08-16-2013 14:00:55.172 INFO  NewTransam - Finalizing. Committing all open txns withheld
08-16-2013 14:01:26.542 INFO  NewTransam - evicted=0, closed=554, event_count=163158, candidate_events=162604, comparison_count=974503
08-16-2013 14:01:26.542 INFO  NewTransam - Finalizing/previewing. Committing all open txns withheld
08-16-2013 14:01:26.547 INFO  NewTransam - evicted=0, closed=554, event_count=163158, candidate_events=162604, comparison_count=974503
08-16-2013 14:01:26.555 INFO  NewTransam - Finalizing/previewing. Committing all open txns withheld
08-16-2013 14:11:27.427 INFO  NewTransam - evicted=0, closed=8, event_count=554, candidate_events=546, comparison_count=670
08-16-2013 14:11:35.686 INFO  script - Invoked script vgformatmaintable with 71613951 input bytes (8 events).  Returned 496 output bytes in 1049 ms.
08-16-2013 14:11:35.692 INFO  UserManager - Unwound user context: spotter -> NULL
08-16-2013 14:11:35.694 INFO  UserManager - Setting user context: spotter
08-16-2013 14:11:35.694 INFO  UserManager - Done setting user context: NULL -> spotter
08-16-2013 14:11:35.694 INFO  UserManager - Unwound user context: spotter -> NULL
08-16-2013 14:11:35.694 INFO  DispatchCommand - DispatchManager::dispatchHasFinished(id='1376686831.442', username='spotter')
08-16-2013 14:11:35.830 INFO  UserManager - Unwound user context: spotter -> NULL

Notice the jump from 14:01 to 14:11, when it is supposedly "Finalizing/previewing". What is it actually doing during those ten minutes? Any suggestions for debugging this?

UPDATE: I just attached to the search process with 'strace'. For 10 minutes the only system calls the process made were 'madvise MADV_DONTNEED' and 'mmap'.

Re: Where does a search process consume its run time?

hexx — Fri, 16 Aug 2013 22:39:04 GMT

I would recommend that you run the search again and look at the search job inspector in order to see a break down of how the search process uses its run time.

Re: Where does a search process consume its run time?

rettops — Fri, 16 Aug 2013 23:48:48 GMT

The job inspector break down accounts for ~60 seconds of the 660 seconds elapsed time. We're still missing 10 minutes.

topic Re: Where does a search process consume its run time? in Splunk Search

Where does a search process consume its run time?

Re: Where does a search process consume its run time?

Re: Where does a search process consume its run time?