Merge pull request #535 from jbenet/test/keep-pprof-data

feat: keep profiling data from test runs

cmd/ipfs/main.go

@@ -35,9 +35,10 @@ var log = eventlog.Logger("cmd/ipfs")
 var errHelpRequested = errors.New("Help Requested")
 
 const (
-	cpuProfile  = "ipfs.cpuprof"
-	heapProfile = "ipfs.memprof"
-	errorFormat = "ERROR: %v\n\n"
+	EnvEnableProfiling = "IPFS_PROF"
+	cpuProfile         = "ipfs.cpuprof"
+	heapProfile        = "ipfs.memprof"
+	errorFormat        = "ERROR: %v\n\n"
 )
 
 type cmdInvocation struct {
@@ -67,6 +68,13 @@ func main() {
 		fmt.Fprintf(os.Stderr, "Error: %s\n", err.Error())
 	}
 
+	stopFunc, err := profileIfEnabled()
+	if err != nil {
+		printErr(err)
+		os.Exit(1)
+	}
+	defer stopFunc() // to be executed as late as possible
+
 	// this is a local helper to print out help text.
 	// there's some considerations that this makes easier.
 	printHelp := func(long bool, w io.Writer) {
@@ -153,16 +161,6 @@ func (i *cmdInvocation) Run(ctx context.Context) (output io.Reader, err error) {
 		u.SetDebugLogging()
 	}
 
-	// if debugging, let's profile.
-	// TODO maybe change this to its own option... profiling makes it slower.
-	if u.Debug {
-		stopProfilingFunc, err := startProfiling()
-		if err != nil {
-			return nil, err
-		}
-		defer stopProfilingFunc() // to be executed as late as possible
-	}
-
 	res, err := callCommand(ctx, i.req, Root, i.cmd)
 	if err != nil {
 		return nil, err
@@ -511,3 +509,16 @@ func allInterruptSignals() chan os.Signal {
 		syscall.SIGTERM)
 	return sigc
 }
+
+func profileIfEnabled() (func(), error) {
+	// FIXME this is a temporary hack so profiling of asynchronous operations
+	// works as intended.
+	if os.Getenv(EnvEnableProfiling) != "" {
+		stopProfilingFunc, err := startProfiling() // TODO maybe change this to its own option... profiling makes it slower.
+		if err != nil {
+			return nil, err
+		}
+		return stopProfilingFunc, nil
+	}
+	return func() {}, nil
+}

test/3nodetest/Makefile

@@ -10,6 +10,9 @@ setup: docker_ipfs_image data/filetiny data/filerand
 save_logs:
 	sh bin/save_logs.sh
 
+save_profiling_data:
+	sh bin/save_profiling_data.sh
+
 data/filetiny: Makefile
 	cp Makefile ./data/filetiny # simple
 
@@ -33,3 +36,4 @@ clean:
 	rm -f data/filetiny
 	rm -f data/filerand
 	rm -rf build/*
+	docker rmi $(docker images | grep "^<none>" | awk "{print \$3}") -f || true

test/3nodetest/bin/save_profiling_data.sh

@@ -0,0 +1,18 @@
+#!/bin/sh
+
+for container in 3nodetest_bootstrap_1 3nodetest_client_1 3nodetest_server_1; do
+    # ipfs binary is required by `go tool pprof`
+    docker cp $container:/go/bin/ipfs build/profiling_data_$container
+done
+
+# since the nodes are executed with the --debug flag, profiling data is written
+# to the the working dir. by default, the working dir is /go.
+
+for container in 3nodetest_bootstrap_1 3nodetest_client_1 3nodetest_server_1; do
+    docker cp $container:/go/ipfs.cpuprof build/profiling_data_$container
+done
+
+# TODO get memprof from client (client daemon isn't terminated, so memprof isn't retrieved)
+for container in 3nodetest_bootstrap_1 3nodetest_server_1; do
+    docker cp $container:/go/ipfs.memprof build/profiling_data_$container
+done

test/3nodetest/bootstrap/Dockerfile

@@ -5,6 +5,7 @@ ADD . /tmp/id
 RUN mv -f /tmp/id/config /root/.go-ipfs/config
 RUN ipfs id
 
+ENV IPFS_PROF true
 ENV IPFS_LOGGING_FMT nocolor
 
 EXPOSE 4011 4012/udp

test/3nodetest/build/.gitignore

@@ -1,2 +1,3 @@
 .built_img
 *.log
+profiling_data*

test/3nodetest/client/Dockerfile

@@ -7,6 +7,7 @@ RUN ipfs id
 
 EXPOSE 4031 4032/udp
 
+ENV IPFS_PROF true
 ENV IPFS_LOGGING_FMT nocolor
 
 ENTRYPOINT ["/bin/bash"]

test/3nodetest/client/run.sh

@@ -1,11 +1,15 @@
 ipfs bootstrap add /ip4/$BOOTSTRAP_PORT_4011_TCP_ADDR/tcp/$BOOTSTRAP_PORT_4011_TCP_PORT/ipfs/QmNXuBh8HFsWq68Fid8dMbGNQTh7eG6hV9rr1fQyfmfomE
 ipfs bootstrap # list bootstrap nodes for debugging
 
-
 echo "3nodetest> starting client daemon"
-ipfs daemon &
+
+ipfs daemon --debug &
 sleep 3
 
+# switch dirs so ipfs client profiling data doesn't overwrite the ipfs daemon
+# profiling data
+cd /tmp
+
 while [ ! -f /data/idtiny ]
 do
     echo "3nodetest> waiting for server to add the file..."

test/3nodetest/fig.yml

@@ -6,6 +6,7 @@ data:
 
 bootstrap:
     build: ./bootstrap
+    command: daemon --debug --init
     expose:
         - "4011"
         - "4012/udp"

test/3nodetest/run-test-on-img.sh

@@ -27,6 +27,10 @@ fig up --no-color | tee build/fig.log
 echo "make save_logs"
 make save_logs
 
+# save the ipfs logs for inspection
+echo "make save_profiling_data"
+make save_profiling_data
+
 # fig up won't report the error using an error code, so we grep the
 # fig.log file to find out whether the call succeeded
 echo 'tail build/fig.log | grep "exited with code 0"'

test/3nodetest/server/Dockerfile

@@ -8,6 +8,7 @@ RUN chmod +x /tmp/test/run.sh
 
 EXPOSE 4021 4022/udp
 
+ENV IPFS_PROF true
 ENV IPFS_LOGGING_FMT nocolor
 
 ENTRYPOINT ["/bin/bash"]

test/3nodetest/server/run.sh

@@ -5,10 +5,16 @@ ipfs bootstrap # list bootstrap nodes for debugging
 # wait for daemon to start/bootstrap
 # alternatively use ipfs swarm connect
 echo "3nodetest> starting server daemon"
-ipfs daemon &
+
+# run daemon in debug mode to collect profiling data
+ipfs daemon --debug &
 sleep 3
 # TODO instead of bootrapping: ipfs swarm connect /ip4/$BOOTSTRAP_PORT_4011_TCP_ADDR/tcp/$BOOTSTRAP_PORT_4011_TCP_PORT/ipfs/QmNXuBh8HFsWq68Fid8dMbGNQTh7eG6hV9rr1fQyfmfomE
 
+# change dir before running add commands so ipfs client profiling data doesn't
+# overwrite the daemon profiling data
+cd /tmp
+
 # must mount this volume from data container
 ipfs add -q /data/filetiny > tmptiny
 mv tmptiny /data/idtiny