blob: f49a67aa4f07a22e67bf2e43211bdb63fb9aca77 [file] [log] [blame]
#
# Copyright OpenEmbedded Contributors
#
# SPDX-License-Identifier: MIT
#
BUILDSTATS_BASE = "${TMPDIR}/buildstats/"
################################################################################
# Build statistics gathering.
#
# The CPU and Time gathering/tracking functions and bbevent inspiration
# were written by Christopher Larson.
#
################################################################################
def get_buildprocess_cputime(pid):
with open("/proc/%d/stat" % pid, "r") as f:
fields = f.readline().rstrip().split()
# 13: utime, 14: stime, 15: cutime, 16: cstime
return sum(int(field) for field in fields[13:16])
def get_process_cputime(pid):
import resource
with open("/proc/%d/stat" % pid, "r") as f:
fields = f.readline().rstrip().split()
stats = {
'utime' : fields[13],
'stime' : fields[14],
'cutime' : fields[15],
'cstime' : fields[16],
}
iostats = {}
if os.path.isfile("/proc/%d/io" % pid):
with open("/proc/%d/io" % pid, "r") as f:
while True:
i = f.readline().strip()
if not i:
break
if not ":" in i:
# one more extra line is appended (empty or containing "0")
# most probably due to race condition in kernel while
# updating IO stats
break
i = i.split(": ")
iostats[i[0]] = i[1]
resources = resource.getrusage(resource.RUSAGE_SELF)
childres = resource.getrusage(resource.RUSAGE_CHILDREN)
return stats, iostats, resources, childres
def get_cputime():
with open("/proc/stat", "r") as f:
fields = f.readline().rstrip().split()[1:]
return sum(int(field) for field in fields)
def set_timedata(var, d, server_time):
d.setVar(var, server_time)
def get_timedata(var, d, end_time):
oldtime = d.getVar(var, False)
if oldtime is None:
return
return end_time - oldtime
def set_buildtimedata(var, d):
import time
time = time.time()
cputime = get_cputime()
proctime = get_buildprocess_cputime(os.getpid())
d.setVar(var, (time, cputime, proctime))
def get_buildtimedata(var, d):
import time
timedata = d.getVar(var, False)
if timedata is None:
return
oldtime, oldcpu, oldproc = timedata
procdiff = get_buildprocess_cputime(os.getpid()) - oldproc
cpudiff = get_cputime() - oldcpu
end_time = time.time()
timediff = end_time - oldtime
if cpudiff > 0:
cpuperc = float(procdiff) * 100 / cpudiff
else:
cpuperc = None
return timediff, cpuperc
def write_task_data(status, logfile, e, d):
with open(os.path.join(logfile), "a") as f:
elapsedtime = get_timedata("__timedata_task", d, e.time)
if elapsedtime:
f.write(d.expand("${PF}: %s\n" % e.task))
f.write(d.expand("Elapsed time: %0.2f seconds\n" % elapsedtime))
cpu, iostats, resources, childres = get_process_cputime(os.getpid())
if cpu:
f.write("utime: %s\n" % cpu['utime'])
f.write("stime: %s\n" % cpu['stime'])
f.write("cutime: %s\n" % cpu['cutime'])
f.write("cstime: %s\n" % cpu['cstime'])
for i in iostats:
f.write("IO %s: %s\n" % (i, iostats[i]))
rusages = ["ru_utime", "ru_stime", "ru_maxrss", "ru_minflt", "ru_majflt", "ru_inblock", "ru_oublock", "ru_nvcsw", "ru_nivcsw"]
for i in rusages:
f.write("rusage %s: %s\n" % (i, getattr(resources, i)))
for i in rusages:
f.write("Child rusage %s: %s\n" % (i, getattr(childres, i)))
if status == "passed":
f.write("Status: PASSED \n")
else:
f.write("Status: FAILED \n")
f.write("Ended: %0.2f \n" % e.time)
def write_host_data(logfile, e, d, type):
import subprocess, os, datetime
# minimum time allowed for each command to run, in seconds
time_threshold = 0.5
limit = 10
# the total number of commands
num_cmds = 0
msg = ""
if type == "interval":
# interval at which data will be logged
interval = d.getVar("BB_HEARTBEAT_EVENT", False)
if interval is None:
bb.warn("buildstats: Collecting host data at intervals failed. Set BB_HEARTBEAT_EVENT=\"<interval>\" in conf/local.conf for the interval at which host data will be logged.")
d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0")
return
interval = int(interval)
cmds = d.getVar('BB_LOG_HOST_STAT_CMDS_INTERVAL')
msg = "Host Stats: Collecting data at %d second intervals.\n" % interval
if cmds is None:
d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0")
bb.warn("buildstats: Collecting host data at intervals failed. Set BB_LOG_HOST_STAT_CMDS_INTERVAL=\"command1 ; command2 ; ... \" in conf/local.conf.")
return
if type == "failure":
cmds = d.getVar('BB_LOG_HOST_STAT_CMDS_FAILURE')
msg = "Host Stats: Collecting data on failure.\n"
msg += "Failed at task: " + e.task + "\n"
if cmds is None:
d.setVar("BB_LOG_HOST_STAT_ON_FAILURE", "0")
bb.warn("buildstats: Collecting host data on failure failed. Set BB_LOG_HOST_STAT_CMDS_FAILURE=\"command1 ; command2 ; ... \" in conf/local.conf.")
return
c_san = []
for cmd in cmds.split(";"):
if len(cmd) == 0:
continue
num_cmds += 1
c_san.append(cmd)
if num_cmds == 0:
if type == "interval":
d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0")
if type == "failure":
d.setVar("BB_LOG_HOST_STAT_ON_FAILURE", "0")
return
# return if the interval is not enough to run all commands within the specified BB_HEARTBEAT_EVENT interval
if type == "interval":
limit = interval / num_cmds
if limit <= time_threshold:
d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0")
bb.warn("buildstats: Collecting host data failed. BB_HEARTBEAT_EVENT interval not enough to run the specified commands. Increase value of BB_HEARTBEAT_EVENT in conf/local.conf.")
return
# set the environment variables
path = d.getVar("PATH")
opath = d.getVar("BB_ORIGENV", False).getVar("PATH")
ospath = os.environ['PATH']
os.environ['PATH'] = path + ":" + opath + ":" + ospath
with open(logfile, "a") as f:
f.write("Event Time: %f\nDate: %s\n" % (e.time, datetime.datetime.now()))
f.write("%s" % msg)
for c in c_san:
try:
output = subprocess.check_output(c.split(), stderr=subprocess.STDOUT, timeout=limit).decode('utf-8')
except (subprocess.CalledProcessError, subprocess.TimeoutExpired, FileNotFoundError) as err:
output = "Error running command: %s\n%s\n" % (c, err)
f.write("%s\n%s\n" % (c, output))
# reset the environment
os.environ['PATH'] = ospath
python run_buildstats () {
import bb.build
import bb.event
import time, subprocess, platform
bn = d.getVar('BUILDNAME')
########################################################################
# bitbake fires HeartbeatEvent even before a build has been
# triggered, causing BUILDNAME to be None
########################################################################
if bn is not None:
bsdir = os.path.join(d.getVar('BUILDSTATS_BASE'), bn)
taskdir = os.path.join(bsdir, d.getVar('PF'))
if isinstance(e, bb.event.HeartbeatEvent) and bb.utils.to_boolean(d.getVar("BB_LOG_HOST_STAT_ON_INTERVAL")):
bb.utils.mkdirhier(bsdir)
write_host_data(os.path.join(bsdir, "host_stats_interval"), e, d, "interval")
if isinstance(e, bb.event.BuildStarted):
########################################################################
# If the kernel was not configured to provide I/O statistics, issue
# a one time warning.
########################################################################
if not os.path.isfile("/proc/%d/io" % os.getpid()):
bb.warn("The Linux kernel on your build host was not configured to provide process I/O statistics. (CONFIG_TASK_IO_ACCOUNTING is not set)")
########################################################################
# at first pass make the buildstats hierarchy and then
# set the buildname
########################################################################
bb.utils.mkdirhier(bsdir)
set_buildtimedata("__timedata_build", d)
build_time = os.path.join(bsdir, "build_stats")
# write start of build into build_time
with open(build_time, "a") as f:
host_info = platform.uname()
f.write("Host Info: ")
for x in host_info:
if x:
f.write(x + " ")
f.write("\n")
f.write("Build Started: %0.2f \n" % d.getVar('__timedata_build', False)[0])
elif isinstance(e, bb.event.BuildCompleted):
build_time = os.path.join(bsdir, "build_stats")
with open(build_time, "a") as f:
########################################################################
# Write build statistics for the build
########################################################################
timedata = get_buildtimedata("__timedata_build", d)
if timedata:
time, cpu = timedata
# write end of build and cpu used into build_time
f.write("Elapsed time: %0.2f seconds \n" % (time))
if cpu:
f.write("CPU usage: %0.1f%% \n" % cpu)
if isinstance(e, bb.build.TaskStarted):
set_timedata("__timedata_task", d, e.time)
bb.utils.mkdirhier(taskdir)
# write into the task event file the name and start time
with open(os.path.join(taskdir, e.task), "a") as f:
f.write("Event: %s \n" % bb.event.getName(e))
f.write("Started: %0.2f \n" % e.time)
elif isinstance(e, bb.build.TaskSucceeded):
write_task_data("passed", os.path.join(taskdir, e.task), e, d)
if e.task == "do_rootfs":
bs = os.path.join(bsdir, "build_stats")
with open(bs, "a") as f:
rootfs = d.getVar('IMAGE_ROOTFS')
if os.path.isdir(rootfs):
try:
rootfs_size = subprocess.check_output(["du", "-sh", rootfs],
stderr=subprocess.STDOUT).decode('utf-8')
f.write("Uncompressed Rootfs size: %s" % rootfs_size)
except subprocess.CalledProcessError as err:
bb.warn("Failed to get rootfs size: %s" % err.output.decode('utf-8'))
elif isinstance(e, bb.build.TaskFailed):
# Can have a failure before TaskStarted so need to mkdir here too
bb.utils.mkdirhier(taskdir)
write_task_data("failed", os.path.join(taskdir, e.task), e, d)
########################################################################
# Lets make things easier and tell people where the build failed in
# build_status. We do this here because BuildCompleted triggers no
# matter what the status of the build actually is
########################################################################
build_status = os.path.join(bsdir, "build_stats")
with open(build_status, "a") as f:
f.write(d.expand("Failed at: ${PF} at task: %s \n" % e.task))
if bb.utils.to_boolean(d.getVar("BB_LOG_HOST_STAT_ON_FAILURE")):
write_host_data(os.path.join(bsdir, "host_stats_%s_failure" % e.task), e, d, "failure")
}
addhandler run_buildstats
run_buildstats[eventmask] = "bb.event.BuildStarted bb.event.BuildCompleted bb.event.HeartbeatEvent bb.build.TaskStarted bb.build.TaskSucceeded bb.build.TaskFailed"
python runqueue_stats () {
import buildstats
from bb import event, runqueue
# We should not record any samples before the first task has started,
# because that's the first activity shown in the process chart.
# Besides, at that point we are sure that the build variables
# are available that we need to find the output directory.
# The persistent SystemStats is stored in the datastore and
# closed when the build is done.
system_stats = d.getVar('_buildstats_system_stats', False)
if not system_stats and isinstance(e, (bb.runqueue.sceneQueueTaskStarted, bb.runqueue.runQueueTaskStarted)):
system_stats = buildstats.SystemStats(d)
d.setVar('_buildstats_system_stats', system_stats)
if system_stats:
# Ensure that we sample at important events.
done = isinstance(e, bb.event.BuildCompleted)
if system_stats.sample(e, force=done):
d.setVar('_buildstats_system_stats', system_stats)
if done:
system_stats.close()
d.delVar('_buildstats_system_stats')
}
addhandler runqueue_stats
runqueue_stats[eventmask] = "bb.runqueue.sceneQueueTaskStarted bb.runqueue.runQueueTaskStarted bb.event.HeartbeatEvent bb.event.BuildCompleted bb.event.MonitorDiskEvent"