From nobody Sun Feb 8 21:47:29 2026 Delivered-To: importer@patchew.org Received-SPF: pass (zoho.com: domain of groups.io designates 66.175.222.12 as permitted sender) client-ip=66.175.222.12; envelope-from=bounce+27952+44976+1787277+3901457@groups.io; helo=web01.groups.io; Authentication-Results: mx.zohomail.com; dkim=pass; spf=pass (zoho.com: domain of groups.io designates 66.175.222.12 as permitted sender) smtp.mailfrom=bounce+27952+44976+1787277+3901457@groups.io; dmarc=fail(p=none dis=none) header.from=intel.com ARC-Seal: i=1; a=rsa-sha256; t=1565151956; cv=none; d=zoho.com; s=zohoarc; b=ey8tsI27WYNIte2DqXkUV/rnwDZ8/pSSYnAkqVqptkJNXoivas0UWrTnYBGXv7VK8MrIe7h0puRPCG77D0Oxkq62kZwHhuAJnBQsWOjwQuGaUKKudfzPUT7i0PGY3BVKF8/gLfnyEDSg7ocWIVachzEV2NrNFB7EWFY0qYETIR0= ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=zoho.com; s=zohoarc; t=1565151956; h=Content-Transfer-Encoding:Cc:Date:From:In-Reply-To:List-Id:List-Unsubscribe:MIME-Version:Message-ID:Reply-To:References:Sender:Subject:To:ARC-Authentication-Results; bh=UOdXUe4Ss+PT7jO6/g27q3yOk5d6O9lb0JDTag8vkZU=; b=SF2LrR4LR5nhiL/WZOmMhRBfi5RUzwQ8NLqJA1bc+JHL1t6pqODxiL//pwIdX/RQYwcA7Gum04t0OcSHGNaGvMGIFXncGXZHJ+BtP96AK4qcqaMKk5esJ15sM0fqGCj7g4LwGoAmmgjkbhUVQyh3IcI7FJFBkdKRrtuKT/IDCMs= ARC-Authentication-Results: i=1; mx.zoho.com; dkim=pass; spf=pass (zoho.com: domain of groups.io designates 66.175.222.12 as permitted sender) smtp.mailfrom=bounce+27952+44976+1787277+3901457@groups.io; dmarc=fail header.from= (p=none dis=none) header.from= Received: from web01.groups.io (web01.groups.io [66.175.222.12]) by mx.zohomail.com with SMTPS id 1565151956987579.2963850474914; Tue, 6 Aug 2019 21:25:56 -0700 (PDT) Return-Path: X-Received: from mga14.intel.com (mga14.intel.com [192.55.52.115]) by groups.io with SMTP; Tue, 06 Aug 2019 21:25:56 -0700 X-Amp-Result: SKIPPED(no attachment in message) X-Amp-File-Uploaded: False X-Received: from orsmga004.jf.intel.com ([10.7.209.38]) by fmsmga103.fm.intel.com with ESMTP/TLS/DHE-RSA-AES256-GCM-SHA384; 06 Aug 2019 21:25:55 -0700 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.64,356,1559545200"; d="scan'208";a="325839813" X-Received: from shwdepsi1121.ccr.corp.intel.com ([10.239.158.47]) by orsmga004.jf.intel.com with ESMTP; 06 Aug 2019 21:25:54 -0700 From: "Bob Feng" To: devel@edk2.groups.io Cc: Liming Gao , Bob Feng Subject: [edk2-devel] [Patch 07/10 V8] BaseTools: Add LogAgent to support multiple process Autogen Date: Wed, 7 Aug 2019 12:25:34 +0800 Message-Id: <20190807042537.11928-8-bob.c.feng@intel.com> In-Reply-To: <20190807042537.11928-1-bob.c.feng@intel.com> References: <20190807042537.11928-1-bob.c.feng@intel.com> MIME-Version: 1.0 Precedence: Bulk List-Unsubscribe: Sender: devel@edk2.groups.io List-Id: Mailing-List: list devel@edk2.groups.io; contact devel+owner@edk2.groups.io Reply-To: devel@edk2.groups.io,bob.c.feng@intel.com Content-Transfer-Encoding: quoted-printable DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=groups.io; q=dns/txt; s=20140610; t=1565151956; bh=zRX1QdMGm+1MnlkHPe4sXD0RlWRl8thmhc0diRivVIw=; h=Cc:Date:From:Reply-To:Subject:To; b=wcR/mRhAFHQhwanvddTB/+gnO27qnqMuaBKqbn+XVyxtE6H2M/0Fo1s6qVeaxnPv1n+ 3BZWfVOUfVWvxOsXvl+hgcryelm2bcqLONgyPRNwWjA6brTPUVIh41amxRTbfj9mRP3KZ vISBZ1qsHk+2YxxILgb6JMm5CdmUj1Eqq5U= X-ZohoMail-DKIM: pass (identity @groups.io) Content-Type: text/plain; charset="utf-8" BZ: https://bugzilla.tianocore.org/show_bug.cgi?id=3D1875 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/S= ource/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=3DNone): + super(LogAgent,self).__init__() + self.log_q =3D log_q + self.log_level =3D log_level + self.log_file =3D log_file + def InitLogger(self): + # For DEBUG level (All DEBUG_0~9 are applicable) + self._DebugLogger_agent =3D logging.getLogger("tool_debug_agent") + _DebugFormatter =3D logging.Formatter("[%(asctime)s.%(msecs)d]: %(= message)s", datefmt=3D"%H:%M:%S") + self._DebugLogger_agent.setLevel(self.log_level) + _DebugChannel =3D logging.StreamHandler(sys.stdout) + _DebugChannel.setFormatter(_DebugFormatter) + self._DebugLogger_agent.addHandler(_DebugChannel) + + # For VERBOSE, INFO, WARN level + self._InfoLogger_agent =3D logging.getLogger("tool_info_agent") + _InfoFormatter =3D logging.Formatter("%(message)s") + self._InfoLogger_agent.setLevel(self.log_level) + _InfoChannel =3D logging.StreamHandler(sys.stdout) + _InfoChannel.setFormatter(_InfoFormatter) + self._InfoLogger_agent.addHandler(_InfoChannel) + + # For ERROR level + self._ErrorLogger_agent =3D logging.getLogger("tool_error_agent") + _ErrorFormatter =3D logging.Formatter("%(message)s") + self._ErrorLogger_agent.setLevel(self.log_level) + _ErrorCh =3D 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 =3D logging.FileHandler(self.log_file) + _Ch.setFormatter(_DebugFormatter) + self._DebugLogger_agent.addHandler(_Ch) + + _Ch=3D logging.FileHandler(self.log_file) + _Ch.setFormatter(_InfoFormatter) + self._InfoLogger_agent.addHandler(_Ch) + + _Ch =3D logging.FileHandler(self.log_file) + _Ch.setFormatter(_ErrorFormatter) + self._ErrorLogger_agent.addHandler(_Ch) + + def run(self): + self.InitLogger() + while True: + log_message =3D self.log_q.get() + if log_message is None: + break + if log_message.name =3D=3D "tool_error": + self._ErrorLogger_agent.log(log_message.levelno,log_messag= e.getMessage()) + elif log_message.name =3D=3D "tool_info": + self._InfoLogger_agent.log(log_message.levelno,log_message= .getMessage()) + elif log_message.name =3D=3D "tool_debug": + self._DebugLogger_agent.log(log_message.levelno,log_messag= e.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 =3D autogen_workers self.feedback_q =3D feedback_q - self.terminate =3D False self.Status =3D True self.error_event =3D error_event def run(self): try: fin_num =3D 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_loc= k, share_data,error_event): + def __init__(self,module_queue,data_pipe_file_path,feedback_q,file_loc= k, share_data,log_q,error_event): mp.Process.__init__(self) self.module_queue =3D module_queue self.data_pipe_file_path =3Ddata_pipe_file_path self.data_pipe =3D None self.feedback_q =3D feedback_q self.PlatformMetaFileSet =3D {} self.file_lock =3D file_lock self.share_data =3D share_data + self.log_q =3D log_q self.error_event =3D 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 =3D MemoryDataPipe() self.data_pipe.load(self.data_pipe_file_path) - EdkLogger.Initialize() + EdkLogger.LogClientInitialize(self.log_q) loglevel =3D self.data_pipe.Get("LogLevel") if not loglevel: loglevel =3D EdkLogger.INFO EdkLogger.SetLevel(loglevel) - logfile =3D self.data_pipe.Get("LogFile") - if logfile: - EdkLogger.SetLogFile(logfile) target =3D self.data_pipe.Get("P_Info").get("Target") toolchain =3D self.data_pipe.Get("P_Info").get("ToolChain") archlist =3D self.data_pipe.Get("P_Info").get("ArchList") =20 active_p =3D 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 =3D {"PackageList": [(dec.MetaFile,dec.Arch) fo= r dec in PlatformInfo.PackageList]} =20 self.DataContainer =3D {"GuidDict": PlatformInfo.Platform._GuidDic= t} =20 self.DataContainer =3D {"DatabasePath":GlobalData.gDatabasePath} + self.DataContainer =3D {"FdfParser": True if GlobalData.gFdfParser= else False} =20 self.DataContainer =3D {"LogLevel": EdkLogger.GetLevel()} - self.DataContainer =3D {"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 =20 ## Log level constants DEBUG_0 =3D 1 DEBUG_1 =3D 2 DEBUG_2 =3D 3 @@ -198,30 +199,30 @@ def error(ToolName, ErrorCode, Message=3DNone, File= =3DNone, Line=3DNone, ExtraData=3DNon =20 # Log information which should be always put out quiet =3D _ErrorLogger.error =20 ## Initialize log system -def Initialize(): +def LogClientInitialize(log_q): # # Since we use different format to log different levels of message int= o 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 =3D logging.StreamHandler(sys.stdout) + _DebugChannel =3D logging.handlers.QueueHandler(log_q) _DebugChannel.setFormatter(_DebugFormatter) _DebugLogger.addHandler(_DebugChannel) =20 # For VERBOSE, INFO, WARN level _InfoLogger.setLevel(INFO) - _InfoChannel =3D logging.StreamHandler(sys.stdout) + _InfoChannel =3D logging.handlers.QueueHandler(log_q) _InfoChannel.setFormatter(_InfoFormatter) _InfoLogger.addHandler(_InfoChannel) =20 # For ERROR level _ErrorLogger.setLevel(INFO) - _ErrorCh =3D logging.StreamHandler(sys.stderr) + _ErrorCh =3D logging.handlers.QueueHandler(log_q) _ErrorCh.setFormatter(_ErrorFormatter) _ErrorLogger.addHandler(_ErrorCh) =20 ## Set log level # @@ -232,10 +233,34 @@ def SetLevel(Level): Level =3D INFO _DebugLogger.setLevel(Level) _InfoLogger.setLevel(Level) _ErrorLogger.setLevel(Level) =20 +## Initialize log system +def Initialize(): + # + # Since we use different format to log different levels of message int= o 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 =3D logging.StreamHandler(sys.stdout) + _DebugChannel.setFormatter(_DebugFormatter) + _DebugLogger.addHandler(_DebugChannel) + + # For VERBOSE, INFO, WARN level + _InfoLogger.setLevel(INFO) + _InfoChannel =3D logging.StreamHandler(sys.stdout) + _InfoChannel.setFormatter(_InfoFormatter) + _InfoLogger.addHandler(_InfoChannel) + + # For ERROR level + _ErrorLogger.setLevel(INFO) + _ErrorCh =3D logging.StreamHandler(sys.stderr) + _ErrorCh.setFormatter(_ErrorFormatter) + _ErrorLogger.addHandler(_ErrorCh) + def InitializeForUnitTest(): Initialize() SetLevel(SILENT) =20 ## Get current log level diff --git a/BaseTools/Source/Python/build/build.py b/BaseTools/Source/Pyth= on/build/build.py index b9305bf7b25a..4daef5652f8d 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 =20 from Common.TargetTxtClassObject import TargetTxt from Common.ToolDefClassObject import ToolDef @@ -697,11 +698,11 @@ class Build(): # # @param Target The build command target, one of gSupp= ortedTarget # @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 =3D WorkspaceDir self.Target =3D Target self.PlatformFile =3D BuildOptions.PlatformFile self.ModuleFile =3D BuildOptions.ModuleFile self.ArchList =3D BuildOptions.TargetArch @@ -828,18 +829,19 @@ class Build(): =20 self.AutoGenMgr =3D None EdkLogger.info("") os.chdir(self.WorkspaceDir) self.share_data =3D Manager().dict() + self.log_q =3D log_q def StartAutoGen(self,mqueue, DataPipe,SkipAutoGen,PcdMaList,share_dat= a): try: if SkipAutoGen: return True,0 feedback_q =3D mp.Queue() file_lock =3D mp.Lock() error_event =3D mp.Event() - auto_workers =3D [AutoGenWorkerInProcess(mqueue,DataPipe.dump_= file,feedback_q,file_lock,share_data,error_event) for _ in range(self.Threa= dNumber)] + auto_workers =3D [AutoGenWorkerInProcess(mqueue,DataPipe.dump_= file,feedback_q,file_lock,share_data,self.log_q,error_event) for _ in range= (self.ThreadNumber)] self.AutoGenMgr =3D AutoGenManager(auto_workers,feedback_q,err= or_event) self.AutoGenMgr.start() for w in auto_workers: w.start() if PcdMaList is not None: @@ -2404,35 +2406,42 @@ def MyOptionParser(): # @retval 1 Tool failed # def Main(): StartTime =3D time.time() =20 + # + # Create a log Queue + # + LogQ =3D mp.Queue() # Initialize log system - EdkLogger.Initialize() + EdkLogger.LogClientInitialize(LogQ) GlobalData.gCommand =3D sys.argv[1:] # # Parse the options and args # (Option, Target) =3D MyOptionParser() GlobalData.gOptions =3D Option GlobalData.gCaseInsensitive =3D Option.CaseInsensitive =20 # Set log level + LogLevel =3D EdkLogger.INFO if Option.verbose is not None: EdkLogger.SetLevel(EdkLogger.VERBOSE) + LogLevel =3D EdkLogger.VERBOSE elif Option.quiet is not None: EdkLogger.SetLevel(EdkLogger.QUIET) + LogLevel =3D EdkLogger.QUIET elif Option.debug is not None: EdkLogger.SetLevel(Option.debug + 1) + LogLevel =3D Option.debug + 1 else: EdkLogger.SetLevel(EdkLogger.INFO) =20 - if Option.LogFile is not None: - EdkLogger.SetLogFile(Option.LogFile) - if Option.WarningAsError =3D=3D True: EdkLogger.SetWarningAsError() + Log_Agent =3D LogAgent(LogQ,LogLevel,Option.LogFile) + Log_Agent.start() =20 if platform.platform().find("Windows") >=3D 0: GlobalData.gIsWindows =3D True else: GlobalData.gIsWindows =3D False @@ -2502,11 +2511,11 @@ def Main(): EdkLogger.error("build", ErrorCode, ExtraData=3DErrorInfo) =20 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") =20 - MyBuild =3D Build(Target, Workspace, Option) + MyBuild =3D Build(Target, Workspace, Option,LogQ) GlobalData.gCommandLineDefines['ARCH'] =3D ' '.join(MyBuild.ArchLi= st) if not (MyBuild.LaunchPrebuildFlag and os.path.exists(MyBuild.Plat= formBuildPath)): MyBuild.Launch() =20 # @@ -2586,10 +2595,12 @@ def Main(): =20 EdkLogger.SetLevel(EdkLogger.QUIET) EdkLogger.quiet("\n- %s -" % Conclusion) EdkLogger.quiet(time.strftime("Build end time: %H:%M:%S, %b.%d %Y", ti= me.localtime())) EdkLogger.quiet("Build total time: %s\n" % BuildDurationStr) + Log_Agent.kill() + Log_Agent.join() return ReturnCode =20 if __name__ =3D=3D '__main__': try: mp.set_start_method('spawn') --=20 2.20.1.windows.1 -=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D- Groups.io Links: You receive all messages sent to this group. View/Reply Online (#44976): https://edk2.groups.io/g/devel/message/44976 Mute This Topic: https://groups.io/mt/32779333/1787277 Group Owner: devel+owner@edk2.groups.io Unsubscribe: https://edk2.groups.io/g/devel/unsub [importer@patchew.org] -=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-=3D-