Community:PerformanceTroubleshooting

From Splunk Wiki

Jump to: navigation, search
Splunk Performance
~~~~~~~~~~~~~~~~~~

Primary inputs:

* Characterization:

 - what actions in splunk are performing poorly, and especially what
   in contrast is not performing poorly
   

* Timing:

 - Are the problems constant, or fluctuating, with any identifiable
   patterns


* Load:

 - Are Disk throughput, memory, or CPU time exhausted?


------

I prefer to start with system performance.  Most problems are much
more comprehensible when the system constraints are understood.

This means looking at:

 - general load on active splunk box
 - changes in load / activity during slow operation (search, ui
   action, etc)

Memory use:

  Linux:  free, ps, vmstat
  Solaris: vmstat, ps
  Windows: Task manager, perfmon

If the system has more than 80% of the memory in use by programs , or
significant swap usage, then this problem becomes the priority.

example: Linux:

        jrodman@support05:~$ free
                     total       used       free     shared    buffers     cached
        Mem:       2062080    1865568     196512          0     146588     866392
        -/+ buffers/cache:     852588    1209492
        Swap:      1951888         24    1951864

This system has only 852 megabytes in use (second line) out of 2GB,
which is a healthy ratio.  You want the majority of your memory in use
by buffers/cache.

We also see almost no swap is in use.  Moderate swap use is not a
problem (perhaps some tens of megabytes).  Frequently changing swap
usage, or high usage (more than a few hundred megabytes) may indicate
swapping, which will kill all performance for any purpose.

Identification of swapping:

 Unix: vmstat <interval>
 Interval is a number in seconds

    jrodman@support05:~$ vmstat 5
    procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
     r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
     0  0     24 131608 173708 894048    0    0     1    26    0    7  0  0 99  0
     0  0     24 131648 173708 894048    0    0     0     0   90  585  0  0 100  0
     0  0     24 131516 173708 894048    0    0     0     3   86  490  1  0 99  0
     0  0     24 131532 173708 894056    0    0     0   151   73  476  0  0 99  0

The useful data here is the swap colums, si for swap-in, so for
swap-out,   This system is not swapping.  A system under significant
memory pressure will often have stairstepping where there is no swap
activity for a time, and then a large chunk of swap activity.  A
system with constant swap activity is one that is thrashing, and will
not perform in any reasonable way until this is resolved.

solaris -- 

There's a nice document about memory troubleshooting on Solaris here:
http://www.princeton.edu/~unix/Solaris/troubleshoot/ram.html

They recommend vmstat or sar -g to review "scan rate" for indication of
memory overload, and vmstat -p to review paging activity.

Disk load:

You can evaluate disk performance on an unused system with Bonnie++,
but for a live system, this isn't useful.  Unix, use iostat with an
polling interval in seconds:

    jrodman@support05:~$ iostat 5
    Linux 2.6.26-2-amd64 (support05) 	01/07/2010 	_x86_64_	(2 CPU)

    avg-cpu:  %user   %nice %system %iowait  %steal   %idle
               0.32    0.05    0.18    0.03    0.00   99.41

    Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
    sda               2.04         2.49       103.80    6303251  262885952

    avg-cpu:  %user   %nice %system %iowait  %steal   %idle
               0.10    0.00    0.20    0.10    0.00   99.59

    Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
    sda               2.00         4.80        33.60         24        168


This system is entirely idle.  However, evaluating the blocks read and
written per second can quickly give you a hint if you are anywhere
near capacity.  5000 blocks/s written is nothing. 50,000 blocks/s
could be easily exhausting your bandwidth.

During searches, you should expect tps (transactions per second) to
surge to high numbers.  If this number never rises above 300, then
probably your system simply doesn't have enough seek performance.
500 would be mediocre, 800-1000 starts to become quite impressive.

CPU load:

This is the hardest to evalute, since CPU cores are segmented.
Searches can be bounded by a single core performance while other
resources remain idle.  The number of CPUs used by indexing will grow
as the data volume grows, from around 2 at lower loads upwards to
around 5-6 at higher volume loads (think 100GB/day).

    Linux: For a rough impression, you can use 'top' with multi-cpu view,
           (press the 1 key),
    Solaris: prstat



