- New +d=execstat; defined in Debug.mo and includes memory consumption

git-svn-id: https://openmodelica.org/svn/OpenModelica/trunk@8891 f25d12d1-65f4-0310-ae8a-bbce733d8d8e

Compiler/BackEnd/BackendDAE.mo

@@ -46,6 +46,7 @@ public import HashTable4;
 public import HashTableCG;
 
 public constant String partialDerivativeNamePrefix="$pDER";
+public constant Integer RT_CLOCK_EXECSTAT_BACKEND_MODULES=12;
 
 public uniontype Type "
 Once we are in BackendDAE, the Type can be only basic types or enumeration.

Compiler/BackEnd/BackendDAEUtil.mo

@@ -5838,6 +5838,7 @@ algorithm
 
   Debug.fcall("dumpdaelow", print, "dumpdaelow:\n");
   Debug.fcall("dumpdaelow", BackendDump.dump, inDAE);
+  System.realtimeTick(BackendDAE.RT_CLOCK_EXECSTAT_BACKEND_MODULES);
   // pre optimisation phase
   (optdae,om,omT) := preoptimiseDAE(inDAE,functionTree,preOptModules,NONE(),NONE());
 
@@ -5849,10 +5850,11 @@ algorithm
   (sode,outM,outMT,outAss1,outAss2,outComps) := pastoptimiseDAE(sode,functionTree,pastOptModules,m,mT,v1,v2,comps,daeHandler);
 
   sode1 := BackendDAECreate.findZeroCrossings(sode);
-  Debug.fcall("execstat",print, "*** BackendMain -> translateDae: " +& realString(clock()) +& "\n" );
+  Debug.execStat("findZeroCrossings",BackendDAE.RT_CLOCK_EXECSTAT_BACKEND_MODULES);
   indexed_dlow := translateDae(sode1,NONE());
-  Debug.fcall("execstat",print, "*** BackendMain -> calculate Values: " +& realString(clock()) +& "\n" );
+  Debug.execStat("translateDAE",BackendDAE.RT_CLOCK_EXECSTAT_BACKEND_MODULES);
   outSODE := calculateValues(inCache, inEnv, indexed_dlow);
+  Debug.execStat("calculateValue",BackendDAE.RT_CLOCK_EXECSTAT_BACKEND_MODULES);
   Debug.fcall("dumpindxdae", print, "dumpindxdae:\n");
   Debug.fcall("dumpindxdae", BackendDump.dump, outSODE);
 end getSolvedSystem;
@@ -5899,8 +5901,8 @@ algorithm
     case (dae,funcs,{},m,mT) then (dae,m,mT);
     case (dae,funcs,(optModule,moduleStr)::rest,m,mT)
       equation
-        Debug.fcall("execstat",print, "*** BackendMain -> preoptimiseDAE Module " +& moduleStr +& " at time: " +& realString(clock()) +& "\n" );
         (dae1,m1,mT1) = optModule(dae,funcs,m,mT);
+        Debug.execStat("preOpt " +& moduleStr,BackendDAE.RT_CLOCK_EXECSTAT_BACKEND_MODULES);
         Debug.fcall("optdaedump", print, stringAppendList({"\nOptimisation Module ",moduleStr,":\n\n"}));
         Debug.fcall("optdaedump", BackendDump.dump, dae1);
         (dae2,m2,mT2) = preoptimiseDAE(dae1,funcs,rest,m1,mT1);
@@ -5973,11 +5975,11 @@ algorithm
         (m,mT) = getIncidenceMatrixfromOption(dae,om,omT);
         match_opts = Util.getOptionOrDefault(inMatchingOptions,(BackendDAE.INDEX_REDUCTION(), BackendDAE.EXACT()));
         // matching algorithm
-        Debug.fcall("execstat",print, "*** BackendMain -> transformDAE get matching at time: " +& realString(clock()) +& " using index Reduction Method " +& methodstr  +& "\n" );
         (v1,v2,ode,m1,mT1) = BackendDAETransform.matchingAlgorithm(dae, m, mT, match_opts, daeHandlerfunc, funcs);
