BaseTools: report build time measured by module of EDKII Build

In the build report, we add AutoGen Phase, Make Phase and GenFds Phase
time duration in the Platform Summary section, and we also add a item
in Module section to display module and library's build time.

Cc: Liming Gao <liming.gao@intel.com>
Contributed-under: TianoCore Contribution Agreement 1.1
Signed-off-by: Yonghong Zhu <yonghong.zhu@intel.com>
Reviewed-by: Liming Gao <liming.gao@intel.com>

BaseTools/Source/Python/AutoGen/AutoGen.py

@@ -2695,6 +2695,7 @@ class ModuleAutoGen(AutoGen):
 
         self.BuildDatabase = self.Workspace.BuildDatabase
         self.BuildRuleOrder = None
+        self.BuildTime      = 0
 
         self._Module          = None
         self._Name            = None

BaseTools/Source/Python/build/BuildReport.py

@@ -307,7 +307,11 @@ class LibraryReport(object):
             LibConstructorList = Lib.ConstructorList
             LibDesstructorList = Lib.DestructorList
             LibDepexList = Lib.DepexExpression[M.Arch, M.ModuleType]
-            self.LibraryList.append((LibInfPath, LibClassList, LibConstructorList, LibDesstructorList, LibDepexList))
+            for LibAutoGen in M.LibraryAutoGenList:
+                if LibInfPath == LibAutoGen.MetaFile.Path:
+                    LibTime = LibAutoGen.BuildTime
+                    break
+            self.LibraryList.append((LibInfPath, LibClassList, LibConstructorList, LibDesstructorList, LibDepexList, LibTime))
 
     ##
     # Generate report for module library information
@@ -344,6 +348,8 @@ class LibraryReport(object):
                     LibDepex = " ".join(LibraryItem[4])
                     if LibDepex:
                         EdkIILibInfo += " Depex = " + LibDepex
+                    if LibraryItem[5]:
+                        EdkIILibInfo += " Time = " + LibraryItem[5]
                     if EdkIILibInfo:
                         FileWrite(File, "{%s: %s}" % (LibClass, EdkIILibInfo))
                     else:
@@ -553,6 +559,7 @@ class ModuleReport(object):
         self.PciDeviceId = M.Module.Defines.get("PCI_DEVICE_ID", "")
         self.PciVendorId = M.Module.Defines.get("PCI_VENDOR_ID", "")
         self.PciClassCode = M.Module.Defines.get("PCI_CLASS_CODE", "")
+        self.BuildTime = M.BuildTime
 
         self._BuildDir = M.BuildDir
         self.ModulePcdSet = {}
@@ -648,6 +655,8 @@ class ModuleReport(object):
             FileWrite(File, "SHA1 HASH:            %s *%s" % (self.Hash, self.ModuleName + ".efi"))
         if self.BuildTimeStamp:
             FileWrite(File, "Build Time Stamp:     %s" % self.BuildTimeStamp)
+        if self.BuildTime:
+            FileWrite(File, "Module Build Time:    %s" % self.BuildTime)
         if self.DriverType:
             FileWrite(File, "Driver Type:          %s" % self.DriverType)
         if self.UefiSpecVersion:
@@ -1696,9 +1705,12 @@ class PlatformReport(object):
     # @param self            The object pointer
     # @param File            The file object for report
     # @param BuildDuration   The total time to build the modules
+    # @param AutoGenTime     The total time of AutoGen Phase
+    # @param MakeTime        The total time of Make Phase
+    # @param GenFdsTime      The total time of GenFds Phase
     # @param ReportType      The kind of report items in the final report file
     #
-    def GenerateReport(self, File, BuildDuration, ReportType):
+    def GenerateReport(self, File, BuildDuration, AutoGenTime, MakeTime, GenFdsTime, ReportType):
         FileWrite(File, "Platform Summary")
         FileWrite(File, "Platform Name:        %s" % self.PlatformName)
         FileWrite(File, "Platform DSC Path:    %s" % self.PlatformDscPath)
