Calculate duration between 2 events everytime those events occur

[raghul725]

Hello,

I am looking to calculate how long it takes to refresh the view using the time of the events "End View Refresh" and "Start View Refresh" i.e. find the difference in time for each of these events whenever these 2 events occur.

Tried number of things using streamstat and range, but it does provide me the desired result.
Any assistance would be appreciated.

Regards

[yuanliu]

Agree with @richgalloway.  To ask an answerable question about data analytics, you need to

• Illustrate data input (in raw text, anonymize as needed), whether they are raw events or output from a search that volunteers here do not have to look at.
• Illustrate the desired output from illustrated data.
• Explain the logic between illustrated data and desired output without SPL.
• If you also illustrate attempted SPL, illustrate actual output and compare with desired output, explain why they look different to you if that is not painfully obvious.

One more suggestion, have you considered transaction command?  People here do not throw transaction into recommendations lightly because there are usually better alternatives.  But without context, transaction is the generic approach that fits your description.

| transaction endswith="End View Refresh" startswith="Start View Refresh"

[raghul725]

Yup sorry, I should have delineated what I have done.

Log Examples:

Time:
10/10/24
6:30:11.478 AM

Start Event:
2024-10-10T06:30:11.478-04:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : Start View Refresh (price_vw) !!!

Time:
10/10/24
6:30:11.509 AM

End Event:
2024-10-10T06:30:11.509-04:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : End View Refresh (price_vw) !!!

index=* ("Start View Refresh (price_vw)" OR "End View Refresh (price_vw)")
| transaction startswith="Start View Refresh (price_vw)" endswith="End View Refresh (price_vw)"
| table duration

Now when I just look for the log events, I get 4 sets of Start and End events.

But when run the above for the same duration I was expecting 4 sets of duration, but I get just 2 sets.

[richgalloway]

With the same log, I would expect a single duration.  Perhaps the maxspan option to the transaction command will help.

[raghul725]

I am afraid I get the same results even with maxspan

[yuanliu]

Can you explain @richgalloway 's main question: How can two events produce 4 transactions (durations)?

Here is an emulation of the two events you illustrated, and the transaction command to follow

| makeresults format=csv data="_raw
2024-10-10T06:30:11.478-04:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : Start View Refresh (price_vw) !!!
2024-10-10T06:30:11.509-04:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : End View Refresh (price_vw) !!!"
| eval _time = strptime(replace(_raw, "(\S+).*", "\1"), "%FT%T.%3N%z")
| sort - _time
``` the above emulates
index=* ("Start View Refresh (price_vw)" OR "End View Refresh (price_vw)")
```
| transaction endswith="End View Refresh" startswith="Start View Refresh"

The result is

_raw	_time	closed_txn	duration	eventcount	field_match_sum	linecount
2024-10-10T06:30:11.478-04:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : Start View Refresh (price_vw) !!! 2024-10-10T06:30:11.509-04:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : End View Refresh (price_vw) !!!	2024-10-10 03:30:11.478	1	0.031	2	0	2

As richgalloway predicted, one duration.

[raghul725]

Hello, 2 events does not produce 4 results, 2 events will produce just 1 result.

The log I provided was just a sample set to show what I am searching.

So, if I search for just "View Refresh" for a duration of 1 hour, I see 4 sets of events - i.e 4 entries of "start" and "end" of each.

So when I ran my query I was expecting 4 duration values, 1 for each set. But I get 2 duration values. 

RichGalloway, suggested to add maxspan along with transaction. I did that, but I still get the same result i.e. 2 duration values and NOT 4 duration values.

[yuanliu]

---

The log I provided was just a sample set to show what I am searching.

So, if I search for just "View Refresh" for a duration of 1 hour, I see 4 sets of events - i.e 4 entries of "start" and "end" of each.

---

To underlying my commandments:

• Illustrate data input (in raw text, anonymize as needed), whether they are raw events or output from a search (SPL that volunteers here do not have to look at).
• Illustrate the desired output from illustrated data.

If volunteers do not see actual data (4 sets of events), how can we tell why you do not get desired results (4 durations)?

[raghul725]

OK, please find the details below

Logs below - 3 sets of Start and End.
And I expected my query to provide 3 duration values. But I get ONLY 2, as observed below.

10/9/24
10:32:31.540 AM

2024-10-09T10:32:31.540+08:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : End View Refresh (price_vw) !!!

10/9/24
10:32:14.000 AM

2024-10-09T09:32:14.000+07:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : End View Refresh (price_vw) !!!

10/9/24
10:30:36.643 AM

2024-10-09T09:30:36.643+07:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : Start View Refresh (price_vw) !!!

10/9/24
10:30:34.337 AM

2024-10-09T10:30:34.337+08:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : Start View Refresh (price_vw) !!!

10/9/24
10:02:32.229 AM

2024-10-09T10:02:32.229+08:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : End View Refresh (price_vw) !!!

10/9/24
10:00:42.108 AM

2024-10-09T10:00:42.108+08:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : Start View Refresh (price_vw) !!!

----------------------------- ------------------------------------------------------------------------------

Durations:

117.203
110.121

[yuanliu]

Is it correct that you posted three (3) sets of start-end, or am I missing something?  Here is my emulation and it gets 3 durations

| makeresults format=csv data="_raw
2024-10-09T10:32:31.540+08:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : End View Refresh (price_vw) !!!
2024-10-09T09:32:14.000+07:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : End View Refresh (price_vw) !!!
2024-10-09T09:30:36.643+07:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : Start View Refresh (price_vw) !!!
2024-10-09T10:30:34.337+08:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : Start View Refresh (price_vw) !!!
2024-10-09T10:02:32.229+08:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : End View Refresh (price_vw) !!!
2024-10-09T10:00:42.108+08:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : Start View Refresh (price_vw) !!!"
| eval _time = strptime(replace(_raw, "(\S+).*", "\1"), "%FT%T.%3N%z")
| sort - _time
``` the above emulates
index=* ("Start View Refresh (price_vw)" OR "End View Refresh (price_vw)")
```
| transaction endswith="End View Refresh" startswith="Start View Refresh"

_raw _time closed_txn duration eventcount field_match_sum linecount

2024-10-09T09:30:36.643+07:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : Start View Refresh (price_vw) !!! 2024-10-09T09:32:14.000+07:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : End View Refresh (price_vw) !!!	2024-10-08 19:30:36.643	1	97.357	2	0	2
2024-10-09T10:30:34.337+08:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : Start View Refresh (price_vw) !!! 2024-10-09T10:32:31.540+08:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : End View Refresh (price_vw) !!!	2024-10-08 19:30:34.337	1	117.203	2	0	2
2024-10-09T10:00:42.108+08:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : Start View Refresh (price_vw) !!! 2024-10-09T10:02:32.229+08:00 | INFO | 1 | | xxxxxxxxxxxxxxxxx : End View Refresh (price_vw) !!!	2024-10-08 19:00:42.108	1	110.121	2	0	2

Play with the emulation and compare with real data.

[richgalloway]

So we don't waste too much of your time repeated what you've already tried, please share your queries, some sample events, the desired results, and the current results.