veyron/runtimes/google/vtrace: Add start and end times to spans.
Change-Id: I0a4a48d3918a369b4260f1faf469d41ddc2a6bc0
diff --git a/runtimes/google/ipc/client.go b/runtimes/google/ipc/client.go
index 135100c..b2bd087 100644
--- a/runtimes/google/ipc/client.go
+++ b/runtimes/google/ipc/client.go
@@ -511,7 +511,7 @@
func (fc *flowClient) Finish(resultptrs ...interface{}) error {
defer vlog.LogCall()()
err := fc.finish(resultptrs...)
- vtrace.FromContext(fc.ctx).Annotate("Finished")
+ vtrace.FromContext(fc.ctx).Finish()
return err
}
diff --git a/runtimes/google/ipc/server.go b/runtimes/google/ipc/server.go
index fd213bc..dba781d 100644
--- a/runtimes/google/ipc/server.go
+++ b/runtimes/google/ipc/server.go
@@ -709,6 +709,8 @@
results, err := fs.processRequest()
+ ivtrace.FromContext(fs).Finish()
+
var traceResponse vtrace.Response
if fs.allowDebug {
traceResponse = ivtrace.Response(fs)
@@ -769,6 +771,9 @@
req, verr := fs.readIPCRequest()
if verr != nil {
+ // We don't know what the ipc call was supposed to be, but we'll create
+ // a placeholder span so we can capture annotations.
+ fs.T, _ = ivtrace.WithNewSpan(fs, "Failed IPC Call")
return nil, verr
}
fs.method = req.Method
diff --git a/runtimes/google/vtrace/collector.go b/runtimes/google/vtrace/collector.go
index 956b2d2..3313384 100644
--- a/runtimes/google/vtrace/collector.go
+++ b/runtimes/google/vtrace/collector.go
@@ -9,6 +9,17 @@
"veyron.io/veyron/veyron2/vtrace"
)
+func copySpanRecord(in *vtrace.SpanRecord) *vtrace.SpanRecord {
+ return &vtrace.SpanRecord{
+ ID: in.ID,
+ Parent: in.Parent,
+ Name: in.Name,
+ Start: in.Start,
+ End: in.End,
+ Annotations: append([]vtrace.Annotation{}, in.Annotations...),
+ }
+}
+
// collectors collect spans and annotations for output or analysis.
// collectors are safe to use from multiple goroutines simultaneously.
// TODO(mattr): collector should support log-based collection
@@ -44,18 +55,53 @@
}
}
-// annotate adds a span annotation to the collection.
-func (c *collector) annotate(s vtrace.Span, msg string) {
+func (c *collector) spanRecordLocked(s *span) *vtrace.SpanRecord {
+ sid := s.ID()
+ record, ok := c.spans[sid]
+ if !ok {
+ record = &vtrace.SpanRecord{
+ ID: sid,
+ Parent: s.parent,
+ Name: s.name,
+ Start: s.start.UnixNano(),
+ }
+ c.spans[sid] = record
+ }
+ return record
+}
+
+// start records the fact that a given span has begun.
+func (c *collector) start(s *span) {
c.mu.Lock()
defer c.mu.Unlock()
if c.method == vtrace.InMemory {
- sid := s.ID()
- record, ok := c.spans[sid]
- if !ok {
- record = &vtrace.SpanRecord{ID: sid, Parent: s.Parent(), Name: s.Name()}
- c.spans[sid] = record
- }
+ // Note that simply fetching the record is enough since
+ // if the record does not exist we will created it according
+ // to the start time in s.
+ c.spanRecordLocked(s)
+ }
+}
+
+// finish records the time that a span finished.
+func (c *collector) finish(s *span) {
+ c.mu.Lock()
+ defer c.mu.Unlock()
+
+ if c.method == vtrace.InMemory {
+ record := c.spanRecordLocked(s)
+ // TODO(mattr): Perhaps we should log an error if we have already been finished?
+ record.End = time.Now().UnixNano()
+ }
+}
+
+// annotate adds a span annotation to the collection.
+func (c *collector) annotate(s *span, msg string) {
+ c.mu.Lock()
+ defer c.mu.Unlock()
+
+ if c.method == vtrace.InMemory {
+ record := c.spanRecordLocked(s)
record.Annotations = append(record.Annotations, vtrace.Annotation{
When: time.Now().UnixNano(),
Message: msg,
@@ -69,7 +115,7 @@
defer c.mu.Unlock()
return vtrace.Response{
Method: c.method,
- Trace: c.recordLocked(),
+ Trace: c.traceRecordLocked(),
}
}
@@ -78,18 +124,13 @@
func (c *collector) Record() vtrace.TraceRecord {
c.mu.Lock()
defer c.mu.Unlock()
- return c.recordLocked()
+ return c.traceRecordLocked()
}
-func (c *collector) recordLocked() vtrace.TraceRecord {
+func (c *collector) traceRecordLocked() vtrace.TraceRecord {
spans := make([]vtrace.SpanRecord, 0, len(c.spans))
for _, span := range c.spans {
- spans = append(spans, vtrace.SpanRecord{
- ID: span.ID,
- Parent: span.Parent,
- Name: span.Name,
- Annotations: append([]vtrace.Annotation{}, span.Annotations...),
- })
+ spans = append(spans, *copySpanRecord(span))
}
return vtrace.TraceRecord{
ID: c.traceID,
@@ -110,12 +151,7 @@
// by assuming that children of parent need to start after parent
// and end before now.
for _, span := range t.Trace.Spans {
- c.spans[span.ID] = &vtrace.SpanRecord{
- ID: span.ID,
- Parent: span.Parent,
- Name: span.Name,
- Annotations: append([]vtrace.Annotation{}, span.Annotations...),
- }
+ c.spans[span.ID] = copySpanRecord(&span)
}
}
diff --git a/runtimes/google/vtrace/vtrace.go b/runtimes/google/vtrace/vtrace.go
index 0600677..3a41e41 100644
--- a/runtimes/google/vtrace/vtrace.go
+++ b/runtimes/google/vtrace/vtrace.go
@@ -4,6 +4,8 @@
package vtrace
import (
+ "time"
+
"veyron.io/veyron/veyron2/context"
"veyron.io/veyron/veyron2/uniqueid"
"veyron.io/veyron/veyron2/vlog"
@@ -16,6 +18,7 @@
parent uniqueid.ID
name string
collector *collector
+ start time.Time
}
func newSpan(parent uniqueid.ID, name string, collector *collector) *span {
@@ -28,8 +31,9 @@
parent: parent,
name: name,
collector: collector,
+ start: time.Now(),
}
- s.Annotate("Started")
+ collector.start(s)
return s
}
@@ -38,6 +42,7 @@
func (c *span) Name() string { return c.name }
func (c *span) Trace() vtrace.Trace { return c.collector }
func (c *span) Annotate(msg string) { c.collector.annotate(c, msg) }
+func (c *span) Finish() { c.collector.finish(c) }
// Request generates a vtrace.Request from the active Span.
func Request(ctx context.T) vtrace.Request {
diff --git a/runtimes/google/vtrace/vtrace_test.go b/runtimes/google/vtrace/vtrace_test.go
index 44b7d53..66c8bd7 100644
--- a/runtimes/google/vtrace/vtrace_test.go
+++ b/runtimes/google/vtrace/vtrace_test.go
@@ -122,11 +122,15 @@
}
func summary(span *vtrace.SpanRecord) string {
- msgs := []string{}
- for _, annotation := range span.Annotations {
- msgs = append(msgs, annotation.Message)
+ summary := span.Name
+ if len(span.Annotations) > 0 {
+ msgs := []string{}
+ for _, annotation := range span.Annotations {
+ msgs = append(msgs, annotation.Message)
+ }
+ summary += ": " + strings.Join(msgs, ", ")
}
- return span.Name + ": " + strings.Join(msgs, ",")
+ return summary
}
func expectSequence(t *testing.T, trace vtrace.TraceRecord, expectedSpans []string) {
@@ -135,16 +139,31 @@
}
spans := map[string]*vtrace.SpanRecord{}
+ summaries := []string{}
for i := range trace.Spans {
span := &trace.Spans[i]
+
+ // All spans should have a start.
+ if span.Start == 0 {
+ t.Errorf("span missing start: %#v", span)
+ }
+ // All spans except the root should have an end.
+ if span.Name != "" && span.End == 0 {
+ t.Errorf("span missing end: %#v", span)
+ if span.Start >= span.End {
+ t.Errorf("span end should be after start: %#v", span)
+ }
+ }
+
summary := summary(span)
+ summaries = append(summaries, summary)
spans[summary] = span
}
for i := range expectedSpans {
child, ok := spans[expectedSpans[i]]
if !ok {
- t.Errorf("expected span not found: %s", expectedSpans[i])
+ t.Errorf("expected span %s not found in %#v", expectedSpans[i], summaries)
continue
}
if i == 0 {
@@ -152,7 +171,7 @@
}
parent, ok := spans[expectedSpans[i-1]]
if !ok {
- t.Errorf("expected span not found: %s", expectedSpans[i-1])
+ t.Errorf("expected span %s not found in %#v", expectedSpans[i-1], summaries)
continue
}
if child.Parent != parent.ID {
@@ -207,11 +226,11 @@
span.Annotate("c0-end")
expectedSpans := []string{
- ": c0-begin,c0-end",
- "Client Call: c1.Run: Started,Finished",
- "Server Call: .Run: c1-begin,c1-end",
- "Client Call: c2.Run: Started,Finished",
- "Server Call: .Run: c2-begin,c2-end",
+ ": c0-begin, c0-end",
+ "Client Call: c1.Run",
+ "Server Call: .Run: c1-begin, c1-end",
+ "Client Call: c2.Run",
+ "Server Call: .Run: c2-begin, c2-end",
}
expectSequence(t, span.Trace().Record(), expectedSpans)
}
@@ -228,10 +247,10 @@
expectedSpans := []string{
": c0-end",
- "Client Call: c1.Run: Finished",
+ "Client Call: c1.Run",
"Server Call: .Run: c1-end",
- "Client Call: c2.Run: Finished",
- "Server Call: .Run: c2-begin,c2-end",
+ "Client Call: c2.Run",
+ "Server Call: .Run: c2-begin, c2-end",
}
expectSequence(t, span.Trace().Record(), expectedSpans)
}