@@ -1708,6 +1720,12 @@ class PlatformReport(object):
         FileWrite(File, "Output Path:          %s" % self.OutputPath)
         FileWrite(File, "Build Environment:    %s" % self.BuildEnvironment)
         FileWrite(File, "Build Duration:       %s" % BuildDuration)
+        if AutoGenTime:
+            FileWrite(File, "AutoGen Duration:     %s" % AutoGenTime)
+        if MakeTime:
+            FileWrite(File, "Make Duration:        %s" % MakeTime)
+        if GenFdsTime:
+            FileWrite(File, "GenFds Duration:      %s" % GenFdsTime)
         FileWrite(File, "Report Content:       %s" % ", ".join(ReportType))
 
         if GlobalData.MixedPcd:
@@ -1782,13 +1800,16 @@ class BuildReport(object):
     #
     # @param self            The object pointer
     # @param BuildDuration   The total time to build the modules
+    # @param AutoGenTime     The total time of AutoGen phase
+    # @param MakeTime        The total time of Make phase
+    # @param GenFdsTime      The total time of GenFds phase
     #
-    def GenerateReport(self, BuildDuration):
+    def GenerateReport(self, BuildDuration, AutoGenTime, MakeTime, GenFdsTime):
         if self.ReportFile:
             try:
                 File = StringIO('')
                 for (Wa, MaList) in self.ReportList:
-                    PlatformReport(Wa, MaList, self.ReportType).GenerateReport(File, BuildDuration, self.ReportType)
+                    PlatformReport(Wa, MaList, self.ReportType).GenerateReport(File, BuildDuration, AutoGenTime, MakeTime, GenFdsTime, self.ReportType)
                 Content = FileLinesSplit(File.getvalue(), gLineMaxLength)
                 SaveFileOnChange(self.ReportFile, Content, True)
                 EdkLogger.quiet("Build report can be found at %s" % os.path.abspath(self.ReportFile))

BaseTools/Source/Python/build/build.py

@@ -257,6 +257,7 @@ def ReadMessage(From, To, ExitFlag):
 # @param  WorkingDir            The directory in which the program will be running
 #
 def LaunchCommand(Command, WorkingDir):
+    BeginTime = time.time()
     # if working directory doesn't exist, Popen() will raise an exception
     if not os.path.isdir(WorkingDir):
         EdkLogger.error("build", FILE_NOT_FOUND, ExtraData=WorkingDir)
@@ -321,6 +322,7 @@ def LaunchCommand(Command, WorkingDir):
             EdkLogger.info(RespContent)
 
         EdkLogger.error("build", COMMAND_FAILURE, ExtraData="%s [%s]" % (Command, WorkingDir))
+    return "%dms" % (int(round((time.time() - BeginTime) * 1000)))
 
 ## The smallest unit that can be built in multi-thread build mode
 #
@@ -665,7 +667,7 @@ class BuildTask:
     #
     def _CommandThread(self, Command, WorkingDir):
         try:
-            LaunchCommand(Command, WorkingDir)
+            self.BuildItem.BuildObject.BuildTime = LaunchCommand(Command, WorkingDir)
             self.CompleteFlag = True
         except:
             #
@@ -763,6 +765,9 @@ class Build():
         self.BuildReport    = BuildReport(BuildOptions.ReportFile, BuildOptions.ReportType)
         self.TargetTxt      = TargetTxtClassObject()
         self.ToolDef        = ToolDefClassObject()
+        self.AutoGenTime    = 0
+        self.MakeTime       = 0
+        self.GenFdsTime     = 0
         GlobalData.BuildOptionPcd     = BuildOptions.OptionPcd
         #Set global flag for build mode
         GlobalData.gIgnoreSource = BuildOptions.IgnoreSources
@@ -1339,7 +1344,7 @@ class Build():
         if BuildModule:
             if Target != 'fds':
                 BuildCommand = BuildCommand + [Target]