+        Debug.execStat("transformDAE -> index Reduction Method " +& methodstr,BackendDAE.RT_CLOCK_EXECSTAT_BACKEND_MODULES);
         // sorting algorithm
-        Debug.fcall("execstat",print, "*** BackendMain -> transformDAE sort components at time: " +& realString(clock()) +& "\n" );
         (comps) = BackendDAETransform.strongComponents(m1, mT1, v1, v2);
+        Debug.execStat("transformDAE -> sort components",BackendDAE.RT_CLOCK_EXECSTAT_BACKEND_MODULES);
       then
         (ode,m1,mT1,v1,v2,comps);
     case (_,_,_,_,_,_)
@@ -6023,8 +6025,8 @@ algorithm
     case (dae,funcs,{},m,mT,v1,v2,comps,_) then (dae,m,mT,v1,v2,comps);
     case (dae,funcs,(optModule,moduleStr)::rest,m,mT,v1,v2,comps,daeHandler)
       equation
-        Debug.fcall("execstat",print, "*** BackendMain -> pastoptimiseDAE " +& moduleStr +& " at time: " +& realString(clock()) +& "\n" );
         (dae1,m1,mT1,v1_1,v2_1,comps1,runMatching) = optModule(dae,funcs,m,mT,v1,v2,comps);
+        Debug.execStat("pastOpt " +& moduleStr,BackendDAE.RT_CLOCK_EXECSTAT_BACKEND_MODULES);
         Debug.fcall("optdaedump", print, stringAppendList({"\nOptimisation Module ",moduleStr,":\n\n"}));
         Debug.fcall("optdaedump", BackendDump.dump, dae1);
         (dae1,m1,mT1,v1_1,v2_1,comps1) = checktransformDAE(runMatching,dae1,funcs,m1,mT1,v1_1,v2_1,comps1,daeHandler);

Compiler/BackEnd/SimCode.mo

@@ -894,14 +894,13 @@ algorithm
    a_cref := Absyn.pathToCref(className);
    fileDir := CevalScript.getFileDir(a_cref, p);
   System.realtimeTick(CevalScript.RT_CLOCK_BUILD_MODEL);
-  Debug.fcall("execstat",print, "*** SimCode -> generateFunctions: " +& realString(clock()) +& "\n" );
   (libs, includes, includeDirs, recordDecls, functions, outIndexedBackendDAE, _) :=
   createFunctions(dae, inBackendDAE, functionTree, className);
-  Debug.fcall("execstat",print, "*** SimCode -> generateSimCode: " +& realString(clock()) +& "\n" );
   simCode := createSimCode(functionTree, outIndexedBackendDAE, equationIndices,
     variableIndices, incidenceMatrix, incidenceMatrixT, strongComponents,
     className, filenamePrefix, fileDir, functions, includes, includeDirs, libs, simSettingsOpt, recordDecls);
   timeSimCode := System.realtimeTock(CevalScript.RT_CLOCK_BUILD_MODEL);
+  Debug.execStat("SimCode",CevalScript.RT_CLOCK_BUILD_MODEL);
 
   System.realtimeTick(CevalScript.RT_CLOCK_BUILD_MODEL);
   Tpl.tplNoret(SimCodeC.translateModel, simCode);
@@ -944,13 +943,13 @@ algorithm
    a_cref := Absyn.pathToCref(className);
    fileDir := CevalScript.getFileDir(a_cref, p);
   System.realtimeTick(CevalScript.RT_CLOCK_BUILD_MODEL);
