Add some top-down timing measurements to compilation

Somewhat confusing, since us_compiling_analysis_liveness is
also contained in us_compiling_irgen, and I'm not sure of a good
way to avoid that for now.

But anyway, for "import re", the breakdown is roughly:
- 215ms definedness analysis
- 50ms liveness analysis
- 80ms phi analysis
- 200ms type analysis
- 5ms irgen
- 25ms other compilation stuff
- 40ms non-compilation time

src/analysis/function_analysis.cpp

@@ -107,6 +107,8 @@ int LivenessAnalysis::getStringIndex(const std::string& s) {
 }
 
 LivenessAnalysis::LivenessAnalysis(CFG* cfg) : cfg(cfg) {
+    Timer _t("LivenessAnalysis()");
+
     for (CFGBlock* b : cfg->blocks) {
         auto visitor = new LivenessBBVisitor(this); // livenessCache unique_ptr will delete it.
         for (AST_stmt* stmt : b->body) {
@@ -114,9 +116,14 @@ LivenessAnalysis::LivenessAnalysis(CFG* cfg) : cfg(cfg) {
         }
         liveness_cache.insert(std::make_pair(b, std::unique_ptr<LivenessBBVisitor>(visitor)));
     }
+
+    static StatCounter us_liveness("us_compiling_analysis_liveness");
+    us_liveness.log(_t.end());
 }
 
 bool LivenessAnalysis::isLiveAtEnd(const std::string& name, CFGBlock* block) {
+    Timer _t("LivenessAnalysis()");
+
     if (name[0] != '#')
         return true;
 
@@ -159,6 +166,10 @@ bool LivenessAnalysis::isLiveAtEnd(const std::string& name, CFGBlock* block) {
         }
     }
 
+    // Note: this one gets counted as part of us_compiling_irgen as well:
+    static StatCounter us_liveness("us_compiling_analysis_liveness");
+    us_liveness.log(_t.end());
+
     return result_cache[idx][block];
 }
 
@@ -315,7 +326,7 @@ DefinednessAnalysis::DefinednessAnalysis(const SourceInfo::ArgNames& arg_names,
         defined_at_end.insert(make_pair(p.first, required));
     }
 
-    static StatCounter us_definedness("us_analysis_definedness");
+    static StatCounter us_definedness("us_compiling_analysis_definedness");
     us_definedness.log(_t.end());
 }
 
@@ -333,6 +344,7 @@ const DefinednessAnalysis::RequiredSet& DefinednessAnalysis::getDefinedNamesAtEn
 PhiAnalysis::PhiAnalysis(const SourceInfo::ArgNames& arg_names, CFG* cfg, LivenessAnalysis* liveness,
                          ScopeInfo* scope_info)
     : definedness(arg_names, cfg, scope_info), liveness(liveness) {
+    Timer _t("PhiAnalysis()");
 
     for (CFGBlock* block : cfg->blocks) {
         RequiredSet required;
@@ -352,6 +364,9 @@ PhiAnalysis::PhiAnalysis(const SourceInfo::ArgNames& arg_names, CFG* cfg, Livene
 
         required_phis.insert(make_pair(block, std::move(required)));
     }
+
+    static StatCounter us_phis("us_compiling_analysis_phis");
+    us_phis.log(_t.end());
 }
 
 const PhiAnalysis::RequiredSet& PhiAnalysis::getAllRequiredAfter(CFGBlock* block) {

src/analysis/type_analysis.cpp

@@ -768,7 +768,7 @@ public:
             }
         }
 
-        static StatCounter us_types("us_analysis_types");
+        static StatCounter us_types("us_compiling_analysis_types");
         us_types.log(_t.end());
 
         return new PropagatingTypeAnalysis(starting_types, expr_types, type_speculations, speculation);

src/codegen/irgen.cpp

