The Problem of Ticket Tracking
Systems tend to have workflows – where an object or ticket are passed around different systems. As someone responsible for monitoring such a system, I need to be able to keep track of the events to ensure that customers get served and orders processed. My main aim in this example is to track how long it takes to process tickets.
This kind of assumes you already have a Logscape environment running. If you don’t, download it now and get started!
Here’s some sample data
2015-02-02 12:31:12,035 ReportingThread INFO Folder:SWAP Ticket:DUMMYTICKET01 Version:2 State:Reporting Ticket. 3 tickets remaining 2015-02-02 12:31:12,207 ReportingThread INFO Folder:SWAP Ticket:DUMMYTICKET01 Version:2 State:Preparing to send to RSS 2015-02-02 12:31:12,207 ReportingThread INFO Folder:SWAP Ticket:DUMMYTICKET01 Version:2 State:Sending to RSS 2015-02-02 12:31:12,285 ReportingThread INFO Folder:SWAP Ticket:DUMMYTICKET01 Version:2 State:Post RSS Processing 2015-02-02 12:31:12,317 ReportingThread INFO Folder:SWAP Ticket:DUMMYTICKET01 Version:2 State:Finished Processing Ticket
Dealing with the Data
First, some preliminaries. Paste the data into the Data Types screen and hit transform. It should look something like this.
You can see that because there are key:value pairs, Logscape automatically forms the data into columns. This makes my life a lot easier – obviously I followed my own earlier advice in designing the log. Now look closely at the data. The first event is the start of the process and the last event marks the end – obviously in the real world these log lines are surrounded by other data. We can tell by the use of the Version number that a ticket can be submitted multiple times – meaning it’s been modified. I therefore cannot be sure of following each individual processing task unless I track the unique combination of the Folder, the Ticket and the Value. So, I’ve created a new field that does just that, called FTV.
Here is the Groovy script I used: groovy-script: def a = “” + Folder + “-” + Ticket + “-” + Version return a Each process now lists a single status for each unique FTV – so now we can track each ticket versions generation.
How long did each FTV process take?
Our initial question is quite simple. How long did it take a single Ticket Version to be generated? The answer may tell us a great deal about the performance of our system – perhaps certain Folders are inefficient or bloated. Now if I control the code and logging output, I could ask my developers to log a time taken within each line, but that would be a rather boring example to read. So instead, we are going to use the TXN function. TXN allows you to track the time between two or more events – Logscape will automatically measure the time between the first registered event and the last and calculate the time between them. So, this is my first search:
* | FTV.txn(elapsed) _type,equals(ExampleType) chart(scatter)
This was my first attempt at a search. It will search every line assigned ExampleType, track every line with a valid FTV field, and display the elapsed time taken. The advantage of this search is that it’s simple to implement. However it is measuring between the first FTV and the last FTV available… meaning that if a file fails to reach the final state, Logscape will give me the time between the first and last known states. It’s also inefficient in that I’m pulling back log lines that don’t have a FTV state.
State | Ticket.txn(elapsed) State.include(Reporting,Finished) _type,equals(ExampleType) chart(scatter)
This is a far more efficient search. It will only give me the initial and end states (meaning it will not report on failed tickets) and it means the log lines retrieved are only those with a valid state, improving my return speed. Your graph should look something like this:
I hope you found this helpful – let us know if there is any other common issue else you’d like to see explained.