-  Debug.fcall("execstat",print, "*** SimCode -> generateFunctions: " +& realString(clock()) +& "\n" );
   (libs, includes, includeDirs, recordDecls, functions, outIndexedBackendDAE, _) :=
   createFunctions(dae, inBackendDAE, functionTree, className);
   simCode := createSimCodeCPP(functionTree, outIndexedBackendDAE, equationIndices,
     variableIndices, incidenceMatrix, incidenceMatrixT, strongComponents,
     className, filenamePrefix, fileDir, functions, includes, includeDirs, libs, simSettingsOpt, recordDecls);
   timeSimCode := System.realtimeTock(CevalScript.RT_CLOCK_BUILD_MODEL);
+  Debug.execStat("SimCode",CevalScript.RT_CLOCK_BUILD_MODEL);
 
   System.realtimeTick(CevalScript.RT_CLOCK_BUILD_MODEL);
   Tpl.tplNoret(SimCodeCpp.translateModel, simCode);
@@ -1151,15 +1150,14 @@ algorithm
    a_cref := Absyn.pathToCref(className);
    fileDir := CevalScript.getFileDir(a_cref, p);
   System.realtimeTick(CevalScript.RT_CLOCK_BUILD_MODEL);
-  Debug.fcall("execstat",print, "*** SimCode -> generateFunctions: " +& realString(clock()) +& "\n" );
   (libs, includes, includeDirs, recordDecls, functions, outIndexedBackendDAE, _) :=
   createFunctions(dae, inBackendDAE, functionTree, className);
-  Debug.fcall("execstat",print, "*** SimCode -> generateSimCode: " +& realString(clock()) +& "\n" );
   simCode := createSimCode(functionTree, outIndexedBackendDAE, equationIndices, 
     variableIndices, incidenceMatrix, incidenceMatrixT, strongComponents, 
     className, filenamePrefix, fileDir, functions, includes, includeDirs, libs, simSettingsOpt, recordDecls);
 
   timeSimCode := System.realtimeTock(CevalScript.RT_CLOCK_BUILD_MODEL);
+  Debug.execStat("SimCode",CevalScript.RT_CLOCK_BUILD_MODEL);
   System.realtimeTick(CevalScript.RT_CLOCK_BUILD_MODEL);
 
   inQSSrequiredData := (outIndexedBackendDAE, equationIndices, variableIndices, incidenceMatrix, incidenceMatrixT, strongComponents);
@@ -1190,7 +1188,7 @@ algorithm
       then ();
     case (simCode,(outIndexedBackendDAE, equationIndices, variableIndices, incidenceMatrix, incidenceMatrixT, strongComponents),"QSS")
       equation
-        Debug.print("Generating QSS solver code\n");
+        Debug.trace("Generating QSS solver code\n");
         qssInfo = BackendQSS.generateStructureCodeQSS(outIndexedBackendDAE, equationIndices, variableIndices, incidenceMatrix, incidenceMatrixT, strongComponents);
         Tpl.tplNoret2(SimCodeQSS.translateModel, simCode, qssInfo);
       then ();

Compiler/FrontEnd/Inst.mo

@@ -97,6 +97,8 @@ public
 constant Boolean alwaysUnroll = true;
 constant Boolean neverUnroll = false;
 
+constant Integer RT_CLOCK_EXECSTAT_MAIN = 11;
+
 // the index of the inst hash table in the global table
 constant Integer instHashIndex = 0;
 
@@ -1048,15 +1050,14 @@ algorithm
 
     case (cache,env,ih,{(c as SCode.CLASS(name = n, classDef = cdef))})
       equation
-        Debug.fcall("execstat",print, "*** Inst -> enter at time: " +& realString(clock()) +& "\n" );
         // Debug.fprint("insttr", "inst_program1: ");
         // Debug.fprint("insttr", n);
         // Debug.fprintln("insttr", "");
         containedInOpt = Env.getEnvPath(env);
         (cache,env_1,ih,store,dae,csets,_,_,_,graph) =
           instClass(cache,env,ih,UnitAbsynBuilder.emptyInstStore(), DAE.NOMOD(),
             Prefix.NOPRE(), Connect.emptySet, c, {}, false, TOP_CALL(), ConnectionGraph.EMPTY) ;
