blob: 0de605200a887460db057b67541af2351176dea3 [file] [log] [blame]
Patrick Williamsc124f4f2015-09-15 14:41:29 -05001BUILDSTATS_BASE = "${TMPDIR}/buildstats/"
Patrick Williamsc124f4f2015-09-15 14:41:29 -05002
3################################################################################
4# Build statistics gathering.
5#
6# The CPU and Time gathering/tracking functions and bbevent inspiration
Patrick Williamsd8c66bc2016-06-20 12:57:21 -05007# were written by Christopher Larson.
Patrick Williamsc124f4f2015-09-15 14:41:29 -05008#
9################################################################################
10
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050011def get_buildprocess_cputime(pid):
Patrick Williamsc124f4f2015-09-15 14:41:29 -050012 with open("/proc/%d/stat" % pid, "r") as f:
13 fields = f.readline().rstrip().split()
14 # 13: utime, 14: stime, 15: cutime, 16: cstime
15 return sum(int(field) for field in fields[13:16])
16
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050017def get_process_cputime(pid):
18 import resource
19 with open("/proc/%d/stat" % pid, "r") as f:
20 fields = f.readline().rstrip().split()
21 stats = {
22 'utime' : fields[13],
23 'stime' : fields[14],
24 'cutime' : fields[15],
25 'cstime' : fields[16],
26 }
27 iostats = {}
28 if os.path.isfile("/proc/%d/io" % pid):
29 with open("/proc/%d/io" % pid, "r") as f:
30 while True:
31 i = f.readline().strip()
32 if not i:
33 break
Brad Bishop6e60e8b2018-02-01 10:27:11 -050034 if not ":" in i:
35 # one more extra line is appended (empty or containing "0")
36 # most probably due to race condition in kernel while
37 # updating IO stats
38 break
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050039 i = i.split(": ")
40 iostats[i[0]] = i[1]
41 resources = resource.getrusage(resource.RUSAGE_SELF)
42 childres = resource.getrusage(resource.RUSAGE_CHILDREN)
43 return stats, iostats, resources, childres
44
Patrick Williamsc124f4f2015-09-15 14:41:29 -050045def get_cputime():
46 with open("/proc/stat", "r") as f:
47 fields = f.readline().rstrip().split()[1:]
48 return sum(int(field) for field in fields)
49
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050050def set_timedata(var, d, server_time):
51 d.setVar(var, server_time)
Patrick Williamsc124f4f2015-09-15 14:41:29 -050052
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050053def get_timedata(var, d, end_time):
54 oldtime = d.getVar(var, False)
55 if oldtime is None:
Patrick Williamsc124f4f2015-09-15 14:41:29 -050056 return
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050057 return end_time - oldtime
Patrick Williamsc124f4f2015-09-15 14:41:29 -050058
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050059def set_buildtimedata(var, d):
Patrick Williamsc124f4f2015-09-15 14:41:29 -050060 import time
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050061 time = time.time()
Patrick Williamsc124f4f2015-09-15 14:41:29 -050062 cputime = get_cputime()
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050063 proctime = get_buildprocess_cputime(os.getpid())
64 d.setVar(var, (time, cputime, proctime))
Patrick Williamsc124f4f2015-09-15 14:41:29 -050065
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050066def get_buildtimedata(var, d):
Patrick Williamsc124f4f2015-09-15 14:41:29 -050067 import time
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050068 timedata = d.getVar(var, False)
Patrick Williamsc124f4f2015-09-15 14:41:29 -050069 if timedata is None:
70 return
71 oldtime, oldcpu, oldproc = timedata
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050072 procdiff = get_buildprocess_cputime(os.getpid()) - oldproc
Patrick Williamsc124f4f2015-09-15 14:41:29 -050073 cpudiff = get_cputime() - oldcpu
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050074 end_time = time.time()
Patrick Williamsc124f4f2015-09-15 14:41:29 -050075 timediff = end_time - oldtime
76 if cpudiff > 0:
77 cpuperc = float(procdiff) * 100 / cpudiff
78 else:
79 cpuperc = None
80 return timediff, cpuperc
81
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050082def write_task_data(status, logfile, e, d):
Patrick Williamsc124f4f2015-09-15 14:41:29 -050083 with open(os.path.join(logfile), "a") as f:
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050084 elapsedtime = get_timedata("__timedata_task", d, e.time)
85 if elapsedtime:
Brad Bishop6e60e8b2018-02-01 10:27:11 -050086 f.write(d.expand("${PF}: %s\n" % e.task))
87 f.write(d.expand("Elapsed time: %0.2f seconds\n" % elapsedtime))
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050088 cpu, iostats, resources, childres = get_process_cputime(os.getpid())
Patrick Williamsc124f4f2015-09-15 14:41:29 -050089 if cpu:
Patrick Williamsd8c66bc2016-06-20 12:57:21 -050090 f.write("utime: %s\n" % cpu['utime'])
91 f.write("stime: %s\n" % cpu['stime'])
92 f.write("cutime: %s\n" % cpu['cutime'])
93 f.write("cstime: %s\n" % cpu['cstime'])
94 for i in iostats:
95 f.write("IO %s: %s\n" % (i, iostats[i]))
96 rusages = ["ru_utime", "ru_stime", "ru_maxrss", "ru_minflt", "ru_majflt", "ru_inblock", "ru_oublock", "ru_nvcsw", "ru_nivcsw"]
97 for i in rusages:
98 f.write("rusage %s: %s\n" % (i, getattr(resources, i)))
99 for i in rusages:
100 f.write("Child rusage %s: %s\n" % (i, getattr(childres, i)))
Andrew Geissler82c905d2020-04-13 13:39:40 -0500101 if status == "passed":
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500102 f.write("Status: PASSED \n")
103 else:
104 f.write("Status: FAILED \n")
105 f.write("Ended: %0.2f \n" % e.time)
106
Andrew Geisslerc926e172021-05-07 16:11:35 -0500107def write_host_data(logfile, e, d, type):
Andrew Geisslerd1e89492021-02-12 15:35:20 -0600108 import subprocess, os, datetime
Andrew Geissler95ac1b82021-03-31 14:34:31 -0500109 # minimum time allowed for each command to run, in seconds
110 time_threshold = 0.5
Andrew Geissler5f350902021-07-23 13:09:54 -0400111 limit = 10
Andrew Geissler95ac1b82021-03-31 14:34:31 -0500112 # the total number of commands
113 num_cmds = 0
Andrew Geisslerc926e172021-05-07 16:11:35 -0500114 msg = ""
115 if type == "interval":
Andrew Geissler5f350902021-07-23 13:09:54 -0400116 # interval at which data will be logged
117 interval = d.getVar("BB_HEARTBEAT_EVENT", False)
118 if interval is None:
119 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.")
120 d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0")
121 return
122 interval = int(interval)
Andrew Geisslerc926e172021-05-07 16:11:35 -0500123 cmds = d.getVar('BB_LOG_HOST_STAT_CMDS_INTERVAL')
Andrew Geissler5f350902021-07-23 13:09:54 -0400124 msg = "Host Stats: Collecting data at %d second intervals.\n" % interval
Andrew Geisslerc926e172021-05-07 16:11:35 -0500125 if cmds is None:
126 d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0")
Andrew Geissler5f350902021-07-23 13:09:54 -0400127 bb.warn("buildstats: Collecting host data at intervals failed. Set BB_LOG_HOST_STAT_CMDS_INTERVAL=\"command1 ; command2 ; ... \" in conf/local.conf.")
Andrew Geisslerc926e172021-05-07 16:11:35 -0500128 return
129 if type == "failure":
130 cmds = d.getVar('BB_LOG_HOST_STAT_CMDS_FAILURE')
131 msg = "Host Stats: Collecting data on failure.\n"
Andrew Geissler5f350902021-07-23 13:09:54 -0400132 msg += "Failed at task: " + e.task + "\n"
Andrew Geisslerc926e172021-05-07 16:11:35 -0500133 if cmds is None:
134 d.setVar("BB_LOG_HOST_STAT_ON_FAILURE", "0")
Andrew Geissler5f350902021-07-23 13:09:54 -0400135 bb.warn("buildstats: Collecting host data on failure failed. Set BB_LOG_HOST_STAT_CMDS_FAILURE=\"command1 ; command2 ; ... \" in conf/local.conf.")
Andrew Geisslerc926e172021-05-07 16:11:35 -0500136 return
Andrew Geissler95ac1b82021-03-31 14:34:31 -0500137 c_san = []
138 for cmd in cmds.split(";"):
139 if len(cmd) == 0:
140 continue
141 num_cmds += 1
142 c_san.append(cmd)
Andrew Geissler5f350902021-07-23 13:09:54 -0400143 if num_cmds == 0:
144 if type == "interval":
145 d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0")
146 if type == "failure":
147 d.setVar("BB_LOG_HOST_STAT_ON_FAILURE", "0")
Andrew Geissler95ac1b82021-03-31 14:34:31 -0500148 return
149
150 # return if the interval is not enough to run all commands within the specified BB_HEARTBEAT_EVENT interval
Andrew Geissler5f350902021-07-23 13:09:54 -0400151 if type == "interval":
152 limit = interval / num_cmds
153 if limit <= time_threshold:
154 d.setVar("BB_LOG_HOST_STAT_ON_INTERVAL", "0")
155 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.")
156 return
Andrew Geissler95ac1b82021-03-31 14:34:31 -0500157
158 # set the environment variables
Andrew Geisslerd1e89492021-02-12 15:35:20 -0600159 path = d.getVar("PATH")
160 opath = d.getVar("BB_ORIGENV", False).getVar("PATH")
161 ospath = os.environ['PATH']
162 os.environ['PATH'] = path + ":" + opath + ":" + ospath
163 with open(logfile, "a") as f:
164 f.write("Event Time: %f\nDate: %s\n" % (e.time, datetime.datetime.now()))
Andrew Geisslerc926e172021-05-07 16:11:35 -0500165 f.write("%s" % msg)
Andrew Geissler95ac1b82021-03-31 14:34:31 -0500166 for c in c_san:
Andrew Geisslerd1e89492021-02-12 15:35:20 -0600167 try:
Andrew Geissler95ac1b82021-03-31 14:34:31 -0500168 output = subprocess.check_output(c.split(), stderr=subprocess.STDOUT, timeout=limit).decode('utf-8')
Andrew Geisslerd1e89492021-02-12 15:35:20 -0600169 except (subprocess.CalledProcessError, subprocess.TimeoutExpired, FileNotFoundError) as err:
Andrew Geissler95ac1b82021-03-31 14:34:31 -0500170 output = "Error running command: %s\n%s\n" % (c, err)
171 f.write("%s\n%s\n" % (c, output))
172 # reset the environment
Andrew Geisslerd1e89492021-02-12 15:35:20 -0600173 os.environ['PATH'] = ospath
174
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500175python run_buildstats () {
176 import bb.build
177 import bb.event
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500178 import time, subprocess, platform
179
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500180 bn = d.getVar('BUILDNAME')
Andrew Geisslerd1e89492021-02-12 15:35:20 -0600181 ########################################################################
182 # bitbake fires HeartbeatEvent even before a build has been
183 # triggered, causing BUILDNAME to be None
184 ########################################################################
185 if bn is not None:
186 bsdir = os.path.join(d.getVar('BUILDSTATS_BASE'), bn)
187 taskdir = os.path.join(bsdir, d.getVar('PF'))
188 if isinstance(e, bb.event.HeartbeatEvent) and bb.utils.to_boolean(d.getVar("BB_LOG_HOST_STAT_ON_INTERVAL")):
189 bb.utils.mkdirhier(bsdir)
Andrew Geissler5f350902021-07-23 13:09:54 -0400190 write_host_data(os.path.join(bsdir, "host_stats_interval"), e, d, "interval")
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500191
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500192 if isinstance(e, bb.event.BuildStarted):
193 ########################################################################
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500194 # If the kernel was not configured to provide I/O statistics, issue
195 # a one time warning.
196 ########################################################################
197 if not os.path.isfile("/proc/%d/io" % os.getpid()):
198 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)")
199
200 ########################################################################
201 # at first pass make the buildstats hierarchy and then
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500202 # set the buildname
203 ########################################################################
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500204 bb.utils.mkdirhier(bsdir)
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500205 set_buildtimedata("__timedata_build", d)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500206 build_time = os.path.join(bsdir, "build_stats")
207 # write start of build into build_time
208 with open(build_time, "a") as f:
209 host_info = platform.uname()
210 f.write("Host Info: ")
211 for x in host_info:
212 if x:
213 f.write(x + " ")
214 f.write("\n")
Andrew Geissler4ed12e12020-06-05 18:00:41 -0500215 f.write("Build Started: %0.2f \n" % d.getVar('__timedata_build', False)[0])
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500216
217 elif isinstance(e, bb.event.BuildCompleted):
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500218 build_time = os.path.join(bsdir, "build_stats")
219 with open(build_time, "a") as f:
220 ########################################################################
221 # Write build statistics for the build
222 ########################################################################
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500223 timedata = get_buildtimedata("__timedata_build", d)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500224 if timedata:
225 time, cpu = timedata
226 # write end of build and cpu used into build_time
227 f.write("Elapsed time: %0.2f seconds \n" % (time))
228 if cpu:
229 f.write("CPU usage: %0.1f%% \n" % cpu)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500230
231 if isinstance(e, bb.build.TaskStarted):
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500232 set_timedata("__timedata_task", d, e.time)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500233 bb.utils.mkdirhier(taskdir)
234 # write into the task event file the name and start time
235 with open(os.path.join(taskdir, e.task), "a") as f:
236 f.write("Event: %s \n" % bb.event.getName(e))
237 f.write("Started: %0.2f \n" % e.time)
238
239 elif isinstance(e, bb.build.TaskSucceeded):
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500240 write_task_data("passed", os.path.join(taskdir, e.task), e, d)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500241 if e.task == "do_rootfs":
242 bs = os.path.join(bsdir, "build_stats")
243 with open(bs, "a") as f:
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500244 rootfs = d.getVar('IMAGE_ROOTFS')
Patrick Williamsc0f7c042017-02-23 20:41:17 -0600245 if os.path.isdir(rootfs):
246 try:
247 rootfs_size = subprocess.check_output(["du", "-sh", rootfs],
248 stderr=subprocess.STDOUT).decode('utf-8')
249 f.write("Uncompressed Rootfs size: %s" % rootfs_size)
250 except subprocess.CalledProcessError as err:
251 bb.warn("Failed to get rootfs size: %s" % err.output.decode('utf-8'))
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500252
253 elif isinstance(e, bb.build.TaskFailed):
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500254 # Can have a failure before TaskStarted so need to mkdir here too
255 bb.utils.mkdirhier(taskdir)
256 write_task_data("failed", os.path.join(taskdir, e.task), e, d)
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500257 ########################################################################
258 # Lets make things easier and tell people where the build failed in
259 # build_status. We do this here because BuildCompleted triggers no
260 # matter what the status of the build actually is
261 ########################################################################
262 build_status = os.path.join(bsdir, "build_stats")
263 with open(build_status, "a") as f:
Patrick Williamsd8c66bc2016-06-20 12:57:21 -0500264 f.write(d.expand("Failed at: ${PF} at task: %s \n" % e.task))
Andrew Geissler5f350902021-07-23 13:09:54 -0400265 if bb.utils.to_boolean(d.getVar("BB_LOG_HOST_STAT_ON_FAILURE")):
266 write_host_data(os.path.join(bsdir, "host_stats_%s_failure" % e.task), e, d, "failure")
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500267}
268
269addhandler run_buildstats
Andrew Geisslerd1e89492021-02-12 15:35:20 -0600270run_buildstats[eventmask] = "bb.event.BuildStarted bb.event.BuildCompleted bb.event.HeartbeatEvent bb.build.TaskStarted bb.build.TaskSucceeded bb.build.TaskFailed"
Patrick Williamsc124f4f2015-09-15 14:41:29 -0500271
Brad Bishop6e60e8b2018-02-01 10:27:11 -0500272python runqueue_stats () {
273 import buildstats
274 from bb import event, runqueue
275 # We should not record any samples before the first task has started,
276 # because that's the first activity shown in the process chart.
277 # Besides, at that point we are sure that the build variables
278 # are available that we need to find the output directory.
279 # The persistent SystemStats is stored in the datastore and
280 # closed when the build is done.
281 system_stats = d.getVar('_buildstats_system_stats', False)
282 if not system_stats and isinstance(e, (bb.runqueue.sceneQueueTaskStarted, bb.runqueue.runQueueTaskStarted)):
283 system_stats = buildstats.SystemStats(d)
284 d.setVar('_buildstats_system_stats', system_stats)
285 if system_stats:
286 # Ensure that we sample at important events.
287 done = isinstance(e, bb.event.BuildCompleted)
288 system_stats.sample(e, force=done)
289 if done:
290 system_stats.close()
291 d.delVar('_buildstats_system_stats')
292}
293
294addhandler runqueue_stats
295runqueue_stats[eventmask] = "bb.runqueue.sceneQueueTaskStarted bb.runqueue.runQueueTaskStarted bb.event.HeartbeatEvent bb.event.BuildCompleted bb.event.MonitorDiskEvent"