Additional Go runtime profiling support

- Refactor profile file writing code for use
  in client as well as server.

- Add SIGUSR2 (same signal as psiphond) handler
  to ConsoleClient and write profiles on signal.

- Add WriteRuntimeProfiles function to mobile
  Psiphon Library API.

- Write "mutex" profile.

ConsoleClient/main.go

@@ -31,6 +31,7 @@ import (
 	"os/signal"
 	"sort"
 	"sync"
+	"syscall"
 
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon"
 	"github.com/Psiphon-Labs/psiphon-tunnel-core/psiphon/common"
@@ -290,15 +291,30 @@ func main() {
 	systemStopSignal := make(chan os.Signal, 1)
 	signal.Notify(systemStopSignal, os.Interrupt, os.Kill)
 
+	writeProfilesSignal := make(chan os.Signal, 1)
+	signal.Notify(writeProfilesSignal, syscall.SIGUSR2)
+
 	// Wait for an OS signal or a Run stop signal, then stop Psiphon and exit
 
-	select {
-	case <-systemStopSignal:
-		psiphon.NoticeInfo("shutdown by system")
-		stopController()
-		controllerWaitGroup.Wait()
-	case <-controllerCtx.Done():
-		psiphon.NoticeInfo("shutdown by controller")
+	for exit := false; !exit; {
+		select {
+		case <-writeProfilesSignal:
+			psiphon.NoticeInfo("write profiles")
+			profileSampleDurationSeconds := 5
+			common.WriteRuntimeProfiles(
+				psiphon.NoticeCommonLogger(),
+				config.DataStoreDirectory,
+				profileSampleDurationSeconds,
+				profileSampleDurationSeconds)
+		case <-systemStopSignal:
+			psiphon.NoticeInfo("shutdown by system")
+			stopController()
+			controllerWaitGroup.Wait()
+			exit = true
+		case <-controllerCtx.Done():
+			psiphon.NoticeInfo("shutdown by controller")
+			exit = true
+		}
 	}
 }
 

MobileLibrary/psi/psi.go

@@ -239,6 +239,19 @@ func GetPacketTunnelDNSResolverIPv6Address() string {
 	return tun.GetTransparentDNSResolverIPv6Address().String()
 }
 
+// WriteRuntimeProfiles writes Go runtime profile information to a set of
+// files in the specified output directory. See common.WriteRuntimeProfiles
+// for more details.
+//
+// If called before Start, log notices will emit to stderr.
+func WriteRuntimeProfiles(outputDirectory string, cpuSampleDurationSeconds, blockSampleDurationSeconds int) {
+	common.WriteRuntimeProfiles(
+		psiphon.NoticeCommonLogger(),
+		outputDirectory,
+		cpuSampleDurationSeconds,
+		blockSampleDurationSeconds)
+}
+
 // Helper function to store a list of server entries.
 // if embeddedServerEntryListFilename is not empty, embeddedServerEntryList will be ignored.
 func storeServerEntries(

psiphon/common/profiles.go

@@ -0,0 +1,118 @@
+/*
+ * Copyright (c) 2018, Psiphon Inc.
+ * All rights reserved.
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ */
+
+package common
+
+import (
+	"os"
+	"path/filepath"
+	"runtime"
+	"runtime/pprof"
+	"time"
+)
+
+// WriteRuntimeProfiles writes Go runtime profile information to a set of
+// files in the specified output directory. The profiles include "heap",
+// "goroutine", and other selected profiles from:
+// https://golang.org/pkg/runtime/pprof/#Profile.
+//
+// The SampleDurationSeconds inputs determine how long to wait and sample
+// profiles that require active sampling. When set to 0, these profiles are
+// skipped.
+func WriteRuntimeProfiles(
+	logger Logger,
+	outputDirectory string,
+	blockSampleDurationSeconds int,
+	cpuSampleDurationSeconds int) {
+
+	openProfileFile := func(profileName string) *os.File {
+		fileName := filepath.Join(outputDirectory, profileName+".profile")
+		file, err := os.OpenFile(
+			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")
+			return nil
+		}
+		return file
+	}
+
+	writeProfile := func(profileName string) {
+
+		file := openProfileFile(profileName)
+		if file == nil {
+			return
+		}
+		err := pprof.Lookup(profileName).WriteTo(file, 1)
+		file.Close()
+		if err != nil {
+			logger.WithContextFields(
+				LogFields{
+					"error":       err,
+					"profileName": profileName}).Error("write profile failed")
+		}
+	}
+
+	// TODO: capture https://golang.org/pkg/runtime/debug/#WriteHeapDump?
+	// May not be useful in its current state, as per:
+	// https://groups.google.com/forum/#!topic/golang-dev/cYAkuU45Qyw
+
+	// Write goroutine, heap, and threadcreate profiles
+	// https://golang.org/pkg/runtime/pprof/#Profile
+	writeProfile("goroutine")
+	writeProfile("heap")
+	writeProfile("threadcreate")
+
+	// Write CPU profile (after sampling)
+	// https://golang.org/pkg/runtime/pprof/#StartCPUProfile
+
+	if cpuSampleDurationSeconds > 0 {
+		file := openProfileFile("cpu")
+		if file != nil {
+			logger.WithContext().Info("start cpu profiling")
+			err := pprof.StartCPUProfile(file)
+			if err != nil {
+				logger.WithContextFields(
+					LogFields{"error": err}).Error("StartCPUProfile failed")
+			} else {
+				time.Sleep(time.Duration(cpuSampleDurationSeconds) * time.Second)
+				pprof.StopCPUProfile()
+				logger.WithContext().Info("end cpu profiling")
+			}
+			file.Close()
+		}
+	}
+
+	// Write block profile (after sampling)
+	// https://golang.org/pkg/runtime/pprof/#Profile
+
+	if blockSampleDurationSeconds > 0 {
+		logger.WithContext().Info("start block/mutex profiling")
+		runtime.SetBlockProfileRate(1)
+		runtime.SetMutexProfileFraction(1)
+		time.Sleep(time.Duration(blockSampleDurationSeconds) * time.Second)
+		runtime.SetBlockProfileRate(0)
+		runtime.SetMutexProfileFraction(0)
+		logger.WithContext().Info("end block/mutex profiling")
+		writeProfile("block")
+		writeProfile("mutex")
+	}
+}

psiphon/common/profiles_test.go

@@ -0,0 +1,75 @@
+/*
+ * Copyright (c) 2018, Psiphon Inc.
+ * All rights reserved.
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ */
+
+package common
+
+import (
+	"fmt"
+	"io/ioutil"
+	"os"
+	"testing"
+)
+
+func TestWriteRuntimeProfiles(t *testing.T) {
+
+	testDirName, err := ioutil.TempDir("", "psiphon-profiles-test")
+	if err != nil {
+		fmt.Printf("TempDir failed: %s\n", err)
+		os.Exit(1)
+	}
+	defer os.RemoveAll(testDirName)
+
+	WriteRuntimeProfiles(&testLogger{}, testDirName, 1, 1)
+}
+
+type testLogger struct {
+}
+
+func (logger *testLogger) panic() {
+	panic("unexpected log call")
+}
+
+func (logger *testLogger) WithContext() LogContext {
+	return &testLoggerContext{}
+}
+
+func (logger *testLogger) WithContextFields(fields LogFields) LogContext {
+	return &testLoggerContext{}
+}
+
+func (logger *testLogger) LogMetric(metric string, fields LogFields) {
+	panic("unexpected log call")
+}
+
+type testLoggerContext struct {
+}
+
+func (context *testLoggerContext) Debug(args ...interface{}) {
+}
+
+func (context *testLoggerContext) Info(args ...interface{}) {
+}
+
+func (context *testLoggerContext) Warning(args ...interface{}) {
+	panic("unexpected log call")
+}
+
+func (context *testLoggerContext) Error(args ...interface{}) {
+	panic("unexpected log call")
+}

psiphon/server/services.go

@@ -27,9 +27,7 @@ import (
 	"math/rand"
 	"os"
 	"os/signal"
-	"path/filepath"
 	"runtime"
-	"runtime/pprof"
 	"sync"
 	"syscall"
 	"time"
@@ -83,7 +81,7 @@ func RunServices(configJSON []byte) error {
 	if config.RunPacketTunnel {
 
 		packetTunnelServer, err := tun.NewServer(&tun.ServerConfig{
-			Logger: CommonLogger(log),
+			Logger:                      CommonLogger(log),
 			SudoNetworkConfigCommands:   config.PacketTunnelSudoNetworkConfigCommands,
 			GetDNSResolverIPv4Addresses: supportServices.DNSResolver.GetAllIPv4,
 			GetDNSResolverIPv6Addresses: supportServices.DNSResolver.GetAllIPv6,
@@ -283,81 +281,11 @@ func outputProcessProfiles(config *Config) {
 	log.WithContextFields(getRuntimeMetrics()).Info("runtime_metrics")
 
 	if config.ProcessProfileOutputDirectory != "" {
-
-		openProfileFile := func(profileName string) *os.File {
-			fileName := filepath.Join(
-				config.ProcessProfileOutputDirectory, profileName+".profile")
-			file, err := os.OpenFile(
-				fileName, os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0666)
-			if err != nil {
-				log.WithContextFields(
-					LogFields{
-						"error":    err,
-						"fileName": fileName}).Error("open profile file failed")
-				return nil
-			}
-			return file
-		}
-
-		writeProfile := func(profileName string) {
-
-			file := openProfileFile(profileName)
-			if file == nil {
-				return
-			}
-			err := pprof.Lookup(profileName).WriteTo(file, 1)
-			file.Close()
-			if err != nil {
-				log.WithContextFields(
-					LogFields{
-						"error":       err,
-						"profileName": profileName}).Error("write profile failed")
-			}
-		}
-
-		// TODO: capture https://golang.org/pkg/runtime/debug/#WriteHeapDump?
-		// May not be useful in its current state, as per:
-		// https://groups.google.com/forum/#!topic/golang-dev/cYAkuU45Qyw
-
-		// Write goroutine, heap, and threadcreate profiles
-		// https://golang.org/pkg/runtime/pprof/#Profile
-		writeProfile("goroutine")
-		writeProfile("heap")
-		writeProfile("threadcreate")
-
-		// Write block profile (after sampling)
-		// https://golang.org/pkg/runtime/pprof/#Profile
-
-		if config.ProcessBlockProfileDurationSeconds > 0 {
-			log.WithContext().Info("start block profiling")
-			runtime.SetBlockProfileRate(1)
-			time.Sleep(
-				time.Duration(config.ProcessBlockProfileDurationSeconds) * time.Second)
-			runtime.SetBlockProfileRate(0)
-			log.WithContext().Info("end block profiling")
-			writeProfile("block")
-		}
-
-		// Write CPU profile (after sampling)
-		// https://golang.org/pkg/runtime/pprof/#StartCPUProfile
-
-		if config.ProcessCPUProfileDurationSeconds > 0 {
-			file := openProfileFile("cpu")
-			if file != nil {
-				log.WithContext().Info("start cpu profiling")
-				err := pprof.StartCPUProfile(file)
-				if err != nil {
-					log.WithContextFields(
-						LogFields{"error": err}).Error("StartCPUProfile failed")
-				} else {
-					time.Sleep(time.Duration(
-						config.ProcessCPUProfileDurationSeconds) * time.Second)
-					pprof.StopCPUProfile()
-					log.WithContext().Info("end cpu profiling")
-				}
-				file.Close()
-			}
-		}
+		common.WriteRuntimeProfiles(
+			CommonLogger(log),
+			config.ProcessProfileOutputDirectory,
+			config.ProcessBlockProfileDurationSeconds,
+			config.ProcessCPUProfileDurationSeconds)
 	}
 }