-        Debug.fcall("execstat",print, "*** Inst -> instClass finished at time: " +& realString(clock()) +& "\n" );
+        Debug.execStat("instClass done",RT_CLOCK_EXECSTAT_MAIN);
         // deal with Overconstrained connections
         dae = ConnectionGraph.handleOverconstrainedConnections(graph, dae, n);
         //print(" ********************** backpatch 3 **********************\n");
@@ -1069,7 +1070,7 @@ algorithm
         source = DAEUtil.addElementSourcePartOfOpt(DAE.emptyElementSource, Env.getEnvPath(env));
 
         // finish with the execution statistics
-        Debug.fcall("execstat",print, "*** Inst -> exit at time: " +& realString(clock()) +& "\n" );
+        Debug.execStat("Instantiation done",RT_CLOCK_EXECSTAT_MAIN);
 
         daeElts = DAEUtil.daeElements(dae);
         comment = extractClassDefComment(cache, env, cdef);

Compiler/Main/Main.mo

@@ -46,6 +46,7 @@ protected import AbsynDep;
 protected import BackendDAE;
 protected import BackendDAECreate;
 protected import BackendDAEUtil;
+protected import CevalScript;
 protected import Dump;
 protected import DumpGraphviz;
 protected import SCode;
@@ -527,7 +528,8 @@ algorithm
     case (f :: libs)
       equation
         //print("Class to instantiate: " +& RTOpts.classToInstantiate() +& "\n");
-        Debug.fcall("execstat", print, "*** Main -> entering at time: " +& realString(clock()) +& "\n");
+        System.realtimeTick(CevalScript.RT_CLOCK_EXECSTAT_MAIN);
+        Debug.execStat("Enter Main",CevalScript.RT_CLOCK_EXECSTAT_MAIN);
         // Check that it's a .mo-file.
         isModelicaFile(f);
         // Parse the first file.
@@ -552,12 +554,11 @@ algorithm
         Debug.fprint("info", "---elaborating\n");
         Debug.fprint("info", "\n------------------------------------------------------------ \n");
         Debug.fprint("info", "---instantiating\n");
-        Debug.fcall("execstat",print, "*** Main -> To instantiate at time: " +& realString(clock()) +& "\n" );
+        Debug.execStat("Parsed file",CevalScript.RT_CLOCK_EXECSTAT_MAIN);
 
         // Instantiate the program.
         (cache, env, d_1, scode, cname) = instantiate(p);
 
-        Debug.fcall("execstat",print, "*** Main -> done instantiation at time: " +& realString(clock()) +& "\n" );
         Debug.fprint("beforefixmodout", "Explicit part:\n");
         Debug.fcall("beforefixmodout", DAEDump.dumpDebug, d_1);
 
@@ -569,18 +570,18 @@ algorithm
 
         Print.clearBuf();
         Debug.fprint("info", "---dumping\n");
-        Debug.fcall("execstat",print, "*** Main -> dumping dae: " +& realString(clock()) +& "\n" );
+        Debug.execStat("Transformations before Dump",CevalScript.RT_CLOCK_EXECSTAT_MAIN);
         s = Debug.fcallret2("flatmodelica", DAEDump.dumpStr, d, funcs, "");
-        Debug.fcall("execstat",print, "*** Main -> done dumping dae: " +& realString(clock()) +& "\n" );
         Debug.fcall("flatmodelica", Print.printBuf, s);
-        Debug.fcall("execstat",print, "*** Main -> dumping dae2 : " +& realString(clock()) +& "\n" );
+        Debug.execStat("Dump done",CevalScript.RT_CLOCK_EXECSTAT_MAIN);
         s = Debug.fcallret2("none", DAEDump.dumpStr, d, funcs, "");
