Top ten pops and drops with Splunk, part 2

In our previous post, we looked at how to use Splunk to identify the most volatile event codes over the past day. In this post we’ll revisit that topic in light of some good feedback, and then look at how to get the detailed hour-by-hour breakdown.

The summary query, revisited

Deb Dey noted in response to the previous post that the hourly change metric–a ratio–is undefined when the denominator is zero. At the time I wasn’t sure whether this concern is real or purely academic, but experience with the query immediately revealed that the concern is very much real. One scenario we want to be able to detect is where a release breaks something that was formerly working. This scenario actually occurred while experimenting with the metric and revealed the need for a fix.

After considering different alternatives, we eventually settled on using the ratio (today’s count + 1) / (yesterday’s count + 1). This solves the zero denominator problem without unduly skewing the ratio.

We’ve made a few other improvements as well:

• For monitoring purposes, we care more about pops than drops here, so we’ve modified the query to focus on pops instead of pops and drops.
• The original query looked at today’s events, Bellevue time. The problem is that we get great focus on recent events at the beginning of the Bellevue day, but a more washed-out view of the day’s events at the end of the Bellevue day. So we changed the window to a rolling window.
• We’re now looking at an 8-hour window, since this gives us a view into more recent events.

Here’s the updated query:

index=summary reporttype=eventcount reporttime=hourly [email protected] latest=now
  | eval currHour = strftime(now(), "%H")
  | eval prevHour = currHour - 1
  | where (prevHour - date_hour) % 24 < 8
  | eval near = if(_time >= relative_time(now(), "[email protected]"), 1, 0)
  | stats sum(count) as jfreq by date_hour EventCode near
  | eval tmp_nearFreq = if(near == 1, jfreq, 0)
  | eval tmp_farFreq = if(near == 0, jfreq, 0)
  | stats max(tmp_farFreq) as farFreq, max(tmp_nearFreq) as nearFreq by date_hour EventCode
  | where nearFreq > farFreq
  | eval change = (nearFreq + 1) / (farFreq + 1)
  | stats sumsq(change) as ssc by EventCode
  | sort ssc desc
  | head 10
  | eval magnitude = log(ssc)

And here’s what it generates (simulated data):

Note that the “volatility” score is now “magnitude”, since we’re looking only at upward behavior here. Magnitude is log_10, just like a Richter scale.

The details query

Now we want to see the behavior of the events that generated the top pops over the past eight hours. Though we could observe the behavior over an arbitrary time period, we’ll use eight hours just to keep things simple. Also, note that we want to see both upward and downward behavior here. In other words, even though we considered only pops for selecting the interesting events, we want to visualize the events holistically.

Here’s the query:

index=summary reporttype=eventcount reporttime=hourly
    [email protected] latest=now
  | join EventCode
      [search index=summary reporttype=eventcount reporttime=hourly
          [email protected] latest=now
        | eval currHour = strftime(now(), "%H")
        | eval prevHour = currHour - 1
        | where (prevHour - date_hour) % 24 < 8
        | eval near = if(_time >= relative_time(now(), "[email protected]"), 1, 0)
        | stats sum(count) as jfreq by date_hour EventCode near
        | eval tmp_nearFreq = if(near == 1, jfreq, 0)
        | eval tmp_farFreq = if(near == 0, jfreq, 0)
        | stats max(tmp_farFreq) as farFreq, max(tmp_nearFreq) as nearFreq
            by date_hour EventCode
        | where nearFreq > farFreq
        | eval change = (nearFreq + 1) / (farFreq + 1)
        | stats sumsq(change) as ssc by EventCode
        | sort ssc desc
        | head 10]
  | eval currHour = strftime(now(), "%H")
  | eval prevHour = currHour - 1
  | where (prevHour - date_hour) % 24 < 8
  | eval near = if(_time >= relative_time(now(), "[email protected]"), 1, 0)
  | stats sum(count) as jfreq by date_hour EventCode near
  | eval tmp_nearFreq = if(near == 1, jfreq, 0)
  | eval tmp_farFreq = if(near == 0, jfreq, 0)
  | stats max(tmp_farFreq) as farFreq, max(tmp_nearFreq) as nearFreq
      by date_hour EventCode
  | eval change = if(nearFreq >= farFreq,
      (nearFreq + 1) / (farFreq + 1), -((farFreq + 1) / (nearFreq + 1)))
  | chart median(change) by date_hour, EventCode

This query uses a slightly simplified version of the summary query as a subquery. This does the initial identification of the events we care about. Then we join on those events to get the hour-by-hour breakdown of those events, and plot them on a chart (actual event codes suppressed in the legend):

The x-axis is the hour of the day and the y-axis is the log scale change score, which is (roughly) the ratio of today’s count over yesterday’s count for pops.

To see a specific event, we just hover over its code in the legend (again, actual event codes suppressed in the legend):

This interactive chart gives us a nice way to understand better what’s happening with problematic event codes. We start by looking at the summary view (the table that lists the problem events in descending order by magnitude), and then highlight the individual events in the details view to see whether the issue is solved or else in progress.

Until next time, happy Splunking!

Acknowledgments

Thanks to Aman Bhutani, Malcolm Jamal Anderson, Deb Dey and Karan Shah for their contributions to the work here.