diff --git a/Makefile.inc1 b/Makefile.inc1 --- a/Makefile.inc1 +++ b/Makefile.inc1 @@ -57,7 +57,9 @@ SRCDIR?= ${.CURDIR} LOCALBASE?= /usr/local -TIME_ENV ?= time env + +# you can disable time logging by setting this variable to an emypty value +TIME_ENV ?= ${.CURDIR}/tools/build/time-buildworld.sh .include "share/mk/src.tools.mk" @@ -789,7 +791,7 @@ MK_MAN_UTILS=yes BMAKE= \ - ${TIME_ENV} ${BMAKEENV} ${MAKE} ${WORLD_FLAGS} -f Makefile.inc1 \ + env TIME_MESSAGE="general bmake" ${TIME_ENV} ${BMAKEENV} ${MAKE} ${WORLD_FLAGS} -f Makefile.inc1 \ ${BSARGS} .if empty(.MAKEOVERRIDES:MMK_LLVM_TARGET_ALL) BMAKE+= MK_LLVM_TARGET_ALL=no @@ -797,7 +799,7 @@ # build-tools stage TMAKE= \ - ${TIME_ENV} ${BMAKEENV} ${MAKE} ${WORLD_FLAGS} -f Makefile.inc1 \ + env TIME_MESSAGE="general tmake" ${TIME_ENV} ${BMAKEENV} ${MAKE} ${WORLD_FLAGS} -f Makefile.inc1 \ TARGET=${TARGET} TARGET_ARCH=${TARGET_ARCH} \ DESTDIR= \ BOOTSTRAPPING=${BOOTSTRAPPING_OSRELDATE} \ @@ -830,7 +832,7 @@ WORLDTMP=${WORLDTMP} \ MAKEFLAGS="-m ${.CURDIR}/tools/build/mk ${.MAKEFLAGS}" -KTMAKE= ${TIME_ENV} \ +KTMAKE= env TIME_MESSAGE="general ktmake" ${TIME_ENV} \ TOOLS_PREFIX=${TOOLS_PREFIX_UNDEF:U${WORLDTMP}} \ ${KTMAKEENV} ${MAKE} ${WORLD_FLAGS} -f Makefile.inc1 \ DESTDIR= \ @@ -964,12 +966,12 @@ @echo "#endif" >> ${.TARGET} .endif -WMAKE= ${TIME_ENV} ${WMAKEENV} ${MAKE} ${WORLD_FLAGS} -f Makefile.inc1 \ +WMAKE= env TIME_MESSAGE="general wmake" ${TIME_ENV} ${WMAKEENV} ${MAKE} ${WORLD_FLAGS} -f Makefile.inc1 \ BWPHASE=${.TARGET:C,^_,,} \ DESTDIR=${WORLDTMP} IMAKEENV= ${CROSSENV} -IMAKE= ${TIME_ENV} ${IMAKEENV} ${MAKE} -f Makefile.inc1 \ +IMAKE= env TIME_MESSAGE="general imake" ${TIME_ENV} ${IMAKEENV} ${MAKE} -f Makefile.inc1 \ ${IMAKE_INSTALL} ${IMAKE_MTREE} .if empty(.MAKEFLAGS:M-n) IMAKEENV+= PATH=${STRICTTMPPATH:Q}:${INSTALLTMP:Q} \ @@ -1052,7 +1054,7 @@ # kernel stage KMAKEENV= ${WMAKEENV:NSYSROOT=*} -KMAKE= ${TIME_ENV} ${KMAKEENV} ${MAKE} ${.MAKEFLAGS} ${KERNEL_FLAGS} KERNEL=${INSTKERNNAME} +KMAKE= env TIME_MESSAGE="general kmake" ${TIME_ENV} ${KMAKEENV} ${MAKE} ${.MAKEFLAGS} ${KERNEL_FLAGS} KERNEL=${INSTKERNNAME} # # buildworld @@ -1137,7 +1139,7 @@ @echo "--------------------------------------------------------------" @echo ">>> stage 1.1: legacy release compatibility shims" @echo "--------------------------------------------------------------" - ${_+_}cd ${.CURDIR}; ${BMAKE} legacy + ${_+_}cd ${.CURDIR}; env STAGE_MESSAGE="1.1 legacy release compatibility shims" ${BMAKE} legacy _bootstrap-tools: @echo @echo "--------------------------------------------------------------" @@ -1146,7 +1148,7 @@ .if ${MK_CLEAN} != "yes" ${_+_}cd ${.CURDIR}; ${BMAKE} _NO_INCLUDE_COMPILERMK=t _cleanobj_fast_depend_hack .endif - ${_+_}cd ${.CURDIR}; ${BMAKE} bootstrap-tools + ${_+_}cd ${.CURDIR}; env STAGE_MESSAGE="1.2 bootstrap tools" ${BMAKE} bootstrap-tools mkdir -p ${WORLDTMP}/usr ${WORLDTMP}/lib/geom ${WORLDTMP}/bin ${WORLDTMP_MTREE} -f ${.CURDIR}/etc/mtree/BSD.usr.dist \ -p ${WORLDTMP}/usr >/dev/null @@ -1171,7 +1173,7 @@ @echo "--------------------------------------------------------------" # Avoid including bsd.compiler.mk in clean and obj with _NO_INCLUDE_COMPILERMK # since the restricted $PATH might not contain a valid cc binary - ${_+_}cd ${.CURDIR}; ${WMAKE} _NO_INCLUDE_COMPILERMK=t ${CLEANDIR} + ${_+_}cd ${.CURDIR}; env STAGE_MESSAGE="2.1 cleaning up the object tree" ${WMAKE} _NO_INCLUDE_COMPILERMK=t ${CLEANDIR} .for LIBCOMPAT in ${_LIBCOMPATS} ${_+_}cd ${.CURDIR}; ${LIB${LIBCOMPAT}WMAKE} _NO_INCLUDE_COMPILERMK=t -f Makefile.inc1 ${CLEANDIR} .endfor @@ -1183,27 +1185,27 @@ @echo "--------------------------------------------------------------" @echo ">>> stage 2.2: rebuilding the object tree" @echo "--------------------------------------------------------------" - ${_+_}cd ${.CURDIR}; ${WMAKE} _NO_INCLUDE_COMPILERMK=t obj + ${_+_}cd ${.CURDIR}; env STAGE_MESSAGE="2.2 rebuilding the object tree" ${WMAKE} _NO_INCLUDE_COMPILERMK=t obj _build-tools: @echo @echo "--------------------------------------------------------------" @echo ">>> stage 2.3: build tools" @echo "--------------------------------------------------------------" - ${_+_}cd ${.CURDIR}; ${TMAKE} build-tools + ${_+_}cd ${.CURDIR}; env STAGE_MESSAGE="2.3 build tools" ${TMAKE} build-tools _cross-tools: @echo @echo "--------------------------------------------------------------" @echo ">>> stage 3: cross tools" @echo "--------------------------------------------------------------" @rm -f ${OBJTOP}/toolchain-metadata.mk - ${_+_}cd ${.CURDIR}; ${XMAKE} cross-tools + ${_+_}cd ${.CURDIR}; env STAGE_MESSAGE="3 cross tools" ${XMAKE} cross-tools ${_+_}cd ${.CURDIR}; ${XMAKE} kernel-tools _build-metadata: @echo @echo "--------------------------------------------------------------" @echo ">>> stage 3.1: recording build metadata" @echo "--------------------------------------------------------------" - ${_+_}cd ${.CURDIR}; ${WMAKE} toolchain-metadata.mk + ${_+_}cd ${.CURDIR}; env STAGE_MESSAGE="3.1: recording build metadata" ${WMAKE} toolchain-metadata.mk ${_+_}cd ${.CURDIR}; ${WMAKE} host-osreldate.h _includes: @echo @@ -1212,7 +1214,7 @@ @echo "--------------------------------------------------------------" # Special handling for SUBDIR_OVERRIDE in buildworld as they most likely need # headers from default SUBDIR. Do SUBDIR_OVERRIDE includes last. - ${_+_}cd ${.CURDIR}; ${WMAKE} SUBDIR_OVERRIDE= SHARED=symlinks \ + ${_+_}cd ${.CURDIR}; env STAGE_MESSAGE="4.1 building includes" ${WMAKE} SUBDIR_OVERRIDE= SHARED=symlinks \ MK_INCLUDES=yes includes .if !empty(SUBDIR_OVERRIDE) && make(buildworld) ${_+_}cd ${.CURDIR}; ${WMAKE} MK_INCLUDES=yes SHARED=symlinks includes @@ -1224,7 +1226,7 @@ @echo ">>> stage 4.2: building libraries" @echo "--------------------------------------------------------------" ${_+_}cd ${.CURDIR}; \ - ${WMAKE} -DNO_FSCHG MK_HTML=no MK_MAN=no \ + env STAGE_MESSAGE="4.2 building libraries" ${WMAKE} -DNO_FSCHG MK_HTML=no MK_MAN=no \ MK_TESTS=no MK_TESTS_SUPPORT=${MK_TESTS_SUPPORT} \ libraries everything: .PHONY @@ -1232,7 +1234,7 @@ @echo "--------------------------------------------------------------" @echo ">>> stage 4.4: building everything" @echo "--------------------------------------------------------------" - ${_+_}cd ${.CURDIR}; _PARALLEL_SUBDIR_OK=1 ${WMAKE} all + ${_+_}cd ${.CURDIR}; _PARALLEL_SUBDIR_OK=1 env STAGE_MESSAGE="4.4 building everything" ${WMAKE} all WMAKE_TGTS= .if !defined(WORLDFAST) @@ -2953,7 +2955,7 @@ ${_+_}@${ECHODIR} "===> ${_tool} (obj,all,install)"; \ cd ${.CURDIR}/${_tool}; \ if [ -z "${NO_OBJWALK}" ]; then ${MAKE} DIRPRFX=${_tool}/ obj; fi; \ - ${MAKE} DIRPRFX=${_tool}/ all; \ + env STAGE_MESSAGE="3.0 cross tool ${_tool}" ${MAKE} DIRPRFX=${_tool}/ all; \ ${MAKE} DIRPRFX=${_tool}/ DESTDIR=${WORLDTMP} install .endfor @@ -3157,12 +3159,17 @@ # interdependencies (__L) are built automatically by the # ${.CURDIR}/tools/make_libdeps.sh script. # +# the normal libraries runs as stage 4.2.x, and the libcompat as stage 4.3.x libraries: .MAKE .PHONY ${_+_}cd ${.CURDIR}; \ - ${MAKE} -f Makefile.inc1 _prereq_libs; \ - ${MAKE} -f Makefile.inc1 _startup_libs; \ - ${MAKE} -f Makefile.inc1 _prebuild_libs -DLIBCRYPTO_WITHOUT_SUBDIRS; \ - ${MAKE} -f Makefile.inc1 _generic_libs + echo ">>> stage 4.2.1: _prereq_libs"; env TIME_MESSAGE="libraries _prereq_libs" STAGE_MESSAGE="4.2.1" \ + ${TIME_ENV} ${MAKE} -f Makefile.inc1 _prereq_libs; \ + echo ">>> stage 4.2.2: _startup_libs"; env TIME_MESSAGE="libraries _startup_libs" STAGE_MESSAGE="4.2.2" \ + ${TIME_ENV} ${MAKE} -f Makefile.inc1 _startup_libs; \ + echo ">>> stage 4.2.3: _prebuild_libs"; env TIME_MESSAGE="libraries _prebuild_libs" STAGE_MESSAGE="4.2.3" \ + ${TIME_ENV} ${MAKE} -f Makefile.inc1 _prebuild_libs -DLIBCRYPTO_WITHOUT_SUBDIRS; \ + echo ">>> stage 4.2.4: _generic_libs"; env TIME_MESSAGE="libraries _generic_libs" STAGE_MESSAGE="4.2.4" \ + ${TIME_ENV} ${MAKE} -f Makefile.inc1 _generic_libs # # static libgcc.a prerequisite for shared libc @@ -3511,7 +3518,7 @@ ${_+_}@${ECHODIR} "===> ${_lib} (obj,all,install)"; \ cd ${.CURDIR}/${_lib}; \ if [ -z "${NO_OBJWALK}" ]; then ${MAKE} MK_TESTS=no DIRPRFX=${_lib}/ obj; fi; \ - ${MAKE} MK_TESTS=no DIRPRFX=${_lib}/ all; \ + env TIME_MESSAGE="sublib ${_lib}" ${TIME_ENV} ${MAKE} MK_TESTS=no DIRPRFX=${_lib}/ all; \ ${MAKE} MK_TESTS=no DIRPRFX=${_lib}/ install .endif .endfor diff --git a/Makefile.libcompat b/Makefile.libcompat --- a/Makefile.libcompat +++ b/Makefile.libcompat @@ -31,7 +31,8 @@ MK_BOOT=no \ MK_CTF=no \ MK_TESTS=no -LIB${_LIBCOMPAT}WMAKE+= ${TIME_ENV} ${LIB${_LIBCOMPAT}WMAKEENV} ${MAKE} \ +LIB${_LIBCOMPAT}WMAKE+= \ + ${LIB${_LIBCOMPAT}WMAKEENV} ${MAKE} \ ${LIB${_LIBCOMPAT}WMAKEFLAGS} \ OBJTOP=${LIB${_LIBCOMPAT}_OBJTOP} \ OBJROOT='$${OBJTOP}/' \ diff --git a/share/mk/bsd.subdir.mk b/share/mk/bsd.subdir.mk --- a/share/mk/bsd.subdir.mk +++ b/share/mk/bsd.subdir.mk @@ -130,6 +130,7 @@ or by using an invalid $${MK_FOO} option. .endif +TIME_ENV ?= ${SRCTOP}/tools/build/time-buildworld.sh # Subdir code shared among 'make ', 'make ' and SUBDIR_PARALLEL. _SUBDIR_SH= \ if test -d ${.CURDIR}/$${dir}.${MACHINE_ARCH}; then \ @@ -137,7 +138,8 @@ fi; \ ${ECHODIR} "===> ${DIRPRFX}$${dir} ($${target})"; \ cd ${.CURDIR}/$${dir}; \ - ${MAKE} $${target} DIRPRFX=${DIRPRFX}$${dir}/ + _subdir=${.CURDIR:C/${SRCTOP}//}/$${dir}; \ + TIME_MESSAGE="subdir $${target} $${_subdir\#/}" ${TIME_ENV} ${MAKE} $${target} DIRPRFX=${DIRPRFX}$${dir}/ # This is kept for compatibility only. The normal handling of attaching to # SUBDIR_TARGETS will create a target for each directory. diff --git a/tools/build/time-buildworld-csv.awk b/tools/build/time-buildworld-csv.awk new file mode 100755 --- /dev/null +++ b/tools/build/time-buildworld-csv.awk @@ -0,0 +1,35 @@ +#!/usr/bin/awk -f +# +# Copyright (c) Mar 2025 Wolfram Schneider +# SPDX-License-Identifier: BSD-2-Clause +# +# time-buildworld-csv.awk - convert the output of time-buildworld.sh to a CSV file +# +# make buildworld > buildworld.log +# ./time-buildworld-csv.awk buildworld.log > time-buildworld.csv +# +# the input from `make buildworld' will look like: +# time: 4.54 real 7.21 user 0.29 sys start: 1742918038 end: 1742918043 exit: 0 message: sublib lib/libregex +# time: 1842.72 real 45627.13 user 1161.79 sys start: 1742918117 end: 1742919960 exit: 0 message: libraries _generic_libs stage: 4.2.4 MACHINE_ARCH=amd64 +# + +BEGIN { + OFS="\t"; # tab separated values for CSV + ORS="" # \n + + # CSV header + print "real", "user", "sys", "start", "end", "exit", "message", "stage" "\n" +} + +/^time: / { + # real, user, sys, start, end, exit + print $3, $5, $7, $9, $11, $13 + + # message/stage + sub(/.*? message: /, OFS) + sub(/ stage: /, OFS) + + print $0 "\n" +} + +#EOF diff --git a/tools/build/time-buildworld.sh b/tools/build/time-buildworld.sh new file mode 100755 --- /dev/null +++ b/tools/build/time-buildworld.sh @@ -0,0 +1,66 @@ +#!/bin/sh +# Copyright (c) Mar 2025 Wolfram Schneider +# SPDX-License-Identifier: BSD-2-Clause +# +# time-buildworld.sh - detailed time logging for `make buildworld' stages and steps +# +# This script will be called from /usr/src/Makefile.inc1. You can disable it by +# setting the variable TIME_ENV to an empty value. +# +# the output will look like: +# time: 4.54 real 7.21 user 0.29 sys start: 1742918038 end: 1742918043 exit: 0 message: sublib lib/libregex +# time: 1842.72 real 45627.13 user 1161.79 sys start: 1742918117 end: 1742919960 exit: 0 message: libraries _generic_libs stage: 4.2.4 MACHINE_ARCH=amd64 +# +# You can parse the output with: make buildworld | grep '^time: ' +# +# The output will appears if a target is done (end timestamp in seconds). + +# the message to display +message=${TIME_MESSAGE-"none"} + +# optional stage number (kind of grouping) +stage=${STAGE_MESSAGE-""} + +# system time(1), not from the shell +: ${time_cmd="/usr/bin/time"} + + +trap 'rm -f $tmpfile' 0 +# mktemp(1) is not portable +tmpfile=$(mktemp /tmp/_time-buildworld-XXXXXXXXX) + +# we want sub directory target "all" only, and ignore others +case $message in + 'subdir all'*) ;; + 'subdir '*) message="";; +esac + +# start time in seconds of command since epoch time, we need this for parallel builds +# note: FreeBSD date(1) does not support miliseconds +start=$(date '+%s') + +# execute the commands, no recursive stage message +# log the time in portable POSIX.2 format (FreeBSD, MacOS, Linux) +$time_cmd -p -o $tmpfile env STAGE_MESSAGE="" "$@" +exit=$? + +end=$(date '+%s') + +# CPU usage plus message / stage +if [ -n "$message" ]; then + m1="time: $(tr '\n' ' ' < $tmpfile)start: $start end: $end exit: $exit message: $message" + + if [ -n "$stage" ]; then + m2=" stage: $stage" + if [ -n "$MACHINE_ARCH" ]; then + m3=" MACHINE_ARCH=$MACHINE_ARCH" + fi + fi + + echo "${m1}${m2}${m3}" +fi + +# exit with command exit status +exit $exit + +#EOF