diff --git a/include/host-build.mk b/include/host-build.mk index 9673d5c03c9..b459c0ab18c 100644 --- a/include/host-build.mk +++ b/include/host-build.mk @@ -182,34 +182,42 @@ ifndef DUMP $(if $(DUMP),,$(call HostHost/Autoclean)) $(HOST_STAMP_PREPARED): + $(call BuildTimeLog,begin,prepare) @-rm -rf $(HOST_BUILD_DIR) @mkdir -p $(HOST_BUILD_DIR) $(foreach hook,$(Hooks/HostPrepare/Pre),$(call $(hook))$(sep)) $(call Host/Prepare) $(foreach hook,$(Hooks/HostPrepare/Post),$(call $(hook))$(sep)) touch $$@ + $(call BuildTimeLog,end,prepare) $(call Host/Exports,$(HOST_STAMP_CONFIGURED)) $(HOST_STAMP_CONFIGURED): $(HOST_STAMP_PREPARED) + $(call BuildTimeLog,begin,configure) $(foreach hook,$(Hooks/HostConfigure/Pre),$(call $(hook))$(sep)) $(call Host/Configure) $(foreach hook,$(Hooks/HostConfigure/Post),$(call $(hook))$(sep)) touch $$@ + $(call BuildTimeLog,end,configure) $(call Host/Exports,$(HOST_STAMP_BUILT)) $(HOST_STAMP_BUILT): $(HOST_STAMP_CONFIGURED) + $(call BuildTimeLog,begin,compile) $(foreach hook,$(Hooks/HostCompile/Pre),$(call $(hook))$(sep)) $(call Host/Compile) $(foreach hook,$(Hooks/HostCompile/Post),$(call $(hook))$(sep)) touch $$@ + $(call BuildTimeLog,end,compile) $(call Host/Exports,$(HOST_STAMP_INSTALLED)) $(HOST_STAMP_INSTALLED): $(HOST_STAMP_BUILT) $(if $(FORCE_HOST_INSTALL),FORCE) + $(call BuildTimeLog,begin,install) $(call Host/Install,$(HOST_BUILD_PREFIX)) $(foreach hook,$(Hooks/HostInstall/Post),$(call $(hook))$(sep)) mkdir -p $$(shell dirname $$@) touch $(HOST_STAMP_BUILT) touch $$@ $(HOST_STAMP_PROGRAMS) + $(call BuildTimeLog,end,install) $(call DefaultTargets,$(patsubst %,host-%,$(DEFAULT_SUBDIR_TARGETS))) ifndef STAMP_BUILT diff --git a/include/kernel-build.mk b/include/kernel-build.mk index 404c318d413..bd859185ee8 100644 --- a/include/kernel-build.mk +++ b/include/kernel-build.mk @@ -90,12 +90,15 @@ define BuildKernel $(Kernel/Autoclean) $(STAMP_PREPARED): $(if $(LINUX_SITE),$(DL_DIR)/$(LINUX_SOURCE)) + $(call BuildTimeLog,begin,prepare) -rm -rf $(KERNEL_BUILD_DIR) -mkdir -p $(KERNEL_BUILD_DIR) $(Kernel/Prepare) touch $$@ + $(call BuildTimeLog,end,prepare) $(KERNEL_BUILD_DIR)/symtab.h: FORCE + $(call BuildTimeLog,begin,compile) rm -f $(KERNEL_BUILD_DIR)/symtab.h touch $(KERNEL_BUILD_DIR)/symtab.h +$(KERNEL_MAKE) vmlinux @@ -124,26 +127,33 @@ define BuildKernel awk '{print "*(___ksymtab_gpl+" $$$$1 ") \\" }'; \ echo; \ ) > $$@ + $(call BuildTimeLog,end,compile) $(STAMP_CONFIGURED): $(STAMP_PREPARED) $(LINUX_KCONFIG_LIST) $(TOPDIR)/.config FORCE + $(call BuildTimeLog,begin,configure) $(Kernel/Configure) touch $$@ + $(call BuildTimeLog,end,configure) $(LINUX_DIR)/.modules: export STAGING_PREFIX=$$(STAGING_DIR_HOST) $(LINUX_DIR)/.modules: export PKG_CONFIG_PATH=$$(STAGING_DIR_HOST)/lib/pkgconfig $(LINUX_DIR)/.modules: export PKG_CONFIG_LIBDIR=$$(STAGING_DIR_HOST)/lib/pkgconfig $(LINUX_DIR)/.modules: export FAIL_ON_UNCONFIGURED=1 $(LINUX_DIR)/.modules: $(STAMP_CONFIGURED) $(LINUX_DIR)/.config FORCE + $(call BuildTimeLog,begin,compile) $(Kernel/CompileModules) touch $$@ + $(call BuildTimeLog,end,compile) $(LINUX_DIR)/.image: export STAGING_PREFIX=$$(STAGING_DIR_HOST) $(LINUX_DIR)/.image: export PKG_CONFIG_PATH=$$(STAGING_DIR_HOST)/lib/pkgconfig $(LINUX_DIR)/.image: export PKG_CONFIG_LIBDIR=$$(STAGING_DIR_HOST)/lib/pkgconfig $(LINUX_DIR)/.image: $(STAMP_CONFIGURED) $(if $(CONFIG_STRIP_KERNEL_EXPORTS),$(KERNEL_BUILD_DIR)/symtab.h) FORCE + $(call BuildTimeLog,begin,compile) $(Kernel/CompileImage) $(Kernel/CollectDebug) touch $$@ + $(call BuildTimeLog,end,compile) mostlyclean: FORCE $(Kernel/Clean) diff --git a/include/package.mk b/include/package.mk index 9f284741df6..fe213f80411 100644 --- a/include/package.mk +++ b/include/package.mk @@ -247,6 +247,7 @@ define Build/CoreTargets $(STAMP_PREPARED) : export PATH=$$(TARGET_PATH_PKG) $(STAMP_PREPARED): $(STAMP_PREPARED_DEPENDS) + $(call BuildTimeLog,begin,prepare) @-rm -rf $(PKG_BUILD_DIR) @mkdir -p $(PKG_BUILD_DIR) touch $$@_check @@ -254,18 +255,22 @@ define Build/CoreTargets $(Build/Prepare) $(foreach hook,$(Hooks/Prepare/Post),$(call $(hook))$(sep)) touch $$@ + $(call BuildTimeLog,end,prepare) $(call Build/Exports,$(STAMP_CONFIGURED)) $(STAMP_CONFIGURED): $(STAMP_PREPARED) $(STAMP_CONFIGURED_DEPENDS) + $(call BuildTimeLog,begin,configure) rm -f $(STAMP_CONFIGURED_WILDCARD) $(CleanStaging) $(foreach hook,$(Hooks/Configure/Pre),$(call $(hook))$(sep)) $(Build/Configure) $(foreach hook,$(Hooks/Configure/Post),$(call $(hook))$(sep)) touch $$@ + $(call BuildTimeLog,end,configure) $(call Build/Exports,$(STAMP_BUILT)) $(STAMP_BUILT): $(STAMP_CONFIGURED) $(STAMP_BUILT_DEPENDS) + $(call BuildTimeLog,begin,compile) rm -f $$@ touch $$@_check $(foreach hook,$(Hooks/Compile/Pre),$(call $(hook))$(sep)) @@ -274,9 +279,11 @@ define Build/CoreTargets $(Build/Install) $(foreach hook,$(Hooks/Install/Post),$(call $(hook))$(sep)) touch $$@ + $(call BuildTimeLog,end,compile) $(STAMP_INSTALLED) : export PATH=$$(TARGET_PATH_PKG) $(STAMP_INSTALLED): $(STAMP_BUILT) + $(call BuildTimeLog,begin,install) rm -rf $(STAGING_TMP_DIR) mkdir -p $(STAGING_TMP_DIR)/host $(STAGING_DIR)/packages $(foreach hook,$(Hooks/InstallDev/Pre),\ @@ -300,6 +307,7 @@ define Build/CoreTargets fi rm -rf $(STAGING_TMP_DIR) touch $$@ + $(call BuildTimeLog,end,install) ifdef Build/InstallDev $(_pkg_target)compile: $(STAMP_INSTALLED) diff --git a/rules.mk b/rules.mk index cef05638354..6a959c2b9d2 100644 --- a/rules.mk +++ b/rules.mk @@ -196,6 +196,16 @@ STAGING_DIR_IMAGE:=$(STAGING_DIR)/image BUILD_LOG_DIR:=$(if $(call qstrip,$(CONFIG_BUILD_LOG_DIR)),$(call qstrip,$(CONFIG_BUILD_LOG_DIR)),$(TOPDIR)/logs) PKG_INFO_DIR := $(STAGING_DIR)/pkginfo +# Set BUILD_TIME_LOG= in the environment to record a begin and an end +# event for every prepare, configure, compile and install stage. Turn the log +# into a report with scripts/build-time-report.pl. +ifneq ($(BUILD_TIME_LOG),) + BUILD_TIME_LOG_FILE:=$(if $(filter /%,$(BUILD_TIME_LOG)),$(BUILD_TIME_LOG),$(TOPDIR)/$(BUILD_TIME_LOG)) + BuildTimeLog = @$(SCRIPT_DIR)/build-time-log.sh $(BUILD_TIME_LOG_FILE) $(1) $(2) "$(if $(BUILD_SUBDIR),$(BUILD_SUBDIR),$(CURDIR))$(if $(BUILD_VARIANT),/$(BUILD_VARIANT))" +else + BuildTimeLog = +endif + BUILD_DIR_HOST:=$(if $(IS_PACKAGE_BUILD),$(BUILD_DIR_BASE)/hostpkg,$(BUILD_DIR_BASE)/host) STAGING_DIR_HOST:=$(abspath $(STAGING_DIR)/../host) STAGING_DIR_HOSTPKG:=$(abspath $(STAGING_DIR)/../hostpkg) diff --git a/scripts/build-time-log.sh b/scripts/build-time-log.sh new file mode 100755 index 00000000000..20c61a261dd --- /dev/null +++ b/scripts/build-time-log.sh @@ -0,0 +1,18 @@ +#!/bin/sh +# +# SPDX-License-Identifier: GPL-2.0-only +# +# Records one build stage event. See scripts/build-time-report.pl. +# +# Usage: build-time-log.sh + +[ $# -eq 4 ] || exit 0 + +now=$(date +%s.%N 2>/dev/null) +case "$now" in + ''|*N*) now=$(date +%s) ;; +esac + +printf '%s\t%s\t%s\t%s\n' "$now" "$2" "$3" "$4" >> "$1" 2>/dev/null + +exit 0 diff --git a/scripts/build-time-report.pl b/scripts/build-time-report.pl new file mode 100755 index 00000000000..3f2e2a1c53b --- /dev/null +++ b/scripts/build-time-report.pl @@ -0,0 +1,181 @@ +#!/usr/bin/env perl +# +# SPDX-License-Identifier: GPL-2.0-only +# +# Turns a BUILD_TIME_LOG file into a report. +# +# Usage: build-time-report.pl [-n ] [-s ] +# +# Wall share is the share of the build duration that a stage is responsible +# for. Each second of the build is divided between the stages that run in it, +# so the wall shares of all stages add up to the busy time. A stage that runs +# alone on an idle machine gets the whole second. Solo time counts only the +# seconds in which a stage is the one thing that runs, so it is the part of +# the build that a faster stage shortens directly. + +use strict; +use warnings; + +my $top = 20; +my $only_stage; + +while (@ARGV && $ARGV[0] =~ /^-/) { + my $opt = shift @ARGV; + if ($opt eq '-n') { $top = shift @ARGV } + elsif ($opt eq '-s') { $only_stage = shift @ARGV } + else { die "Usage: $0 [-n ] [-s ] \n" } +} + +my $file = shift @ARGV or die "Usage: $0 [-n ] [-s ] \n"; + +open(my $fh, '<', $file) or die "$0: cannot read $file: $!\n"; + +my (@iv, %pending); + +while (my $line = <$fh>) { + chomp $line; + my ($time, $event, $stage, $name) = split(/\t/, $line, 4); + next unless defined $name; + next unless defined $time && $time =~ /^[0-9]+(\.[0-9]+)?$/; + next if defined $only_stage && $stage ne $only_stage; + + my $key = "$stage\t$name"; + + if ($event eq 'begin') { + push @{$pending{$key}}, $time; + next; + } + + next unless $event eq 'end'; + my $start = $pending{$key} ? pop @{$pending{$key}} : undef; + next unless defined $start; + + push @iv, { + idx => scalar @iv, + start => $start, + end => $time, + dur => $time - $start, + stage => $stage, + name => $name, + share => 0, + solo => 0, + }; +} + +close($fh); + +my $incomplete = 0; +$incomplete += scalar @{$pending{$_}} for keys %pending; + +die "$0: no completed stages in $file\n" unless @iv; + +my @events; +for my $iv (@iv) { + push @events, [ $iv->{start}, 1, $iv ]; + push @events, [ $iv->{end}, 0, $iv ]; +} + +# An end event sorts before a begin event at the same instant. One stage that +# hands over to the next one must not look like parallel work. +@events = sort { $a->[0] <=> $b->[0] || $a->[1] <=> $b->[1] } @events; + +my (%active, $idle, $busy); +$idle = 0; +$busy = 0; + +my $prev = $events[0][0]; + +for my $ev (@events) { + my ($t, $is_start, $iv) = @$ev; + my $dt = $t - $prev; + + if ($dt > 0) { + my @cur = values %active; + my $n = scalar @cur; + + if (!$n) { + $idle += $dt; + } + else { + $busy += $dt; + my $part = $dt / $n; + $_->{share} += $part for @cur; + $cur[0]->{solo} += $dt if $n == 1; + } + } + + if ($is_start) { $active{$iv->{idx}} = $iv } + else { delete $active{$iv->{idx}} } + + $prev = $t; +} + +my $total = $events[-1][0] - $events[0][0]; +my $sum_dur = 0; +$sum_dur += $_->{dur} for @iv; + +my (%st, %pkg); + +for my $iv (@iv) { + my $s = $st{$iv->{stage}} ||= { count => 0, dur => 0, share => 0, solo => 0 }; + $s->{count}++; + $s->{dur} += $iv->{dur}; + $s->{share} += $iv->{share}; + $s->{solo} += $iv->{solo}; + + my $key = sprintf("%s [%s]", $iv->{name}, $iv->{stage}); + my $p = $pkg{$key} ||= { dur => 0, share => 0, solo => 0 }; + $p->{dur} += $iv->{dur}; + $p->{share} += $iv->{share}; + $p->{solo} += $iv->{solo}; +} + +sub hms { + my $s = shift; + return sprintf("%d:%02d:%05.2f", + int($s / 3600), int($s / 60) % 60, $s - 60 * int($s / 60)); +} + +sub pct { + my ($a, $b) = @_; + return $b > 0 ? 100 * $a / $b : 0; +} + +printf "build window %s\n", hms($total); +printf "busy %s (%.1f%%)\n", hms($busy), pct($busy, $total); +printf "idle %s (%.1f%%)\n", hms($idle), pct($idle, $total); +printf "stage time %s\n", hms($sum_dur); +printf "mean parallelism %.2f\n", $busy > 0 ? $sum_dur / $busy : 0; +printf "stages completed %d\n", scalar @iv; +printf "stages unfinished %d\n", $incomplete if $incomplete; +print "\n"; + +printf "%-10s %6s %12s %12s %8s %12s %8s\n", + 'stage', 'count', 'sum', 'wall share', 'of wall', 'solo', 'of wall'; + +for my $name (sort { $st{$b}{share} <=> $st{$a}{share} } keys %st) { + my $s = $st{$name}; + printf "%-10s %6d %12s %12s %7.1f%% %12s %7.1f%%\n", + $name, $s->{count}, hms($s->{dur}), hms($s->{share}), + pct($s->{share}, $total), hms($s->{solo}), pct($s->{solo}, $total); +} + +sub table { + my ($title, $key, $ref) = @_; + + print "\n$title\n"; + printf "%-56s %12s %12s %12s\n", 'stage', 'duration', 'wall share', 'solo'; + + my @k = sort { $ref->{$b}{$key} <=> $ref->{$a}{$key} } keys %$ref; + splice(@k, $top) if @k > $top; + + for my $name (@k) { + my $e = $ref->{$name}; + printf "%-56s %12s %12s %12s\n", + $name, hms($e->{dur}), hms($e->{share}), hms($e->{solo}); + } +} + +table("top $top by wall share", 'share', \%pkg); +table("top $top by solo time", 'solo', \%pkg); +table("top $top by duration", 'dur', \%pkg);