maxAge int64 = 604800
)
-var defaultFormatter = &logrus.TextFormatter{DisableColors: true}
+var defaultFormatter = &logrus.TextFormatter{
+ DisableColors: true,
+ TimestampFormat: time.StampMicro,
+}
func InitLogFile(config *config.Config) error {
logPath := config.LogDir()
--- /dev/null
+Measure is a tool for help precise analysis of the performance of the goroutine, and it's designed for thread-safe.
+Just simply call Start() and defer End() on top of the function it will handle all the stack issue and print the tree
+struct result when the root function is ended.
+
+#sample usage
+func processBlock() {
+ measure.Start()
+ defer measure.End()
+
+ ......
+}
+
+
+#sample result
+|--github.com/bytom/vapor/protocol.(*Chain).processBlock: 9.009746ms (100.00)
+ |--github.com/bytom/vapor/protocol.(*Chain).saveBlock: 8.086023ms (89.75)
+ |--github.com/bytom/vapor/protocol.(*Chain).validateSign: 1.443966ms (17.86)
+ |--github.com/bytom/vapor/protocol/validation.ValidateBlock: 195.333µs (2.42)
+ |--github.com/bytom/vapor/protocol/validation.ValidateBlockHeader: 26.48µs (13.56)
+ |--github.com/bytom/vapor/protocol/validation.ValidateTxs: 88.312µs (45.21)
+ |--github.com/bytom/vapor/protocol.(*Chain).connectBlock: 767.073µs (8.51)
\ No newline at end of file
--- /dev/null
+package measure
+
+import (
+ "fmt"
+ "runtime/debug"
+ "strings"
+ "sync"
+
+ log "github.com/sirupsen/logrus"
+)
+
+const (
+ logModule = "measure"
+)
+
+var store sync.Map
+
+// Start trigger record of stack trace run time record as a graph view
+func Start() {
+ routineID, stacks, err := traceStacks()
+ if err != nil {
+ log.WithFields(log.Fields{"module": logModule, "err": err}).Error("fail on measure get stacks")
+ return
+ }
+
+ data, ok := store.Load(routineID)
+ if !ok {
+ store.Store(routineID, NewTimer(stacks[0]))
+ return
+ }
+
+ if err := data.(*Timer).StartTimer(stacks); err != nil {
+ log.WithFields(log.Fields{"module": logModule, "err": err, "routine": routineID, "stack": stacks}).Error("fail on start timer")
+ }
+}
+
+// End end the stack trace run time
+func End() {
+ routineID, stacks, err := traceStacks()
+ if err != nil {
+ log.WithFields(log.Fields{"module": logModule, "err": err}).Error("fail on measure get stacks")
+ return
+ }
+
+ data, ok := store.Load(routineID)
+ if !ok {
+ log.WithFields(log.Fields{"module": logModule, "err": err}).Error("fail on measure timer by routine ID")
+ return
+ }
+
+ rootTimer := data.(*Timer)
+ if err := rootTimer.EndTimer(stacks); err != nil {
+ log.WithFields(log.Fields{"module": logModule, "err": err, "routine": routineID, "stack": stacks}).Error("fail on end timer")
+ }
+
+ if rootTimer.IsEnd() {
+ log.WithField("module", logModule).Info(rootTimer.String())
+ store.Delete(routineID)
+ }
+}
+
+func traceStacks() (string, []string, error) {
+ stacks := []string{}
+ for _, stack := range strings.Split(string(debug.Stack()), "\n") {
+ // skip the file path stack
+ if strings.HasPrefix(stack, " ") {
+ continue
+ }
+
+ // delete the func memory address stuff
+ if subPos := strings.LastIndexAny(stack, "("); subPos > 0 {
+ stacks = append(stacks, stack[:subPos])
+ } else {
+ stacks = append(stacks, stack)
+ }
+ }
+
+ if len(stacks) < 4 {
+ return "", nil, fmt.Errorf("fail to decode stack")
+ }
+
+ return stacks[0], stacks[4:], nil
+}
--- /dev/null
+package measure
+
+import (
+ "fmt"
+ "strings"
+ "time"
+)
+
+const (
+ summaryPrefix = "|--"
+)
+
+// Timer is created for analysis of the function performance
+type Timer struct {
+ name string
+ start *time.Time
+ total time.Duration
+
+ subtimerMap map[string]*Timer
+}
+
+// NewTimer create a new timer, only use for root timer only
+func NewTimer(name string) *Timer {
+ now := time.Now()
+ return &Timer{name: name, start: &now, subtimerMap: map[string]*Timer{}}
+}
+
+// StartTimer start track time for sub func
+func (t *Timer) StartTimer(stacks []string) error {
+ stacks, err := t.locateStack(stacks)
+ if err != nil {
+ return nil
+ }
+
+ return t.startSubtimer(stacks)
+}
+
+// String implement the print interface
+func (t *Timer) String() string {
+ return t.summary(0, t.total)
+}
+
+// EndTimer always run on end of the func
+func (t *Timer) EndTimer(stacks []string) error {
+ stacks, err := t.locateStack(stacks)
+ if err != nil {
+ return err
+ }
+
+ return t.endSubtimer(stacks)
+}
+
+// IsEnd check wheather the ticker is close
+func (t *Timer) IsEnd() bool {
+ return t.start == nil
+}
+
+func (t *Timer) startSubtimer(stacks []string) error {
+ if len(stacks) == 0 {
+ if !t.IsEnd() {
+ return fmt.Errorf("try to start an unclose timer")
+ }
+
+ now := time.Now()
+ t.start = &now
+ return nil
+ }
+
+ nextStack := stacks[len(stacks)-1]
+ if _, ok := t.subtimerMap[nextStack]; !ok {
+ t.subtimerMap[nextStack] = &Timer{name: nextStack, subtimerMap: map[string]*Timer{}}
+ }
+
+ return t.subtimerMap[nextStack].startSubtimer(stacks[:len(stacks)-1])
+}
+
+func (t *Timer) endSubtimer(stacks []string) error {
+ if len(stacks) == 0 {
+ if t.IsEnd() {
+ return fmt.Errorf("timer didn't start")
+ }
+
+ t.total += time.Now().Sub(*t.start)
+ t.start = nil
+ return nil
+ }
+
+ subtimer, ok := t.subtimerMap[stacks[len(stacks)-1]]
+ if !ok {
+ return fmt.Errorf("endSubtimer didn't find sub timer")
+ }
+
+ return subtimer.endSubtimer(stacks[:len(stacks)-1])
+}
+
+// locateStack is using to exclude dust stacks
+func (t *Timer) locateStack(stacks []string) ([]string, error) {
+ for i := len(stacks) - 1; i >= 0; i-- {
+ if stacks[i] == t.name {
+ return stacks[:i], nil
+ }
+ }
+
+ return nil, fmt.Errorf("locateStack didn't match the expect stack")
+}
+
+// summary will convert the time spend graph to tree string
+func (t *Timer) summary(depth int, parentDuration time.Duration) string {
+ result := strings.Repeat(" ", depth) + summaryPrefix
+ result += t.name + ": "
+ if !t.IsEnd() {
+ return result + "<timer didn't ends>\n"
+ }
+
+ result += fmt.Sprintf("%s (%.2f)\n", t.total.String(), float64(t.total.Nanoseconds())/float64(parentDuration.Nanoseconds())*100)
+
+ // handle the case that skip middle level time measure case
+ nextDepth, total := depth+1, t.total
+ if t.total == 0 {
+ result = ""
+ nextDepth, total = depth, parentDuration
+ }
+
+ for _, sub := range t.subtimerMap {
+ result += sub.summary(nextDepth, total)
+ }
+
+ return result
+}
OSDN Git Service
