Windows CPU monitoring with Splunk

I needed to overcome the Nagios limitation of a slow polling interval for CPU utilization. Splunk provides robust tools for leveraging WMI to monitor windows performance. So you think to yourself: “Great, lets look at CPU usage per process on important servers”, and you bump right up into the catch. Windows perf counters come in two flavors: “raw” and “formatted”, and Splunk only reads the formatted ones. This is fine for most things, but for CPU usage, the data isn’t accurate on multi-core systems. This post covers how to use the raw data, and “cook” the values to match what you’re used to seeing in task manager.

 

CPU utilization on muti-core systems

CPU utilization is measured by % Processor Time over a set period. A mutli-threaded application makes calculating utilization on multi-core systems not as simple 0 to 100 scale. During a time slice, several different threads may have had processor time on a core, or more likely, different threads will have had different utilization on different cores. When calculating CPU usage on a Windows system, the maximum is actually 100% x # of cores.

 

2016-01-06 20_09_15-silo - Remote Desktop Connection

Per core CPU usage average

The formatted CPU usage per process counter doesn’t take this into effect, and the results will not be consistent with what you see in performance monitor or task manager.

 

Cooking the values

So what you actually have to do is take two samples of CPU utilization, determine the elapsed time between them, and calculate the difference. Thanks to a very detailed blog post by Greg Stemp at Microsoft, I worked out that the counter type is PERF_100NSEC_TIMER making the formula:

100* (CounterValue2 - CounterValue1) / (TimeValue2 - TimeValue1)

I’ll get into applying that formula in Splunk in a minute, but first, getting the data in.

 

Get the data in

Like I said, Splunk has great first class Windows support, and has built in support for WMI inputs. It also has support for monitoring performance counters automatically, but since they don’t support RAW values, we’re going to use WMI. So, here it is:

[WMI:process]
index = test
interval = 10
server = RABBIT
wql = Select IDProcess,Name,PercentProcessorTime,TimeStamp_Sys100NS from Win32_PerfRawData_PerfProc_Process

The file must go in wmi.conf, it’ll appear in the GUI as a remote performance monitor.

Querying the data

And at long last, show me the chart! First off, a long Splunk query that is going to run off the end of the page (don’t worry, we’ll unpack it and go over it):

earliest=-3m index=test Name!=_Total Name!=Idle | reverse | streamstats current=f last(PercentProcessorTime) as last_PercentProcessorTime last(Timestamp_Sys100NS) as last_Timestamp_Sys100NS by Name | eval cputime = 100 * (PercentProcessorTime - last_PercentProcessorTime) / (Timestamp_Sys100NS - last_Timestamp_Sys100NS) | search cputime > 0 AND cputime < 400 |  timechart span=3 avg(cputime) by Name

The pieces explained:

Name!=_Total Name!=Idle
  • _Total and Idle make the time chart look bad, and can be more easily added with an | addtotals
reverse
  • We need the results from oldest to newest, because the calculations are based on a “previous value”
streamstats current=f
last(PercentProcessorTime) as last_PercentProcessorTime
last(Timestamp_Sys100NS) as last_Timestamp_Sys100NS
by Name
  • Streamstats pulls values from the previous record forward. We don’t need the current value, so we drop it.
  • last(PercentProcessorTime) and last(Timestamp_Sys100NS) pull the previous values forward and alias them
  • by Name groups the events together, so that you’re getting the “right” previous PercentProcessorTime. Without it, you would be getting values from some previous process
eval cputime = 100 *
(PercentProcessorTime – last_PercentProcessorTime) /
(Timestamp_Sys100NS – last_Timestamp_Sys100NS)
  • This is the math. It works out the CPU usage between the slices, and the time between the slices
search cputime > 0 AND cputime < 400
  • Throw out anomalous values. * 400 is 100 x the number of cores on this box. Adjust yours accordingly.
timechart span=3 avg(cputime) by Name
  • Make it pretty!

* PercentProcessorTime increments forever, if you plot it on a chart it rises over time. When running the math on a single process, it’s fine, the next value is always higher than the last. There are issues around the transitions though. If the last value of PercentProcessorTime for ProcessA is 40000, and the first value for ProcessB is 10000, then the delta is 30000 and it throws the graphs way out of whack. The easiest thing to do is just drop those values. We’re going to pipe the values through an avg() in timechart anyway, so little gaps like that will get smoothed out.

The results

I used a little app called CpuKiller to throttle the CPUs and make the results more obvious.

 

2016-01-06 15_39_39-rabbit - Remote Desktop Connection

Windows performance monitor Green – CPU killer Red – VMWare

 

2016-01-06 15_39_53-Photos

The same data plotted in Splunk. Note that Splunkd doesn’t appear in the perfmon graph because I didn’t include that process, but the WQL being run by Splunk watches all processes.

 

Some of the fun things you can do with this are look at processes from a number of servers across an entire farm (for example, your web servers), or plot application response times against resource utilization. Yay for Splunk!

