.CONF & SPLUNKLIVE!

Tracking indexing status in splunkd.log and metrics.log

Splunk By Splunk September 10, 2012

To continue the discussion of internal logs, here are some examples of indexing-related activity in splunkd.log and metrics.log

splunkd.log

This scripted input returned new events

09-03-2012 21:12:50.421 -0700 INFO  ExecProcessor - Ran script: /Applications/splunk/splunk7000/etc/apps/unix/bin/iostat.sh, took 8.590 seconds to run, 660 bytes read

This file we already know about has more to read

09-02-2012 07:41:07.093 -0700 INFO  WatchedFile - Will begin reading at offset=1228866737 for file='/var/log/apache2/spinnyspinny_access_log'.

This file rolled, so read the new one from the beginning

09-03-2012 00:00:22.310 -0700 INFO  WatchedFile - Checksum for seekptr didn't match, will re-read entire file='/var/log/system.log'.
09-03-2012 00:00:22.310 -0700 INFO  WatchedFile - Will begin reading at offset=0 for file='/var/log/system.log'.

This new file is one we already read before it rolled

09-03-2012 00:00:22.763 -0700 INFO  TailingProcessor - Archive file='/var/log/system.log.0.bz2' updated less than 10000ms ago, will not read it until it stops changing.
09-03-2012 00:00:32.768 -0700 INFO  TailingProcessor - Archive file='/var/log/system.log.0.bz2' has stopped changing, will read it now.
09-03-2012 00:00:32.768 -0700 INFO  ArchiveProcessor - handling file=/var/log/system.log.0.bz2
09-03-2012 00:00:32.769 -0700 INFO  ArchiveProcessor - reading path=/var/log/system.log.0.bz2 (seek=0 len=145503)
09-03-2012 00:00:33.358 -0700 INFO  ArchiveProcessor - Archive with path="/var/log/system.log.0.bz2" was already indexed as a non-archive, skipping.

This archive we’ve already seen

09-03-2012 18:02:11.253 -0700 INFO  ArchiveProcessor - handling file=/var/log/system.log.3.bz2
09-03-2012 18:02:11.254 -0700 INFO  ArchiveProcessor - new tailer already processed path=/var/log/system.log.3.bz2

metrics.log

metrics.log contains a number of different kinds of statistics. Keep in mind that the thruput numbers here are a snapshot and cannot be directly compared to what the licenser is counting. Here are a few things you will find here:

  • Snapshot of top data sources and pipelines every 30 seconds
  • Number of thruput items configurable in limits.conf
  • the group is the type of statistics
  • the series is the individual source

Thruput statistics

09-03-2012 21:22:39.559 -0700 INFO  Metrics - group=per_source_thruput, series="/var/log/filemonitortest.log", kbps=0.566628, eps=3.242395, kb=17.475586, ev=100, avg_age=233.030000, max_age=427
09-03-2012 21:35:24.947 -0700 INFO  Metrics - group=per_index_thruput, series="www_comics", kbps=0.006237, eps=0.032420, kb=0.192383, ev=1, avg_age=2.000000, max_age=2
09-03-2012 21:34:54.100 -0700 INFO  Metrics - group=per_sourcetype_thruput, series="iostat", kbps=0.020784, eps=0.032246, kb=0.644531, ev=1, avg_age=0.000000, max_age=0
09-03-2012 21:35:24.947 -0700 INFO  Metrics - group=per_host_thruput, series="grumpy", kbps=0.041981, eps=0.324195, kb=1.294922, ev=10, avg_age=1.900000, max_age=4
09-06-2012 17:13:51.987 -0700 INFO  Metrics - group=per_source_thruput, series="tcp:8888", kbps=0.153792, eps=3.261877, kb=4.714844, ev=100, avg_age=0.000000, max_age=0

Incoming data from forwarder at 10.10.67.125

09-06-2012 17:20:28.716 -0700 INFO  Metrics - group=tcpin_connections, 10.10.67.125:58579:9997, connectionType=cooked, sourcePort=58579, sourceHost=10.10.67.125, sourceIp=10.10.67.125, destPort=9997, _tcp_Bps=98342.80, _tcp_KBps=96.04, _tcp_avg_thruput=50.61, kb=2933.89, _tcp_Kprocessed=3031.88, _tcp_eps=90.41, build=133620, version=4.3.4, os=Darwin, arch=x86_64, hostname=alongo-mbp15.sv.splunk.com, guid=189A0984-20BE-4266-9504-081B202508F6, fwdType=full, ssl=false, lastIndexer=10.10.67.247:9997, ack=false

Incoming data on port 8888

09-06-2012 17:13:38.823 -0700 INFO  StatusMgr - destPort=8888, eventType=connect_done, sourceHost=10.10.67.125, sourceIp=10.10.67.125, sourcePort=58319, statusee=TcpInputProcessor
09-06-2012 17:13:38.824 -0700 INFO  StatusMgr - sourcePort=8888, ssl=false, statusee=TcpInputProcessor
09-06-2012 17:13:38.826 -0700 INFO  StatusMgr - destPort=8888, eventType=connect_close, sourceHost=10.10.67.125, sourceIp=10.10.67.125, sourcePort=58319, statusee=TcpInputProcessor

Splunk
Posted by

Splunk