Community:PerformanceTroubleshooting
From Splunk Wiki
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.