Add timing output for analysis phases.

Former-commit-id: 4f3e70021a2b509b80db0caf8c99b2141896333f

src/base/SMPProgram.cpp

@@ -44,6 +44,7 @@
 #include <cstring>
 #include <cstdlib>
 #include <cassert>
+#include <ctime>
 
 #include "interfaces/SMPDBInterface.h"
 #include "base/SMPDataFlowAnalysis.h"
@@ -228,6 +229,7 @@ void SMPProgram::Analyze(ProfilerInformation *pi, FILE *AnnotFile, FILE *InfoAnn
 	long TotalUntypedPhiDefs = 0;
 	long TotalSafeFuncs = 0;
 	size_t TotalInstructions = 0;
+	time_t StartTime = time(NULL), EndTime;
 
 	this->ProfInfo = pi;
 
@@ -345,6 +347,11 @@ void SMPProgram::Analyze(ProfilerInformation *pi, FILE *AnnotFile, FILE *InfoAnn
 	SMP_msg("INFO: Number of functions in FuncMap: %zu\n", this->FuncMap.size());
 #endif
 
+	EndTime = time(NULL);
+	double TimeDiff = difftime(EndTime, StartTime);
+	SMP_msg("INFO: TIME: Phase 1: AnalyzeFunc: %7.2f\n", TimeDiff);
+	StartTime = time(NULL);
+
 	if (global_STARS_program->ShouldSTARSPerformReducedAnalysis()) {
 		this->EmitDataAnnotations(this->AnnotationFile, this->InfoAnnotationFile);
 		this->GlobalVarTable.clear();
@@ -366,6 +373,11 @@ void SMPProgram::Analyze(ProfilerInformation *pi, FILE *AnnotFile, FILE *InfoAnn
 		} // end for all functions in FuncList
 	} // end for all functions in TempFuncMap
 
+	EndTime = time(NULL);
+	TimeDiff = difftime(EndTime, StartTime);
+	SMP_msg("INFO: TIME: Phase 2: AdvancedAnalysis: %7.2f\n", TimeDiff);
+	StartTime = time(NULL);
+
 	// In order to reduce memory consumption, emit the global data annotations now,
 	//  and then release the memory for the global data. Note that this means we
 	//  cannot presently apply type inference info to the global data table. If we
@@ -375,6 +387,11 @@ void SMPProgram::Analyze(ProfilerInformation *pi, FILE *AnnotFile, FILE *InfoAnn
 	this->GlobalVarTable.clear();
 	this->GlobalNameMap.clear();
 
+	EndTime = time(NULL);
+	TimeDiff = difftime(EndTime, StartTime);
+	SMP_msg("INFO: TIME: Phase 3: EmitDataAnnotations: %7.2f\n", TimeDiff);
+	StartTime = time(NULL);
+
 #ifndef SMP_REDUCED_ANALYSIS
 
 	// STEP 2: Compute SSA form.
@@ -407,6 +424,11 @@ void SMPProgram::Analyze(ProfilerInformation *pi, FILE *AnnotFile, FILE *InfoAnn
 		CurrFunc->FreeUnusedMemory3(); // free memory
 	}
 
+	EndTime = time(NULL);
+	TimeDiff = difftime(EndTime, StartTime);
+	SMP_msg("INFO: TIME: Phase 4: SSA+SCCP+FuncSafe: %7.2f\n", TimeDiff);
+	StartTime = time(NULL);
+
 #if 0  // need to debug
 	// Remove any basic blocks that had a direct indication of being unreachable, e.g. "call 0" instruction.
 	//  If any function becomes empty as a result, the function is unreachable, so any block calling it
@@ -446,6 +468,11 @@ void SMPProgram::Analyze(ProfilerInformation *pi, FILE *AnnotFile, FILE *InfoAnn
 	}
 	// end of step 3
 
+	EndTime = time(NULL);
+	TimeDiff = difftime(EndTime, StartTime);
+	SMP_msg("INFO: TIME: Phase 5: RetAddrStatus: %7.2f\n", TimeDiff);
+	StartTime = time(NULL);
+
 	for (FuncListIter = this->PrioritizedFuncList.begin(); FuncListIter != this->PrioritizedFuncList.end(); ++FuncListIter) {
 		CurrFunc = (*FuncListIter);
 		if (NULL == CurrFunc) {
@@ -536,6 +563,11 @@ void SMPProgram::Analyze(ProfilerInformation *pi, FILE *AnnotFile, FILE *InfoAnn
 		TotalInstructions += CurrFunc->GetInstCount();
 	} // end for all functions
 
+	EndTime = time(NULL);
+	TimeDiff = difftime(EndTime, StartTime);
+	SMP_msg("INFO: TIME: Phase 6: MetaData+InferTypes+InferFG: %7.2f\n", TimeDiff);
+	StartTime = time(NULL);
+
 #if STARS_INTERPROCEDURAL_TYPE_INFERENCE
 	// STEP 4: Interprocedural type inference and propagation.
 	SMP_msg("Performing interprocedural type inference.\n");
@@ -582,6 +614,10 @@ void SMPProgram::Analyze(ProfilerInformation *pi, FILE *AnnotFile, FILE *InfoAnn
 
 #endif
 
+	EndTime = time(NULL);
+	TimeDiff = difftime(EndTime, StartTime);
+	SMP_msg("INFO: TIME: Phase 7: InterproceduralTypes: %7.2f\n", TimeDiff);
+
 	// Free memory not needed to emit annotations, now that type inference is done.
 	CurrFunc->FreeUnusedMemory4();
 
@@ -728,6 +764,7 @@ void SMPProgram::EmitDataAnnotations(FILE *AnnotFile, FILE *InfoAnnotFile) {
 void SMPProgram::EmitAnnotations(FILE *AnnotFile, FILE *InfoAnnotFile) {
 	long TotalSafeBlocks = 0; // basic blocks with no unsafe writes
 	long TotalUnsafeBlocks = 0; // basic blocks with unsafe writes
+	time_t StartTime = time(NULL), EndTime;
 
 	// Mark exception-handling functions as unsafe for fast returns.
 	if (this->ProgramThrowsExceptions()) {
@@ -749,6 +786,10 @@ void SMPProgram::EmitAnnotations(FILE *AnnotFile, FILE *InfoAnnotFile) {
 #endif
 	} // end for all functions
 
+	EndTime = time(NULL);
+	double TimeDiff = difftime(EndTime, StartTime);
+	SMP_msg("INFO: TIME: Phase 8: EmitAnnotations: %7.2f\n", TimeDiff);
+
 #if ZST_EMIT_SPARK_ADA_TRANSLATION
 	SMP_msg("SPARK: Total subword registers translated: %lu\n", SubwordRegCount);
 	SMP_msg("SPARK: Total subword memory accesses translated: %lu\n", SubwordMemCount);