#!/usr/bin/env python

#

# Copyright (c) 2010 Nokia Corporation and/or its subsidiary(-ies).

# All rights reserved.

# This component and the accompanying materials are made available

# under the terms of the License "Eclipse Public License v1.0"

# which accompanies this distribution, and is available

# at the URL "http://www.eclipse.org/legal/epl-v10.html".

#

# Initial Contributors:

# Nokia Corporation - initial contribution.

#

# Contributors:

#

# Description: 

# grokbuild

#

"""

Gathers performance metrics from the logs of a complex multi-step build.

Supports Helium 9 at the moment but is adaptable.

Can read from emake annotation files.  

"""

import sys

import os

import re

from  optparse import OptionParser

import annofile

import datetime

class UndeterminedBuildID(Exception):

	pass

class LogfileNotFound(Exception):

	pass

class HeliumLog(object):

	""" Some common properties of any log file in a helium build """

	filenamesuffix = None

	def __init__(self, logpath, buildid, options=None):

		self.logfilename = os.path.join(logpath, buildid + self.filenamesuffix)

		self.buildid = buildid

		self.options = options

	@classmethod

	def findall(c, logpath):

		""" Find all the logs that are of this type - essentially also finds all builds 

		    which dumped their output in the same place """

		filename_re = re.compile('(.*/)?(?P<buildid>[^\\\/]*)' + c.filenamesuffix)

		logs = {}

		for f in os.listdir(logpath):

			m = filename_re.match(f)

			if m:

				file_buildid = m.groupdict()['buildid']

				logs[file_buildid] = os.path.join(logpath,f)

		return logs

	def __str__(self):

		return "<metric name='buildid'  value='%s'>\n" % self.buildid

class MainAntLog(HeliumLog):

	""" This is the primary log of the helium build.  Useful for obtaining the total build time. Not good for this if the build failed. """

	# output/logs/92_7952_201020_003_main.ant.log

	filenamesuffix = "_main.ant.log"

	timeformat = "%Y/%m/%d %H:%M:%S:%f" # e.g. Thu 2010/06/24 09:15:42:625 AM

	def __init__(self, logpath, buildid, options=None):

		super(MainAntLog,self).__init__(logpath, buildid, options)

		# Starting logging into y:\output\logs\mcl_7901_201024_20100623181534_main.ant.log at Wed 2010/06/23 21:16:12:972 PM

		# Stopping logging into y:\output\logs\mcl_7901_201024_20100623181534_main.ant.log from hlm:record task at Thu 2010/06/24 09:15:42:625 AM

		start_re = re.compile("Starting logging into [^ ]+ at ... ([^ ]+ +[^ ]+) .*")

		stop_re = re.compile("Stopping logging into [^ ]+ from [^ ]+ task at ... ([^ ]+ +[^ ]+) (AM)|(PM).*")

		start_time = None

		stop_time = None

		with open(self.logfilename) as f:

			for l in f:

				if start_time is None:

					m = start_re.match(l)

					if m:

						#sys.stderr.write("start TIME: %s\n" %m.groups()[0])

						start_time = datetime.datetime.strptime(m.groups()[0], self.timeformat)

				else: # if there are many stop lines then make sure the last one overrides the others

					m = stop_re.match(l)

					if m:

						stop_time = datetime.datetime.strptime(m.groups()[0], self.timeformat)

						#sys.stderr.write("stop TIME: %s\n" %m.groups()[0])

		#sys.stderr.write("build start/stop: %s / %s  from %s\n" % (start_time, stop_time, self.logfilename))

		build_duration = stop_time - start_time  # returns a timedelta object

		self.build_duration = build_duration.seconds +  86400 * build_duration.days  # seconds

	def __str__(self):

		return "<metric name='build_duration'  value='%d'>\n" % self.build_duration

class AntEnvLog(HeliumLog):

	# output/logs/92_7952_201020_003_ant_env.log

	filenamesuffix = "_ant_env.log"

	def __init__(self, logpath, buildid):

		super(AntEnvLog,self).__init__(logpath, buildid)

