Golang implemented sidechain for Bytom
Revision | 36ed0fa1af1b068729a5bd88f663fedee5854295 (tree) |
---|---|
Time | 2020-10-28 15:02:28 |
Author | Paladz <yzhu101@uott...> |
Commiter | GitHub |
run time performance measure (#553)
* run time performance measure
* allow for loop cont time
* add read me doc
Co-authored-by: paladz <colt@ColtdeMacBook-Pro.local>
@@ -20,7 +20,10 @@ const ( | ||
20 | 20 | maxAge int64 = 604800 |
21 | 21 | ) |
22 | 22 | |
23 | -var defaultFormatter = &logrus.TextFormatter{DisableColors: true} | |
23 | +var defaultFormatter = &logrus.TextFormatter{ | |
24 | + DisableColors: true, | |
25 | + TimestampFormat: time.StampMicro, | |
26 | +} | |
24 | 27 | |
25 | 28 | func InitLogFile(config *config.Config) error { |
26 | 29 | logPath := config.LogDir() |
@@ -0,0 +1,21 @@ | ||
1 | +Measure is a tool for help precise analysis of the performance of the goroutine, and it's designed for thread-safe. | |
2 | +Just simply call Start() and defer End() on top of the function it will handle all the stack issue and print the tree | |
3 | +struct result when the root function is ended. | |
4 | + | |
5 | +#sample usage | |
6 | +func processBlock() { | |
7 | + measure.Start() | |
8 | + defer measure.End() | |
9 | + | |
10 | + ...... | |
11 | +} | |
12 | + | |
13 | + | |
14 | +#sample result | |
15 | +|--github.com/bytom/vapor/protocol.(*Chain).processBlock: 9.009746ms (100.00) | |
16 | + |--github.com/bytom/vapor/protocol.(*Chain).saveBlock: 8.086023ms (89.75) | |
17 | + |--github.com/bytom/vapor/protocol.(*Chain).validateSign: 1.443966ms (17.86) | |
18 | + |--github.com/bytom/vapor/protocol/validation.ValidateBlock: 195.333µs (2.42) | |
19 | + |--github.com/bytom/vapor/protocol/validation.ValidateBlockHeader: 26.48µs (13.56) | |
20 | + |--github.com/bytom/vapor/protocol/validation.ValidateTxs: 88.312µs (45.21) | |
21 | + |--github.com/bytom/vapor/protocol.(*Chain).connectBlock: 767.073µs (8.51) | |
\ No newline at end of file |
@@ -0,0 +1,83 @@ | ||
1 | +package measure | |
2 | + | |
3 | +import ( | |
4 | + "fmt" | |
5 | + "runtime/debug" | |
6 | + "strings" | |
7 | + "sync" | |
8 | + | |
9 | + log "github.com/sirupsen/logrus" | |
10 | +) | |
11 | + | |
12 | +const ( | |
13 | + logModule = "measure" | |
14 | +) | |
15 | + | |
16 | +var store sync.Map | |
17 | + | |
18 | +// Start trigger record of stack trace run time record as a graph view | |
19 | +func Start() { | |
20 | + routineID, stacks, err := traceStacks() | |
21 | + if err != nil { | |
22 | + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("fail on measure get stacks") | |
23 | + return | |
24 | + } | |
25 | + | |
26 | + data, ok := store.Load(routineID) | |
27 | + if !ok { | |
28 | + store.Store(routineID, NewTimer(stacks[0])) | |
29 | + return | |
30 | + } | |
31 | + | |
32 | + if err := data.(*Timer).StartTimer(stacks); err != nil { | |
33 | + log.WithFields(log.Fields{"module": logModule, "err": err, "routine": routineID, "stack": stacks}).Error("fail on start timer") | |
34 | + } | |
35 | +} | |
36 | + | |
37 | +// End end the stack trace run time | |
38 | +func End() { | |
39 | + routineID, stacks, err := traceStacks() | |
40 | + if err != nil { | |
41 | + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("fail on measure get stacks") | |
42 | + return | |
43 | + } | |
44 | + | |
45 | + data, ok := store.Load(routineID) | |
46 | + if !ok { | |
47 | + log.WithFields(log.Fields{"module": logModule, "err": err}).Error("fail on measure timer by routine ID") | |
48 | + return | |
49 | + } | |
50 | + | |
51 | + rootTimer := data.(*Timer) | |
52 | + if err := rootTimer.EndTimer(stacks); err != nil { | |
53 | + log.WithFields(log.Fields{"module": logModule, "err": err, "routine": routineID, "stack": stacks}).Error("fail on end timer") | |
54 | + } | |
55 | + | |
56 | + if rootTimer.IsEnd() { | |
57 | + log.WithField("module", logModule).Info(rootTimer.String()) | |
58 | + store.Delete(routineID) | |
59 | + } | |
60 | +} | |
61 | + | |
62 | +func traceStacks() (string, []string, error) { | |
63 | + stacks := []string{} | |
64 | + for _, stack := range strings.Split(string(debug.Stack()), "\n") { | |
65 | + // skip the file path stack | |
66 | + if strings.HasPrefix(stack, " ") { | |
67 | + continue | |
68 | + } | |
69 | + | |
70 | + // delete the func memory address stuff | |
71 | + if subPos := strings.LastIndexAny(stack, "("); subPos > 0 { | |
72 | + stacks = append(stacks, stack[:subPos]) | |
73 | + } else { | |
74 | + stacks = append(stacks, stack) | |
75 | + } | |
76 | + } | |
77 | + | |
78 | + if len(stacks) < 4 { | |
79 | + return "", nil, fmt.Errorf("fail to decode stack") | |
80 | + } | |
81 | + | |
82 | + return stacks[0], stacks[4:], nil | |
83 | +} |
@@ -0,0 +1,129 @@ | ||
1 | +package measure | |
2 | + | |
3 | +import ( | |
4 | + "fmt" | |
5 | + "strings" | |
6 | + "time" | |
7 | +) | |
8 | + | |
9 | +const ( | |
10 | + summaryPrefix = "|--" | |
11 | +) | |
12 | + | |
13 | +// Timer is created for analysis of the function performance | |
14 | +type Timer struct { | |
15 | + name string | |
16 | + start *time.Time | |
17 | + total time.Duration | |
18 | + | |
19 | + subtimerMap map[string]*Timer | |
20 | +} | |
21 | + | |
22 | +// NewTimer create a new timer, only use for root timer only | |
23 | +func NewTimer(name string) *Timer { | |
24 | + now := time.Now() | |
25 | + return &Timer{name: name, start: &now, subtimerMap: map[string]*Timer{}} | |
26 | +} | |
27 | + | |
28 | +// StartTimer start track time for sub func | |
29 | +func (t *Timer) StartTimer(stacks []string) error { | |
30 | + stacks, err := t.locateStack(stacks) | |
31 | + if err != nil { | |
32 | + return nil | |
33 | + } | |
34 | + | |
35 | + return t.startSubtimer(stacks) | |
36 | +} | |
37 | + | |
38 | +// String implement the print interface | |
39 | +func (t *Timer) String() string { | |
40 | + return t.summary(0, t.total) | |
41 | +} | |
42 | + | |
43 | +// EndTimer always run on end of the func | |
44 | +func (t *Timer) EndTimer(stacks []string) error { | |
45 | + stacks, err := t.locateStack(stacks) | |
46 | + if err != nil { | |
47 | + return err | |
48 | + } | |
49 | + | |
50 | + return t.endSubtimer(stacks) | |
51 | +} | |
52 | + | |
53 | +// IsEnd check wheather the ticker is close | |
54 | +func (t *Timer) IsEnd() bool { | |
55 | + return t.start == nil | |
56 | +} | |
57 | + | |
58 | +func (t *Timer) startSubtimer(stacks []string) error { | |
59 | + if len(stacks) == 0 { | |
60 | + if !t.IsEnd() { | |
61 | + return fmt.Errorf("try to start an unclose timer") | |
62 | + } | |
63 | + | |
64 | + now := time.Now() | |
65 | + t.start = &now | |
66 | + return nil | |
67 | + } | |
68 | + | |
69 | + nextStack := stacks[len(stacks)-1] | |
70 | + if _, ok := t.subtimerMap[nextStack]; !ok { | |
71 | + t.subtimerMap[nextStack] = &Timer{name: nextStack, subtimerMap: map[string]*Timer{}} | |
72 | + } | |
73 | + | |
74 | + return t.subtimerMap[nextStack].startSubtimer(stacks[:len(stacks)-1]) | |
75 | +} | |
76 | + | |
77 | +func (t *Timer) endSubtimer(stacks []string) error { | |
78 | + if len(stacks) == 0 { | |
79 | + if t.IsEnd() { | |
80 | + return fmt.Errorf("timer didn't start") | |
81 | + } | |
82 | + | |
83 | + t.total += time.Now().Sub(*t.start) | |
84 | + t.start = nil | |
85 | + return nil | |
86 | + } | |
87 | + | |
88 | + subtimer, ok := t.subtimerMap[stacks[len(stacks)-1]] | |
89 | + if !ok { | |
90 | + return fmt.Errorf("endSubtimer didn't find sub timer") | |
91 | + } | |
92 | + | |
93 | + return subtimer.endSubtimer(stacks[:len(stacks)-1]) | |
94 | +} | |
95 | + | |
96 | +// locateStack is using to exclude dust stacks | |
97 | +func (t *Timer) locateStack(stacks []string) ([]string, error) { | |
98 | + for i := len(stacks) - 1; i >= 0; i-- { | |
99 | + if stacks[i] == t.name { | |
100 | + return stacks[:i], nil | |
101 | + } | |
102 | + } | |
103 | + | |
104 | + return nil, fmt.Errorf("locateStack didn't match the expect stack") | |
105 | +} | |
106 | + | |
107 | +// summary will convert the time spend graph to tree string | |
108 | +func (t *Timer) summary(depth int, parentDuration time.Duration) string { | |
109 | + result := strings.Repeat(" ", depth) + summaryPrefix | |
110 | + result += t.name + ": " | |
111 | + if !t.IsEnd() { | |
112 | + return result + "<timer didn't ends>\n" | |
113 | + } | |
114 | + | |
115 | + result += fmt.Sprintf("%s (%.2f)\n", t.total.String(), float64(t.total.Nanoseconds())/float64(parentDuration.Nanoseconds())*100) | |
116 | + | |
117 | + // handle the case that skip middle level time measure case | |
118 | + nextDepth, total := depth+1, t.total | |
119 | + if t.total == 0 { | |
120 | + result = "" | |
121 | + nextDepth, total = depth, parentDuration | |
122 | + } | |
123 | + | |
124 | + for _, sub := range t.subtimerMap { | |
125 | + result += sub.summary(nextDepth, total) | |
126 | + } | |
127 | + | |
128 | + return result | |
129 | +} |