From 1937dcc4059ae89e2132a87ed3910e72f1151725 Mon Sep 17 00:00:00 2001 From: Anthony Geay Date: Fri, 29 Dec 2023 08:46:49 +0100 Subject: [PATCH] [EDF29150] : clean separation of Verbosity and VerbosityLevel + implementation of first metrics stored in SALOME containers. --- bin/salome_utils.py | 20 ++++- idl/SALOME_Component.idl | 7 ++ src/Container/Container_i.cxx | 15 ++++ src/Container/SALOME_Container.py | 129 +++++++++++++++++++++++++++ src/Container/SALOME_Container_i.hxx | 1 + src/Container/SALOME_PyNode.py | 27 ++++++ 6 files changed, 195 insertions(+), 4 deletions(-) diff --git a/bin/salome_utils.py b/bin/salome_utils.py index c9bd502f7..7963b4e9f 100644 --- a/bin/salome_utils.py +++ b/bin/salome_utils.py @@ -444,14 +444,14 @@ def positionVerbosityOfLoggerRegardingState(): def verbose(): """ - Get current verbosity level. + Get current verbosity activation. Default verbosity level is specified via the environment variable SALOME_VERBOSE, e.g. in bash: $ export SALOME_VERBOSE=1 - The function `setVerbose()` can be used to explicitly set verbosity level. + The function `setVerbose()` can be used to explicitly set verbosity activation. :return current verbosity level """ @@ -462,7 +462,7 @@ def verbose(): def setVerbose(status): """ - Change verbosity level. + Change verbosity activation status. The function `verbose()` can be used to get current verbosity level. :param status : verbosity status :type status: bool @@ -477,13 +477,25 @@ KernelLogLevelToLogging = {"INFO":logging.INFO, "DEBUG":logging.DEBUG, "WARNING" LoggingToKernelLogLevel = {v: k for k, v in KernelLogLevelToLogging.items()} def verboseLevel(): + """ + Get current verbosity level. + + Default verbosity level is specified via the environment variable SALOME_VERBOSE, + e.g. in bash: + + $ export SALOME_VERBOSE_LEVEL=7 + + The function `setVerboseLevel()` can be used to explicitly set verbosity level. + + :return current verbosity level + """ import KernelBasis return KernelLogLevelToLogging[ KernelBasis.VerbosityLevel() ] def setVerboseLevel(level): """ Change verbosity level. - The function `verbose()` can be used to get current verbosity level. + The function `verboseLevel()` can be used to get current verbosity level. :param level : verbosity level """ import KernelBasis diff --git a/idl/SALOME_Component.idl b/idl/SALOME_Component.idl index fba9652e2..bcce8b779 100644 --- a/idl/SALOME_Component.idl +++ b/idl/SALOME_Component.idl @@ -31,6 +31,7 @@ #include "SALOME_Exception.idl" #include "SALOME_PyNode.idl" #include "SALOME_Embedded_NamingService.idl" +#include "SALOME_Comm.idl" /*! \file SALOME_Component.idl \brief interfaces for EngineComponent and Container */ @@ -186,6 +187,12 @@ module Engines void setVerbosity(in boolean activated, in string level); + //void addInfoOnLevel1(in long pos, in string key, in SALOME::vectorOfByte value); + + //void addInfoOnLevel2(in long pos0, in long pos1, in string key, in SALOME::vectorOfByte value); + + SALOME::vectorOfByte getAllInfo(); + //! Shutdown the Container process. void Shutdown(); diff --git a/src/Container/Container_i.cxx b/src/Container/Container_i.cxx index 429efb8b9..9b71def0b 100644 --- a/src/Container/Container_i.cxx +++ b/src/Container/Container_i.cxx @@ -352,6 +352,21 @@ void Abstract_Engines_Container_i::setVerbosity(bool activated, const char *leve } } +SALOME::vectorOfByte *Abstract_Engines_Container_i::getAllInfo() +{ + AutoGIL gstate; + PyObject *result = PyObject_CallMethod(_pyCont, (char*)"getAllInfo",nullptr); + char *buffer = nullptr; + Py_ssize_t length = 0; + PyBytes_AsStringAndSize(result,&buffer,&length); + SALOME::vectorOfByte *ret = new SALOME::vectorOfByte; + ret->length(length); + for(auto i = 0 ; i < length ; ++i) + (*ret)[i] = buffer[i]; + Py_XDECREF(result); + return ret; +} + //============================================================================= //! Get container host name /*! diff --git a/src/Container/SALOME_Container.py b/src/Container/SALOME_Container.py index 8203c6b57..e58adf565 100644 --- a/src/Container/SALOME_Container.py +++ b/src/Container/SALOME_Container.py @@ -41,12 +41,122 @@ import Engines, Engines__POA from SALOME_NamingServicePy import * from SALOME_ComponentPy import * import SALOME_PyNode +from collections import defaultdict from SALOME_utilities import * from Utils_Identity import getShortHostName from launchConfigureParser import verbose from KernelBasis import VerbosityActivated +class ScriptExecInfo: + @classmethod + def GetRepresentationOfTimeDelta(cls,endTime, startTime): + if endTime is None and startTime is None: + return "not measured" + td = endTime - startTime + import time + ts_of_td = time.gmtime(td.total_seconds()) + return "{}.{:06d}".format(time.strftime("%H:%M:%S",ts_of_td),td.microseconds) + + def __init__(self): + self._start_exec_time = None + self._end_exec_time = None + self._start_input_time = None + self._end_input_time = None + self._start_output_time = None + self._end_output_time = None + + @property + def startInputTime(self): + return self._start_input_time + + @startInputTime.setter + def startInputTime(self,value): + self._start_input_time = value + + @property + def endInputTime(self): + return self._end_input_time + + @endInputTime.setter + def endInputTime(self,value): + self._end_input_time = value + + @property + def startExecTime(self): + return self._start_exec_time + + @startExecTime.setter + def startExecTime(self,value): + self._start_exec_time = value + + @property + def endExecTime(self): + return self._end_exec_time + + @endExecTime.setter + def endExecTime(self,value): + self._end_exec_time = value + + @property + def startOutputTime(self): + return self._start_output_time + + @startOutputTime.setter + def startOutputTime(self,value): + self._start_output_time = value + + @property + def endOutputTime(self): + return self._end_output_time + + @endOutputTime.setter + def endOutputTime(self,value): + self._end_output_time = value + + @property + def execTimeStr(self): + return ScriptExecInfo.GetRepresentationOfTimeDelta(self.endExecTime,self.startExecTime) + + @property + def inputTimeStr(self): + return ScriptExecInfo.GetRepresentationOfTimeDelta(self.endInputTime,self.startInputTime) + + def __str__(self): + return """start exec time = {self.startExecTime} +end exec time = {self.endExecTime} +exec_time = {self.execTimeStr} +input unpickling and ev load from disk time = {self.inputTimeStr} +output serialization and ev write to disk time = {self.inputTimeStr}""".format(**locals()) + +class ScriptInfo: + def __init__(self, nodeName): + self._node_name = nodeName + self._code = "" + self._exec = defaultdict(ScriptExecInfo) + + @property + def execs(self): + return self._exec + + @property + def nodeName(self): + return self._node_name + + @property + def code(self): + return self._code + + @code.setter + def code(self,value): + self._code = value + + def __str__(self): + return """code = {self.code}\nexecs = {self.execs}""".format(**locals()) + + def __repr__(self): + return """ScriptInfo \"{self.nodeName}\"""".format(**locals()) + #============================================================================= #define an implementation of the container interface for embedding in Container implemented in C++ @@ -71,6 +181,7 @@ class SALOME_Container_i: self._orb = CORBA.ORB_init(argv, CORBA.ORB_ID) self._poa = self._orb.resolve_initial_references("RootPOA") self._containerName = containerName + self._dbg_info = [] if verbose(): print("SALOME_Container.SALOME_Container_i : _containerName ",self._containerName) self._container = self._orb.string_to_object(containerIORStr) @@ -145,8 +256,12 @@ class SALOME_Container_i: return 1,"".join(l) def create_pyscriptnode(self,nodeName,code): + import pickle try: + self._dbg_info.append( ScriptInfo(nodeName) ) node=SALOME_PyNode.PyScriptNode_i(nodeName,code,self._poa,self) + node.setIDInContainer(len(self._dbg_info)-1) + self.addInfoOnLevel1(node.getIDInContainer(),"code",code) id_o = self._poa.activate_object(node) comp_o = self._poa.id_to_reference(id_o) comp_iors = self._orb.object_to_string(comp_o) @@ -160,3 +275,17 @@ class SALOME_Container_i: if VerbosityActivated(): import salome_utils salome_utils.positionVerbosityOfLoggerRegardingState() + + def addInfoOnLevel1(self, pos, key, value): + setattr(self._dbg_info[pos],key,value) + + def addInfoOnLevel2(self, pos0, pos1, key, value): + setattr(self._dbg_info[pos0].execs[pos1],key,value) + + def addTimeInfoOnLevel2(self, pos0, pos1, key): + from datetime import datetime + self.addInfoOnLevel2(pos0, pos1, key,datetime.now()) + + def getAllInfo(self): + import pickle + return pickle.dumps( self._dbg_info ) diff --git a/src/Container/SALOME_Container_i.hxx b/src/Container/SALOME_Container_i.hxx index 94f427996..882581e69 100644 --- a/src/Container/SALOME_Container_i.hxx +++ b/src/Container/SALOME_Container_i.hxx @@ -121,6 +121,7 @@ public: void locallogfilename(const char *name) override; void verbosity(bool& activated, CORBA::String_out level) override; void setVerbosity(bool activated, const char *level) override; + SALOME::vectorOfByte *getAllInfo() override; virtual void Shutdown(); char *getHostName(); diff --git a/src/Container/SALOME_PyNode.py b/src/Container/SALOME_PyNode.py index 5c58e38e2..6e04446e8 100644 --- a/src/Container/SALOME_PyNode.py +++ b/src/Container/SALOME_PyNode.py @@ -379,11 +379,27 @@ class PyScriptNode_i (Engines__POA.PyScriptNode,Generic): Generic.__init__(self,poa) self.nodeName=nodeName self.code=code + self.my_container_py = my_container self.my_container=my_container._container linecache.cache[nodeName]=0,None,code.split('\n'),nodeName self.ccode=compile(code,nodeName,'exec') self.context={} self.context[MY_CONTAINER_ENTRY_IN_GLBS] = self.my_container + self._pos = None + self._current_exec = 0 + + #start of non remote callable methods + + def setIDInContainer(self, pos): + """ + Method that store the rank of creation of self inside Container instance + """ + self._pos = pos + + def getIDInContainer(self): + return self._pos + + #end of non remote callable methods def __del__(self): # force removal of self.context. Don t know why it s not done by default @@ -428,6 +444,7 @@ class PyScriptNode_i (Engines__POA.PyScriptNode,Generic): except Exception: exc_typ,exc_val,exc_fr=sys.exc_info() l=traceback.format_exception(exc_typ,exc_val,exc_fr) + print("".join(l)) ; sys.stdout.flush() # print error also in logs of remote container raise SALOME.SALOME_Exception(SALOME.ExceptionStruct(SALOME.BAD_PARAM,"".join(l),"PyScriptNode: %s" % (self.nodeName),0)) def execute(self,outargsname,argsin): @@ -446,6 +463,7 @@ class PyScriptNode_i (Engines__POA.PyScriptNode,Generic): except Exception: exc_typ,exc_val,exc_fr=sys.exc_info() l=traceback.format_exception(exc_typ,exc_val,exc_fr) + print("".join(l)) ; sys.stdout.flush() # print error also in logs of remote container raise SALOME.SALOME_Exception(SALOME.ExceptionStruct(SALOME.BAD_PARAM,"".join(l),"PyScriptNode: %s, outargsname: %s" % (self.nodeName,outargsname),0)) def executeFirst(self,argsin): @@ -453,6 +471,7 @@ class PyScriptNode_i (Engines__POA.PyScriptNode,Generic): import time try: data = None + self.my_container_py.addTimeInfoOnLevel2(self.getIDInContainer(),self._current_exec,"startInputTime") if True: # to force call of SeqByteReceiver's destructor argsInPy = SeqByteReceiver( argsin ) data = argsInPy.data() @@ -461,15 +480,21 @@ class PyScriptNode_i (Engines__POA.PyScriptNode,Generic): # fetch real data if necessary kws[elt] = UnProxyObjectSimple( kws[elt] ) self.context.update(kws) + self.my_container_py.addTimeInfoOnLevel2(self.getIDInContainer(),self._current_exec,"endInputTime") except Exception: exc_typ,exc_val,exc_fr=sys.exc_info() l=traceback.format_exception(exc_typ,exc_val,exc_fr) + print("".join(l)) ; sys.stdout.flush() # print error also in logs of remote container raise SALOME.SALOME_Exception(SALOME.ExceptionStruct(SALOME.BAD_PARAM,"".join(l),"PyScriptNode:First %s" % (self.nodeName),0)) def executeSecond(self,outargsname): """ Same than second part of self.execute to reduce memory peak.""" + import sys try: + self.my_container_py.addTimeInfoOnLevel2(self.getIDInContainer(),self._current_exec,"startExecTime") exec(self.ccode, self.context) + self.my_container_py.addTimeInfoOnLevel2(self.getIDInContainer(),self._current_exec,"endExecTime") + self.my_container_py.addTimeInfoOnLevel2(self.getIDInContainer(),self._current_exec,"startOutputTime") argsout=[] for arg in outargsname: if arg not in self.context: @@ -483,10 +508,12 @@ class PyScriptNode_i (Engines__POA.PyScriptNode,Generic): id_o = self.poa.activate_object(retArg) retObj = self.poa.id_to_reference(id_o) ret.append( retObj._narrow( SALOME.SenderByte ) ) + self.my_container_py.addTimeInfoOnLevel2(self.getIDInContainer(),self._current_exec,"endOutputTime") return ret except Exception: exc_typ,exc_val,exc_fr=sys.exc_info() l=traceback.format_exception(exc_typ,exc_val,exc_fr) + print("".join(l)) ; sys.stdout.flush() # print error also in logs of remote container raise SALOME.SALOME_Exception(SALOME.ExceptionStruct(SALOME.BAD_PARAM,"".join(l),"PyScriptNode:Second %s, outargsname: %s" % (self.nodeName,outargsname),0)) def listAllVarsInContext(self): -- 2.39.2