用 Kibana4 实现 PHP 慢日志函数堆栈分析

#!/usr/bin/env pypy
#coding:utf-8
import re
import sys
import time
import socket
import urllib2
import optparse
try: import simplejson as json
except ImportError: import json
from common import grokFpmSlow
defaultLogTag='fpmSlow'
hostname = socket.gethostname()
timeout = 120
def getOptions():
    usage = "usage: %prog [options]"
    OptionParser = optparse.OptionParser
    parser = OptionParser(usage)
    parser.add_option("-t","--logTag",action="store",type="string",dest="logTag",default=defaultLogTag,help="default log tag.")
    options,args = parser.parse_args()
    return options,args
def send_es(data, logtag):
    url = 'http://esdomain:9200/logstash-mweibo-' + data['@timestamp'].split('T')[0].replace('-','.') + '/' + logtag
    req = urllib2.Request(url, json.dumps(data), {'Content-Type':'application/json'})
    try:
        res = urllib2.urlopen(req)
        print "Return content:",res.read()
    except urllib2.URLError, e:
        if hasattr(e,"reason"):
            if e.reason == 'Bad Request' and data.has_key('jsoncontent'):
                data['message'] = json.dumps(data.pop('jsoncontent'))
                send_es(data, logtag)
            else:
                print "The reason:",e.reason
        elif hasattr(e,"code"):
            print "Error code:",e.code
            print "Return content:",e.read()
def flush(log_buffer, grokObj):
    data = "".join(log_buffer)
    match = re.match(grokObj.msg_regexp, data)
    if match:
        ret = grokObj.grokData(match)
        ret["host"] = hostname
    else:
        ret = {
            "host":hostname,
            "message":data,
            "@timestamp":time.strftime('%FT%T')+'+0800'
        }
    send_es(ret, grokObj.logtag)
def get_log(grokObj):
    start_time = time.time()
    log_buffer = []
    while True:
        try:
            line = sys.stdin.readline()
        except:
            break
        if not line:
            flush(log_buffer, grokObj)
            break
        if line:
            match = re.match(grokObj.start_regexp, line)
            if match and len(log_buffer) > 0:
                flush(log_buffer, grokObj)
                start_time = time.time()
                log_buffer = []
            log_buffer.append(line.rstrip())
        else:
            if (time.time() - startime > timeout ):
                flush(log_buffer, grokObj)
                start_time = time.time()
                log_buffer = []
            time.sleep(1)
if __name__ == '__main__':
    options,args = getOptions()
    if options.logTag == '':
        get_log(grokFpmSlow.fpmSlow(options.logTag))

#/usr/bin/pypy
#coding:utf-8
import re
import datetime
class fpmSlow():
    def __init__(self, _logtag):
        self.logtag = _logtag
        self.start_regexp = re.compile('^\[\d{2}-\w{3}-\d{4}')
        self.msg_regexp = re.compile('(?m)\[(?P<timestamp>\d{2}-\w{3}-\d{4} \d{2}:\d{2}:\d{2})\]  \[pool (?P<pool>\S+)\] pid (?P<pid>\d+)script_filename = (?P<slow_script>\S+)(?P<message>\[\w{18}\] (?P<slow_func>[^\[]*?:\d+).*\[\w{18}\](?P<begin_func>[^\[]*?:\d+))$')
    def grokData(self,match):
        ret = match.groupdict()
        ret['slow'] = {k: v for k, v in enumerate(re.split(r'\[\w{18}\] ', ret.pop('message'))) if k > 0 }
        ret["@timestamp"] = datetime.datetime.strptime(ret.pop("timestamp"), "%d-%b-%Y %H:%M:%S").strftime("%FT%T+0800")
        return ret

[13-May-2013 05:17:12]  [pool www] pid 13557
script_filename = /opt/www/inkebook/index.php
[0x000000000292e0f0] commit() /opt/www/inkebook/includes/database/mysql/database.inc:166
[0x000000000292de88] popCommittableTransactions() /opt/www/inkebook/includes/database/database.inc:1128
[0x000000000292dcf0] popTransaction() /opt/www/inkebook/includes/database/database.inc:1905
[0x00007fffe78cc460] __destruct() unknown:0
[0x000000000292c690] execute() /opt/www/inkebook/modules/statistics/statistics.module:73
[0x00007fffe78cc900] statistics_exit() unknown:0
[0x000000000292c208] call_user_func_array() /opt/www/inkebook/includes/module.inc:857
[0x000000000292bf10] module_invoke_all() /opt/www/inkebook/includes/common.inc:2688
[0x000000000292ade0] drupal_page_footer() /opt/www/inkebook/includes/common.inc:2676
[0x000000000292aa28] drupal_deliver_html_page() /opt/www/inkebook/includes/common.inc:2560
[0x000000000292a378] drupal_deliver_page() /opt/www/inkebook/includes/menu.inc:532
[0x000000000292a198] menu_execute_active_handler() /opt/www/inkebook/index.php:21

{
  "pool": "www",
  "pid": "13557",
  "slow_script": "/opt/www/inkebook/index.php",
  "slow_func": "commit() /opt/www/inkebook/includes/database/mysql/database.inc:166",
  "begin_func": "menu_execute_active_handler() /opt/www/inkebook/index.php:21", 
  "@timestamp": "2013-05-13T05:17:12+0800",
  "slow": {
    "1": "commit() /opt/www/inkebook/includes/database/mysql/database.inc:166",
    "2": "popCommittableTransactions() /opt/www/inkebook/includes/database/database.inc:1128",
    "3": "popTransaction() /opt/www/inkebook/includes/database/database.inc:1905",
    "4": "__destruct() unknown:0",
    "5": "execute() /opt/www/inkebook/modules/statistics/statistics.module:73",
    "6": "statistics_exit() unknown:0",
    "7": "call_user_func_array() /opt/www/inkebook/includes/module.inc:857",
    "8": "module_invoke_all() /opt/www/inkebook/includes/common.inc:2688",
    "9": "drupal_page_footer() /opt/www/inkebook/includes/common.inc:2676",
    "10": "drupal_deliver_html_page() /opt/www/inkebook/includes/common.inc:2560",
    "11": "drupal_deliver_page() /opt/www/inkebook/includes/menu.inc:532",
    "12": "menu_execute_active_handler() /opt/www/inkebook/index.php:21"
  }
}