------------------------

What aspects of splunk are using what sort of system load?

    For a rough quick look, splunkd cpu use is primarily
    indexing-related.  splunk-optimize processes are also
    indexing-related.

    The majority of search cpu use occurs in short-lived splunk-search
    processes.

    User interface related activity occurs in the python process named
    mrsparkle, eg:

    jrodman   7504   0.2  0.8   126584  32216   ??  S    11:47AM   1:11.12 python -O /Applications/splunk4/lib/python2.6/site-packages/splunk/appserver/mrsparkle/root.py start

If you need to break down system i/o load by process (splunk-search vs
splunkd), iotop may be useful:
http://guichaz.free.fr/iotop/


You can use the built-in splunk metrics.logs to evaluate how much cpu
time splunk believes it is using for various performance purposes.
This is the cpu_seconds value from metrics.log, eg:

Splunk > index=_internal source=*metrics.log group=pipeline | timechart sum(cpu_seconds) by processor

This breaks down the cpu accounting by individual widget in our data
processing.  You could also break it down by more rough categories:

Splunk > index=_internal source=*metrics.log group=pipeline | timechart sum(cpu_seconds) by name

In some environments regex may be dominant, in others, parsing, while
in others the indexing pipeline may be the majority of time.


You can get a plot of all the cpu activity with a fairly comparable
values like so:

index="_internal" source="*metrics.log" group=pipeline NOT sendout |timechart span=1m sum(cpu_seconds)

Now we can compare these values to the per-cpu maximum of 60.  If the
chart hovers around 240, you have approximately 4 cores in use by
indexing data processing inside splunk.  If it's more around 30, you
have only half a core in use by these things.


-----------------------
For indexing problems:

Review KBps values (per_sourcetype_thruput, per_index_thruput) in
metrics log to measure improvements, make sure you're making it
better!

Explicitly declare single-line formats with
SHOULD_LINEMERGE=false

Explicitly declare time format with 
TIME_FORMAT, TIME_PREFIX, and MAX_TIMESTAMP_LOOKAHEAD

If the majority of cputime is spent in indexing, not parsing or regex,
it may help to add an indexing thread in indexes.conf 

Aside: indexing speed is negatively affected by poorly ordered event
streams.  Clean data is faster, and good housekeeping anyway (your
search results will be more meaningful).  Keep systems on the same
clock, set up parsing for ill-defined sourcetypes.

----------------
For search performance:

Two avenues: 

 - compare/contrast speed of various searches
  (some searches are slow, some searches are fast)

 - look at system behavior when running trouble searches


Common causes of slow searches:

 - slow disk
 - extremely large OR lists (1 OR 2 OR 3 OR 4 ..... 5000) 
   these can be caused by tags
 - complex subsearches (effectively end up being large OR lists)
 - phrase searches, eg Splunk > 1.2.3.4

Search tuning:

 - be more specific:
    - Add sourcetypes, hosts, source values where possible
    - add strings which will only exist in your desired events
    - narrow the time range as appropriate
    - cut the data at a quantity of events, eg * 
       Slow: Splunk > *  
       Fast: Splunk > * | head 1000
 - Avoid NOT expressions when possible.
     Avoid: (NOT host=d NOT host=e)
     Prefer: (host=a OR host=b OR host=c)
 - In some cases, when there is no natural way to describe the data
   efficiently with the splunk engine, but it can be identified at
   input time, parse-time ("indexed") fields may be appropriate

Investigation:

 - Try to determine which phase of the search is taking what amounts
   of time.  If your search involves a number of invocations of
   rename, eval, stats, subsearches, etc.  Break the search down piece
   by piece to figure out which parts are taking what amounts of time.

 - Run 'vmstat 5' and 'iostat 5' prior to running your search, let
   them run while search is executing, until completion

 - Try search from the command line, especially using the time
   command, eg:
   time splunk search 'my search terms .....'

 - In the UI from a slow search you can click on 
     Actions -> Get link to results...

     This will give you the search ID, such as sid=1262914985.83

