Finding execution time from kibana search queries

Elastic Stack Kibana
1

Hi,
I have the following pattern of tomcat logs:

INFO >2016-12-20 04:03:58,123 com.pkg.test.controller.JavaClassName[abc-0123-123]: Some text. Time taken:17
INFO >2016-12-20 04:04:19,123 com.pkg.test.controller.JavaClassName[art-9999-321]: ClassName(-,-) -> Some text; time taken:1
INFO >2016-12-20 04:04:53,123 com.pkg.test.controller.JavaClassName[uyt-8888-888]: someFunction (list): Completed. Time taken:2ms

I have multiple log patterns and it changes for different scenarios, so i can't write multiple patterns in my conf file. I have written the below grok pattern for my logs :

'%{LOGLEVEL:severity}%{SPACE}>%{TIMESTAMP_ISO8601:timestamp} %{JAVACLASS:class}[%{DATA:threadname}]:%{DATA:message}'

Now i want to find out the time taken by a particular class and create a graph for it. But the challenge is, i don't have an "Time taken" field and i have different "Time taken" text in my logs :

a) Time taken:17, with capital "T".
b) time taken:1, with small "t".
c) Time taken:2ms, with capital "T" and "ms" appended with it.

I want to find out all the classes whose time taken is greater than 5ms.

Thanks in advance!

2

I think you can do this by adjusting your grok pattern. You should be able to capture a time taken field with a grok pattern like so:

%{LOGLEVEL:severity}%{SPACE}>%{TIMESTAMP_ISO8601:timestamp} %{JAVACLASS:class}\[%{DATA:threadname}\]: %{DATA:message}[Tt]ime taken:%{NUMBER:TIME_TAKEN}

Are the values all in ms even if ms is missing?

By the way, in case you are unfamiliar, you can play around with grok patterns here

3

Hi Stacey,

Thanks for the response :slight_smile:
The above grok filter worked.

Yes, all the Time taken values are in "ms" even if is not appended.

Now I got another pattern for which I have written multiple grok pattern, but only one of the filter works which comes first and other fails. How this thing can be resolved?

Grok :

match => [
"message" , '%{LOGLEVEL:severity}%{SPACE}>%{TIMESTAMP_ISO8601:timestamp} %{JAVACLASS:class}[%{DATA:threadname}]: %{DATA:message}',
"message" , '%{LOGLEVEL:severity}%{SPACE}>%{TIMESTAMP_ISO8601:timestamp} %{JAVACLASS:class}[%{DATA:threadname}]: %{DATA:message}[Tt]ime [Tt]aken:%{NUMBER:TIME_TAKEN}'
]

Log pattern :

INFO >2016-12-27 08:00:38,006 com.pkg.test.controller.JavaClassName[abc-0553-123]: Some text.
INFO >2016-12-20 04:03:58,123 com.pkg.test.controller.JavaClassName[abc-0123-123]: Some text. Time taken:17
INFO >2016-12-20 04:04:19,123 com.pkg.test.controller.JavaClassName[art-9999-321]: ClassName(-,-) -> Some text; time taken:1
INFO >2016-12-20 04:04:53,123 com.pkg.test.controller.JavaClassName[uyt-8888-888]: someFunction (list): Completed. Time taken:2ms

Thanks!

4

If I'm understanding the situation correctly, the lines are matching on the first filter when you want it to match on the second filter (the one with [Tt]ime [Tt]aken). I suspect because the first one still matches the line so it never tries the second? If you put the more specific filter first, does it change the outcome?

You can also probably do this with one match line by making the last part options by changing it to (?:[Tt]ime taken:%{NUMBER:TIME_TAKEN}|). Though I seem to be having a problem matching the message that way, without using greedy data.

This one might work:
%{LOGLEVEL:severity}%{SPACE}>%{TIMESTAMP_ISO8601:timestamp} %{JAVACLASS:class}\[%{DATA:threadname}\]: (?:%{DATA:message}[Tt]ime taken:%{NUMBER:TIME_TAKEN}|%{GREEDYDATA:message})

By the way, you will probably get better help asking these questions in the logstash channel - there are people more versed in grok filters than I in there. :slight_smile:

Hope this helps!

5

I found a new pattern in my logs which has capital "T" in both "Time Taken", due to which I have changed the pattern to "[Tt]ime [Tt]aken".

The above pattern is working but there is an error:

If I am using GREEDYDATA:message, it shows two messages

Let me check the pattern with some more use cases as well.

Thanks for all the help :slight_smile:

6

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.