add some perf log for unsweetenning process, and output IR to file

include/hobbes/eval/cc.H

@@ -219,6 +219,11 @@ public:
   // dump the contents of the generated module (useful for debugging)
   void dumpModule();
 
+#if LLVM_VERSION_MAJOR < 11
+  // show jit functions in name:addr format
+  [[nodiscard]] std::string showJitMemoryAddresses() const;
+#endif
+
   // get the x86 machine code for an expression (useful for debugging)
   using bytes = std::vector<unsigned char>;
   bytes machineCodeForExpr(const std::string &expr);
@@ -375,6 +380,9 @@ private:
   // the JIT engine that compiles our monotyped expressions
   jitcc *jit;
 
+  struct PerfTracer;
+  std::unique_ptr<PerfTracer> perfTracer;
+
 public:
   // compiler-local type structure caches for internal use
   std::unordered_map<MonoType *, MonoTypePtr> unappTyDefns;

include/hobbes/eval/funcdefs.H

@@ -15,6 +15,8 @@ char* memalloc(size_t, size_t);
 const array<char>* makeString(const std::string& x);
 std::string makeStdString(const array<char>* x);
 
+[[nodiscard]] std::string showDetailedMemoryPool();
+
 }
 
 #endif

include/hobbes/eval/jitcc.H

@@ -57,6 +57,8 @@ public:
   void* getSymbolAddress(const std::string&);
 
 #if LLVM_VERSION_MAJOR < 11
+  [[nodiscard]] std::string showJitMemoryAddresses();
+
   // print all module contents
   void dump() const;
 #endif

include/hobbes/lang/expr.H

@@ -19,6 +19,7 @@ public:
   virtual ~Expr();
 
   virtual void show(std::ostream&) const = 0;
+  [[nodiscard]] std::string toString() const;
   virtual void showAnnotated(std::ostream&) const = 0;
   virtual Expr* clone() const = 0;
   virtual bool operator==(const Expr&) const = 0;

include/hobbes/lang/module.H