You can find the directory containing the actual data about the search at:
     $SPLUNK_HOME/var/run/splunk/dispatch/<search_id>
     eg 
     /opt/splunk/var/run/splunk/dispatch/1262914985.83

These directories are auto-deleted after ten minutes, to keep one,
create an empty file, 'save' in the directory, or copy it out.

The most interesting thing is usually the search.log.  It may contain
errors or timing information in extreme cases.  You can also see the
number of 'results' that splunk-search pulled off disk before further
filtration.

Manually running a search:

   If you capture the exact commandline used to launch splunk-search
   when you run a UI search, 

   (while true; do ps aux |grep '[s]earch term'; done) 
   
   you can run these yourself.  This will enable you to run them under
   investigation tools such as gdb, strace, valgrind, whatever you
   wish.  It is convenient to choose the search-id yourself for this
   purpose, which will cause the dispatch dir to be created
   with the same name.

Anatomy of a search:

  From a performance perspective, here are the major pieces of a
  search.  This can sometimes help to pin down what types of things
  may or may not be slow:

1 - Your search is expanded according to its explicitly stated tags
and eventtypes.  The full version can be viewed in the dispatch
search.log (above).

Steps 2-4 are quite seek intensive.  They are typically bound on disk
head movement, or I/Os per second.

2 - The disk-access code that walks the indexes traverses the
appropriate buckets for the time range.

3 - For each bucket, test are made for whether the desired
sourcetypes, sources, and hosts are present in the bucket at all

4 - assuming the bucket cannot be eliminated on these criteria, the
index files are opened (all of them, in turn, that match the time
range)

 4a - the start of the index has a dictionary of indexed terms, a
 "lexicon".  We identify the terms that are appropriate (such as for
 wildcards.
 
 4a - for all identified terms, we identify all the event IDs which
 match for each term

 4c - set logic is used to determine which event IDs are desired
 for the expressed search.  eg for 'host=a OR host=b', all events for
 either host are desired, while for 'host=a AND host=b', only events
 for both are desired.

5 - for all desired events, the appropriate rawdata files are
accesssed.  These are typically compressed, so this can be quite CPU
intensive.  There is also a moderately significant amount of
sequential reads here.
  

6 - Various automatic processing steps occur, eg 

6a - eventtypes are identified, which involves applying search
expressions against all the resturned invents.

6b - automatic key-value extraction is applied, where sequences like
'a=4' are identified and provided as fields for matching, charting,
etc.

7 - n -- the rest of the search steps are highly dependent upon the
search expression.  

Finally: for the UI only, the search text is parsed into 'segments' so
that the UI can visually present clickable items that can be searched,
as a usability aid.


Search performance remedies:

Disk seek limited

 - Use 64 bit.  This is always a win, in any event

 - If your data is sparse (buried in a larger volume of unrelated
   data) it may help to store it in its own index

Disk bandwidth exhaustion:

 - In this case you will simply have to reduce the load on the I/O
   subsystem.  Possible remedies:

    - Add more index nodes
    - Move non-splunk tasks off the system
    - Check for extremely large numbers of source, sourcetypes, or
      host values (tens of thousands).  They can cause unnecessary
      I/O.

CPU limited:

 - If splunk-search seems CPU bound, you may want to evaluate storing
   your rawdata in uncompressed form.  This will use a great deal more
   disk space, but will not incur the decompression CPU cost at search
   time.

 - If you have very large events, especially with a great deal of
   punctuation.  Try disabling search-time segmentation (raw) in the
   UI.

 - If your events have large numbers of apparent Key-value pairs, like

       hostname=foo access=much food=hotdogs

   and you do not care about the vast majority of the values, you may
   wish to disable automatic key-value extraction with KV_MODE=none in
   props.conf


Initial rev, Jrodman 10:40, 12 January 2010 (PST) please do modify etc.

Personal tools
Hot Wiki Topics


About Splunk >
  • Search and navigate IT data from applications, servers and network devices in real-time.
  • Download Splunk