1# 2# Copyright OpenEmbedded Contributors 3# 4# SPDX-License-Identifier: MIT 5# 6 7BUILDSTATS_BASE = "${TMPDIR}/buildstats/" 8 9################################################################################ 10# Build statistics gathering. 11# 12# The CPU and Time gathering/tracking functions and bbevent inspiration 13# were written by Christopher Larson. 14# 15################################################################################ 16 17def get_buildprocess_cputime(pid): 18 with open("/proc/%d/stat" % pid, "r") as f: 19 fields = f.readline().rstrip().split() 20 # 13: utime, 14: stime, 15: cutime, 16: cstime 21 return sum(int(field) for field in fields[13:16]) 22 23def get_process_cputime(pid): 24 import resource 25 with open("/proc/%d/stat" % pid, "r") as f: 26 fields = f.readline().rstrip().split() 27 stats = { 28 'utime' : fields[13], 29 'stime' : fields[14], 30 'cutime' : fields[15], 31 'cstime' : fields[16], 32 } 33 iostats = {} 34 if os.path.isfile("/proc/%d/io" % pid): 35 with open("/proc/%d/io" % pid, "r") as f: 36 while True: 37 i = f.readline().strip() 38 if not i: 39 break 40 if not ":" in i: 41 # one more extra line is appended (empty or containing "0") 42 # most probably due to race condition in kernel while 43 # updating IO stats 44 break 45 i = i.split(": ") 46 iostats[i[0]] = i[1] 47 resources = resource.getrusage(resource.RUSAGE_SELF) 48 childres = resource.getrusage(resource.RUSAGE_CHILDREN) 49 return stats, iostats, resources, childres 50 51def get_cputime(): 52 with open("/proc/stat", "r") as f: 53 fields = f.readline().rstrip().split()[1:] 54 return sum(int(field) for field in fields) 55 56def set_timedata(var, d, server_time): 57 d.setVar(var, server_time) 58 59def get_timedata(var, d, end_time): 60 oldtime = d.getVar(var, False) 61 if oldtime is None: 62 return 63 return end_time - oldtime 64 65def set_buildtimedata(var, d): 66 import time 67 time = time.time() 68 cputime = get_cputime() 69 proctime = get_buildprocess_cputime(os.getpid()) 70 d.setVar(var, (time, cputime, proctime)) 71 72def get_buildtimedata(var, d): 73 import time 74 timedata = d.getVar(var, False) 75 if timedata is None: 76 return 77 oldtime, oldcpu, oldproc = timedata 78 procdiff = get_buildprocess_cputime(os.getpid()) - oldproc 79 cpudiff = get_cputime() - oldcpu 80 end_time = time.time() 81 timediff = end_time - oldtime 82 if cpudiff > 0: 83 cpuperc = float(procdiff) * 100 / cpudiff 84 else: 85 cpuperc = None 86 return timediff, cpuperc 87 88def write_task_data(status, logfile, e, d): 89 with open(os.path.join(logfile), "a") as f: 90 elapsedtime = get_timedata("__timedata_task", d, e.time) 91 if elapsedtime: 92 f.write(d.expand("${PF}: %s\n" % e.task)) 93 f.write(d.expand("Elapsed time: %0.2f seconds\n" % elapsedtime)) 94 cpu, iostats, resources, childres = get_process_cputime(os.getpid()) 95 if cpu: 96 f.write("utime: %s\n" % cpu['utime']) 97 f.write("stime: %s\n" % cpu['stime']) 98 f.write("cutime: %s\n" % cpu['cutime']) 99 f.write("cstime: %s\n" % cpu['cstime']) 100 for i in iostats: 101 f.write("IO %s: %s\n" % (i, iostats[i])) 102 rusages = ["ru_utime", "ru_stime", "ru_maxrss", "ru_minflt", "ru_majflt", "ru_inblock", "ru_oublock", "ru_nvcsw", "ru_nivcsw"] 103 for i in rusages: 104 f.write("rusage %s: %s\n" % (i, getattr(resources, i))) 105 for i in rusages: 106 f.write("Child rusage %s: %s\n" % (i, getattr(childres, i))) 107 if status == "passed": 108 f.write("Status: PASSED \n") 109 else: 110 f.write("Status: FAILED \n") 111 f.write("Ended: %0.2f \n" % e.time) 112 113def write_host_data(logfile, e, d, type): 114 import subprocess, os, datetime 115 # minimum time allowed for each command to run, in seconds 116 time_threshold = 0.5 117 limit = 10 118 # the total number of commands 119 num_cmds = 0 120 msg = "" 121 if type == "interval": 122 # interval at which data will be logged 123 interval = d.getVar("BB_HEARTBEAT_EVENT", False) 124 if interval is None: 125 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.") 126 d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0") 127 return 128 interval = int(interval) 129 cmds = d.getVar('BB_LOG_HOST_STAT_CMDS_INTERVAL') 130 msg = "Host Stats: Collecting data at %d second intervals.\n" % interval 131 if cmds is None: 132 d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0") 133 bb.warn("buildstats: Collecting host data at intervals failed. Set BB_LOG_HOST_STAT_CMDS_INTERVAL=\"command1 ; command2 ; ... \" in conf/local.conf.") 134 return 135 if type == "failure": 136 cmds = d.getVar('BB_LOG_HOST_STAT_CMDS_FAILURE') 137 msg = "Host Stats: Collecting data on failure.\n" 138 msg += "Failed at task: " + e.task + "\n" 139 if cmds is None: 140 d.setVar("BB_LOG_HOST_STAT_ON_FAILURE", "0") 141 bb.warn("buildstats: Collecting host data on failure failed. Set BB_LOG_HOST_STAT_CMDS_FAILURE=\"command1 ; command2 ; ... \" in conf/local.conf.") 142 return 143 c_san = [] 144 for cmd in cmds.split(";"): 145 if len(cmd) == 0: 146 continue 147 num_cmds += 1 148 c_san.append(cmd) 149 if num_cmds == 0: 150 if type == "interval": 151 d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0") 152 if type == "failure": 153 d.setVar("BB_LOG_HOST_STAT_ON_FAILURE", "0") 154 return 155 156 # return if the interval is not enough to run all commands within the specified BB_HEARTBEAT_EVENT interval 157 if type == "interval": 158 limit = interval / num_cmds 159 if limit <= time_threshold: 160 d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0") 161 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.") 162 return 163 164 # set the environment variables 165 path = d.getVar("PATH") 166 opath = d.getVar("BB_ORIGENV", False).getVar("PATH") 167 ospath = os.environ['PATH'] 168 os.environ['PATH'] = path + ":" + opath + ":" + ospath 169 with open(logfile, "a") as f: 170 f.write("Event Time: %f\nDate: %s\n" % (e.time, datetime.datetime.now())) 171 f.write("%s" % msg) 172 for c in c_san: 173 try: 174 output = subprocess.check_output(c.split(), stderr=subprocess.STDOUT, timeout=limit).decode('utf-8') 175 except (subprocess.CalledProcessError, subprocess.TimeoutExpired, FileNotFoundError) as err: 176 output = "Error running command: %s\n%s\n" % (c, err) 177 f.write("%s\n%s\n" % (c, output)) 178 # reset the environment 179 os.environ['PATH'] = ospath 180 181python run_buildstats () { 182 import bb.build 183 import bb.event 184 import time, subprocess, platform 185 186 bn = d.getVar('BUILDNAME') 187 ######################################################################## 188 # bitbake fires HeartbeatEvent even before a build has been 189 # triggered, causing BUILDNAME to be None 190 ######################################################################## 191 if bn is not None: 192 bsdir = os.path.join(d.getVar('BUILDSTATS_BASE'), bn) 193 taskdir = os.path.join(bsdir, d.getVar('PF')) 194 if isinstance(e, bb.event.HeartbeatEvent) and bb.utils.to_boolean(d.getVar("BB_LOG_HOST_STAT_ON_INTERVAL")): 195 bb.utils.mkdirhier(bsdir) 196 write_host_data(os.path.join(bsdir, "host_stats_interval"), e, d, "interval") 197 198 if isinstance(e, bb.event.BuildStarted): 199 ######################################################################## 200 # If the kernel was not configured to provide I/O statistics, issue 201 # a one time warning. 202 ######################################################################## 203 if not os.path.isfile("/proc/%d/io" % os.getpid()): 204 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)") 205 206 ######################################################################## 207 # at first pass make the buildstats hierarchy and then 208 # set the buildname 209 ######################################################################## 210 bb.utils.mkdirhier(bsdir) 211 set_buildtimedata("__timedata_build", d) 212 build_time = os.path.join(bsdir, "build_stats") 213 # write start of build into build_time 214 with open(build_time, "a") as f: 215 host_info = platform.uname() 216 f.write("Host Info: ") 217 for x in host_info: 218 if x: 219 f.write(x + " ") 220 f.write("\n") 221 f.write("Build Started: %0.2f \n" % d.getVar('__timedata_build', False)[0]) 222 223 elif isinstance(e, bb.event.BuildCompleted): 224 build_time = os.path.join(bsdir, "build_stats") 225 with open(build_time, "a") as f: 226 ######################################################################## 227 # Write build statistics for the build 228 ######################################################################## 229 timedata = get_buildtimedata("__timedata_build", d) 230 if timedata: 231 time, cpu = timedata 232 # write end of build and cpu used into build_time 233 f.write("Elapsed time: %0.2f seconds \n" % (time)) 234 if cpu: 235 f.write("CPU usage: %0.1f%% \n" % cpu) 236 237 if isinstance(e, bb.build.TaskStarted): 238 set_timedata("__timedata_task", d, e.time) 239 bb.utils.mkdirhier(taskdir) 240 # write into the task event file the name and start time 241 with open(os.path.join(taskdir, e.task), "a") as f: 242 f.write("Event: %s \n" % bb.event.getName(e)) 243 f.write("Started: %0.2f \n" % e.time) 244 245 elif isinstance(e, bb.build.TaskSucceeded): 246 write_task_data("passed", os.path.join(taskdir, e.task), e, d) 247 if e.task == "do_rootfs": 248 bs = os.path.join(bsdir, "build_stats") 249 with open(bs, "a") as f: 250 rootfs = d.getVar('IMAGE_ROOTFS') 251 if os.path.isdir(rootfs): 252 try: 253 rootfs_size = subprocess.check_output(["du", "-sh", rootfs], 254 stderr=subprocess.STDOUT).decode('utf-8') 255 f.write("Uncompressed Rootfs size: %s" % rootfs_size) 256 except subprocess.CalledProcessError as err: 257 bb.warn("Failed to get rootfs size: %s" % err.output.decode('utf-8')) 258 259 elif isinstance(e, bb.build.TaskFailed): 260 # Can have a failure before TaskStarted so need to mkdir here too 261 bb.utils.mkdirhier(taskdir) 262 write_task_data("failed", os.path.join(taskdir, e.task), e, d) 263 ######################################################################## 264 # Lets make things easier and tell people where the build failed in 265 # build_status. We do this here because BuildCompleted triggers no 266 # matter what the status of the build actually is 267 ######################################################################## 268 build_status = os.path.join(bsdir, "build_stats") 269 with open(build_status, "a") as f: 270 f.write(d.expand("Failed at: ${PF} at task: %s \n" % e.task)) 271 if bb.utils.to_boolean(d.getVar("BB_LOG_HOST_STAT_ON_FAILURE")): 272 write_host_data(os.path.join(bsdir, "host_stats_%s_failure" % e.task), e, d, "failure") 273} 274 275addhandler run_buildstats 276run_buildstats[eventmask] = "bb.event.BuildStarted bb.event.BuildCompleted bb.event.HeartbeatEvent bb.build.TaskStarted bb.build.TaskSucceeded bb.build.TaskFailed" 277 278python runqueue_stats () { 279 import buildstats 280 from bb import event, runqueue 281 # We should not record any samples before the first task has started, 282 # because that's the first activity shown in the process chart. 283 # Besides, at that point we are sure that the build variables 284 # are available that we need to find the output directory. 285 # The persistent SystemStats is stored in the datastore and 286 # closed when the build is done. 287 system_stats = d.getVar('_buildstats_system_stats', False) 288 if not system_stats and isinstance(e, (bb.runqueue.sceneQueueTaskStarted, bb.runqueue.runQueueTaskStarted)): 289 system_stats = buildstats.SystemStats(d) 290 d.setVar('_buildstats_system_stats', system_stats) 291 if system_stats: 292 # Ensure that we sample at important events. 293 done = isinstance(e, bb.event.BuildCompleted) 294 if system_stats.sample(e, force=done): 295 d.setVar('_buildstats_system_stats', system_stats) 296 if done: 297 system_stats.close() 298 d.delVar('_buildstats_system_stats') 299} 300 301addhandler runqueue_stats 302runqueue_stats[eventmask] = "bb.runqueue.sceneQueueTaskStarted bb.runqueue.runQueueTaskStarted bb.event.HeartbeatEvent bb.event.BuildCompleted bb.event.MonitorDiskEvent" 303