@@ -17,6 +17,7 @@ namespace hobbes {
 struct ModuleDef : public LexicallyAnnotated {
   virtual ~ModuleDef();
   virtual void show(std::ostream&) const = 0;
+  [[nodiscard]] std::string toString() const;
 
   // improves performance of case-analysis over instances (to avoid 'dynamic_cast')
 public:
@@ -243,6 +244,7 @@ public:
   const ModuleDefs&  definitions() const;
 
   void show(std::ostream& out) const;
+  [[nodiscard]] std::string toString() const;
 
   // allow language options set within modules
   void setOption(const std::string&, const LexicalAnnotation&);

include/hobbes/lang/preds/class.H

@@ -68,6 +68,7 @@ public:
 
   // show this class definition
   void show(std::ostream&) const;
+  [[nodiscard]] std::string toString() const;
 public:
   const TCInstances& instances() const;
   bool hasGroundInstanceAt(const MonoTypes&) const;
@@ -122,6 +123,7 @@ public:
 
   // show this instance definition
   void show(std::ostream&) const;
+  [[nodiscard]] std::string toString() const;
 private:
   std::string   tcname;
   MonoTypes     itys;
@@ -152,6 +154,7 @@ public:
 
   // show this instance-generator definition
   void show(std::ostream&) const;
+  [[nodiscard]] std::string toString() const;
 
   // produce a sequence of type variables and constraints unique to this invocation
   using IFnDef = std::pair<Constraints, MonoTypes>;

include/hobbes/lang/type.H

@@ -41,6 +41,7 @@ public:
   using ptr = std::shared_ptr<MonoType>;
 
   virtual void show(std::ostream&) const = 0;
+  [[nodiscard]] std::string toString() const;
   bool operator==(const MonoType& rhs) const;
 
   // improves performance of case-analysis over instances (to avoid 'dynamic_cast')
@@ -109,6 +110,8 @@ public:
   // get access to the parent and root type environment from here
   const TEnvPtr& parentTypeEnv() const;
   TEnv* root();
+
+  [[nodiscard]] std::string toString() const;
 public:
   // get access to the internal type environment map (should only be used for debugging)
   using PolyTypeEnv = std::map<std::string, PolyTypePtr>;
@@ -179,6 +182,7 @@ public:
   QualTypePtr instantiate() const;
 
   void show(std::ostream&) const;
+  [[nodiscard]] std::string toString() const;
   bool operator==(const PolyType& rhs) const;
 
   // this should only be used if you don't mind capturing bound type variables
@@ -206,6 +210,7 @@ public:
   void monoType(const MonoTypePtr&);
 
   void show(std::ostream&) const;
+  [[nodiscard]] std::string toString() const;
   bool operator==(const QualType& rhs) const;
 private:
   Constraints cs;
@@ -238,6 +243,7 @@ public:
 
   // compare/show
   void show(std::ostream&) const;
+  [[nodiscard]] std::string toString() const;
   bool operator==(const Constraint& rhs) const;
 
   // are there free variables referenced in this constraint?

lib/hobbes/eval/cc.C

@@ -1,4 +1,3 @@
-
 #include <hobbes/eval/cc.H>
 #include <hobbes/eval/funcdefs.H>
 #include <hobbes/eval/ctype.H>
@@ -7,6 +6,8 @@
 #include <hobbes/lang/closcvt.H>
 #include <hobbes/lang/typepreds.H>
 #include <hobbes/lang/macroexpand.H>
+#include <hobbes/lang/preds/consrecord.H>
+#include <hobbes/lang/preds/consvariant.H>
 #include <hobbes/util/llvm.H>
 #include <hobbes/util/array.H>
 #include <hobbes/util/codec.H>
@@ -24,14 +25,96 @@
 #include <csignal>
 #include <cstdlib>
 
+#include <algorithm>
+#include <chrono>
 #include <fstream>
 #include <memory>
 #include <mutex>
+#include <numeric>
 #include <stdexcept>
 #include <unordered_map>
 
 namespace hobbes {
 
+struct cc::PerfTracer {
+  PerfTracer() {
+    const char* name = std::getenv("HOBBES_PERF_TRACE_FILE");
+    if (name == nullptr) {
+      return;
+    }
+
+    ofs.open(name);
+    if (!ofs) {
+      ofs.close();
+      return;
+    }
+
+    const char* th = std::getenv("HOBBES_PERF_TRACE_THRESHOLD_IN_SECS");
+    if (th == nullptr) {
+      ofs.close();
+      return;
+    }
+    threshold = std::chrono::seconds(atoi(th));
+  }
+
+  template <typename T, typename F>
+  [[nodiscard]] std::size_t nonHiddenSz(const T& t, F f) {
+    const auto& ms = t.members();
+    return std::accumulate(ms.cbegin(), ms.cend(), 0UL, [f](auto a, const auto& m) {
+      return a + (f(m).substr(0, 2) != ".p" ? 1UL : 0UL);
+    });
+  }
+
+  template <typename TT>
+  void log(const std::string& name, const ExprPtr& e, const Definitions& defs, TT delta) {
+    if (!isEnabled() || delta <= threshold || name.empty() || name.substr(0, 5) == ".rfn.") {
+      return;
+    }
+
+    constexpr const char* MARK = "HOBBES_PERF";
+    ofs << MARK << ':' << name
+        << ":BEGIN:" << std::chrono::duration_cast<std::chrono::seconds>(delta).count() << ":";
+    e->show(ofs);
+    ofs << '\n';
+
+    for (auto i = defs.size(); i > 0; --i) {
+      std::ostringstream oss;
+      if (Assump::type_case_id != defs[i - 1].second->case_id()) {
+        continue;
+      }
+      const auto a = rcast<const Assump*>(defs[i - 1].second.get());
+      if (!a->ty() || a->ty()->constraints().empty()) {
+        continue;
+      }
+
+      const auto& cs = a->ty()->constraints()[0];
+      if (cs->name() == VariantDeconstructor::constraintName()) {
+        const auto& var = cs->arguments()[1];
+        var->show(oss);
+        const int sz = nonHiddenSz(*is<Variant>(var), [](const auto& m) { return m.selector; });
+        i -= static_cast<std::size_t>(sz - 1);
+        ofs << MARK << ':' << name << ':' << sz << ':' << std::move(oss).str() << '\n';
+      } else if (cs->name() == RecordDeconstructor::constraintName()) {
+        const auto& rec = cs->arguments()[2];
+        rec->show(oss);
+        const int sz = nonHiddenSz(*is<Record>(rec), [](const auto& m) { return m.field; });
+        i -= static_cast<std::size_t>(sz - 1);
+        ofs << MARK << ':' << name << ':' << sz << ':' << std::move(oss).str() << '\n';
+      }
+    }
+
+    ofs << MARK << ':' << name << ":END:" << defs.size() << '\n' << std::endl;
+  }
+
+private:
+  [[nodiscard]] bool isEnabled() const noexcept {
+    return ofs.good();
+  }
+
+  std::ofstream ofs;
+  std::chrono::seconds threshold{0};
+};
+
 // protect access to hobbes/llvm resources
 static std::recursive_mutex hccmtx;
 hlock:: hlock() { hccmtx.lock();   }
@@ -52,7 +135,8 @@ cc::cc() :
   lowerPrimMatchTables(false),
   columnwiseMatches(false),
   tenv(new TEnv()),
-  objs(new Objs())
+  objs(new Objs()),
+  perfTracer(std::make_unique<PerfTracer>())
 {
   // protect access to LLVM
   hlock _;
@@ -230,6 +314,7 @@ ExprPtr cc::unsweetenExpression(const TEnvPtr& te, const std::string& vname, con
   hlock _;
   Definitions ds;
 
+  const auto timingStart = std::chrono::steady_clock::now();
   ExprPtr result;
   try {
     result = macroExpand(unqualifyTypes(te, validateType(te, vname, closureConvert(this->tenv, vname, e), &ds), &ds));
@@ -239,6 +324,9 @@ ExprPtr cc::unsweetenExpression(const TEnvPtr& te, const std::string& vname, con
   }
 
   drainUnqualifyDefs(ds);
+  const auto delta = std::chrono::duration_cast<std::chrono::seconds>(
+      std::chrono::steady_clock::now() - timingStart);
+  perfTracer->log(vname, e, ds, delta);
   return result;
 }
 
@@ -565,6 +653,13 @@ void cc::dumpModule() {
 #endif
 }
 
+#if LLVM_VERSION_MAJOR < 11
+std::string cc::showJitMemoryAddresses() const {
+  hlock _;
+  return this->jit->showJitMemoryAddresses();
+}
+#endif
+
 cc::bytes cc::machineCodeForExpr(const std::string& expr) {
   hlock _;
   return this->jit->machineCodeForExpr(unsweetenExpression(readExpr(expr)));

lib/hobbes/eval/funcdefs.C

@@ -154,6 +154,18 @@ void printMemoryPool() {
   std::cout << showMemoryPool() << std::flush;
 }
 
+std::string showDetailedMemoryPool() {
+  std::ostringstream oss;
+  oss << "{";
+  std::string sep;
+  for (const auto& region: threadRegions()) {
+    oss << sep << "\n\"" << region.first << "\": " << region.second->show();
+    sep = ",";
+  }
+  oss << "\n}";
+  return std::move(oss).str();
+}
+
 void resetMemoryPool() {
   threadRegion().clear();
 }

lib/hobbes/eval/jitcc.C

@@ -8,15 +8,23 @@
 #include <llvm/IR/Constant.h>
 #include <llvm/IR/Constants.h>
 #include <llvm/IR/DerivedTypes.h>
+#include <llvm/IR/Function.h>
 #include <llvm/IR/GlobalVariable.h>
 #include <llvm/IR/LLVMContext.h>
 #include <llvm/IR/Value.h>
 #include <llvm/IR/ValueHandle.h>
+#include <llvm/IR/ValueSymbolTable.h>
 #include <llvm/Support/Casting.h>
 #include <llvm/Support/Compiler.h>
 #include <llvm/Support/Error.h>
+#include <llvm/Support/FileSystem.h>
+#include <llvm/Support/raw_ostream.h>
 #include <llvm/Target/TargetMachine.h>
+
+#include <algorithm>
+#include <cstdint>
 #include <stdexcept>
+#include <system_error>
 #include <utility>
 
 #pragma GCC diagnostic push
@@ -550,7 +558,8 @@ private:
 jitcc::jitcc(const TEnvPtr& tenv)
     : tenv(tenv), vtenv(std::make_unique<VTEnv>()), ignoreLocalScope(false),
       globals(std::make_unique<Globals>()), globalData(32768 /* min global page size = 32K */),
-      constants(std::make_unique<ConstantList>()) {
+      constants(std::make_unique<ConstantList>())
+       {
   llvm::InitializeNativeTarget();
   llvm::InitializeNativeTargetAsmParser();
   llvm::InitializeNativeTargetAsmPrinter();
@@ -662,6 +671,21 @@ llvm::Module* jitcc::module() {
   }
   return this->currentModule;
 }
+
+std::string jitcc::showJitMemoryAddresses() {
+  std::string s;
+  llvm::raw_string_ostream os(s);
+  for (const auto* m: this->modules) {
+    for (const auto& f: *m) {
+      if (!f.isDeclaration()) {
+        if (void* addr = this->getSymbolAddress(f.getName().str())) {
+          os << f.getName() << ':' << addr << '\n';
+        }
+      }
+    }
+  }
+  return s;
+}
 #endif
 
 #if LLVM_VERSION_MAJOR >= 11
@@ -792,7 +816,7 @@ void* jitcc::getMachineCode(llvm::Function* f, llvm::JITEventListener* listener)
   ee->finalizeObject();
 
   // now we can't touch this module again
-  this->currentModule = 0;
+  this->currentModule = nullptr;
 
   // and _now_ we must be able to get machine code for this function
   void* pf = ee->getPointerToFunction(f);
@@ -1197,7 +1221,6 @@ void jitcc::defineGlobal(const std::string& vn, const ExprPtr& ue) {
     // compile and run this function, it should then perform the global variable assignment
     // (make sure that any allocation happens in the global context iff we need it)
     auto f = reinterpret_cast<Thunk>(getMachineCode(initfn));
-
     if (hasPointerRep(uety)) {
       size_t oldregion = pushGlobalRegion();
       f();