Greatly reduce verbosity in -v mode

All the old prints still exist, but at -vv or even -vvv mode.

The basic system is:
-v mode gives information about the overall execution: what functions we
    run into, what things take longer than we expected, etc.
-vv mode gives information about each function: the cfg, llvm ir, etc.
-vvv gives information about each BB.

src/analysis/function_analysis.cpp

@@ -147,7 +147,7 @@ public:
 };
 
 LivenessAnalysis::LivenessAnalysis(CFG* cfg) : cfg(cfg) {
-    Timer _t("LivenessAnalysis()", 10);
+    Timer _t("LivenessAnalysis()", 100);
 
     for (CFGBlock* b : cfg->blocks) {
         auto visitor = new LivenessBBVisitor(this); // livenessCache unique_ptr will delete it.
@@ -361,7 +361,7 @@ void DefinednessBBAnalyzer::processBB(Map& starting, CFGBlock* block) const {
         block->body[i]->accept(&visitor);
     }
 
-    if (VERBOSITY("analysis") >= 2) {
+    if (VERBOSITY("analysis") >= 3) {
         printf("At end of block %d:\n", block->idx);
         for (const auto& p : starting) {
             printf("%s: %d\n", p.first.c_str(), p.second);

src/analysis/type_analysis.cpp

@@ -132,7 +132,7 @@ private:
         void* raw_rtn = node->accept_expr(this);
         CompilerType* rtn = static_cast<CompilerType*>(raw_rtn);
 
-        if (VERBOSITY() >= 2) {
+        if (VERBOSITY() >= 3) {
             print_ast(node);
             printf(" %s\n", rtn->debugName().c_str());
         }
@@ -735,10 +735,10 @@ public:
 
             TypeMap ending;
 
-            if (VERBOSITY("types")) {
+            if (VERBOSITY("types") >= 3) {
                 printf("processing types for block %d\n", block->idx);
             }
-            if (VERBOSITY("types") >= 2) {
+            if (VERBOSITY("types") >= 3) {
                 printf("before:\n");
                 TypeMap& starting = starting_types[block];
                 for (const auto& p : starting) {
@@ -750,7 +750,7 @@ public:
             BasicBlockTypePropagator::propagate(block, starting_types[block], ending, expr_types, type_speculations,
                                                 speculation, scope_info);
 
-            if (VERBOSITY("types") >= 2) {
+            if (VERBOSITY("types") >= 3) {
                 printf("before (after):\n");
                 TypeMap& starting = starting_types[block];
                 for (const auto& p : starting) {
@@ -775,11 +775,11 @@ public:
         }
 
         if (VERBOSITY("types")) {
-            printf("%ld BBs, %d evaluations = %.1f evaluations/block\n", cfg->blocks.size(), num_evaluations,
-                   1.0 * num_evaluations / cfg->blocks.size());
+            printf("Type analysis: %ld BBs, %d evaluations = %.1f evaluations/block\n", cfg->blocks.size(),
+                   num_evaluations, 1.0 * num_evaluations / cfg->blocks.size());
         }
 
-        if (VERBOSITY("types") >= 2) {
+        if (VERBOSITY("types") >= 3) {
             for (CFGBlock* b : cfg->blocks) {
                 printf("Types at beginning of block %d:\n", b->idx);
 

src/asm_writing/icinfo.cpp

@@ -61,7 +61,7 @@ ICSlotRewrite::ICSlotRewrite(ICInfo* ic, const char* debug_name) : ic(ic), debug
     assembler = new Assembler(buf, ic->getSlotSize());
     assembler->nop();
 
-    if (VERBOSITY())
+    if (VERBOSITY() >= 2)
         printf("starting %s icentry\n", debug_name);
 }
 
@@ -86,7 +86,7 @@ void ICSlotRewrite::commit(CommitHook* hook) {
         }
     }
     if (!still_valid) {
-        if (VERBOSITY())
+        if (VERBOSITY() >= 2)
             printf("not committing %s icentry since a dependency got updated before commit\n", debug_name);
         return;
     }
@@ -165,14 +165,14 @@ ICSlotInfo* ICInfo::pickEntryForRewrite(const char* debug_name) {
         if (sinfo.num_inside)
             continue;
 
-        if (VERBOSITY()) {
+        if (VERBOSITY() >= 3) {
             printf("committing %s icentry to in-use slot %d at %p\n", debug_name, i, start_addr);
         }
         next_slot_to_try = i + 1;
 
         return &sinfo;
     }
-    if (VERBOSITY())
+    if (VERBOSITY() >= 3)
         printf("not committing %s icentry since there are no available slots\n", debug_name);
     return NULL;
 }
@@ -259,7 +259,7 @@ void ICInfo::clear(ICSlotInfo* icentry) {
 
     uint8_t* start = (uint8_t*)start_addr + icentry->idx * getSlotSize();
 
-    if (VERBOSITY())
+    if (VERBOSITY() >= 3)
         printf("clearing patchpoint %p, slot at %p\n", start_addr, start);
 
     std::unique_ptr<Assembler> writer(new Assembler(start, getSlotSize()));

src/asm_writing/rewriter.cpp

@@ -1483,7 +1483,7 @@ bool spillFrameArgumentIfNecessary(StackMap::Record::Location& l, uint8_t*& inst
 
             auto it = remapped.find(ru);
             if (it != remapped.end()) {
-                if (VERBOSITY()) {
+                if (VERBOSITY() >= 3) {
                     printf("Already spilled ");
                     ru.dump();
                 }
@@ -1491,7 +1491,7 @@ bool spillFrameArgumentIfNecessary(StackMap::Record::Location& l, uint8_t*& inst
                 return false;
             }
 
-            if (VERBOSITY()) {
+            if (VERBOSITY() >= 3) {
                 printf("Spilling reg ");
                 ru.dump();
             }
@@ -1595,7 +1595,7 @@ std::pair<uint8_t*, uint8_t*> initializePatchpoint3(void* slowpath_func, uint8_t
             abort();
     }
 
-    if (VERBOSITY())
+    if (VERBOSITY() >= 3)
         printf("Have to spill %ld regs around the slowpath\n", regs_to_spill.size());
 
     // TODO: some of these registers could already have been pushed via the frame saving code

src/codegen/irgen.cpp

@@ -507,11 +507,11 @@ static void emitBBs(IRGenState* irstate, TypeAnalysis* types, const OSREntryDesc
         CFGBlock* block = traversal_order[_i].first;
         CFGBlock* pred = traversal_order[_i].second;
 
-        if (VERBOSITY("irgen") >= 1)
+        if (VERBOSITY("irgen") >= 2)
             printf("processing block %d\n", block->idx);
 
         if (!blocks.count(block)) {
-            if (VERBOSITY("irgen") >= 1)
+            if (VERBOSITY("irgen") >= 2)
                 printf("Skipping this block\n");
             // created_phis[block] = NULL;
             // ending_symbol_tables[block] = NULL;
@@ -955,7 +955,7 @@ CompiledFunction* doCompile(SourceInfo* source, ParamNames* param_names, const O
 
     assert((entry_descriptor != NULL) + (spec != NULL) == 1);
 
-    if (VERBOSITY("irgen") >= 1)
+    if (VERBOSITY("irgen") >= 2)
         source->cfg->print();
 
     assert(g.cur_module == NULL);
@@ -1056,7 +1056,7 @@ CompiledFunction* doCompile(SourceInfo* source, ParamNames* param_names, const O
 
     delete types;
 
-    if (VERBOSITY("irgen") >= 1) {
+    if (VERBOSITY("irgen") >= 2) {
         printf("generated IR:\n");
         printf("\033[33m");
         fflush(stdout);

src/codegen/irgen/hooks.cpp

@@ -183,7 +183,7 @@ static void compileIR(CompiledFunction* cf, EffortLevel effort) {
 // The codegen_lock needs to be held in W mode before calling this function:
 CompiledFunction* compileFunction(CLFunction* f, FunctionSpecialization* spec, EffortLevel effort,
                                   const OSREntryDescriptor* entry_descriptor) {
-    Timer _t("for compileFunction()");
+    Timer _t("for compileFunction()", 1000);
 
     assert((entry_descriptor != NULL) + (spec != NULL) == 1);
 

src/codegen/irgen/irgenerator.cpp

@@ -1396,7 +1396,7 @@ private:
             assert(rtn);
 
             ConcreteCompilerType* speculated_type = typeFromClass(speculated_class);
-            if (VERBOSITY("irgen") >= 1) {
+            if (VERBOSITY("irgen") >= 2) {
                 printf("Speculating that %s is actually %s, at ", rtn->getConcreteType()->debugName().c_str(),
                        speculated_type->debugName().c_str());
                 PrintVisitor printer;
@@ -2492,7 +2492,7 @@ public:
     }
 
     void run(const CFGBlock* block) override {
-        if (VERBOSITY("irgenerator") >= 1) { // print starting symbol table
+        if (VERBOSITY("irgenerator") >= 2) { // print starting symbol table
             printf("  %d init:", block->idx);
             for (auto it = symbol_table.begin(); it != symbol_table.end(); ++it)
                 printf(" %s", it->first.c_str());
@@ -2504,7 +2504,7 @@ public:
             assert(state != FINISHED);
             doStmt(block->body[i], UnwindInfo(block->body[i], NULL));
         }
-        if (VERBOSITY("irgenerator") >= 1) { // print ending symbol table
+        if (VERBOSITY("irgenerator") >= 2) { // print ending symbol table
             printf("  %d fini:", block->idx);
             for (auto it = symbol_table.begin(); it != symbol_table.end(); ++it)
                 printf(" %s", it->first.c_str());

src/codegen/parser.cpp

@@ -58,7 +58,7 @@ public:
         end -= start;
         start = 0;
         end += fread(buf + end, 1, BUFSIZE - end, fp);
-        if (VERBOSITY("parsing") >= 2)
+        if (VERBOSITY("parsing") >= 3)
             printf("filled, now at %d-%d\n", start, end);
     }
 
@@ -118,7 +118,7 @@ InternedString BufferedReader::readAndInternString() {
 
 void BufferedReader::readAndInternStringVector(std::vector<InternedString>& v) {
     int num_elts = readShort();
-    if (VERBOSITY("parsing") >= 2)
+    if (VERBOSITY("parsing") >= 3)
         printf("%d elts to read\n", num_elts);
     for (int i = 0; i < num_elts; i++) {
         v.push_back(readAndInternString());
@@ -127,7 +127,7 @@ void BufferedReader::readAndInternStringVector(std::vector<InternedString>& v) {
 
 static void readStringVector(std::vector<std::string>& vec, BufferedReader* reader) {
     int num_elts = reader->readShort();
-    if (VERBOSITY("parsing") >= 2)
+    if (VERBOSITY("parsing") >= 3)
         printf("%d elts to read\n", num_elts);
     for (int i = 0; i < num_elts; i++) {
         vec.push_back(readString(reader));
@@ -136,7 +136,7 @@ static void readStringVector(std::vector<std::string>& vec, BufferedReader* read
 
 static void readStmtVector(std::vector<AST_stmt*>& vec, BufferedReader* reader) {
     int num_elts = reader->readShort();
-    if (VERBOSITY("parsing") >= 2)
+    if (VERBOSITY("parsing") >= 3)
         printf("%d elts to read\n", num_elts);
     for (int i = 0; i < num_elts; i++) {
         vec.push_back(readASTStmt(reader));
@@ -145,7 +145,7 @@ static void readStmtVector(std::vector<AST_stmt*>& vec, BufferedReader* reader)
 
 static void readExprVector(std::vector<AST_expr*>& vec, BufferedReader* reader) {
     int num_elts = reader->readShort();
-    if (VERBOSITY("parsing") >= 2)
+    if (VERBOSITY("parsing") >= 3)
         printf("%d elts to read\n", num_elts);
     for (int i = 0; i < num_elts; i++) {
         vec.push_back(readASTExpr(reader));
@@ -154,7 +154,7 @@ static void readExprVector(std::vector<AST_expr*>& vec, BufferedReader* reader)
 
 template <class T> static void readMiscVector(std::vector<T*>& vec, BufferedReader* reader) {
     int num_elts = reader->readShort();
-    if (VERBOSITY("parsing") >= 2)
+    if (VERBOSITY("parsing") >= 3)
         printf("%d elts to read\n", num_elts);
     for (int i = 0; i < num_elts; i++) {
         AST* read = readASTMisc(reader);
@@ -182,7 +182,7 @@ AST_alias* read_alias(BufferedReader* reader) {
 }
 
 AST_arguments* read_arguments(BufferedReader* reader) {
-    if (VERBOSITY("parsing") >= 2)
+    if (VERBOSITY("parsing") >= 3)
         printf("reading arguments\n");
 
     AST_arguments* rtn = new AST_arguments();
@@ -416,7 +416,7 @@ AST_For* read_for(BufferedReader* reader) {
 }
 
 AST_FunctionDef* read_functiondef(BufferedReader* reader) {
-    if (VERBOSITY("parsing") >= 2)
+    if (VERBOSITY("parsing") >= 3)
         printf("reading functiondef\n");
     AST_FunctionDef* rtn = new AST_FunctionDef();
 
@@ -541,7 +541,7 @@ AST_ListComp* read_listcomp(BufferedReader* reader) {
 }
 
 AST_Module* read_module(BufferedReader* reader) {
-    if (VERBOSITY("parsing") >= 2)
+    if (VERBOSITY("parsing") >= 3)
         printf("reading module\n");
 
     AST_Module* rtn = new AST_Module(reader->createInternedPool());
@@ -775,7 +775,7 @@ AST_Yield* read_yield(BufferedReader* reader) {
 
 AST_expr* readASTExpr(BufferedReader* reader) {
     uint8_t type = reader->readByte();
-    if (VERBOSITY("parsing") >= 2)
+    if (VERBOSITY("parsing") >= 3)
         printf("type = %d\n", type);
     if (type == 0)
         return NULL;
@@ -841,7 +841,7 @@ AST_expr* readASTExpr(BufferedReader* reader) {
 
 AST_stmt* readASTStmt(BufferedReader* reader) {
     uint8_t type = reader->readByte();
-    if (VERBOSITY("parsing") >= 2)
+    if (VERBOSITY("parsing") >= 3)
         printf("type = %d\n", type);
     if (type == 0)
         return NULL;
@@ -905,7 +905,7 @@ AST_stmt* readASTStmt(BufferedReader* reader) {
 
 AST* readASTMisc(BufferedReader* reader) {
     uint8_t type = reader->readByte();
-    if (VERBOSITY("parsing") >= 2)
+    if (VERBOSITY("parsing") >= 3)
         printf("type = %d\n", type);
     if (type == 0)
         return NULL;
@@ -953,7 +953,7 @@ AST_Module* parse_string(const char* code) {
     char* tmpdir = mkdtemp(buf);
     assert(tmpdir);
     std::string tmp = std::string(tmpdir) + "/in.py";
-    if (VERBOSITY() >= 1) {
+    if (VERBOSITY() >= 3) {
         printf("writing %d bytes to %s\n", size, tmp.c_str());
     }
 

src/codegen/patchpoints.cpp

@@ -168,7 +168,7 @@ void processStackmap(CompiledFunction* cf, StackMap* stackmap) {
         PatchpointInfo* pp = reinterpret_cast<PatchpointInfo*>(r->id);
         assert(pp);
 
-        if (VERBOSITY()) {
+        if (VERBOSITY() >= 2) {
             printf("Processing pp %ld; [%d, %d)\n", reinterpret_cast<int64_t>(pp), r->offset,
                    r->offset + pp->patchpointSize());
         }

src/codegen/unwinding.cpp

@@ -500,7 +500,7 @@ BoxedTraceback* getTraceback() {
         return new BoxedTraceback();
     }
 
-    Timer _t("getTraceback");
+    Timer _t("getTraceback", 1000);
 
     std::vector<const LineInfo*> entries;
     for (auto& frame_iter : unwindPythonFrames()) {

src/core/cfg.cpp

@@ -2513,7 +2513,7 @@ CFG* computeCFG(SourceInfo* source, std::vector<AST_stmt*> body) {
         visitor.push_back(return_stmt);
     }
 
-    if (VERBOSITY("cfg") >= 2) {
+    if (VERBOSITY("cfg") >= 3) {
         printf("Before cfg checking and transformations:\n");
         rtn->print();
     }
@@ -2634,7 +2634,7 @@ CFG* computeCFG(SourceInfo* source, std::vector<AST_stmt*> body) {
                 break;
             }
 
-            if (VERBOSITY()) {
+            if (VERBOSITY("cfg") >= 2) {
                 // rtn->print();
                 printf("Joining blocks %d and %d\n", b->idx, b2->idx);
             }
@@ -2653,7 +2653,7 @@ CFG* computeCFG(SourceInfo* source, std::vector<AST_stmt*> body) {
         }
     }
 
-    if (VERBOSITY("cfg") >= 1) {
+    if (VERBOSITY("cfg") >= 2) {
         printf("Final cfg:\n");
         rtn->print();
     }

src/core/util.cpp

@@ -53,7 +53,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 && desc) {
+        if (VERBOSITY("time") >= 2 && desc) {
             if (us > min_usec) {
                 for (int i = 0; i < Timer::level; i++) {
                     putchar(' ');
@@ -116,7 +116,7 @@ void removeDirectoryIfExists(const std::string& path) {
         if (llvm::sys::fs::is_directory(status)) {
             removeDirectoryIfExists(it->path());
         } else {
-            if (VERBOSITY())
+            if (VERBOSITY() >= 2)
                 llvm::errs() << "Removing file " << it->path() << '\n';
             code = llvm::sys::fs::remove(it->path(), false);
             assert(!code);
@@ -126,7 +126,7 @@ void removeDirectoryIfExists(const std::string& path) {
         assert(!code);
     }
 
-    if (VERBOSITY())
+    if (VERBOSITY() >= 2)
         llvm::errs() << "Removing directory " << path << '\n';
     code = llvm::sys::fs::remove(path, false);
     assert(!code);