-        Debug.fcall("execstat",print, "*** Main -> done dumping dae2 : " +& realString(clock()) +& "\n" );
+        Debug.execStat("DAEDump done",CevalScript.RT_CLOCK_EXECSTAT_MAIN);
         Debug.fcall("none", Print.printBuf, s);
         Debug.fcall2("daedump", DAEDump.dump, d, funcs);
         Debug.fcall("daedump2", DAEDump.dump2, d);
         Debug.fcall("daedumpdebug", DAEDump.dumpDebug, d);
         Debug.fcall("daedumpgraphv", DAEDump.dumpGraphviz, d);
+        Debug.execStat("Misc Dump",CevalScript.RT_CLOCK_EXECSTAT_MAIN);
 
         // Do any transformations required before going into code generation, e.g. if-equations to expressions.
         d = Debug.bcallret1(boolNot(RTOpts.debugFlag("transformsbeforedump")),DAEUtil.transformationsBeforeBackend,d,d);
@@ -589,7 +590,7 @@ algorithm
         silent = RTOpts.silent();
         notsilent = boolNot(silent);
         Debug.bcall(notsilent, print, str);
-        Debug.fcall("execstat",print, "*** Main -> To optimizedae at time: " +& realString(clock()) +& "\n" );
+        Debug.execStat("Transformations before backend",CevalScript.RT_CLOCK_EXECSTAT_MAIN);
 
         // Run the backend.
         optimizeDae(cache, env, scode, p, d, d, cname);
@@ -760,11 +761,11 @@ algorithm
     case (cache,env,p,ap,dae,daeimpl,classname)
       equation
         true = runBackendQ();
-        Debug.fcall("execstat",print, "*** Main -> To lower dae at time: " +& realString(clock()) +& "\n" );
         funcs = Env.getFunctionTree(cache);
         dlow = BackendDAECreate.lower(dae,funcs,true);
         (dlow_1,m,mT,v1,v2,comps) = BackendDAEUtil.getSolvedSystem(cache,env,dlow,funcs,NONE(),NONE(),NONE());
         modpar(dlow_1,v1,v2,comps);
+        Debug.execStat("Lowering Done",CevalScript.RT_CLOCK_EXECSTAT_MAIN);
         simcodegen(dlow_1,funcs,classname,p,ap,daeimpl,m,mT,v1,v2,comps);
       then
         ();
@@ -872,13 +873,13 @@ algorithm
 
     case (dlow,functionTree,classname,p,ap,dae,m,mt,ass1,ass2,comps) /* classname ass1 ass2 blocks */
       equation
-        Debug.fcall("execstat",print, "*** Main -> entering simcodgen: " +& realString(clock()) +& "\n" );
         true = RTOpts.simulationCg();
         Print.clearErrorBuf();
         Print.clearBuf();
         cname_str = Absyn.pathString(classname);
         simSettings = SimCode.createSimulationSettings(0.0, 1.0, 500, 1e-6,"dassl","","mat",".*",false,"");
         (_,_,_,_,_,_) = SimCode.generateModelCode(dlow,functionTree,ap,dae,classname,cname_str,SOME(simSettings),m,mt,ass1,ass2,comps);
+        Debug.execStat("Codegen Done",CevalScript.RT_CLOCK_EXECSTAT_MAIN);
       then
         ();
     /* If not generating simulation code: Succeed so no error messages are printed */

Compiler/Script/CevalScript.mo

@@ -105,6 +105,8 @@ protected import ComponentReference;
 public constant Integer RT_CLOCK_SIMULATE_TOTAL = 8;
 public constant Integer RT_CLOCK_SIMULATE_SIMULATION = 9;
 public constant Integer RT_CLOCK_BUILD_MODEL = 10;