@@ -908,6 +908,8 @@ static std::string getUniqueFunctionName(std::string nameprefix, EffortLevel::Ef
 CompiledFunction* doCompile(SourceInfo* source, const OSREntryDescriptor* entry_descriptor,
                             EffortLevel::EffortLevel effort, FunctionSpecialization* spec, std::string nameprefix) {
     Timer _t("in doCompile");
+    Timer _t2;
+    long irgen_us = 0;
 
     if (VERBOSITY("irgen") >= 1)
         source->cfg->print();
@@ -964,12 +966,16 @@ CompiledFunction* doCompile(SourceInfo* source, const OSREntryDescriptor* entry_
 
     llvm::MDNode* dbg_funcinfo = setupDebugInfo(source, f, nameprefix);
 
+    irgen_us += _t2.split();
+
     TypeAnalysis::SpeculationLevel speculation_level = TypeAnalysis::NONE;
     if (ENABLE_SPECULATION && effort >= EffortLevel::MODERATE)
         speculation_level = TypeAnalysis::SOME;
     TypeAnalysis* types = doTypeAnalysis(source->cfg, source->arg_names, spec->arg_types, speculation_level,
                                          source->scoping->getScopeInfoForNode(source->ast));
 
+    _t2.split();
+
     GuardList guards;
 
     BlockSet full_blocks, partial_blocks;
@@ -1003,8 +1009,11 @@ CompiledFunction* doCompile(SourceInfo* source, const OSREntryDescriptor* entry_
 
         assert(deopt_full_blocks.size() || deopt_partial_blocks.size());
 
+        irgen_us += _t2.split();
         TypeAnalysis* deopt_types = doTypeAnalysis(source->cfg, source->arg_names, spec->arg_types, TypeAnalysis::NONE,
                                                    source->scoping->getScopeInfoForNode(source->ast));
+        _t2.split();
+
         emitBBs(&irstate, "deopt", deopt_guards, guards, deopt_types, NULL, deopt_full_blocks, deopt_partial_blocks);
         assert(deopt_guards.isEmpty());
         deopt_guards.assertGotPatched();
@@ -1044,9 +1053,9 @@ CompiledFunction* doCompile(SourceInfo* source, const OSREntryDescriptor* entry_
     }
 #endif
 
-    long us = _t.end();
+    irgen_us += _t2.split();
     static StatCounter us_irgen("us_compiling_irgen");
-    us_irgen.log(us);
+    us_irgen.log(irgen_us);
 
     if (ENABLE_LLVMOPTS)
         optimizeIR(f, effort);

src/core/util.cpp

@@ -27,9 +27,6 @@ namespace pyston {
 
 int Timer::level = 0;
 
-Timer::Timer(const char* desc) : min_usec(-1), ended(true) {
-    restart(desc);
-}
 Timer::Timer(const char* desc, long min_usec) : min_usec(min_usec), ended(true) {
     restart(desc);
 }
@@ -55,7 +52,7 @@ long Timer::end() {
         long us = 1000000L * (end.tv_sec - start_time.tv_sec) + (end.tv_usec - start_time.tv_usec);
 
         Timer::level--;
-        if (VERBOSITY("time") >= 1) {
+        if (VERBOSITY("time") >= 1 && desc) {
             if (us > min_usec) {
                 for (int i = 0; i < Timer::level; i++) {
                     putchar(' ');

src/core/util.h

@@ -32,15 +32,14 @@ private:
     bool ended;
 
 public:
-    Timer(const char* desc);
-    Timer(const char* desc, long min_usec);
+    Timer(const char* desc=NULL, long min_usec=-1);
     ~Timer();
 
     void restart(const char* newdesc, long new_min_usec);
-    void restart(const char* newdesc);
+    void restart(const char* newdesc=NULL);
 
     long end();
-    long split(const char* newdesc) {
+    long split(const char* newdesc=NULL) {
         long rtn = end();
         restart(newdesc);
         return rtn;