Measure config parse / file scan time, actual total time (#1069)

Author: jakebailey

cmd/tsgo/sys.go

@@ -21,6 +21,11 @@ type osSys struct {
 	defaultLibraryPath string
 	newLine            string
 	cwd                string
+	start              time.Time
+}
+
+func (s *osSys) SinceStart() time.Duration {
+	return time.Since(s.start)
 }
 
 func (s *osSys) Now() time.Time {
@@ -65,5 +70,6 @@ func newSystem() *osSys {
 		defaultLibraryPath: bundled.LibPath(),
 		writer:             os.Stdout,
 		newLine:            core.IfElse(runtime.GOOS == "windows", "\r\n", "\n"),
+		start:              time.Now(),
 	}
 }

internal/execute/outputs.go

@@ -79,6 +79,9 @@ func reportStatistics(sys System, program *compiler.Program, result compileAndEm
 	stats.add("Instantiations", program.InstantiationCount())
 	stats.add("Memory used", fmt.Sprintf("%vK", memStats.Alloc/1024))
 	stats.add("Memory allocs", strconv.FormatUint(memStats.Mallocs, 10))
+	if result.configTime != 0 {
+		stats.add("Config time", result.configTime)
+	}
 	stats.add("Parse time", result.parseTime)
 	if result.bindTime != 0 {
 		stats.add("Bind time", result.bindTime)

internal/execute/system.go

@@ -10,11 +10,13 @@ import (
 type System interface {
 	Writer() io.Writer
 	EndWrite() // needed for testing
-	Now() time.Time
 	FS() vfs.FS
 	DefaultLibraryPath() string
 	GetCurrentDirectory() string
 	NewLine() string // #241 eventually we want to use "\n"
+
+	Now() time.Time
+	SinceStart() time.Duration
 }
 
 type ExitStatus int

internal/execute/testsys_test.go

@@ -28,6 +28,7 @@ func newTestSys(fileOrFolderList FileMap, cwd string, args ...string) *testSys {
 		files:              slices.Collect(maps.Keys(fileOrFolderList)),
 		output:             []string{},
 		currentWrite:       &strings.Builder{},
+		start:              time.Now(),
 	}
 }
 
@@ -41,6 +42,8 @@ type testSys struct {
 	defaultLibraryPath string
 	cwd                string
 	files              []string
+
+	start time.Time
 }
 
 func (s *testSys) IsTestDone() bool {
@@ -53,6 +56,10 @@ func (s *testSys) Now() time.Time {
 	return time.Now()
 }
 
+func (s *testSys) SinceStart() time.Duration {
+	return time.Since(s.start)
+}
+
 func (s *testSys) FS() vfs.FS {
 	return s.fs
 }

internal/execute/tsc.go

@@ -114,8 +114,10 @@ func executeCommandLineWorker(sys System, cb cbType, commandLine *tsoptions.Pars
 	compilerOptionsFromCommandLine := commandLine.CompilerOptions()
 
 	if configFileName != "" {
+		configStart := sys.Now()
 		extendedConfigCache := map[tspath.Path]*tsoptions.ExtendedConfigCacheEntry{}
 		configParseResult, errors := tsoptions.GetParsedCommandLineOfConfigFile(configFileName, compilerOptionsFromCommandLine, sys, extendedConfigCache)
+		configTime := sys.Now().Sub(configStart)
 		if len(errors) != 0 {
 			// these are unrecoverable errors--exit to report them as diagnostics
 			for _, e := range errors {
@@ -137,6 +139,7 @@ func executeCommandLineWorker(sys System, cb cbType, commandLine *tsoptions.Pars
 			cb,
 			configParseResult,
 			reportDiagnostic,
+			configTime,
 		), nil
 	} else {
 		if compilerOptionsFromCommandLine.ShowConfig.IsTrue() {
@@ -155,6 +158,7 @@ func executeCommandLineWorker(sys System, cb cbType, commandLine *tsoptions.Pars
 		cb,
 		commandLine,
 		reportDiagnostic,
+		0, /*configTime*/
 	), nil
 }
 
@@ -172,24 +176,25 @@ func findConfigFile(searchPath string, fileExists func(string) bool, configName
 	return result
 }
 
-func performCompilation(sys System, cb cbType, config *tsoptions.ParsedCommandLine, reportDiagnostic diagnosticReporter) ExitStatus {
+func performCompilation(sys System, cb cbType, config *tsoptions.ParsedCommandLine, reportDiagnostic diagnosticReporter, configTime time.Duration) ExitStatus {
 	host := compiler.NewCachedFSCompilerHost(config.CompilerOptions(), sys.GetCurrentDirectory(), sys.FS(), sys.DefaultLibraryPath())
 	// todo: cache, statistics, tracing
-	parseStart := time.Now()
+	parseStart := sys.Now()
 	program := compiler.NewProgram(compiler.ProgramOptions{
 		Config: config,
 		Host:   host,
 	})
-	parseTime := time.Since(parseStart)
+	parseTime := sys.Now().Sub(parseStart)
 
 	result := emitFilesAndReportErrors(sys, program, reportDiagnostic)
 	if result.status != ExitStatusSuccess {
 		// compile exited early
 		return result.status
 	}
 
+	result.configTime = configTime
 	result.parseTime = parseTime
-	result.totalTime = time.Since(parseStart)
+	result.totalTime = sys.SinceStart()
 
 	if config.CompilerOptions().Diagnostics.IsTrue() || config.CompilerOptions().ExtendedDiagnostics.IsTrue() {
 		var memStats runtime.MemStats
@@ -217,11 +222,12 @@ type compileAndEmitResult struct {
 	diagnostics []*ast.Diagnostic
 	emitResult  *compiler.EmitResult
 	status      ExitStatus
+	configTime  time.Duration
 	parseTime   time.Duration
 	bindTime    time.Duration
 	checkTime   time.Duration
-	emitTime    time.Duration
 	totalTime   time.Duration
+	emitTime    time.Duration
 }
 
 func emitFilesAndReportErrors(sys System, program *compiler.Program, reportDiagnostic diagnosticReporter) (result compileAndEmitResult) {
@@ -236,19 +242,19 @@ func emitFilesAndReportErrors(sys System, program *compiler.Program, reportDiagn
 		// Options diagnostics include global diagnostics (even though we collect them separately),
 		// and global diagnostics create checkers, which then bind all of the files. Do this binding
 		// early so we can track the time.
-		bindStart := time.Now()
+		bindStart := sys.Now()
 		_ = program.GetBindDiagnostics(ctx, nil)
-		result.bindTime = time.Since(bindStart)
+		result.bindTime = sys.Now().Sub(bindStart)
 
 		allDiagnostics = append(allDiagnostics, program.GetOptionsDiagnostics(ctx)...)
 
 		if options.ListFilesOnly.IsFalseOrUnknown() {
 			allDiagnostics = append(allDiagnostics, program.GetGlobalDiagnostics(ctx)...)
 
 			if len(allDiagnostics) == configFileParsingDiagnosticsLength {
-				checkStart := time.Now()
+				checkStart := sys.Now()
 				allDiagnostics = append(allDiagnostics, program.GetSemanticDiagnostics(ctx, nil)...)
-				result.checkTime = time.Since(checkStart)
+				result.checkTime = sys.Now().Sub(checkStart)
 			}
 
 			if options.NoEmit.IsTrue() && options.GetEmitDeclarations() && len(allDiagnostics) == configFileParsingDiagnosticsLength {
@@ -259,9 +265,9 @@ func emitFilesAndReportErrors(sys System, program *compiler.Program, reportDiagn
 
 	emitResult := &compiler.EmitResult{EmitSkipped: true, Diagnostics: []*ast.Diagnostic{}}
 	if !options.ListFilesOnly.IsTrue() {
-		emitStart := time.Now()
+		emitStart := sys.Now()
 		emitResult = program.Emit(compiler.EmitOptions{})
-		result.emitTime = time.Since(emitStart)
+		result.emitTime = sys.Now().Sub(emitStart)
 	}
 	allDiagnostics = append(allDiagnostics, emitResult.Diagnostics...)