How to calculate IIS Events In Progress over Time?

[rstankus]

Our IIS logs contain a "time_taken" field which indicates the number of milliseconds each event took. I'd like to use the data from this field, along with the actual event _time (what I'm thinking of as the time the server responded, or the "responseTime") to create a chart showing how many events were "in progress" over time. It's easy enough to calculate the "requestTime" by doing something like this:

          eval requestTime = _time - time_taken

What I'm missing is how to generate a graph with time (to the second) along the X-axis and total number of events in progress at that time on the Y-axis. For example, if a request was logged at 12:00:06 pm and had a time_taken of 3,000 ms (thus the "requestTime" was 12:00:03), then I would want it to be counted in 4 columns: 12:00:03, 12:00:04, 12:00:05, 12:00:06, indicating that this request was "in progress" during each of those times. 

Essentially, I want something like the output of the command below, but I want it to be a count of all events in progress during each of those seconds rather than just a discreet count of events based on their "_time"

          timechart count span=1s

[rstankus]

Thank you - that's starting to look better. Still a few oddities, though - when I select a 1 minute time range (in this case 5:00:00 - 5:01:00), the X-axis on the resulting table goes from 04:59:54 to 05:00:12 - why is that?

Also,  each of the vertical bars in the chart appears to contain 2 sections, and only 1 of those can be selected when I mouseOver it. See in the image above that the bar for 5:00:02 clearly crosses over the 500 line, but when I mouseOver it, only the lower part of the bar is highlighted and the number listed of 471. Why?

[ITWhisperer]

What search did you use to create these stats?

[rstankus]

host="myHost" source="*W3SVC1\\*"
| eval requestTime=_time-(time_taken/1000)
| eval row=mvrange(0,2)
| mvexpand row
| eval _time=if(row=0,requestTime,_time)
| bin span=1s _time
| sort 0 _time
| streamstats count(eval(row=0)) as starts count(eval(row=1)) as ends
| eval inprogress=starts-ends
| table _time inprogress

[ITWhisperer]

The time goes back because _time is reset to the time that the request started so that the inprogress count can be done.

There shouldn't be two parts to the bars. Can you share the stats table?

[rstankus]

Sure - here are 2 examples: 

And:

[ITWhisperer]

You have multiple lines for the same time - try adding this

| stats max(inprogress) as inprogress by _time

[rstankus · Accepted solution]

Thank you - I think that's giving me what I want now! Would you mind explaining it a little? I see that it creates a multivalue field called row that is 0 or 1. It then expands that field to create new events for these values, yes? For row 0, it uses the requestTime and for row 1 it uses the _time.  That's about where I get lost. 

Here's the final search that I used:

host="myHost" source="*W3SVC1\\*"
| eval requestTime=_time-(time_taken/1000)
| eval row=mvrange(0,2) 
| mvexpand row
| eval _time=if(row=0,requestTime,_time)
| bin span=1s _time
| sort 0 _time
| streamstats count(eval(row=0)) as starts count(eval(row=1)) as ends
| eval inprogress=starts-ends
| stats max(inprogress) as inprogress by _time
| table _time inprogress

And here's the output that I'm seeing now, which so far seems perfect:

[ITWhisperer]

This line puts _time into 1 second buckets, i.e. this is the same as doing eval _time=floor(_time) - it removes the milliseconds

| bin span=1s _time

Sort the events by _time - there could be (and in fact are in your data) multiple events for the same second

| sort 0 _time

Generate a running total of start events and end events

| streamstats count(eval(row=0)) as starts count(eval(row=1)) as ends

In progress is the difference between start events and end events so far for any particular event

| eval inprogress=starts-ends

Where there are multiple events for the same second, we are only interested in the last value. Note that this is a change to the solution I proposed.

| stats last(inprogress) as inprogress by _time

[rstankus]

Very helpful - I appreciate it very much. I've implemented the change that you proposed and I'm testing it now. 

[ITWhisperer]

| eval requestTime=_time-time_taken
| eval row=mvrange(0,2) 
| mvexpand row
| eval _time=if(row=0,requestTime,_time)
| bin span=1s _time
| sort 0 _time
| streamstats count(eval(row=0)) as starts count(eval(row=1)) as ends
| eval inprogress=starts-ends
| table _time inprogress

[rstankus]

Thanks, but that doesn't seem quite right. The results I get start with 1 event and increment the "inprogress" event count by 1 every second: 

[ITWhisperer]

If time_taken is in milliseconds, try it like this:

| eval requestTime=_time-(time_taken/1000)

 _time is in seconds