buildstats.bbclass 13 KB

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