#!/usr/bin/env python
#
#
# Licensed to the Apache Software Foundation (ASF) under one
# or more contributor license agreements. See the NOTICE file
# distributed with this work for additional information
# regarding copyright ownership. The ASF licenses this file
# to you under the Apache License, Version 2.0 (the
# "License"); you may not use this file except in compliance
# with the License. You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing,
# software distributed under the License is distributed on an
# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
# KIND, either express or implied. See the License for the
# specific language governing permissions and limitations
# under the License.
import os
import re
import datetime
import sys
import string
from optparse import OptionParser
from datetime import datetime, timedelta
import shutil
def showUsage():
log("./pT.py [-b|--broker-log-dir]
[-t|--test-dir] ")
ACCESS="Access"
MODIFY="Modify"
BROKER_LOG="broker.log"
BROKER_PID="broker.pid"
BROKER_CPU="broker_cpu.log"
BROKER_CPU_DATED="broker_cpu.log.dated"
BROKER_GC="gc.log"
GRAPH_DATA="graph.data"
_verbose = False
_debug = False
_brokerLogs = ""
def exitError(message):
log(message)
sys.exit(1)
def main():
global _log, _verbose, _debug, _brokerLogs
# Load the
parser = OptionParser()
parser.add_option("-v", "--verbose", dest="verbose",
action="store_true", default=False, help="enable verbose output")
parser.add_option("-d", "--debug", dest="debug",
action="store_true", default=False, help="enable debug output")
parser.add_option("-b", "--broker-log-dir", dest="brokerLogs",
action="store", default=True, help="Broker Logs")
parser.add_option("-t", "--test-dir", dest="testDir",
action="store", default="", help="Test Results")
(options, args) = parser.parse_args()
_verbose = options.verbose
_debug = options.debug
testDir = options.testDir
_brokerLogs = options.brokerLogs
if testDir == "" or _brokerLogs == "" :
log("Broker Log Dir and Test Dir are both requried.")
showUsage()
if not os.path.exists(testDir):
exitError("Test directory does not exist:" + testDir)
if not os.path.exists(_brokerLogs):
exitError("Broker log directory does not exist:" + _brokerLogs)
# Standardize the format of the broker logs
preProcessBrokerLogs(_brokerLogs)
# Get list of test results from test_dir
processTestResults(testDir)
#
# Process the log files we know of
#
def preProcessBrokerLogs(resultDir):
# Pre-Process GC - no pre processing required
# Process Log4j - no processing required as file is already time stamped.
# Pre-Process broker_cpu
processCPUUsage(resultDir)
#
# Process the broker CPU log file and create an output file of format
#
#
#
def processCPUUsage(resultDir):
logfile=resultDir+os.sep+BROKER_CPU
datedFile=resultDir+os.sep+BROKER_CPU_DATED
start = extractTime(ACCESS, logfile+".stat")
pid = getPID(BROKER_PID)
topRate = getFirstLine(_brokerLogs+os.sep+"top.rate")
#
# Calulate addition required per process line output
#
if topRate.find(".") == -1:
second = topRate
millis = 0
else:
split = topRate.split('.')
seconds = split[0]
# Convert
millis = float("0."+split[1]) * 1000
offset = timedelta(seconds=int(seconds),milliseconds=int(millis))
#
# Process the CPU log file and make a file of format:
# datetime
#
# Open log CPU file for reading
logfile = open(logfile, "r")
# Open the output file, erasing any existing version
output= open(datedFile, "w")
for line in logfile:
if line.find(pid) != -1:
# Split line on whitespace
data = line.split()
#
# Data format
# 0 1 2 3 4 5 6 7 8 9 10 11
# PID USER PR NI %CPU TIME+ %MEM VIRT RES SHR S COMMAND
#
#Write out the date time (ISO-8601 format)
output.write(str(start))
# Output the %CPU value
output.write(" "+str(data[4]))
# Output the %MEM value
output.write(" "+str(data[5]))
output.write('\n')
# Add the offset based on the logging rate
start = start + offset
# Close the files
logfile.close
output.close
log("Pre Process of CPU Log file '"+BROKER_CPU+"' complete")
#
# Give an known process type get the recorded PID.
#
def getPID(process):
return getFirstLine(_brokerLogs+os.sep+process)
#
# Get the first line of the file without EOL chars.
# NOTE: this will load the entire file into memory to do it.
#
def getFirstLine(fileName):
f = open(fileName,"r")
line = f.read().splitlines()[0]
f.close
return line
#
# Walk the directory given and process all csv test results
#
def processTestResults(resultDir):
for root, dirs, files in os.walk(resultDir, topdown=False):
if len(files) == 0:
exitError("Test result directory is empty:" + resultDir)
for file in files:
if file.endswith(".csv"):
processTestResult(root , file)
def processTestResult(root, resultFile):
# Open stat file and extract test times, we determine:
# -start time based on the 'Access' value
# -end time based on the 'Modify' value 'Change' would also work
statFile=root+os.sep+resultFile+".stat"
if not os.path.exists(statFile):
log("Unable to process : Unable to open stat file:" + statFile)
return
createResultSetPackage(root, resultFile)
def extractTime(field, statFile):
stats = open(statFile, "r")
for line in stats:
if line.startswith(field):
if line.find("(") == -1:
dt = lineToDate(" ".join(line.split()[1:]))
#
# TODO We need to handle time time zone issues as I'm sure we will have issues with the
# log4j matching.
stats.close
return dt
#
# Given a text line in ISO format convert it to a date object
#
def lineToDate(line):
#2009-06-22 17:04:44,320
#2009-06-22 17:04:44.320
pattern = re.compile(r'(?P^[0-9][0-9][0-9][0-9])-(?P[0-9][0-9])-(?P[0-9][0-9]) (?P[0-9][0-9]):(?P[0-9][0-9]):(?P[0-9][0-9])')
m = pattern.match(line)
if m:
year = int(m.group('year'))
month = int(m.group('month'))
day = int(m.group('day'))
hour = int(m.group('hour'))
minute = int(m.group('minute'))
seconds = int(m.group('seconds'))
pattern = re.compile(r'(?P^[0-9][0-9][0-9][0-9])-(?P[0-9][0-9])-(?P[0-9][0-9]) (?P[0-9][0-9]):(?P[0-9][0-9]):(?P[0-9][0-9])[.|,](?P[0-9]+)')
m = pattern.match(line)
micro = None
if m:
micro = m.group('micro')
if micro == None:
micro = 0
return datetime(year,month,day,hour,minute,seconds,int(micro))
else:
# Error we shouldn't get here
return null
def createResultSetPackage(root, resultFile):
# Get the Name of the test to make a directory with said name
testName = resultFile.split(".csv")[0]
resultDir = root+ os.sep + testName
log("Processing Result set for:"+ testName)
mkdir(resultDir)
# Move result file to new directory
shutil.move(root + os.sep + resultFile, resultDir)
# Move stat file to new directory
shutil.move(root + os.sep + resultFile + ".stat", resultDir)
statFile=resultDir + os.sep + resultFile + ".stat"
#
# Get start and end time for test run
#
start = extractTime(ACCESS, statFile)
end = extractTime(MODIFY, statFile)
sliceBrokerLogs(resultDir, start, end)
createGraphData(resultDir, testName)
log("Created Result Package for:"+ testName)
def sliceBrokerLogs(resultDir, start, end):
sliceCPULog(resultDir, start, end)
sliceLog4j(resultDir, start, end)
sliceGCLog(resultDir, start, end)
def sliceCPULog(resultDir, start, end):
global _brokerLogs
logfilePath=_brokerLogs+os.sep+BROKER_CPU_DATED
cpuSliceFile=resultDir+os.sep+BROKER_CPU
# Process the CPU log file and make a file of format:
# datetime
#
# Open log CPU file for reading
logFile = open(logfilePath, "r")
#
# Create outputfile
#
cpuslice = open(cpuSliceFile,"w")
for line in logFile:
data = line.split()
#
# //fixme remove tz addition.
#
lineTime = lineToDate(" ".join(data[0:2])+" +0000")
if lineTime > start:
if lineTime < end:
cpuslice.writelines(line)
logFile.close()
cpuslice.close()
log("Sliced CPU log")
def sliceGCLog(resultDir, start, end):
global _brokerLogs
logfilePath=_brokerLogs+os.sep+BROKER_GC
sliceFile=resultDir+os.sep+BROKER_GC
gcstart = extractTime(ACCESS, logfilePath+".stat")
# Open log GC file for reading
logFile = open(logfilePath, "r")
# Open the output file, erasing any existing version
output= open(sliceFile, "w")
# Use a regular expression to pull out the Seconds.Millis values from the
# Start of the gc log line.
pattern = re.compile(r'(?P^[0-9]+)\.(?P[0-9]+):')
for line in logFile:
m = pattern.match(line)
if m:
seconds = m.group('seconds');
millis = m.group('millis');
offset = timedelta(seconds=int(seconds),milliseconds=int(millis))
lineTime = gcstart + offset
if lineTime > start:
if lineTime < end:
output.writelines(line)
# Close the files
logFile.close
output.close()
log("Sliced gc log")
def sliceLog4j(resultDir, start, end):
global _brokerLogs
logfilePath=_brokerLogs+os.sep+BROKER_LOG
log4jSliceFile=resultDir+os.sep+BROKER_LOG
log4jstart = extractTime(ACCESS, logfilePath+".stat")
#
# Say that first line is the start of the file,
# This value will give a time value to the initial
# logging before Log4j kicks in.
#
lineTime = log4jstart
# Process the broker log4j file
# Open log CPU file for reading
logFile = open(logfilePath, "r")
#
# Create outputfile
#
log4jslice = open(log4jSliceFile,"w")
for line in logFile:
data = line.split()
#
# If the line has a time at the start then process it
# otherwise use the previous time. This means if there is
# a stack trace in the middle of the log file then it will
# be copied over to the split file as long as it is in the
# split time.
#
if (hasTime(data)):
#
# //fixme remove tz addition.
#
lineTime = lineToDate(" ".join(data[0:2])+" +0000")
if lineTime > start:
if lineTime < end:
print line
log4jslice.writelines(line)
logFile.close()
log4jslice.close()
log("Sliced broker log")
#
# Check the first two entries of data can make a datetime object
#
def hasTime(data):
date = data[0]
time = data[1]
# Examples:
# 2009-06-22 17:04:44,246
# 2009-06-22 17:04:44.2464
# 2009-06-22 17:04:44
# ISO-8601 '-' format date
dateRE = re.compile('[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9]')
#
# Check for times with/out millis
# e.g.
# 10:00:00,000 - log4j
# 10:00:00.0000 - generated in script for cpu time
#
timeRE = re.compile('[0-9][0-9]:[0-9][0-9]:[0-9][0-9]?[0-9]*')
return dateRE.match(date) and timeRE.match(time)
def createGraphData(resultDir, testName):
# Create graph.data file for process.sh
# Format two lines : Title and filename
# $version $type : $volume% volume
# $version-$brokerState-$type-$volume
version=getBrokerVersion()
test= extractTestValue("n",resultDir, testName)
volume = int(float(extractTestResult("Test * Size Throughput", resultDir, testName)) * 1000)
messageSize = extractTestValue("messageSize",resultDir, testName)
ackMode = ackModeToString(extractTestValue("consAckMode",resultDir, testName))
graphDataFile=resultDir+os.sep+GRAPH_DATA
graphData = open(graphDataFile, "w")
#
# Write Title
graphData.write(version+":"+test+":"+str(messageSize)+"kb x "+str(volume)+" msg/sec using "+ackMode)
graphData.write('\n')
#
# Write FileName
graphData.writelines(version+"-"+testName)
graphData.write('\n')
graphData.close
log("Created graph.data")
def getBrokerVersion():
global _brokerLogs
READY = "Qpid Broker Ready"
brokerLogFile = _brokerLogs + os.sep + BROKER_LOG
log = open(brokerLogFile, "r")
dataLine = ""
for line in log:
if line.find(READY) != -1:
dataLine = line
break
# Log Entry
#2009-06-19 17:04:02,493 INFO [main] server.Main (Main.java:456) - Qpid Broker Ready :2.3.0.1 build: 727403M
# Split on READY
data = dataLine.split(READY)
# So [1] should be
# :2.3.0.1 build: 727403M
readyEntries = data[1].split()
# so spliting on white space should give us ':version'
# and a quick split on ':' will give us the version
version = readyEntries[0].split(':')[1]
# Strip to ensure we have no whitespace
return version.strip()
def extractTestValue(property,resultDir,testName):
return extractTestData(property,resultDir,testName," =")
def extractTestResult(property,resultDir,testName):
return extractTestData(property,resultDir,testName,":")
def extractTestData(property,resultDir,testName,type):
resultFile = resultDir + os.sep + testName+".csv"
results = open(resultFile, "r")
dataLine = ""
for line in results:
if line.find("Total Tests:") == 0:
dataLine = line
results.close()
# Data is CSV
data = dataLine.split(',')
found = False
result = ""
searchProperty = property+type
for entry in data:
if found:
result = entry
break
if entry.strip() == searchProperty:
found=True
return result.strip()
def ackModeToString(ackMode):
if ackMode == '0':
return "Transacted"
elif ackMode == '1':
return "AutoAck"
elif ackMode == '2':
return "ClientAck"
elif ackMode == '3':
return "DupsOK"
elif ackMode == '257':
return "NoAck"
elif ackMode == '258':
return "PreAck"
else:
return str(ackMode)
def debug(msg):
global _debug
if _debug:
log(msg)
def log(msg):
print msg
def mkdir(dir):
if not os.path.exists(dir):
os.mkdir(dir)
if __name__ == "__main__":
main()