Chart timing of several events

[BradenFTL]

I have an automated script that creates a log file that marks the beginning and end of specific events during a web page process that I am wanting to monitor how long each process takes. I have put flags in the log file to notate the beginning of a process and the end of that process. OpenPage, Login, Search, Book, CustomerInfo, Seats, ClosePage. I can monitor that a certain process runs and the duration with the transaction command

transaction startswith="LoginProcessStart" endswith="LoginProcessEnd"

I don't know how to monitor several processes to add to the same table/chart. I have tried using multiple transaction commands, but I get an error stating the preceding search does not guarantee time-ordered events.

Any ideas of how to approach this problem? Thank you for any ideas you may have.

[BradenFTL]

2/1/2022 6:05:42 PM - Opening Browser and navigating to xxxx.com
2/1/2022 6:05:42 PM - WholeProcessStart
2/1/2022 6:05:50 PM - Cookie use Policy was accepted.
2/1/2022 6:05:51 PM - Running new page subflow.
2/1/2022 6:05:51 PM - NewPage
2/1/2022 6:05:53 PM - Starting Login process.
2/1/2022 6:05:53 PM - LoginProcessStart
2/1/2022 6:06:05 PM - Sign in button Overlay detected, waiting.....
2/1/2022 6:06:06 PM - Overlay closed successfully.
2/1/2022 6:06:08 PM - Login process complete.
2/1/2022 6:06:08 PM - LoginProcessEnd
2/1/2022 6:06:09 PM - Overlay detected, waiting.....
2/1/2022 6:06:14 PM - Overlay closed successfully.
2/1/2022 6:06:14 PM - SearchProcessStart
2/1/2022 6:06:17 PM - Populated Departure with FLL.
2/1/2022 6:06:19 PM - Populated Arrival with ORD.
2/1/2022 6:06:21 PM - Detected passenger count as: 1 Adult | 0 Children | 0 Infants
2/1/2022 6:06:22 PM - Detected Departure Location as: Fort Lauderdale, FL.
2/1/2022 6:06:24 PM - Detected Arrival Location as: Chicago, IL - O'Hare.
2/1/2022 6:06:24 PM - SearchProcessEnd
2/1/2022 6:06:25 PM - /book/flights Overlay detected, waiting.....
2/1/2022 6:06:25 PM - BookProcessStart
2/1/2022 6:06:34 PM - Overlay closed successfully.
2/1/2022 6:06:34 PM - Flight search button pressed.
2/1/2022 6:06:36 PM - Arrived at "https://www.xxxx.com/book/flights"
2/1/2022 6:06:40 PM - Following flight info selected:\nDeparture: Fort Lauderdale (FLL) to Chicago (ORD)
2/1/2022 6:06:40 PM - BookProcessEnd
2/1/2022 6:06:41 PM - /book/bundles Overlay detected, waiting.....
2/1/2022 6:06:41 PM - BundleProcessStart
2/1/2022 6:06:46 PM - Overlay closed successfully.
2/1/2022 6:06:47 PM - Continue with Standard button clicked.
2/1/2022 6:06:47 PM - Arrived at "https://www.xxxx.com/book/bundles".
2/1/2022 6:06:51 PM - Clicked on bundles "Continue" button.
2/1/2022 6:06:51 PM - BundleProcessEnd
2/1/2022 6:06:51 PM - CustomerProcessStart
2/1/2022 6:06:52 PM - Arrived at "https://www.xxxx.com/book/passenger".\n\nPassenger first name: Braden\nPassenger middle name: \nPassenger last name: Franklin\n\n\nClicking Continue button.
2/1/2022 6:06:52 PM - CustomerProcessEnd
2/1/2022 6:06:54 PM - /book/seats Overlay detected, waiting.....
2/1/2022 6:06:54 PM - SeatsProcessStart
2/1/2022 6:07:03 PM - Overlay closed successfully.
2/1/2022 6:07:04 PM - Arrived at "https://www.xxxx.com/book/seats", skipping and clicking on "Continue with standard" button.
2/1/2022 6:07:05 PM - /book/bags Overlay detected, waiting.....
2/1/2022 6:07:05 PM - SeatsProcessEnd
2/1/2022 6:07:06 PM - Overlay closed successfully.
2/1/2022 6:07:06 PM - BagsProcessStart
2/1/2022 6:07:10 PM - Selected 1 checked bag for departure and return.\nChecked bag total price: $69.00\n\nHitting Continue....
2/1/2022 6:07:12 PM - /book/options Overlay detected, waiting.....
2/1/2022 6:07:14 PM - Overlay closed successfully.
2/1/2022 6:07:14 PM - BagsProcessEnd
2/1/2022 6:07:14 PM - Arrived at "https://www.xxxx.com/book/options"
2/1/2022 6:07:14 PM - OptionsProcessStart
2/1/2022 6:07:19 PM - Modified Checkin Method.\nExpected: I'm not sure, I'll decide later\nActual: I'm not sure, I'll decide later\n\n\nPressing Continue.
2/1/2022 6:07:21 PM - Book option popup seen.
2/1/2022 6:07:22 PM - Book option popup closed.
2/1/2022 6:07:22 PM - OptionsProcessEnd
2/1/2022 6:07:22 PM - NewPage
2/1/2022 6:07:22 PM - WholeProcessEnd