class TargetTimesLog(HeliumLog):

	"""Very useful timing data from Ant but does not get created in all builds by default (must be configured"""

	# output/logs/92_7952_custom_dilbert_201022_dilbert_targetTimesLog.csv

	filenamesuffix = "_targetTimesLog.csv"

	def __init__(self, logpath, buildid):

		super(TargetTimesLog,self).__init__(logpath, buildid)

		self.raptorsecs = 0

		self.totalsecs = 0

		with open(self.logfilename) as f:

			for ll in f:

				l = ll.rstrip("\n")

				#print self.logfilename

				#print "L:",l

				(rname, rsecs) = l.split(",")

				rsecs = int(rsecs)

				#print "rname, rsecs: %s %d"%(rname,rsecs)

				self.totalsecs += rsecs

				if rname == "compile-sbs":

					self.raptorsecs += rsecs

	def __str__(self):

		s = "<metric name='build_duration'  value='%s'>" % self.totalsecs  \

			+ "\n<metric name='raptor_duration'  value='%s'>\n" % self.raptorsecs

		return s

class RaptorAnnofile(object):

	"""Thin wrapper around the annofile class to make it relevant to this utility."""

	# Examples:

	# 92_7952_custom_dilbert_201022_dilbert_dfs_build_sf_tools_all.resource.emake.anno

	# 92_7952_custom_dilbert_201022_dilbert_dfs_build_sf_dfs_variants.default.emake.anno

	# 92_7952_201022_003_dfs_build_ncp_dfs_variants.resource_deps.emake.anno

	def __init__(self, filename, buildid, maxagents):

		self.phase = ""

		self.filename = filename

		self.buildid = buildid

		self.annofile = annofile.Annofile(self.filename, maxagents)

	def __str__(self):

		return "<annofile name='%s' phase='%s'>\n%s</annofile>\n" \

	         % (os.path.basename(self.filename), self.phase, str(self.annofile))

class RaptorBuild(HeliumLog):

	"""Any Raptor logfile.  Mainly used for getting the names of the 

	annotation files which the annofile parser will use. Also gets

	the version of raptor and the total time taken by this particular

	invocation of Raptor"""

	def __init__(self, logpath, buildid, build, options=None):

		self.filenamesuffix = '_%s' % build

		super(RaptorBuild,self).__init__(os.path.join(logpath, "compile"), buildid, options)

		self.build = build

		if not os.path.isfile(self.logfilename):

			raise LogfileNotFound("missing log file: %s\n" % self.logfilename)

		self.annofile_refs = []	

		self.build_duration = None

		status_re = re.compile("<status exit='([a-z]+)'")

		emake_invocation_re = re.compile("<info>Executing.*--emake-annofile=([^ ]+)")

		emake_maxagents_re = re.compile("--emake-maxagents=(\d+)")

		sbs_version_re = re.compile("<info>sbs: version ([^\n\r]*)")

		run_time_re = re.compile("<info>Run time ([0-9]+) seconds</info>")

		self.recipes = { 'TOTAL':0, 'ok':0, 'failed':0, 'retry':0 }

		with open(self.logfilename) as f:

			sys.stderr.write("      parsing build log %s\n" % os.path.split(self.logfilename)[1])

			for l in f:

				# match in order of likelihood (most probable first)

				m = status_re.match(l)

				if m:

					self.recipes['TOTAL'] += 1

					status = m.group(1)

					try:

						self.recipes[status] += 1

					except KeyError:

						sys.stderr.write("unknown recipe status '%s'" % status)

					continue

				m = emake_invocation_re.match(l)

				if m:

					(adir, aname) = os.path.split(m.group(1))

					if aname.find("pp")==-1: # no parallel parsing ones preferably

						sys.stderr.write("        found annotation file %s\n" % aname)

						# if --emake-maxagents is present then use that, otherwise use

						# the value passed in through the options.

						m = emake_maxagents_re.match(l)

						if m:

							maxagents = int(m.group(1))

						else:

							maxagents = options.maxagents

							sys.stderr.write("          using maxagents %d as there is no record in the logs\n" % maxagents)

						self.annofile_refs.append( (os.path.join(logpath, "makefile", aname), maxagents) )

					continue

				m = run_time_re.match(l)

				if m:

					self.build_duration = int(m.group(1))

					continue

				m = sbs_version_re.match(l)

				if m:

					self.version = m.group(1)

		self.annofiles = []

		for p in self.annofile_refs:

			self.annofiles.append(RaptorAnnofile(p[0], buildid, p[1]))

	def __str__(self):

		recipes = [" <metric name='raptor_%s_recipes' value='%d'/>\n" % x for x in self.recipes.items()]

		return 	"<raptorbuild logfile='%s'>\n" % os.path.split(self.logfilename)[-1] + \

			" <metric name='raptor_version'  value='%s' />\n" % (self.version) + \

			" <metric name='raptor_duration_%s'  value='%d' />\n" % (self.build, self.build_duration) + \

			"".join(recipes) + \

			"".join([str(a) for a in self.annofiles]) + \

			"</raptorbuild>\n"

