How to track application startup time?

[thesteve]

I have an application log that has two log lines I'm interested in trending.

The first line is:

timestamp Application is Starting up

The second line is

timestamp Application is Ready

I'd like to :

1. Be able to search for these pairs (transactions?)
2. Run a report that will show me T2(Ready)-T1(Starting) over time. In other words - I want to be able to see if the startup time is getting longer, or if there is a particular instance where the startup time is abnormally long.

Note: The second log line does not necessarily immediately follow the first. It is likely that there are other log messages in between.

[MuS]

Hi thesteve,

this is completely un-tested and I don't know if this will work, but you could try streamstats for this:

YourBaseSearchHere | streamstats current=f last(eval(if(match(_raw, "Application is Starting up"), _time , null() ))) AS start_time | eval ready_time=if(match(_raw, "Application is Ready"), _time, null() ) | eval duration=ready_time-start_time 

I'm not sure about the eval-if-match thingy, this just came up by ready the docs about eval....so this could also fails here, but streamstats is a good way to go. Also, the duration time would be in second format and probably needs some reformatting using strftime.

hope this helps ...

cheers, MuS

[MuS]

update: just to add, the last(eval(if(match(... works well 😉

[thesteve]

It didn't work for me. I have "Application is Starting up" and "Application child is Starting up" messages, so I'm wondering if that might be a problem. In either instance, using your search I don't see any duration values. I appreciate the insight though. I'm going to look into streamstats a bit more now.

[thesteve · Accepted solution]

The following search command yielded the results I was looking for:

index="myIndex" sourcetype="mySourceType" | transaction startswith="Application is Starting up" endswith="Application is Ready" | timechart avg(duration)

The search itself groups all of the log entries between start and end, and automatically calculates the duration from beginning to end. I did have to add the duration field to the results list by clicking the arrow on the left of the search result row and selecting the field to see it.

[thesteve]

Great idea! Thanks!

[martin_mueller]

As long as you're only interested in the duration I recommend throwing out the non-ready and non-startup events early:

index="myIndex" sourcetype="mySourceType" ("Application is Starting up" OR "Application is Ready") | transaction ...

That potentially saves your Splunk instances a lot of work building up huge transactions.

[MuS]

That's the obvious one, nice 🙂
Could you please try my search as well, just curious if this will work ...