How to group and calculate the program execute time in group?

[blueyuan]

Hi expert, currently I am study Splunk and have some question, could you help me to resolve them? Thank you in advance.

22-Apr-2016 12:04:56.213 start-1
22-Apr-2016 12:04:57.228 -exec_1
22-Apr-2016 12:04:58.123 -exec_2
22-Apr-2016 12:04:59.957 -exec_3
22-Apr-2016 12:05:00.854 -exec_4
22-Apr-2016 12:05:01.364 -exec_5
22-Apr-2016 12:05:02.951 end-1
22-Apr-2016 12:05:03.665 start-2
22-Apr-2016 12:05:04.751 -exec_1
22-Apr-2016 12:05:05.598 -exec_2
22-Apr-2016 12:05:06.165 end-2
22-Apr-2016 12:05:07.977 start-1
22-Apr-2016 12:05:08.315 -exec_1
22-Apr-2016 12:05:09.671 -exec_2
22-Apr-2016 12:05:10.139 end-1

As above example, I want to calculate only between start-1 and end-1 all -exec_* (*=1, 2, 3, ...) execute time, how can I do?
Currently I know can use 'transaction source startswith="start-1" endswith="end-1"' to group them, but I don't know how to calculate the all -exec_* (*=1, 2, 3, ...) execute time?

I want to the result like:
-exec_1 0.895 (22-Apr-2016 12:04:58.123 - 22-Apr-2016 12:04:57.228)
-exec_1 1.356 (22-Apr-2016 12:05:09.671 - 22-Apr-2016 12:05:08.315)
-exec_2 1.834 (22-Apr-2016 12:04:59.957 - 22-Apr-2016 12:04:58.123)
-exec_2 0.468 (22-Apr-2016 12:05:10.139 - 22-Apr-2016 12:05:09.671)
-exec_3 0.897 (22-Apr-2016 12:05:00.854 - 22-Apr-2016 12:04:59.957)
-exec_4 0.510 (22-Apr-2016 12:05:01.364 - 22-Apr-2016 12:05:00.854)
-exec_5 1.587 (22-Apr-2016 12:05:02.951 - 22-Apr-2016 12:05:01.364)

[Richfez · Accepted solution]

IF and only if they're always in order like that, you could use streamstats.

... my root search ... | rex field=_raw "^(?<datestring>\S+\s+\S+*)\s+(?<controlpoint>\S+"
| streamstats window=2 first(controlpoint) as portion, first(datestring) as start, last(datestring) as end
| table controlpoint, start, end

Obviously this isn't well tested. I think the rex should be right but if it isn't just post back.

The big drawback to this method is it'll treat those dates as strings. If you want to do math on them, and if they're the _time field (e.g. they're already extracted as the timestamp of the event), you could just ADD to the above...

... my root search ... | rex field=_raw "^(?<datestring>\S+\s+\S+*)\s+(?<controlpoint>\S+"
| streamstats window=2 first(controlpoint) as portion, first(datestring) as start, last(datestring) as end
  first(_time) as starttime, last(_time) as endtime
| eval elapsed=starttime-endtime
| table controlpoint, start, end, elapsed

Now, obviously, even LESS tested, but now it should show the elapsed time between each subsequent set of events. As always when I deal with streamstats, I'm positive I've gotten the first and last backwards so double-check all that. Probably did my math backwards then too. 😞

[blueyuan]

Thank you for your help, but I still can't catch, could you please explain more detail? thanks.

[blueyuan]

When I try this but show error message:
⚠ Error in 'rex' command: Encountered the following error while compiling the regex '^(?\S+\s+\S+*)\s+(?\S+': Regex: nothing to repeat.
How should I fix it? Thanks.

[Richfez]

I can't tell what rex you used. Can you please be sure to use the code button (101010) in the mini-editor in these text boxes, then paste your code there? "^(?<datestring>\S+\s+\S+*)\s+(?<controlpoint>\S+" is what you should have.

[Richfez]

First off, though - does it work and solve your problem?

Some explanations.

The rex uses a regular expression to create to fields, one called "datestring" which is two sets of characters ( \S+ which means non-space) separated by a space ( \s+ ) (like "22-Apr-2016 12:05:04.751") and another called "controlpoint" which is a bunch of non-space characters ( \S+ ).

For more on rex and regular expressions, along with some links of things to learn more, see the comment on the answer I wrote on the question How to extract a value of a field, when the field contains quotes(") Inside?.

The easiest way to think of streamstats is to think of a rolling window. As events stream by in the search results (first event, second event, third event and so on), streamstats groups each of these with previous ones. In this case window=2 so it groups the current event it's looking at with the previous event it just had. Setting window=8 would do 8 at a time. As it does so, it can calculate various statistics on those 2 or 8 or whatever. If you did an average, you'd have a running average of the past few events. I'm not doing that style of work with streamstats but am instead just grabbing values. First() and last() grab whichever as appropriate. You can read about streamstats (especially check the examples) or about the sorts of calculations it can do in the docs.

The eval statement created a new field elapsed, which is your starttime minus the endtime. Starttime being the first _time of each pair of events, endtime being the last _time of the pair, hence giving you an elapsed between each set of events. (Or they're backwards, again you may need to adjust because I always get those wrong in my head...)

Then I just added elapsed to your table.

Does that help?

[blueyuan]

Thank you very much, I will try it again.