class HeliumBuild(object):

	"""A build with any version of Helium"""

	def __init__(self, logpath, buildid, options=None):

		self.options = options

		self.buildid = buildid

		self.logpath = logpath

		self.logfiles=[]

	def __str__(self):

		return  self.buildid + \

			"\n"+[str(a) for a in self.annofiles] + "\n"

class Helium9Build(HeliumBuild):

	""" Filenames, structure etc conform to Helium 9 """

	def __init__(self, logpath, buildid, options=None):

		super(Helium9Build,self).__init__(logpath, buildid, options)

		self.mainantlog = MainAntLog(logpath, buildid, options)

		self.raptorbuilds = []

		# mcl_7901_201024_20100623181534_dfs_build_ncp_variants.build_input_compile.log

		# mcl_7901_201024_20100623181534_dfs_build_sf_variants.build_input_compile.log

		# mcl_7901_201024_20100623181534_dfs_build_winscw_dfs_build_winscw_input_compile.log

		#

		# ....but the problem is that the anno files have a slightly differing convention:

		#        92_7952_201022_003_dfs_build_ncp_dfs_variants.resource_deps.emake.anno

		#  _dfs_build_ncp_variants

		#  _dfs_build_ncp_dfs_variants

                # read the annofile names from inside the raptor log output

		for r in ["dfs_build_ncp_variants.build_input_compile.log","dfs_build_sf_variants.build_input_compile.log","dfs_build_winscw_dfs_build_winscw_input_compile.log", "ncp_symbian_build_symtb_input_compile.log"]:

			try:

				self.raptorbuilds.append(RaptorBuild(logpath, buildid, r, options))

			except LogfileNotFound, ex:

				sys.stderr.write(str(ex))

	def __str__(self):

		raptor_duration = reduce(lambda x, y: x + y,[y.build_duration for y in self.raptorbuilds],0)

		return "<heliumbuild ver='9' id='%s'>\n" % (self.buildid) + \

			"<metric name='total_duration'  value='%d' />\n" % (self.mainantlog.build_duration) + \

			"<metric name='raptor_duration'  value='%d' />\n" % (raptor_duration) + \

	 		"".join([str(a) for a in self.raptorbuilds ]) + \

	 		"</heliumbuild>\n"

class HeliumLogDir(object):

	"""Multiple builds can be done one after another (usually when rebuilding 

	   things that failed, apparently) and their logs left in the output dir.

	   The naming convention ensures that they don't overwrite each other.

	   This class identifies each build and tries to analyse them one by one."""

	def __init__(self, epocroot, options=None):

		self.logpath = os.path.join(epocroot, "output/logs")

		logs = MainAntLog.findall(self.logpath)

		self.builds = []

		for b in logs.keys():

			try:

				sys.stderr.write("  Found build with id %s\n" % b)

				build = Helium9Build(self.logpath, b, options)

				self.builds.append(build)

			except IOError,e:

				sys.stderr.write("  Buildid %s found but does not refer to a complete build\n" % b)

				sys.stderr.write(str(e)+"\n")

	def write(self, stream):

		for b in self.builds:

			stream.write(str(b)+"\n")

parser = OptionParser(prog = "grokbuild",

                      usage = """%prog [-h | options] path_to_EPOCROOT 

The build logs are usually in $EPOCROOT/output/logs""")

parser.add_option("--maxagents", type="int", dest="maxagents", default=30,

				 help="The number of simultaneous agents used in the build. You need to supply this if --emake-class was used rather than --emake-maxagents since this is then a property of the build cluster and is not usually recorded in the logs. The default is %default."

				 )

(options, args) = parser.parse_args()

if len(args) == 0:

	sys.stderr.write("Need at least one argument: a path to the logs.\n")

	sys.exit(-1)

epocroot = args[0]

sys.stderr.write("Gathering Performance Metrics for %s\n" % epocroot)

b = HeliumLogDir(epocroot, options)

b.write(sys.stdout)