0

I want to find out how long different actions in my old PHP web-application take. There is a log-file that writes out messages when an action is started and ended. It looks like this.

LOGFILE

2018-08-13 13:05:07,217 [30813] ControllerA: actionA start
2018-08-13 13:05:07,280 [30813] ControllerA: actionA end
2018-08-13 13:05:08,928 [30813] ControllerB: actionA start
2018-08-13 13:05:08,942 [30813] ControllerB: actionA end
2018-08-13 13:05:09,035 [17685] ControllerC: actionA start
2018-08-13 13:05:09,049 [17685] ControllerC: actionA end
2018-08-13 13:05:09,115 [8885] ControllerB: actionB start
2018-08-13 13:05:09,128 [8885] ControllerB: actionB end

I parsed the logs with logstash and a grok filter to get a JSON format that ElasticSearch can understand.

LOGSTASH FILTER

grok {
    match => { "message" => "%{EXIM_DATE:timestamp} \[%{NUMBER:pid}\] %{WORD:controller}: %{WORD:action} %{WORD:status}" }
}

The result is then indexed by ElasticSearch, but I don't know how I can find out how long each Action takes. Based on the pid, the name of the controller and the name of the action and the start/end status, I have all the information that are needed to find out how long the action takes. I want to display the duration of each action in Kibana, but I tried first to get data out of the index with a query. I read about aggregations and thought that they may be suitable for this kind of task.

I created the following query:

ES QUERY

{
    "aggs":{
        "group_by_pid": {
            "terms": {
                "field": "pid"
            }
        },
        "aggs": {
            "group_by_controller": {
                "terms": {
                    "field": "controller"
                }
            }
            "aggs": {
                "group_by_action": {
                    "terms":{
                        "field": "action"
                    }
                }
            }
        }
    }
}

But the response is always empty. I'm currently unsure if I can even calculate between each start and end action, or if I have to update the complete logging and calculate the duration in PHP.

Any suggestions are welcome!

Philip Koch
  • 197
  • 1
  • 11
  • 1
    this answer should help: https://stackoverflow.com/questions/37353365/calculating-time-between-events/37359000#37359000 – Val Aug 13 '18 at 12:10

1 Answers1

0

Thanks to the tip of Val and his response to another question I managed to get aggregated times for the different log-events using logstash.

This is the configuration:

input {
    file {
        path => "path/to/log.log"
    }
}
filter {
    grok {
        match => { "message" => "%{EXIM_DATE:timestamp} \[%{NUMBER:pid}\] %{WORD:controller}: %{WORD:action} %{WORD:status}" }
        add_tag => [ "%{status}" ]
    }

    elapsed {
        unique_id_field => "pid"
        start_tag => "start"
        end_tag => "end"
        new_event_on_match => false
    }

    if "elapsed" in [tags] {
        aggregate {
            task_id => "%{pid}"
            code => "map['duration'] = [(event.get('elapsed_time')*1000).to_i]"
            map_action => "create"
        }
    }
}
output {
    elasticsearch {
        hosts => [ "localhost:9200" ]
        index => "my_index_%{+xxxx_M}"
        action => "index"
    }
}

In Kibana I can now use the elapsed_time field created by the elapsed-filter to visualize the time each request takes.

Philip Koch
  • 197
  • 1
  • 11