allow for loop cont time

diff --git a/toolbar/measure/method.go b/toolbar/measure/method.go
index 7b0441b..d49376b 100644 (file)
--- a/toolbar/measure/method.go
+++ b/toolbar/measure/method.go
@@ -15,7 +15,7 @@ const (
 
 var store sync.Map
 
-// Start trigger record of stack trace run time record as graph view
+// Start trigger record of stack trace run time record as a graph view
 func Start() {
        routineID, stacks, err := stacks()
        if err != nil {
@@ -29,8 +29,8 @@ func Start() {
                return
        }
 
-       if err := data.(*Timer).AddSubtimer(stacks); err != nil {
-               log.WithFields(log.Fields{"module": logModule, "err": err, "routine": routineID, "stack": stacks}).Error("fail on add sub timer")
+       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")
        }
 }
 
@@ -48,9 +48,15 @@ func End() {
                return
        }
 
-       if err := data.(*Timer).EndTimer(stacks); err != nil {
+       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 stacks() (string, []string, error) {

diff --git a/toolbar/measure/timer.go b/toolbar/measure/timer.go
index ef6780b..801a4a2 100644 (file)
--- a/toolbar/measure/timer.go
+++ b/toolbar/measure/timer.go
@@ -4,36 +4,40 @@ import (
        "fmt"
        "strings"
        "time"
-
-       log "github.com/sirupsen/logrus"
 )
 
 const (
        summaryPrefix = "|--"
 )
 
-// Timer is created for record the func performance status as the tree struct
+// Timer is created for analysis of the function performance
 type Timer struct {
-       name        string
-       start       time.Time
-       end         time.Time
+       name  string
+       start *time.Time
+       total time.Duration
+
        subtimerMap map[string]*Timer
 }
 
-// NewTimer create a new timer
+// NewTimer create a new timer, only use for root timer only
 func NewTimer(name string) *Timer {
-       return &Timer{name: name, start: time.Now(), subtimerMap: map[string]*Timer{}}
+       now := time.Now()
+       return &Timer{name: name, start: &now, subtimerMap: map[string]*Timer{}}
 }
 
-// AddSubtimer start track time for sub func
-func (t *Timer) AddSubtimer(stacks []string) error {
+// StartTimer start track time for sub func
+func (t *Timer) StartTimer(stacks []string) error {
        stacks, err := t.locateStack(stacks)
        if err != nil {
                return nil
        }
 
-       t.addSubtimer(stacks)
-       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
@@ -43,45 +47,53 @@ func (t *Timer) EndTimer(stacks []string) error {
                return err
        }
 
-       if err := t.endTimer(stacks); err != nil {
-               return err
-       }
+       return t.endSubtimer(stacks)
+}
 
-       if len(stacks) == 0 {
-               log.WithField("module", logModule).Info(t.summary(0, nil))
-       }
-       return nil
+// IsEnd check wheather the ticker is close
+func (t *Timer) IsEnd() bool {
+       return t.start == nil
 }
 
-func (t *Timer) addSubtimer(stacks []string) {
+func (t *Timer) startSubtimer(stacks []string) error {
        if len(stacks) == 0 {
-               return
+               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] = NewTimer(nextStack)
+               t.subtimerMap[nextStack] = &Timer{name: nextStack, subtimerMap: map[string]*Timer{}}
        }
 
-       t.subtimerMap[nextStack].addSubtimer(stacks[:len(stacks)-1])
+       return t.subtimerMap[nextStack].startSubtimer(stacks[:len(stacks)-1])
 }
 
-func (t *Timer) endTimer(stacks []string) error {
+func (t *Timer) endSubtimer(stacks []string) error {
        if len(stacks) == 0 {
-               t.end = time.Now()
+               if t.IsEnd() {
+                       return fmt.Errorf("timer didn't start")
+               }
+
+               t.total += time.Now().Sub(*t.start)
+               t.start = nil
                return nil
        }
 
-       nextStack := stacks[len(stacks)-1]
-       subtimer, ok := t.subtimerMap[nextStack]
+       subtimer, ok := t.subtimerMap[stacks[len(stacks)-1]]
        if !ok {
-               return fmt.Errorf("endTimer didn't find sub timer")
+               return fmt.Errorf("endSubtimer didn't find sub timer")
        }
 
-       return subtimer.endTimer(stacks[:len(stacks)-1])
+       return subtimer.endSubtimer(stacks[:len(stacks)-1])
 }
 
-// locateStack is use for elitimate dust stacks
+// 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 {
@@ -93,21 +105,24 @@ func (t *Timer) locateStack(stacks []string) ([]string, error) {
 }
 
 // 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
+func (t *Timer) summary(depth int, parentDuration time.Duration) string {
+       result := strings.Repeat("  ", depth) + summaryPrefix
        result += t.name + ": "
-       if t.start.IsZero() || t.end.IsZero() {
+       if !t.IsEnd() {
                return result + "<timer didn't ends>\n"
        }
 
-       duration := t.end.Sub(t.start)
-       if parentDuration == nil {
-               parentDuration = &duration
+       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
        }
 
-       result += fmt.Sprintf("%s (%.2f)\n", duration.String(), float64(duration.Nanoseconds())/float64(parentDuration.Nanoseconds())*100)
        for _, sub := range t.subtimerMap {
-               result += sub.summary(depth+1, &duration)
+               result += sub.summary(nextDepth, total)
        }
 
        return result