From fc82f195b9c577ac7d3da88117053981dcae8838 Mon Sep 17 00:00:00 2001 From: Richard Liu Date: Fri, 13 Jul 2018 13:55:43 -0700 Subject: [PATCH 1/7] use vendor --- log/handler.go | 2 +- log/logger.go | 2 +- stack/stack.go | 324 ------------------------------------------------- 3 files changed, 2 insertions(+), 326 deletions(-) delete mode 100644 stack/stack.go diff --git a/log/handler.go b/log/handler.go index 768e7ac40..3c99114dc 100644 --- a/log/handler.go +++ b/log/handler.go @@ -8,7 +8,7 @@ import ( "reflect" "sync" - "harmony-benchmark/stack" + "github.com/go-stack/stack" ) // Handler defines where and how log records are written. diff --git a/log/logger.go b/log/logger.go index 798df4c24..5e5924a3d 100644 --- a/log/logger.go +++ b/log/logger.go @@ -5,7 +5,7 @@ import ( "os" "time" - "harmony-benchmark/stack" + "github.com/go-stack/stack" ) const timeKey = "t" diff --git a/stack/stack.go b/stack/stack.go deleted file mode 100644 index 1bc6971d8..000000000 --- a/stack/stack.go +++ /dev/null @@ -1,324 +0,0 @@ -// +build go1.7 - -// Package stack implements utilities to capture, manipulate, and format call -// stacks. It provides a simpler API than package runtime. -// -// The implementation takes care of the minutia and special cases of -// interpreting the program counter (pc) values returned by runtime.Callers. -// -// Package stack's types implement fmt.Formatter, which provides a simple and -// flexible way to declaratively configure formatting when used with logging -// or error tracking packages. -package stack - -import ( - "bytes" - "errors" - "fmt" - "io" - "runtime" - "strconv" - "strings" -) - -// Call records a single function invocation from a goroutine stack. -type Call struct { - frame runtime.Frame -} - -// Caller returns a Call from the stack of the current goroutine. The argument -// skip is the number of stack frames to ascend, with 0 identifying the -// calling function. -func Caller(skip int) Call { - // As of Go 1.9 we need room for up to three PC entries. - // - // 0. An entry for the stack frame prior to the target to check for - // special handling needed if that prior entry is runtime.sigpanic. - // 1. A possible second entry to hold metadata about skipped inlined - // functions. If inline functions were not skipped the target frame - // PC will be here. - // 2. A third entry for the target frame PC when the second entry - // is used for skipped inline functions. - var pcs [3]uintptr - n := runtime.Callers(skip+1, pcs[:]) - frames := runtime.CallersFrames(pcs[:n]) - frame, _ := frames.Next() - frame, _ = frames.Next() - - return Call{ - frame: frame, - } -} - -// String implements fmt.Stinger. It is equivalent to fmt.Sprintf("%v", c). -func (c Call) String() string { - return fmt.Sprint(c) -} - -// MarshalText implements encoding.TextMarshaler. It formats the Call the same -// as fmt.Sprintf("%v", c). -func (c Call) MarshalText() ([]byte, error) { - if c.frame == (runtime.Frame{}) { - return nil, ErrNoFunc - } - - buf := bytes.Buffer{} - fmt.Fprint(&buf, c) - return buf.Bytes(), nil -} - -// ErrNoFunc means that the Call has a nil *runtime.Func. The most likely -// cause is a Call with the zero value. -var ErrNoFunc = errors.New("no call stack information") - -// Format implements fmt.Formatter with support for the following verbs. -// -// %s source file -// %d line number -// %n function name -// %k last segment of the package path -// %v equivalent to %s:%d -// -// It accepts the '+' and '#' flags for most of the verbs as follows. -// -// %+s path of source file relative to the compile time GOPATH -// %#s full path of source file -// %+n import path qualified function name -// %+k full package path -// %+v equivalent to %+s:%d -// %#v equivalent to %#s:%d -func (c Call) Format(s fmt.State, verb rune) { - if c.frame == (runtime.Frame{}) { - fmt.Fprintf(s, "%%!%c(NOFUNC)", verb) - return - } - - switch verb { - case 's', 'v': - file := c.frame.File - switch { - case s.Flag('#'): - // done - case s.Flag('+'): - file = file[pkgIndex(file, c.frame.Function):] - default: - const sep = "/" - if i := strings.LastIndex(file, sep); i != -1 { - file = file[i+len(sep):] - } - } - io.WriteString(s, file) - if verb == 'v' { - buf := [7]byte{':'} - s.Write(strconv.AppendInt(buf[:1], int64(c.frame.Line), 10)) - } - - case 'd': - buf := [6]byte{} - s.Write(strconv.AppendInt(buf[:0], int64(c.frame.Line), 10)) - - case 'k': - name := c.frame.Function - const pathSep = "/" - start, end := 0, len(name) - if i := strings.LastIndex(name, pathSep); i != -1 { - start = i + len(pathSep) - } - const pkgSep = "." - if i := strings.Index(name[start:], pkgSep); i != -1 { - end = start + i - } - if s.Flag('+') { - start = 0 - } - io.WriteString(s, name[start:end]) - - case 'n': - name := c.frame.Function - if !s.Flag('+') { - const pathSep = "/" - if i := strings.LastIndex(name, pathSep); i != -1 { - name = name[i+len(pathSep):] - } - const pkgSep = "." - if i := strings.Index(name, pkgSep); i != -1 { - name = name[i+len(pkgSep):] - } - } - io.WriteString(s, name) - } -} - -// Frame returns the call frame infomation for the Call. -func (c Call) Frame() runtime.Frame { - return c.frame -} - -// PC returns the program counter for this call frame; multiple frames may -// have the same PC value. -// -// Deprecated: Use Call.Frame instead. -func (c Call) PC() uintptr { - return c.frame.PC -} - -// CallStack records a sequence of function invocations from a goroutine -// stack. -type CallStack []Call - -// String implements fmt.Stinger. It is equivalent to fmt.Sprintf("%v", cs). -func (cs CallStack) String() string { - return fmt.Sprint(cs) -} - -var ( - openBracketBytes = []byte("[") - closeBracketBytes = []byte("]") - spaceBytes = []byte(" ") -) - -// MarshalText implements encoding.TextMarshaler. It formats the CallStack the -// same as fmt.Sprintf("%v", cs). -func (cs CallStack) MarshalText() ([]byte, error) { - buf := bytes.Buffer{} - buf.Write(openBracketBytes) - for i, pc := range cs { - if i > 0 { - buf.Write(spaceBytes) - } - fmt.Fprint(&buf, pc) - } - buf.Write(closeBracketBytes) - return buf.Bytes(), nil -} - -// Format implements fmt.Formatter by printing the CallStack as square brackets -// ([, ]) surrounding a space separated list of Calls each formatted with the -// supplied verb and options. -func (cs CallStack) Format(s fmt.State, verb rune) { - s.Write(openBracketBytes) - for i, pc := range cs { - if i > 0 { - s.Write(spaceBytes) - } - pc.Format(s, verb) - } - s.Write(closeBracketBytes) -} - -// Trace returns a CallStack for the current goroutine with element 0 -// identifying the calling function. -func Trace() CallStack { - var pcs [512]uintptr - n := runtime.Callers(1, pcs[:]) - - frames := runtime.CallersFrames(pcs[:n]) - cs := make(CallStack, 0, n) - - // Skip extra frame retrieved just to make sure the runtime.sigpanic - // special case is handled. - frame, more := frames.Next() - - for more { - frame, more = frames.Next() - cs = append(cs, Call{frame: frame}) - } - - return cs -} - -// TrimBelow returns a slice of the CallStack with all entries below c -// removed. -func (cs CallStack) TrimBelow(c Call) CallStack { - for len(cs) > 0 && cs[0] != c { - cs = cs[1:] - } - return cs -} - -// TrimAbove returns a slice of the CallStack with all entries above c -// removed. -func (cs CallStack) TrimAbove(c Call) CallStack { - for len(cs) > 0 && cs[len(cs)-1] != c { - cs = cs[:len(cs)-1] - } - return cs -} - -// pkgIndex returns the index that results in file[index:] being the path of -// file relative to the compile time GOPATH, and file[:index] being the -// $GOPATH/src/ portion of file. funcName must be the name of a function in -// file as returned by runtime.Func.Name. -func pkgIndex(file, funcName string) int { - // As of Go 1.6.2 there is no direct way to know the compile time GOPATH - // at runtime, but we can infer the number of path segments in the GOPATH. - // We note that runtime.Func.Name() returns the function name qualified by - // the import path, which does not include the GOPATH. Thus we can trim - // segments from the beginning of the file path until the number of path - // separators remaining is one more than the number of path separators in - // the function name. For example, given: - // - // GOPATH /home/user - // file /home/user/src/pkg/sub/file.go - // fn.Name() pkg/sub.Type.Method - // - // We want to produce: - // - // file[:idx] == /home/user/src/ - // file[idx:] == pkg/sub/file.go - // - // From this we can easily see that fn.Name() has one less path separator - // than our desired result for file[idx:]. We count separators from the - // end of the file path until it finds two more than in the function name - // and then move one character forward to preserve the initial path - // segment without a leading separator. - const sep = "/" - i := len(file) - for n := strings.Count(funcName, sep) + 2; n > 0; n-- { - i = strings.LastIndex(file[:i], sep) - if i == -1 { - i = -len(sep) - break - } - } - // get back to 0 or trim the leading separator - return i + len(sep) -} - -var runtimePath string - -func init() { - var pcs [3]uintptr - runtime.Callers(0, pcs[:]) - frames := runtime.CallersFrames(pcs[:]) - frame, _ := frames.Next() - file := frame.File - - idx := pkgIndex(frame.File, frame.Function) - - runtimePath = file[:idx] - if runtime.GOOS == "windows" { - runtimePath = strings.ToLower(runtimePath) - } -} - -func inGoroot(c Call) bool { - file := c.frame.File - if len(file) == 0 || file[0] == '?' { - return true - } - if runtime.GOOS == "windows" { - file = strings.ToLower(file) - } - return strings.HasPrefix(file, runtimePath) || strings.HasSuffix(file, "/_testmain.go") -} - -// TrimRuntime returns a slice of the CallStack with the topmost entries from -// the go runtime removed. It considers any calls originating from unknown -// files, files under GOROOT, or _testmain.go as part of the runtime. -func (cs CallStack) TrimRuntime() CallStack { - for len(cs) > 0 && inGoroot(cs[len(cs)-1]) { - cs = cs[:len(cs)-1] - } - return cs -} From bf79190647a1bf4a80ceb8b50bff29ead585811b Mon Sep 17 00:00:00 2001 From: Richard Liu Date: Fri, 13 Jul 2018 15:56:31 -0700 Subject: [PATCH 2/7] updated setup.sh --- aws-scripts/setup.sh | 3 +++ 1 file changed, 3 insertions(+) diff --git a/aws-scripts/setup.sh b/aws-scripts/setup.sh index 8925e45da..30f699c38 100644 --- a/aws-scripts/setup.sh +++ b/aws-scripts/setup.sh @@ -18,6 +18,9 @@ export GOPATH=$MyHOME/projects export PATH=$PATH:$GOROOT/bin source $MyHOME/.bash_profile +# go get dependencies +go get github.com/go-stack/stack + # build executables cd $GOPATH/src/harmony-benchmark go build -o bin/soldier aws-experiment-launch/experiment/soldier/main.go From 91251e6fb3e133356d8c4c6803e4c760a76e528a Mon Sep 17 00:00:00 2001 From: Richard Liu Date: Fri, 13 Jul 2018 16:46:27 -0700 Subject: [PATCH 3/7] updated setup.sh --- aws-scripts/setup.sh | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/aws-scripts/setup.sh b/aws-scripts/setup.sh index 30f699c38..2142fcaaa 100644 --- a/aws-scripts/setup.sh +++ b/aws-scripts/setup.sh @@ -18,11 +18,11 @@ export GOPATH=$MyHOME/projects export PATH=$PATH:$GOROOT/bin source $MyHOME/.bash_profile +cd $GOPATH/src/harmony-benchmark # go get dependencies -go get github.com/go-stack/stack +go get ./... # build executables -cd $GOPATH/src/harmony-benchmark go build -o bin/soldier aws-experiment-launch/experiment/soldier/main.go go build -o bin/benchmark benchmark.go go build -o bin/txgen client/txgen/main.go From 6db78520c96c2d194cc6e5f9d842c975ea8d3e97 Mon Sep 17 00:00:00 2001 From: Richard Liu Date: Fri, 13 Jul 2018 16:50:32 -0700 Subject: [PATCH 4/7] updated .travis.yml --- .travis.yml | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/.travis.yml b/.travis.yml index 7b8c14f3f..2ec7c0daa 100644 --- a/.travis.yml +++ b/.travis.yml @@ -7,8 +7,7 @@ install: - cd $HOME/gopath/src - mv github.com/simple-rules/harmony-benchmark ./ - cd harmony-benchmark - # TODO: @RL, get this back after the AWS deployment is unblocked. - # - go get github.com/go-stack/stack + - go get ./... - ./.travis.gofmt.sh - go build -v ./... notifications: From ed0c72c36f316b81dcdda6a1d3616e8e486777f4 Mon Sep 17 00:00:00 2001 From: Richard Liu Date: Fri, 13 Jul 2018 18:09:32 -0700 Subject: [PATCH 5/7] use gopsutil --- benchmark.go | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/benchmark.go b/benchmark.go index ed7df08dc..bf1744a3c 100644 --- a/benchmark.go +++ b/benchmark.go @@ -15,6 +15,8 @@ import ( "runtime" "strings" "time" + + "github.com/shirou/gopsutil/process" ) const ( @@ -102,6 +104,21 @@ func logMemUsage(consensus *consensus.Consensus) { } } +// TODO: @ricl, start another process for reporting. +func logCPUUsage(consensus *consensus.Consensus) { + log.Info("PPID", "ppid", os.Getpid()) + p, _ := process.NewProcess(int32(os.Getpid())) + for { + percent, _ := p.CPUPercent() + times, err := p.Times() + if err != nil { + log.Info("ERR", "Err", err) + } + log.Info("CPU Report", "Percent", percent, "Times", times, "consensus", consensus) + time.Sleep(10 * time.Second) + } +} + func main() { ip := flag.String("ip", "127.0.0.1", "IP of the node") port := flag.String("port", "9000", "port of the node.") @@ -140,7 +157,10 @@ func main() { // Consensus object. consensus := consensus.NewConsensus(*ip, *port, shardID, peers, leader) // Logging for consensus. + log.Info("PID", "pid", os.Getpid()) go logMemUsage(consensus) + go logCPUUsage(consensus) + // Set logger to attack model. attack.GetInstance().SetLogger(consensus.Log) // Current node. From 837d7d71883d559d9990b054b0d55cc5358a801b Mon Sep 17 00:00:00 2001 From: Richard Liu Date: Fri, 13 Jul 2018 19:31:15 -0700 Subject: [PATCH 6/7] updated mem and cpu usage. --- benchmark.go | 17 +++++------------ 1 file changed, 5 insertions(+), 12 deletions(-) diff --git a/benchmark.go b/benchmark.go index bf1744a3c..ebb9c6b38 100644 --- a/benchmark.go +++ b/benchmark.go @@ -9,10 +9,8 @@ import ( "harmony-benchmark/log" "harmony-benchmark/node" "harmony-benchmark/p2p" - "harmony-benchmark/utils" "math/rand" "os" - "runtime" "strings" "time" @@ -95,25 +93,21 @@ func attackDetermination(attackedMode int) bool { } func logMemUsage(consensus *consensus.Consensus) { + p, _ := process.NewProcess(int32(os.Getpid())) for { - var m runtime.MemStats - runtime.ReadMemStats(&m) - log.Info("Mem Report", "Alloc", utils.BToMb(m.Alloc), "TotalAlloc", utils.BToMb(m.TotalAlloc), - "Sys", utils.BToMb(m.Sys), "NumGC", m.NumGC, "consensus", consensus) + info, _ := p.MemoryInfo() + memMap, _ := p.MemoryMaps(false) + log.Info("Mem Report", "info", info, "map", memMap) time.Sleep(10 * time.Second) } } // TODO: @ricl, start another process for reporting. func logCPUUsage(consensus *consensus.Consensus) { - log.Info("PPID", "ppid", os.Getpid()) p, _ := process.NewProcess(int32(os.Getpid())) for { percent, _ := p.CPUPercent() - times, err := p.Times() - if err != nil { - log.Info("ERR", "Err", err) - } + times, _ := p.Times() log.Info("CPU Report", "Percent", percent, "Times", times, "consensus", consensus) time.Sleep(10 * time.Second) } @@ -157,7 +151,6 @@ func main() { // Consensus object. consensus := consensus.NewConsensus(*ip, *port, shardID, peers, leader) // Logging for consensus. - log.Info("PID", "pid", os.Getpid()) go logMemUsage(consensus) go logCPUUsage(consensus) From 778c35dce97cc3daf7350f56171d98a50b46c451 Mon Sep 17 00:00:00 2001 From: Richard Liu Date: Fri, 13 Jul 2018 21:09:37 -0700 Subject: [PATCH 7/7] added report_extract.py --- .../get_leader_tps_average.sh | 9 -- aws-experiment-launch/report_extractor.py | 96 +++++++++++++++++++ benchmark.go | 4 +- 3 files changed, 98 insertions(+), 11 deletions(-) delete mode 100755 aws-experiment-launch/get_leader_tps_average.sh create mode 100644 aws-experiment-launch/report_extractor.py diff --git a/aws-experiment-launch/get_leader_tps_average.sh b/aws-experiment-launch/get_leader_tps_average.sh deleted file mode 100755 index 5b53e0872..000000000 --- a/aws-experiment-launch/get_leader_tps_average.sh +++ /dev/null @@ -1,9 +0,0 @@ -if [ $# -eq 0 ]; then - echo "Please the directory of the log" - exit 1 -fi -DIR=$1 -for file in $(ls $DIR/*leader*) -do - cat $file | egrep -o "TPS=[0-9]+" | cut -f2 -d "=" | awk '{ sum += $1; n++ } END { if (n > 0) print sum / n; }'; -done \ No newline at end of file diff --git a/aws-experiment-launch/report_extractor.py b/aws-experiment-launch/report_extractor.py new file mode 100644 index 000000000..a6758f61f --- /dev/null +++ b/aws-experiment-launch/report_extractor.py @@ -0,0 +1,96 @@ +import json +import sys +import os +import argparse + +def formatFloat(v): + return "%.2f" % v + +def formatPercent(v): + return formatFloat(v) + "%" + +def formatMem(v): + return formatFloat(float(v) / 10**6) + "MB" + +class Profiler: + def __init__(self): + self.tps = 0 + self.tps_max = 0 + self.tps_min = sys.maxsize + self.tps_count = 0 + + self.cpu_percent = 0 + self.cpu_usr = 0 + self.cpu_sys = 0 + self.cpu_count = 0 + + self.mem_rss = 0 + self.mem_rss_max = 0 + self.mem_count = 0 + + def handleTPS(self, obj): + tps = obj["TPS"] + self.tps += tps + self.tps_max = max(self.tps_max, tps) + self.tps_min = min(self.tps_min, tps) + self.tps_count += 1 + + def handleCPU(self, obj): + # http://psutil.readthedocs.io/en/latest/#psutil.Process.cpu_times + # https://stackoverflow.com/questions/556405/what-do-real-user-and-sys-mean-in-the-output-of-time1 + # http://psutil.readthedocs.io/en/latest/#psutil.Process.cpu_percent + self.cpu_percent += obj["percent"] + times = json.loads(obj["times"]) + self.cpu_usr = times["user"] + self.cpu_sys = times["system"] + self.cpu_count += 1 + + def handleMem(self, obj): + # http://psutil.readthedocs.io/en/latest/#psutil.Process.memory_info + info = json.loads(obj["info"]) + rss = info["rss"] + self.mem_rss += rss + self.mem_rss_max = max(self.mem_rss_max, rss) + self.mem_count += 1 + + def report(self): + print("TPS", + "Avg", formatFloat(self.tps / self.tps_count), + "Min", formatFloat(self.tps_min), + "Max", formatFloat(self.tps_max)) + print("CPU", + "Percent (Avg)", formatPercent(self.cpu_percent / self.cpu_count), + "Time (Usr)", str(self.cpu_usr) + "s", + "Time (Sys)", str(self.cpu_sys) + "s") + print("Mem", + "RSS (Max)", formatMem(self.mem_rss_max), + "RSS (Avg)", formatMem(self.mem_rss / self.mem_count)) + +def profileFile(path): + print(path) + profiler = Profiler() + with open(path) as f: + for line in f: + obj = json.loads(line) + if obj["lvl"] != "info": + continue + if obj["msg"] == "TPS Report": + profiler.handleTPS(obj) + elif obj["msg"] == "CPU Report": + profiler.handleCPU(obj) + elif obj["msg"] == "Mem Report": + profiler.handleMem(obj) + profiler.report() + +# Example: python report_extractor.py --folder ../tmp_log/log-20180713-205431 +if __name__ == "__main__": + parser = argparse.ArgumentParser( + description="This script extracts reports from log files") + parser.add_argument("--folder", type=str, dest="folder", + default="", + help="the path to the log folder") + args = parser.parse_args() + + for filename in os.listdir(args.folder): + if "leader" in filename: + profileFile(os.path.join(args.folder, filename)) \ No newline at end of file diff --git a/benchmark.go b/benchmark.go index ebb9c6b38..b5f9f5188 100644 --- a/benchmark.go +++ b/benchmark.go @@ -108,7 +108,7 @@ func logCPUUsage(consensus *consensus.Consensus) { for { percent, _ := p.CPUPercent() times, _ := p.Times() - log.Info("CPU Report", "Percent", percent, "Times", times, "consensus", consensus) + log.Info("CPU Report", "percent", percent, "times", times, "consensus", consensus) time.Sleep(10 * time.Second) } } @@ -143,7 +143,7 @@ func main() { logFileName := fmt.Sprintf("./%v/%s-%v-%v.log", *logFolder, role, *ip, *port) h := log.MultiHandler( log.StdoutHandler, - log.Must.FileHandler(logFileName, log.LogfmtFormat()), // Log to file + log.Must.FileHandler(logFileName, log.JSONFormat()), // Log to file // log.Must.NetHandler("tcp", ":3000", log.JSONFormat()) // Log to remote ) log.Root().SetHandler(h)