From d56917d86014d1a724d1f0fd8482e21889037857 Mon Sep 17 00:00:00 2001 From: Brian Tiger Chow Date: Mon, 12 Jan 2015 20:12:45 -0800 Subject: [PATCH 1/5] fix(main): profile at top-level since work may be async --- cmd/ipfs/main.go | 32 ++++++++++++++++++++++---------- 1 file changed, 22 insertions(+), 10 deletions(-) diff --git a/cmd/ipfs/main.go b/cmd/ipfs/main.go index 48e6429df..31ea2c46a 100644 --- a/cmd/ipfs/main.go +++ b/cmd/ipfs/main.go @@ -67,6 +67,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 +160,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 +508,18 @@ 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 u.GetenvBool("DEBUG") || os.Getenv("IPFS_LOGGING") == "debug" { + u.Debug = true + u.SetDebugLogging() + 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 +} From 093c87ef45f9f6206db4cc557a015cf51d956f21 Mon Sep 17 00:00:00 2001 From: Brian Tiger Chow Date: Sat, 10 Jan 2015 00:34:06 -0800 Subject: [PATCH 2/5] feat: keep profiling data from test runs --- test/3nodetest/Makefile | 3 +++ test/3nodetest/bin/save_profiling_data.sh | 18 ++++++++++++++++++ test/3nodetest/build/.gitignore | 1 + test/3nodetest/client/run.sh | 8 ++++++-- test/3nodetest/fig.yml | 1 + test/3nodetest/run-test-on-img.sh | 4 ++++ test/3nodetest/server/run.sh | 8 +++++++- 7 files changed, 40 insertions(+), 3 deletions(-) create mode 100644 test/3nodetest/bin/save_profiling_data.sh diff --git a/test/3nodetest/Makefile b/test/3nodetest/Makefile index ec13b9367..3dc3b4621 100644 --- a/test/3nodetest/Makefile +++ b/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 diff --git a/test/3nodetest/bin/save_profiling_data.sh b/test/3nodetest/bin/save_profiling_data.sh new file mode 100644 index 000000000..03c0cbabe --- /dev/null +++ b/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 diff --git a/test/3nodetest/build/.gitignore b/test/3nodetest/build/.gitignore index ffb6b09b3..84820c767 100644 --- a/test/3nodetest/build/.gitignore +++ b/test/3nodetest/build/.gitignore @@ -1,2 +1,3 @@ .built_img *.log +profiling_data* diff --git a/test/3nodetest/client/run.sh b/test/3nodetest/client/run.sh index 9bb1fb6fa..7a34d7bbc 100644 --- a/test/3nodetest/client/run.sh +++ b/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..." diff --git a/test/3nodetest/fig.yml b/test/3nodetest/fig.yml index 677078a97..18a28c8ff 100644 --- a/test/3nodetest/fig.yml +++ b/test/3nodetest/fig.yml @@ -6,6 +6,7 @@ data: bootstrap: build: ./bootstrap + command: daemon --debug --init expose: - "4011" - "4012/udp" diff --git a/test/3nodetest/run-test-on-img.sh b/test/3nodetest/run-test-on-img.sh index d53cde34b..1baf02650 100755 --- a/test/3nodetest/run-test-on-img.sh +++ b/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"' diff --git a/test/3nodetest/server/run.sh b/test/3nodetest/server/run.sh index 68a45d4a3..325ae3c3c 100644 --- a/test/3nodetest/server/run.sh +++ b/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 From 4af79b71354559bbd4f764caea70f9107e45d715 Mon Sep 17 00:00:00 2001 From: Brian Tiger Chow Date: Mon, 12 Jan 2015 20:48:42 -0800 Subject: [PATCH 3/5] clean old docker images --- test/3nodetest/Makefile | 1 + 1 file changed, 1 insertion(+) diff --git a/test/3nodetest/Makefile b/test/3nodetest/Makefile index 3dc3b4621..1c20a6837 100644 --- a/test/3nodetest/Makefile +++ b/test/3nodetest/Makefile @@ -36,3 +36,4 @@ clean: rm -f data/filetiny rm -f data/filerand rm -rf build/* + docker rmi $(docker images | grep "^" | awk "{print \$3}") -f || true From 097c8a1166113490a28e760a7c5475575250d979 Mon Sep 17 00:00:00 2001 From: Brian Tiger Chow Date: Mon, 12 Jan 2015 21:30:37 -0800 Subject: [PATCH 4/5] feat(main): change pprof flag to IPFS_PROF @jbenet @whyrusleeping thoughts? --- cmd/ipfs/main.go | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/cmd/ipfs/main.go b/cmd/ipfs/main.go index 31ea2c46a..6916c401e 100644 --- a/cmd/ipfs/main.go +++ b/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 { @@ -512,9 +513,7 @@ func allInterruptSignals() chan os.Signal { func profileIfEnabled() (func(), error) { // FIXME this is a temporary hack so profiling of asynchronous operations // works as intended. - if u.GetenvBool("DEBUG") || os.Getenv("IPFS_LOGGING") == "debug" { - u.Debug = true - u.SetDebugLogging() + 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 From 07529fa56aea9d2bcafbf3b20c502f2f973f4cf3 Mon Sep 17 00:00:00 2001 From: Brian Tiger Chow Date: Mon, 12 Jan 2015 21:31:03 -0800 Subject: [PATCH 5/5] run profiler in test --- test/3nodetest/bootstrap/Dockerfile | 1 + test/3nodetest/client/Dockerfile | 1 + test/3nodetest/server/Dockerfile | 1 + 3 files changed, 3 insertions(+) diff --git a/test/3nodetest/bootstrap/Dockerfile b/test/3nodetest/bootstrap/Dockerfile index 562b38ded..3b97d58d0 100644 --- a/test/3nodetest/bootstrap/Dockerfile +++ b/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 diff --git a/test/3nodetest/client/Dockerfile b/test/3nodetest/client/Dockerfile index 88d15dd0c..0ff89819f 100644 --- a/test/3nodetest/client/Dockerfile +++ b/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"] diff --git a/test/3nodetest/server/Dockerfile b/test/3nodetest/server/Dockerfile index 03cdbc595..f735fe1d8 100644 --- a/test/3nodetest/server/Dockerfile +++ b/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"]