+public constant Integer RT_CLOCK_EXECSTAT_MAIN = Inst.RT_CLOCK_EXECSTAT_MAIN;
+public constant Integer RT_CLOCK_EXECSTAT_BACKEND_MODULES = BackendDAE.RT_CLOCK_EXECSTAT_BACKEND_MODULES;
 
 protected constant DAE.Type simulationResultType_rtest = (DAE.T_COMPLEX(ClassInf.RECORD(Absyn.IDENT("SimulationResult")),{
   DAE.TYPES_VAR("resultFile",DAE.ATTR(SCode.NOT_FLOW(),SCode.NOT_STREAM(),SCode.RO(),SCode.VAR(),Absyn.BIDIR(),Absyn.NOT_INNER_OUTER()),SCode.PUBLIC(),DAE.T_STRING_DEFAULT,DAE.UNBOUND(),NONE()),

Compiler/Util/Debug.mo

@@ -47,15 +47,7 @@ encapsulated package Debug
 // protected imports
 protected import RTOpts;
 protected import Print;
-
-public function print
-"function: print
-  author: PR
-  This function is used for debug printing."
-  input String s;
-algorithm
-  fprint("olddebug", s);
-end print;
+protected import System;
 
 public function trace
 "function: print
@@ -567,6 +559,55 @@ algorithm
   end matchcontinue;
 end printList;
 
+public function execStat
+  "Prints an execution stat on the format:
+  *** %name% -> time: %time%, memory %memory%
+  Where you provide name, and time is the time since the last call using this
+  index (the clock is reset after each call). The memory is the total memory
+  consumed by the compiler at this point in time.
+  "
+  input String name;
+  input Integer clockIndex;
+algorithm
+  execStat2(RTOpts.debugFlag("execstat"),name,clockIndex);
+end execStat;
+
+protected function execStat2
+  input Boolean cond;
+  input String name;
+  input Integer clockIndex;
+algorithm
+  _ := match (cond,name,clockIndex)
+    local
+      Real t;
+      Integer used,allocated;
+    case (false,_,_) then ();
+    case (_,name,clockIndex)
+      equation
+        t = System.realtimeTock(clockIndex);
+        (used,allocated) = System.getGCStatus();
+        print("*** ");
+        print(name);
+        print(" -> time: ");
+        print(realString(t));
+        print(" , memory: ");
+        print(bytesToRealMBString(used));
+        print("/");
+        print(bytesToRealMBString(allocated));
+        print(" MB (");
+        print(realString(realMul(100.0,realDiv(intReal(used),intReal(allocated)))));
+        print("%)\n");
+        System.realtimeTick(clockIndex);
+      then ();
+  end match;
+end execStat2;
+
+protected function bytesToRealMBString
+  input Integer bytes;
+  output String str;
+algorithm
+  str := realString(realDiv(intReal(bytes),realMul(1024.0,1024.0)));
+end bytesToRealMBString;
 
 end Debug;
 

Compiler/Util/System.mo

@@ -798,4 +798,10 @@ public function openModelicaPlatform "
   external "C" System_openModelicaPlatform() annotation(Library = "omcruntime");
 end openModelicaPlatform;
 
+public function getGCStatus
+  output Integer used;
+  output Integer allocated;
+  external "C" System_getGCStatus(used,allocated);
+end getGCStatus;
+
 end System;

Compiler/runtime/System_omc.cpp

@@ -582,4 +582,10 @@ extern const char* System_openModelicaPlatform()
   return CONFIG_OPENMODELICA_SPEC_PLATFORM;
 }
 
+extern void getGCStatus(int *used, int *allocated)
+{
+  *used = -1;
+  *allocated = -1;
+}
+
 }

Compiler/runtime/System_rml.c

@@ -2001,3 +2001,14 @@ RML_BEGIN_LABEL(System__openModelicaPlatform)
   RML_TAILCALLK(rmlSC);
 }
 RML_END_LABEL
+
+RML_BEGIN_LABEL(System__getGCStatus)
+{
+  long used = RML_SIZE_INT*((unsigned long)(rml_state_young_next - rml_young_region)
+             + (unsigned long)(rml_current_next - rml_current_region));
+  long allocated = RML_SIZE_INT*(rml_older_size + rml_young_size);
+  rmlA0 = mk_icon(used);
+  rmlA1 = mk_icon(allocated);
+  RML_TAILCALLK(rmlSC);
+}
+RML_END_LABEL