From mboxrd@z Thu Jan 1 00:00:00 1970 Authentication-Results: mx.groups.io; dkim=missing; spf=fail (domain: intel.com, ip: , mailfrom: bob.c.feng@intel.com) Received: from mga05.intel.com (mga05.intel.com []) by groups.io with SMTP; Tue, 06 Aug 2019 00:15:28 -0700 X-Amp-Result: SKIPPED(no attachment in message) X-Amp-File-Uploaded: False Received: from orsmga004.jf.intel.com ([10.7.209.38]) by fmsmga105.fm.intel.com with ESMTP/TLS/DHE-RSA-AES256-GCM-SHA384; 06 Aug 2019 00:15:27 -0700 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.64,352,1559545200"; d="scan'208";a="325551429" Received: from shwdepsi1121.ccr.corp.intel.com ([10.239.158.47]) by orsmga004.jf.intel.com with ESMTP; 06 Aug 2019 00:15:26 -0700 From: "Bob Feng" To: devel@edk2.groups.io Cc: Liming Gao , Bob Feng Subject: [Patch 07/10 V7] BaseTools: Add LogAgent to support multiple process Autogen Date: Tue, 6 Aug 2019 15:15:08 +0800 Message-Id: <20190806071511.11836-8-bob.c.feng@intel.com> X-Mailer: git-send-email 2.20.1.windows.1 In-Reply-To: <20190806071511.11836-1-bob.c.feng@intel.com> References: <20190806071511.11836-1-bob.c.feng@intel.com> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit 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 --- .../Source/Python/AutoGen/AutoGenWorker.py | 74 +++++++++++++++++-- BaseTools/Source/Python/AutoGen/DataPipe.py | 2 +- BaseTools/Source/Python/Common/EdkLogger.py | 33 ++++++++- BaseTools/Source/Python/build/build.py | 27 +++++-- 4 files changed, 117 insertions(+), 19 deletions(-) diff --git a/BaseTools/Source/Python/AutoGen/AutoGenWorker.py b/BaseTools/Source/Python/AutoGen/AutoGenWorker.py index 9d06b45ec03f..1296604f688d 100644 --- a/BaseTools/Source/Python/AutoGen/AutoGenWorker.py +++ b/BaseTools/Source/Python/AutoGen/AutoGenWorker.py @@ -24,16 +24,80 @@ def clearQ(q): try: while True: 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): try: fin_num = 0 @@ -62,19 +126,20 @@ class AutoGenManager(threading.Thread): def TerminateWorkers(self): self.error_event.set() 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 self.data_pipe = None self.feedback_q = feedback_q 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: return self.PlatformMetaFileSet[(filepath,root)] except: @@ -86,18 +151,15 @@ class AutoGenWorkerInProcess(mp.Process): with self.file_lock: if not os.path.exists(self.data_pipe_file_path): 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") active_p = self.data_pipe.Get("P_Info").get("ActivePlatform") diff --git a/BaseTools/Source/Python/AutoGen/DataPipe.py b/BaseTools/Source/Python/AutoGen/DataPipe.py index 62992080567f..2052084bdb4b 100644 --- a/BaseTools/Source/Python/AutoGen/DataPipe.py +++ b/BaseTools/Source/Python/AutoGen/DataPipe.py @@ -152,9 +152,9 @@ class MemoryDataPipe(DataPipe): self.DataContainer = {"PackageList": [(dec.MetaFile,dec.Arch) for dec in PlatformInfo.PackageList]} 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 ae2070bebba3..f6a5e3b4daf9 100644 --- a/BaseTools/Source/Python/Common/EdkLogger.py +++ b/BaseTools/Source/Python/Common/EdkLogger.py @@ -8,10 +8,11 @@ ## Import modules 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 DEBUG_1 = 2 DEBUG_2 = 3 @@ -198,30 +199,30 @@ def error(ToolName, ErrorCode, Message=None, File=None, Line=None, ExtraData=Non # Log information which should be always put out 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) ## Set log level # @@ -232,10 +233,34 @@ def SetLevel(Level): Level = INFO _DebugLogger.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) ## Get current log level diff --git a/BaseTools/Source/Python/build/build.py b/BaseTools/Source/Python/build/build.py index 4bddd80ee112..60b22053cd9d 100644 --- a/BaseTools/Source/Python/build/build.py +++ b/BaseTools/Source/Python/build/build.py @@ -28,11 +28,12 @@ from subprocess import Popen,PIPE from collections import OrderedDict, defaultdict 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 from Common.TargetTxtClassObject import TargetTxt from Common.ToolDefClassObject import ToolDef @@ -697,11 +698,11 @@ class Build(): # # @param Target The build command target, one of gSupportedTarget # @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 self.ModuleFile = BuildOptions.ModuleFile self.ArchList = BuildOptions.TargetArch @@ -828,18 +829,19 @@ class Build(): self.AutoGenMgr = None 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: return True,0 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: w.start() if PcdMaList is not None: @@ -2405,35 +2407,42 @@ def MyOptionParser(): # @retval 1 Tool failed # 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 # (Option, Target) = MyOptionParser() GlobalData.gOptions = Option 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 else: GlobalData.gIsWindows = False @@ -2503,11 +2512,11 @@ def Main(): EdkLogger.error("build", ErrorCode, ExtraData=ErrorInfo) 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() # @@ -2587,10 +2596,12 @@ def Main(): EdkLogger.SetLevel(EdkLogger.QUIET) 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__': try: mp.set_start_method('spawn') -- 2.20.1.windows.1