[ITWhisperer]

You could do something like this:

| makeresults
| eval _raw="2/1/2022 6:05:42 PM - Opening Browser and navigating to xxxx.com
2/1/2022 6:05:42 PM - WholeProcessStart
2/1/2022 6:05:50 PM - Cookie use Policy was accepted.
2/1/2022 6:05:51 PM - Running new page subflow.
2/1/2022 6:05:51 PM - NewPage
2/1/2022 6:05:53 PM - Starting Login process.
2/1/2022 6:05:53 PM - LoginProcessStart
2/1/2022 6:06:05 PM - Sign in button Overlay detected, waiting.....
2/1/2022 6:06:06 PM - Overlay closed successfully.
2/1/2022 6:06:08 PM - Login process complete.
2/1/2022 6:06:08 PM - LoginProcessEnd
2/1/2022 6:06:09 PM - Overlay detected, waiting.....
2/1/2022 6:06:14 PM - Overlay closed successfully.
2/1/2022 6:06:14 PM - SearchProcessStart
2/1/2022 6:06:17 PM - Populated Departure with FLL.
2/1/2022 6:06:19 PM - Populated Arrival with ORD.
2/1/2022 6:06:21 PM - Detected passenger count as: 1 Adult | 0 Children | 0 Infants
2/1/2022 6:06:22 PM - Detected Departure Location as: Fort Lauderdale, FL.
2/1/2022 6:06:24 PM - Detected Arrival Location as: Chicago, IL - O'Hare.
2/1/2022 6:06:24 PM - SearchProcessEnd
2/1/2022 6:06:25 PM - /book/flights Overlay detected, waiting.....
2/1/2022 6:06:25 PM - BookProcessStart
2/1/2022 6:06:34 PM - Overlay closed successfully.
2/1/2022 6:06:34 PM - Flight search button pressed.
2/1/2022 6:06:36 PM - Arrived at \"https://www.xxxx.com/book/flights\"
2/1/2022 6:06:40 PM - Following flight info selected:\\nDeparture: Fort Lauderdale (FLL) to Chicago (ORD)
2/1/2022 6:06:40 PM - BookProcessEnd
2/1/2022 6:06:41 PM - /book/bundles Overlay detected, waiting.....
2/1/2022 6:06:41 PM - BundleProcessStart
2/1/2022 6:06:46 PM - Overlay closed successfully.
2/1/2022 6:06:47 PM - Continue with Standard button clicked.
2/1/2022 6:06:47 PM - Arrived at \"https://www.xxxx.com/book/bundles\".
2/1/2022 6:06:51 PM - Clicked on bundles \"Continue\" button.
2/1/2022 6:06:51 PM - BundleProcessEnd
2/1/2022 6:06:51 PM - CustomerProcessStart
2/1/2022 6:06:52 PM - Arrived at \"https://www.xxxx.com/book/passenger\".\\n\\nPassenger first name: Braden\\nPassenger middle name: \\nPassenger last name: Franklin\\n\\n\\nClicking Continue button.
2/1/2022 6:06:52 PM - CustomerProcessEnd
2/1/2022 6:06:54 PM - /book/seats Overlay detected, waiting.....
2/1/2022 6:06:54 PM - SeatsProcessStart
2/1/2022 6:07:03 PM - Overlay closed successfully.
2/1/2022 6:07:04 PM - Arrived at \"https://www.xxxx.com/book/seats\", skipping and clicking on \"Continue with standard\" button.
2/1/2022 6:07:05 PM - /book/bags Overlay detected, waiting.....
2/1/2022 6:07:05 PM - SeatsProcessEnd
2/1/2022 6:07:06 PM - Overlay closed successfully.
2/1/2022 6:07:06 PM - BagsProcessStart
2/1/2022 6:07:10 PM - Selected 1 checked bag for departure and return.\\nChecked bag total price: $69.00\\n\\nHitting Continue....
2/1/2022 6:07:12 PM - /book/options Overlay detected, waiting.....
2/1/2022 6:07:14 PM - Overlay closed successfully.
2/1/2022 6:07:14 PM - BagsProcessEnd
2/1/2022 6:07:14 PM - Arrived at \"https://www.xxxx.com/book/options\"
2/1/2022 6:07:14 PM - OptionsProcessStart
2/1/2022 6:07:19 PM - Modified Checkin Method.\\nExpected: I'm not sure, I'll decide later\\nActual: I'm not sure, I'll decide later\\n\\n\\nPressing Continue.
2/1/2022 6:07:21 PM - Book option popup seen.
2/1/2022 6:07:22 PM - Book option popup closed.
2/1/2022 6:07:22 PM - OptionsProcessEnd
2/1/2022 6:07:22 PM - NewPage
2/1/2022 6:07:22 PM - WholeProcessEnd"
| multikv noheader=t
| fields _raw
| eval _time=strptime(_raw,"%m/%d/%Y %I:%M:%S %p")
| rex "(?<process>\w+Process)(?<event>(Start|End))"
| eval {event}=_time
| stats values(Start) as Start values(End) as End by process

Given that your sample data has unique process names, this works. If your real data has repeated process names, you will need a way to distinguish between different instances of these process (as I alluded to in my earlier question).

[BradenFTL]

Yes. Each Process has a start name and an end name. i.e. 

transaction startswith="WholeProcessStart" endswith="WholeProcessEnd"

transaction startswith="LoginProcessStart" endswith="LoginProcessEnd"

transaction startswith="SearchProcessStart" endswith="SearchProcessEnd"

Each query works on its own, but I don't know how to get the timing data of all the various processes. In code it would be easy enough to put into a data table, but since Splunk is one big query line ... I don't know how to proceed.

Thank you.

[ITWhisperer]

Possibly you need to go back a step - what do your events look like? Can you share some sample (anonymised) events, preferably in a code block </>

[ITWhisperer]

Do you have a way to identify each process instance, so that you can distinguish between the start of one process and start of another process, for example?

[BradenFTL]

I don't think I am understanding the question. Each process has a start and end and your script was able to capture them for one time period. How does Splunk handle moving through time and recording the next instance of the event pair? A series of occurrences of an event can be charted by time, I thought the only difference in this query is that the series of occurrences is a pair of events. I apologize if I am not understanding you clearly. I do appreciate your time and assistance.