Splunk forwarders on CoreOS with JournalD

The team at TNWDevLabs started a new effort to develop an internal SaaS product. It’s a greenfield project, and since everything is new, it let us pick up some new technology and workflows, including neo4j and nodejs. In my role as DevOps Engineer, the big change was running all the application components in Docker containers hosted on CoreOS.

CoreOS is a minimalist version of Linux, basically life support for Docker containers. It is generally not recommended to install applications on the host, which raises a question: “How am I going to get my application logs into Splunk?”.
With a more traditional Linux system, you would just install a Splunk forwarder on the host, and pick up files from the file system.

image00

With CoreOS, you can’t really install applications on the host, so there is the possibility of putting a forwarder in every container.

image02

This would work, but it seems wasteful to have a number of instances of Splunk running on the same host, and it doesn’t give you any information about the host.
CoreOS leverages SystemD which has an improved logging facility called JournalD. All system events (updates, etcd, fleet, etc) from CoreOS are written to JournalD. Apps running inside docker containers generally log to stdout, and all those events are sent to JournalD as well. This improved logging facility means getting JournalD into Splunk is the obvious solution.

The first step was to get the Splunk Universal Forwarder into a docker container. There were already some around, but I wanted to take a different approach. The idea is instead of trying to manage .conf files and getting them into the container, I leverage the Deployment Server feature already built into Splunk. The result is a public image called tnwinc/splunkforwarder. It takes two parameters passed in as environment variables: DEPLOYMENTSERVER and CLIENTNAME. These two parameters are fed into $SPLUNK_HOME/etc/system/local/deploymentclient.conf when the container is started. This is the bare minimum to get the container up and talking to the deployment server.

image03

Setting up CoreOS

Running CoreOS, the container is started as a service. The service definition might look like: ExecStart=/usr/bin/docker run -h %H -e DEPLOYMENTSERVER=splunk.example.com:8089 -e CLIENTNAME=%H -v /var/splunk:/opt/splunk –name splunk tnwinc/splunkforwarder

-h %H Sets the hostname inside the container to match the hostname of the CoreOS host. %H gets expanded to the CoreOS hostname when the .service file is processed.
-e DEPLOYMENTSERVER The host and port of your deployment server
-e CLIENTNAME =%H This is the friendly client name.
-v /var/splunk:/opt/splunk This exposes the real directory /var/splunk as /opt/splunk inside the container. This directory persists on disk when the container is restarted.

Now that Splunk is running and has a place to live, we need to feed data to it. To do this, I setup another service, which uses the journalctl tool to export the journal to a text file. This is required as Splunk can’t read the native JournalD binary format:

ExecStart=/bin/bash -c '/usr/bin/journalctl --no-tail -f -o json > /var/splunk/journald'

This command dumps everything in the journal out to JSON format (more on that later), then tails the journal. The process doesn’t exit, and continues to write out to /var/splunk/journald, which exists as /opt/splunk/journald inside the container.

Also note that as the journald file will continue to grow, I have an ExecStartPre directive that will trim the journal before the export happens:

ExecStartPre=/usr/bin/journalctl --vacuum-size=10M

Since I’m not appending, every time the service starts, the file is replaced. You may want to consider a timer to restart the service on a regular interval, based on usage.

Get the data into Splunk

This was my first experience with Deployment Server, it’s pretty slick. The clients picked up and reached out to the deployment server. My app lives in $SPLUNK_HOME\etc\deployment-apps\journald\local. I’m not going to re-hash the process of setting up a deployment server, there is great documentation at Splunk.com on how to do it.

My inputs.conf simply monitors the file inside the container:

[monitor:/opt/splunk/journald]
sourcetype = journald

The outputs.conf then feeds it back to the appropriate indexer:

