From: Feng, Bob C Date: Wed, 31 Jul 2019 05:31:15 +0000 (+0800) Subject: BaseTools: Add LogAgent to support multiple process Autogen X-Git-Tag: edk2-stable201908~128 X-Git-Url: https://git.proxmox.com/?p=mirror_edk2.git;a=commitdiff_plain;h=636ed13a7f9339aea7fdb74de24be1703e9d482c BaseTools: Add LogAgent to support multiple process Autogen BZ: https://bugzilla.tianocore.org/show_bug.cgi?id=1875 AutoGen processes race the logfile. To resolve this issue, this patch create a LogAgent thread in main process to write the log content to console or file, Other process will send the log content to the LogAgent. Cc: Liming Gao Signed-off-by: Bob Feng Acked-by: Laszlo Ersek Tested-by: Laszlo Ersek Acked-by: Liming Gao --- diff --git a/BaseTools/Source/Python/AutoGen/AutoGenWorker.py b/BaseTools/Source/Python/AutoGen/AutoGenWorker.py index 9d06b45ec0..1296604f68 100644 --- a/BaseTools/Source/Python/AutoGen/AutoGenWorker.py +++ b/BaseTools/Source/Python/AutoGen/AutoGenWorker.py @@ -26,12 +26,76 @@ def clearQ(q): q.get_nowait() except Empty: pass +import logging + +class LogAgent(threading.Thread): + def __init__(self,log_q,log_level,log_file=None): + super(LogAgent,self).__init__() + self.log_q = log_q + self.log_level = log_level + self.log_file = log_file + def InitLogger(self): + # For DEBUG level (All DEBUG_0~9 are applicable) + self._DebugLogger_agent = logging.getLogger("tool_debug_agent") + _DebugFormatter = logging.Formatter("[%(asctime)s.%(msecs)d]: %(message)s", datefmt="%H:%M:%S") + self._DebugLogger_agent.setLevel(self.log_level) + _DebugChannel = logging.StreamHandler(sys.stdout) + _DebugChannel.setFormatter(_DebugFormatter) + self._DebugLogger_agent.addHandler(_DebugChannel) + + # For VERBOSE, INFO, WARN level + self._InfoLogger_agent = logging.getLogger("tool_info_agent") + _InfoFormatter = logging.Formatter("%(message)s") + self._InfoLogger_agent.setLevel(self.log_level) + _InfoChannel = logging.StreamHandler(sys.stdout) + _InfoChannel.setFormatter(_InfoFormatter) + self._InfoLogger_agent.addHandler(_InfoChannel) + + # For ERROR level + self._ErrorLogger_agent = logging.getLogger("tool_error_agent") + _ErrorFormatter = logging.Formatter("%(message)s") + self._ErrorLogger_agent.setLevel(self.log_level) + _ErrorCh = logging.StreamHandler(sys.stderr) + _ErrorCh.setFormatter(_ErrorFormatter) + self._ErrorLogger_agent.addHandler(_ErrorCh) + + if self.log_file: + if os.path.exists(self.log_file): + os.remove(self.log_file) + _Ch = logging.FileHandler(self.log_file) + _Ch.setFormatter(_DebugFormatter) + self._DebugLogger_agent.addHandler(_Ch) + + _Ch= logging.FileHandler(self.log_file) + _Ch.setFormatter(_InfoFormatter) + self._InfoLogger_agent.addHandler(_Ch) + + _Ch = logging.FileHandler(self.log_file) + _Ch.setFormatter(_ErrorFormatter) + self._ErrorLogger_agent.addHandler(_Ch) + + def run(self): + self.InitLogger() + while True: + log_message = self.log_q.get() + if log_message is None: + break + if log_message.name == "tool_error": + self._ErrorLogger_agent.log(log_message.levelno,log_message.getMessage()) + elif log_message.name == "tool_info": + self._InfoLogger_agent.log(log_message.levelno,log_message.getMessage()) + elif log_message.name == "tool_debug": + self._DebugLogger_agent.log(log_message.levelno,log_message.getMessage()) + else: + self._InfoLogger_agent.log(log_message.levelno,log_message.getMessage()) + + def kill(self): + self.log_q.put(None) class AutoGenManager(threading.Thread): def __init__(self,autogen_workers, feedback_q,error_event): super(AutoGenManager,self).__init__() self.autogen_workers = autogen_workers self.feedback_q = feedback_q - self.terminate = False self.Status = True self.error_event = error_event def run(self): @@ -64,7 +128,7 @@ class AutoGenManager(threading.Thread): def kill(self): self.feedback_q.put(None) class AutoGenWorkerInProcess(mp.Process): - def __init__(self,module_queue,data_pipe_file_path,feedback_q,file_lock, share_data,error_event): + def __init__(self,module_queue,data_pipe_file_path,feedback_q,file_lock, share_data,log_q,error_event): mp.Process.__init__(self) self.module_queue = module_queue self.data_pipe_file_path =data_pipe_file_path @@ -73,6 +137,7 @@ class AutoGenWorkerInProcess(mp.Process): self.PlatformMetaFileSet = {} self.file_lock = file_lock self.share_data = share_data + self.log_q = log_q self.error_event = error_event def GetPlatformMetaFile(self,filepath,root): try: @@ -88,14 +153,11 @@ class AutoGenWorkerInProcess(mp.Process): self.feedback_q.put(taskname + ":" + "load data pipe %s failed." % self.data_pipe_file_path) self.data_pipe = MemoryDataPipe() self.data_pipe.load(self.data_pipe_file_path) - EdkLogger.Initialize() + EdkLogger.LogClientInitialize(self.log_q) loglevel = self.data_pipe.Get("LogLevel") if not loglevel: loglevel = EdkLogger.INFO EdkLogger.SetLevel(loglevel) - logfile = self.data_pipe.Get("LogFile") - if logfile: - EdkLogger.SetLogFile(logfile) target = self.data_pipe.Get("P_Info").get("Target") toolchain = self.data_pipe.Get("P_Info").get("ToolChain") archlist = self.data_pipe.Get("P_Info").get("ArchList") diff --git a/BaseTools/Source/Python/AutoGen/DataPipe.py b/BaseTools/Source/Python/AutoGen/DataPipe.py index 6299208056..2052084bdb 100644 --- a/BaseTools/Source/Python/AutoGen/DataPipe.py +++ b/BaseTools/Source/Python/AutoGen/DataPipe.py @@ -154,7 +154,7 @@ class MemoryDataPipe(DataPipe): self.DataContainer = {"GuidDict": PlatformInfo.Platform._GuidDict} self.DataContainer = {"DatabasePath":GlobalData.gDatabasePath} + self.DataContainer = {"FdfParser": True if GlobalData.gFdfParser else False} self.DataContainer = {"LogLevel": EdkLogger.GetLevel()} - self.DataContainer = {"LogFile": GlobalData.gOptions.LogFile if GlobalData.gOptions.LogFile is not None else ""} diff --git a/BaseTools/Source/Python/Common/EdkLogger.py b/BaseTools/Source/Python/Common/EdkLogger.py index ae2070bebb..f6a5e3b4da 100644 --- a/BaseTools/Source/Python/Common/EdkLogger.py +++ b/BaseTools/Source/Python/Common/EdkLogger.py @@ -10,6 +10,7 @@ from __future__ import absolute_import import Common.LongFilePathOs as os, sys, logging import traceback from .BuildToolError import * +import logging.handlers ## Log level constants DEBUG_0 = 1 @@ -200,26 +201,26 @@ def error(ToolName, ErrorCode, Message=None, File=None, Line=None, ExtraData=Non quiet = _ErrorLogger.error ## Initialize log system -def Initialize(): +def LogClientInitialize(log_q): # # Since we use different format to log different levels of message into different # place (stdout or stderr), we have to use different "Logger" objects to do this. # # For DEBUG level (All DEBUG_0~9 are applicable) _DebugLogger.setLevel(INFO) - _DebugChannel = logging.StreamHandler(sys.stdout) + _DebugChannel = logging.handlers.QueueHandler(log_q) _DebugChannel.setFormatter(_DebugFormatter) _DebugLogger.addHandler(_DebugChannel) # For VERBOSE, INFO, WARN level _InfoLogger.setLevel(INFO) - _InfoChannel = logging.StreamHandler(sys.stdout) + _InfoChannel = logging.handlers.QueueHandler(log_q) _InfoChannel.setFormatter(_InfoFormatter) _InfoLogger.addHandler(_InfoChannel) # For ERROR level _ErrorLogger.setLevel(INFO) - _ErrorCh = logging.StreamHandler(sys.stderr) + _ErrorCh = logging.handlers.QueueHandler(log_q) _ErrorCh.setFormatter(_ErrorFormatter) _ErrorLogger.addHandler(_ErrorCh) @@ -234,6 +235,30 @@ def SetLevel(Level): _InfoLogger.setLevel(Level) _ErrorLogger.setLevel(Level) +## Initialize log system +def Initialize(): + # + # Since we use different format to log different levels of message into different + # place (stdout or stderr), we have to use different "Logger" objects to do this. + # + # For DEBUG level (All DEBUG_0~9 are applicable) + _DebugLogger.setLevel(INFO) + _DebugChannel = logging.StreamHandler(sys.stdout) + _DebugChannel.setFormatter(_DebugFormatter) + _DebugLogger.addHandler(_DebugChannel) + + # For VERBOSE, INFO, WARN level + _InfoLogger.setLevel(INFO) + _InfoChannel = logging.StreamHandler(sys.stdout) + _InfoChannel.setFormatter(_InfoFormatter) + _InfoLogger.addHandler(_InfoChannel) + + # For ERROR level + _ErrorLogger.setLevel(INFO) + _ErrorCh = logging.StreamHandler(sys.stderr) + _ErrorCh.setFormatter(_ErrorFormatter) + _ErrorLogger.addHandler(_ErrorCh) + def InitializeForUnitTest(): Initialize() SetLevel(SILENT) diff --git a/BaseTools/Source/Python/build/build.py b/BaseTools/Source/Python/build/build.py index b9305bf7b2..4daef5652f 100644 --- a/BaseTools/Source/Python/build/build.py +++ b/BaseTools/Source/Python/build/build.py @@ -30,7 +30,8 @@ from optparse import OptionParser from AutoGen.PlatformAutoGen import PlatformAutoGen from AutoGen.ModuleAutoGen import ModuleAutoGen from AutoGen.WorkspaceAutoGen import WorkspaceAutoGen -from AutoGen.AutoGenWorker import AutoGenWorkerInProcess,AutoGenManager +from AutoGen.AutoGenWorker import AutoGenWorkerInProcess,AutoGenManager,\ + LogAgent from AutoGen import GenMake from Common import Misc as Utils @@ -699,7 +700,7 @@ class Build(): # @param WorkspaceDir The directory of workspace # @param BuildOptions Build options passed from command line # - def __init__(self, Target, WorkspaceDir, BuildOptions): + def __init__(self, Target, WorkspaceDir, BuildOptions,log_q): self.WorkspaceDir = WorkspaceDir self.Target = Target self.PlatformFile = BuildOptions.PlatformFile @@ -830,6 +831,7 @@ class Build(): EdkLogger.info("") os.chdir(self.WorkspaceDir) self.share_data = Manager().dict() + self.log_q = log_q def StartAutoGen(self,mqueue, DataPipe,SkipAutoGen,PcdMaList,share_data): try: if SkipAutoGen: @@ -837,7 +839,7 @@ class Build(): feedback_q = mp.Queue() file_lock = mp.Lock() error_event = mp.Event() - auto_workers = [AutoGenWorkerInProcess(mqueue,DataPipe.dump_file,feedback_q,file_lock,share_data,error_event) for _ in range(self.ThreadNumber)] + auto_workers = [AutoGenWorkerInProcess(mqueue,DataPipe.dump_file,feedback_q,file_lock,share_data,self.log_q,error_event) for _ in range(self.ThreadNumber)] self.AutoGenMgr = AutoGenManager(auto_workers,feedback_q,error_event) self.AutoGenMgr.start() for w in auto_workers: @@ -2406,8 +2408,12 @@ def MyOptionParser(): def Main(): StartTime = time.time() + # + # Create a log Queue + # + LogQ = mp.Queue() # Initialize log system - EdkLogger.Initialize() + EdkLogger.LogClientInitialize(LogQ) GlobalData.gCommand = sys.argv[1:] # # Parse the options and args @@ -2417,20 +2423,23 @@ def Main(): GlobalData.gCaseInsensitive = Option.CaseInsensitive # Set log level + LogLevel = EdkLogger.INFO if Option.verbose is not None: EdkLogger.SetLevel(EdkLogger.VERBOSE) + LogLevel = EdkLogger.VERBOSE elif Option.quiet is not None: EdkLogger.SetLevel(EdkLogger.QUIET) + LogLevel = EdkLogger.QUIET elif Option.debug is not None: EdkLogger.SetLevel(Option.debug + 1) + LogLevel = Option.debug + 1 else: EdkLogger.SetLevel(EdkLogger.INFO) - if Option.LogFile is not None: - EdkLogger.SetLogFile(Option.LogFile) - if Option.WarningAsError == True: EdkLogger.SetWarningAsError() + Log_Agent = LogAgent(LogQ,LogLevel,Option.LogFile) + Log_Agent.start() if platform.platform().find("Windows") >= 0: GlobalData.gIsWindows = True @@ -2504,7 +2513,7 @@ def Main(): if Option.Flag is not None and Option.Flag not in ['-c', '-s']: EdkLogger.error("build", OPTION_VALUE_INVALID, "UNI flag must be one of -c or -s") - MyBuild = Build(Target, Workspace, Option) + MyBuild = Build(Target, Workspace, Option,LogQ) GlobalData.gCommandLineDefines['ARCH'] = ' '.join(MyBuild.ArchList) if not (MyBuild.LaunchPrebuildFlag and os.path.exists(MyBuild.PlatformBuildPath)): MyBuild.Launch() @@ -2588,6 +2597,8 @@ def Main(): EdkLogger.quiet("\n- %s -" % Conclusion) EdkLogger.quiet(time.strftime("Build end time: %H:%M:%S, %b.%d %Y", time.localtime())) EdkLogger.quiet("Build total time: %s\n" % BuildDurationStr) + Log_Agent.kill() + Log_Agent.join() return ReturnCode if __name__ == '__main__':