-            LaunchCommand(BuildCommand, AutoGenObject.MakeFileDir)
+            AutoGenObject.BuildTime = LaunchCommand(BuildCommand, AutoGenObject.MakeFileDir)
             self.CreateAsBuiltInf()
             return True
 
@@ -1760,6 +1765,7 @@ class Build():
             GlobalData.gGlobalDefines['TARGET'] = BuildTarget
             index = 0
             for ToolChain in self.ToolChainList:
+                WorkspaceAutoGenTime = time.time()
                 GlobalData.gGlobalDefines['TOOLCHAIN'] = ToolChain
                 GlobalData.gGlobalDefines['TOOL_CHAIN_TAG'] = ToolChain
                 GlobalData.gGlobalDefines['FAMILY'] = self.ToolChainFamily[index]
@@ -1791,7 +1797,11 @@ class Build():
                 Wa.CreateMakeFile(False)
                 self.Progress.Stop("done!")
                 MaList = []
+                ExitFlag = threading.Event()
+                ExitFlag.clear()
+                self.AutoGenTime += int(round((time.time() - WorkspaceAutoGenTime)))
                 for Arch in Wa.ArchList:
+                    AutoGenStart = time.time()
                     GlobalData.gGlobalDefines['ARCH'] = Arch
                     Pa = PlatformAutoGen(Wa, self.PlatformFile, BuildTarget, ToolChain, Arch)
                     for Module in Pa.Platform.Modules:
@@ -1800,8 +1810,35 @@ class Build():
                             if Ma == None: continue
                             MaList.append(Ma)
                             self.BuildModules.append(Ma)
-                            if not Ma.IsBinaryModule:
+                    self.AutoGenTime += int(round((time.time() - AutoGenStart)))
-                                self._Build(self.Target, Ma, BuildModule=True)
+                    MakeStart = time.time()
+                    for Ma in self.BuildModules:
+                        if not Ma.IsBinaryModule:
+                            Bt = BuildTask.New(ModuleMakeUnit(Ma, self.Target))
+                        # Break build if any build thread has error
+                        if BuildTask.HasError():
+                            # we need a full version of makefile for platform
+                            ExitFlag.set()
+                            BuildTask.WaitForComplete()
+                            Pa.CreateMakeFile(False)
+                            EdkLogger.error("build", BUILD_ERROR, "Failed to build module", ExtraData=GlobalData.gBuildingModule)
+                        # Start task scheduler
+                        if not BuildTask.IsOnGoing():
+                            BuildTask.StartScheduler(self.ThreadNumber, ExitFlag)
+
+                    # in case there's an interruption. we need a full version of makefile for platform
+                    Pa.CreateMakeFile(False)
+                    if BuildTask.HasError():
+                        EdkLogger.error("build", BUILD_ERROR, "Failed to build module", ExtraData=GlobalData.gBuildingModule)
+                    self.MakeTime += int(round((time.time() - MakeStart)))
+
+                MakeContiue = time.time()
+                ExitFlag.set()
+                BuildTask.WaitForComplete()
+                self.CreateAsBuiltInf()
+                self.MakeTime += int(round((time.time() - MakeContiue)))
+                if BuildTask.HasError():
+                    EdkLogger.error("build", BUILD_ERROR, "Failed to build module", ExtraData=GlobalData.gBuildingModule)
 
                 self.BuildReport.AddPlatformReport(Wa, MaList)
                 if MaList == []:
@@ -1842,7 +1879,9 @@ class Build():
                     #
                     # create FDS again for the updated EFI image
                     #
+                    GenFdsStart = time.time()
                     self._Build("fds", Wa)
+                    self.GenFdsTime += int(round((time.time() - GenFdsStart)))
                     #
                     # Create MAP file for all platform FVs after GenFds.
                     #
@@ -1860,6 +1899,7 @@ class Build():
             GlobalData.gGlobalDefines['TARGET'] = BuildTarget
             index = 0
             for ToolChain in self.ToolChainList:
