| 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 |
| # the total number of commands |
| num_cmds = 0 |
| # interval at which data will be logged |
| interval = int(d.getVar("BB_HEARTBEAT_EVENT", False)) |
| msg = "" |
| if type == "interval": |
| cmds = d.getVar('BB_LOG_HOST_STAT_CMDS_INTERVAL') |
| msg = "Host Stats: Collecting data at interval.\n" |
| 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\n") |
| 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\n") |
| return |
| c_san = [] |
| for cmd in cmds.split(";"): |
| if len(cmd) == 0: |
| continue |
| num_cmds += 1 |
| c_san.append(cmd) |
| if num_cmds <= 0: |
| d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0") |
| 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 |
| limit = interval / num_cmds |
| if limit <= time_threshold: |
| d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0") |
| d.setVar("BB_LOG_HOST_STAT_ON_FAILURE", "0") |
| bb.warn("buildstats: Collecting host data failed. BB_HEARTBEAT_EVENT interval not enough to run the specified commands. HINT: Increase value of BB_HEARTBEAT_EVENT in conf/local.conf\n") |
| 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"), 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"), 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) |
| system_stats.sample(e, force=done) |
| 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" |