[tcpout]
defaultGroup = default-autolb-group
[tcpout:default-autolb-group]
server = indexer.example.com:9997
[tcpout-server://indexer.example.com:9997]

Do something useful with it

None of getting the data into Splunk is special, but the props.conf is fun so I’m covering it separately. Running the journal out in JSON structures the data in a very nice format, and the following props.conf helps Splunk understand it:

[journald]
KV_MODE = json
MAX_TIMESTAMP_LOOKAHEAD = 10
NO_BINARY_CHECK = 1
SHOULD_LINEMERGE = false
TIME_FORMAT = %s
TIME_PREFIX = \"__REALTIME_TIMESTAMP\" : \"
pulldown_type = 1
TZ=UTC
KV_MODE=json Magically parse JSON data. Thanks, Splunk!
TIME_PREFIX This ugly bit of regex pulls out the timestamp from a field called __REALTIME_TIMESTAMP
TIME_FORMAT Standard strpdate for seconds
MAX_TIMESTAMP_LOOKAHEAD JournalD uses GNU time which is in microseconds (16 characters). This setting tells splunk to use the first 10.

Once that app was published to all the agents, I could query the data out of Splunk. It looks great!

image01

This is where the JSON output format from journald really shines. I get PID, UID, the command line, executable, message, and more. For me, coming from a Windows background, this is the kind of logging we’ve had for 20 years, now finally in Linux, and easily analyzed with Splunk.

The journal provides a standard transport, so I don’t have to think about application logging on Linux ever again. The contract with the developers is: You get it into the journal, I’ll get it into Splunk.

Splunk user agent string lookups with TA-browscap_express

I got a requirement to find out what browsers our clients are using. We run a SaaS product, and every client is clientname.ourdomain.com, so I could use the cs_hostname field in the log. Using a 3rd party analytic tool was totally out of the question, all I had to go on were the IIS logs.

We’re already getting the IIS logs into Splunk, so with a bit of Googling I found the TA-browscap app by Dave Shpritz. It’s powered by the browscap project and it works. The problem is that the browscap file is now 18MB and searching it has become very slow. What started as an hack to cache matches in a separate file has turned into a total fork and re-write of most of the app, and has become TA-browscap_express.

There are installation instructions on the application page at Splunk.com, also in the GitHub repo, so I won’t rehash them here.

The Browscap file

The Browser Capabilities Project (browscap) is an effort to identify all known User Agent (UA) strings, which regretfully are a total mess. The project is active, and the data is accurate. They provide the data in a number of formats, the legacy INI file still used by PHP and ASP, and a CSV file, among others. The file is 18MB and 58,000 lines long.

The structure of the file is a name pattern for a UA string, followed by all the known properties. My UA string is:

Mozilla/5.0 (Windows NT 6.1; WOW64; rv:31.0) Gecko/20100101 Firefox/31.0

And the matching name pattern is:

Mozilla/5.0 (*Windows NT 6.1*WOW64*) Gecko* Firefox/31.0*

The example above matches FireFox 31 on Windows 7 x64. Now here is an interesting challenge:

Mozilla/5.0 (*Windows NT 6.1*) Gecko* Firefox/31.0*

This name pattern matches FireFox 31 ono Windows 7 x86. It also matches x64. If you take the first match, you’ll get the wrong information. To get an accurate lookup, you need to compare all 58,000 name patterns, and the longest one which matches is the most correct. You can imagine, this is quite a challenge.

Parsing the browscap.csv file

The TA-browscap app uses pybrowscap, which is a Python library for parsing and managing the browscap.csv file. The library returns an object with properties for all the fields in the browscap file. I didn’t want to check 58,000 name patterns every time, so I wanted the successful pattern as well. pybrowscap doesn’t provide it, and it’s actually hard to re-create because they’re using python’s internal CSV buster.

The solution was to lift the core logic from pybrowscap and re-write it myself, busting strings as CSV data instead of files. The first thing you have to do is convert the name pattern into regex, which is easy, then compare your challenge string against it. Like I described above, after that  you loop through every name pattern until you find the longest match.

Knowing what to cache

The last entry in the file is “*” which will match anything. It returns a set of properties called “Default Browser” where everything is false. The idea is you’ll always get some response, you won’t get null. I didn’t want to cache these “Generic” or “Default” browsers, because once they’re in the cache, they’ll come up for every new UA string, and the data will be junk.

How it works

The app (TA-browscap_express) caches matched UA strings in a file and searches it first. During a query it also keeps matches in memory, using the memory cache before the disk cache. It also supports blacklisting obviously bad UA strings and storing the cache file on a network share to help with distributed search.

When a UA string is passed into the app, it checks 4 things:

  1. Is it blacklisted? If yes, return default browser.
  2. Is it in the memory cache? If yes, return the entry.
  3. Is it in the browscap_lite.csv file? If yes, add to memory cache and return.
  4. Is it in browscap.csv? If yes, add to browscap_lite.csv, the memory cache and return.
  5. If totally unidentifiable, return the default browser.

 

Browscap_lite.csv

The browscap_lite.csv file is the cache file which is checked before browscap.csv. It’s in the same format, and has the same fields. Matched UA strings are written to it.

The default location for the file is in the application\bin directory for the app. In a Splunk distributed environment, that’s not really a good idea. You never know what search head or indexer the app will run on, and you’ll end up rebuilding the cache over and over. The browscap_lookup.ini file lets you specify a location for the file.

The blacklist

Some UA strings are junk, and won’t ever be added to the browscap file. Others could be added, and I suggest you report any new strings to browscap.org, but it may take a while, or you just don’t care. The blacklist.txt file is used to weed out garbage UA strings so that you don’t waste time trying to look them up in the browscap.csv file, only to get “*” Default Browser.

 

The fields

The app returns all fields available in the browscap file. Two I find especially interesting are:

ua_comment This is a combination of the browser name and version, so that Internet Explorer 11 becomes IE 11.

ua_platform This is a combination of the operating system and version, so that Windows 7 becomes Win7.

 

There is one additional field which I added, ua_fromcache, which returns true, false, or blacklist, depending on where the data came from.

 

The demo

Sorry in advance for my droning voice, but if you want to see the setup and usage in action, check out my Youtube Video.