+                WorkspaceAutoGenTime = time.time()
                 GlobalData.gGlobalDefines['TOOLCHAIN'] = ToolChain
                 GlobalData.gGlobalDefines['TOOL_CHAIN_TAG'] = ToolChain
                 GlobalData.gGlobalDefines['FAMILY'] = self.ToolChainFamily[index]
@@ -1889,7 +1929,9 @@ class Build():
                 # multi-thread exit flag
                 ExitFlag = threading.Event()
                 ExitFlag.clear()
+                self.AutoGenTime += int(round((time.time() - WorkspaceAutoGenTime)))
                 for Arch in Wa.ArchList:
+                    AutoGenStart = time.time()
                     GlobalData.gGlobalDefines['ARCH'] = Arch
                     Pa = PlatformAutoGen(Wa, self.PlatformFile, BuildTarget, ToolChain, Arch)
                     if Pa == None:
@@ -1924,7 +1966,8 @@ class Build():
                                 continue
                         self.BuildModules.append(Ma)
                     self.Progress.Stop("done!")
-
+                    self.AutoGenTime += int(round((time.time() - AutoGenStart)))
+                    MakeStart = time.time()
                     for Ma in self.BuildModules:
                         # Generate build task for the module
                         if not Ma.IsBinaryModule:
@@ -1944,7 +1987,9 @@ class Build():
                     Pa.CreateMakeFile(False)
                     if BuildTask.HasError():
                         EdkLogger.error("build", BUILD_ERROR, "Failed to build module", ExtraData=GlobalData.gBuildingModule)
+                    self.MakeTime += int(round((time.time() - MakeStart)))
 
+                MakeContiue = time.time()
                 #
                 # Save temp tables to a TmpTableDict.
                 #
@@ -1960,7 +2005,7 @@ class Build():
                 ExitFlag.set()
                 BuildTask.WaitForComplete()
                 self.CreateAsBuiltInf()
-
+                self.MakeTime += int(round((time.time() - MakeContiue)))
                 #
                 # Check for build error, and raise exception if one
                 # has been signaled.
@@ -1997,12 +2042,14 @@ class Build():
                         #
                         # Generate FD image if there's a FDF file found
                         #
+                        GenFdsStart = time.time()
                         LaunchCommand(Wa.GenFdsCommand, os.getcwd())
 
                         #
                         # Create MAP file for all platform FVs after GenFds.
                         #
                         self._CollectFvMapBuffer(MapBuffer, Wa, ModuleList)
+                        self.GenFdsTime += int(round((time.time() - GenFdsStart)))
                     #
                     # Save MAP buffer into MAP file.
                     #
@@ -2151,6 +2198,18 @@ def SingleCheckCallback(option, opt_str, value, parser):
     else:
         parser.error("Option %s only allows one instance in command line!" % option)
 
+def LogBuildTime(Time):
+    if Time:
+        TimeDurStr = ''
+        TimeDur = time.gmtime(Time)
+        if TimeDur.tm_yday > 1:
+            TimeDurStr = time.strftime("%H:%M:%S", TimeDur) + ", %d day(s)" % (TimeDur.tm_yday - 1)
+        else:
+            TimeDurStr = time.strftime("%H:%M:%S", TimeDur)
+        return TimeDurStr
+    else:
+        return None
+
 ## Parse command line options
 #
 # Using standard Python module optparse to parse command line option of this tool.
@@ -2407,7 +2466,7 @@ def Main():
         BuildDurationStr = time.strftime("%H:%M:%S", BuildDuration)
     if MyBuild != None:
         if not BuildError:
-            MyBuild.BuildReport.GenerateReport(BuildDurationStr)
+            MyBuild.BuildReport.GenerateReport(BuildDurationStr, LogBuildTime(MyBuild.AutoGenTime), LogBuildTime(MyBuild.MakeTime), LogBuildTime(MyBuild.GenFdsTime))
         MyBuild.Db.Close()
     EdkLogger.SetLevel(EdkLogger.QUIET)
     EdkLogger.quiet("\n- %s -" % Conclusion)