Dump profiles during delayed/hung shutdown

ConsoleClient/main.go

@@ -303,6 +303,7 @@ func main() {
 			common.WriteRuntimeProfiles(
 				psiphon.NoticeCommonLogger(),
 				config.DataStoreDirectory,
+				"",
 				profileSampleDurationSeconds,
 				profileSampleDurationSeconds)
 		case <-systemStopSignal:

MobileLibrary/psi/psi.go

@@ -248,6 +248,7 @@ func WriteRuntimeProfiles(outputDirectory string, cpuSampleDurationSeconds, bloc
 	common.WriteRuntimeProfiles(
 		psiphon.NoticeCommonLogger(),
 		outputDirectory,
+		"",
 		cpuSampleDurationSeconds,
 		blockSampleDurationSeconds)
 }

psiphon/common/profiles.go

@@ -38,18 +38,22 @@ import (
 func WriteRuntimeProfiles(
 	logger Logger,
 	outputDirectory string,
+	filenameSuffix string,
 	blockSampleDurationSeconds int,
 	cpuSampleDurationSeconds int) {
 
 	openProfileFile := func(profileName string) *os.File {
-		fileName := filepath.Join(outputDirectory, profileName+".profile")
+		filename := filepath.Join(outputDirectory, profileName+".profile")
+		if filenameSuffix != "" {
+			filename += "." + filenameSuffix
+		}
 		file, err := os.OpenFile(
-			fileName, os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0666)
+			filename, os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0666)
 		if err != nil {
 			logger.WithContextFields(
 				LogFields{
 					"error":    err,
-					"fileName": fileName}).Error("open profile file failed")
+					"fileName": filename}).Error("open profile file failed")
 			return nil
 		}
 		return file

psiphon/common/profiles_test.go

@@ -35,7 +35,7 @@ func TestWriteRuntimeProfiles(t *testing.T) {
 	}
 	defer os.RemoveAll(testDirName)
 
-	WriteRuntimeProfiles(&testLogger{}, testDirName, 1, 1)
+	WriteRuntimeProfiles(&testLogger{}, testDirName, "suffix", 1, 1)
 }
 
 type testLogger struct {

psiphon/server/services.go

@@ -24,6 +24,7 @@
 package server
 
 import (
+	"fmt"
 	"math/rand"
 	"os"
 	"os/signal"
@@ -177,7 +178,7 @@ func RunServices(configJSON []byte) error {
 		for {
 			select {
 			case <-signalProcessProfiles:
-				outputProcessProfiles(supportServices.Config)
+				outputProcessProfiles(supportServices.Config, "")
 			case <-shutdownBroadcast:
 				return
 			}
@@ -244,9 +245,29 @@ loop:
 		}
 	}
 
+	// During any delayed or hung shutdown, periodically dump profiles to help
+	// diagnose the cause.
+	signalProfileDumperStop := make(chan struct{}, 1)
+	go func() {
+		tickSeconds := 10
+		ticker := time.NewTicker(time.Duration(tickSeconds) * time.Second)
+		defer ticker.Stop()
+		for i := tickSeconds; i <= 60; i += tickSeconds {
+			select {
+			case <-signalProfileDumperStop:
+				return
+			case <-ticker.C:
+				filenameSuffix := fmt.Sprintf("delayed_shutdown_%ds", i)
+				outputProcessProfiles(supportServices.Config, filenameSuffix)
+			}
+		}
+	}()
+
 	close(shutdownBroadcast)
 	waitGroup.Wait()
 
+	close(signalProfileDumperStop)
+
 	return err
 }
 
@@ -276,7 +297,7 @@ func getRuntimeMetrics() LogFields {
 	}
 }
 
-func outputProcessProfiles(config *Config) {
+func outputProcessProfiles(config *Config, filenameSuffix string) {
 
 	log.WithContextFields(getRuntimeMetrics()).Info("runtime_metrics")
 
@@ -284,6 +305,7 @@ func outputProcessProfiles(config *Config) {
 		common.WriteRuntimeProfiles(
 			CommonLogger(log),
 			config.ProcessProfileOutputDirectory,
+			filenameSuffix,
 			config.ProcessBlockProfileDurationSeconds,
 			config.ProcessCPUProfileDurationSeconds)
 	}