tracez.go

Documentation: go.opencensus.io/zpages

     1  // Copyright 2017, OpenCensus Authors
     2  //
     3  // Licensed under the Apache License, Version 2.0 (the "License");
     4  // you may not use this file except in compliance with the License.
     5  // You may obtain a copy of the License at
     6  //
     7  //     http://www.apache.org/licenses/LICENSE-2.0
     8  //
     9  // Unless required by applicable law or agreed to in writing, software
    10  // distributed under the License is distributed on an "AS IS" BASIS,
    11  // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    12  // See the License for the specific language governing permissions and
    13  // limitations under the License.
    14  //
    15  
    16  package zpages
    17  
    18  import (
    19  	"fmt"
    20  	"io"
    21  	"log"
    22  	"net/http"
    23  	"sort"
    24  	"strconv"
    25  	"strings"
    26  	"text/tabwriter"
    27  	"time"
    28  
    29  	"go.opencensus.io/internal"
    30  	"go.opencensus.io/trace"
    31  )
    32  
    33  const (
    34  	// spanNameQueryField is the header for span name.
    35  	spanNameQueryField = "zspanname"
    36  	// spanTypeQueryField is the header for type (running = 0, latency = 1, error = 2) to display.
    37  	spanTypeQueryField = "ztype"
    38  	// spanSubtypeQueryField is the header for sub-type:
    39  	// * for latency based samples [0, 8] representing the latency buckets, where 0 is the first one;
    40  	// * for error based samples, 0 means all, otherwise the error code;
    41  	spanSubtypeQueryField = "zsubtype"
    42  	// maxTraceMessageLength is the maximum length of a message in tracez output.
    43  	maxTraceMessageLength = 1024
    44  )
    45  
    46  var (
    47  	defaultLatencies = [...]time.Duration{
    48  		10 * time.Microsecond,
    49  		100 * time.Microsecond,
    50  		time.Millisecond,
    51  		10 * time.Millisecond,
    52  		100 * time.Millisecond,
    53  		time.Second,
    54  		10 * time.Second,
    55  		100 * time.Second,
    56  	}
    57  	canonicalCodes = [...]string{
    58  		"OK",
    59  		"CANCELLED",
    60  		"UNKNOWN",
    61  		"INVALID_ARGUMENT",
    62  		"DEADLINE_EXCEEDED",
    63  		"NOT_FOUND",
    64  		"ALREADY_EXISTS",
    65  		"PERMISSION_DENIED",
    66  		"RESOURCE_EXHAUSTED",
    67  		"FAILED_PRECONDITION",
    68  		"ABORTED",
    69  		"OUT_OF_RANGE",
    70  		"UNIMPLEMENTED",
    71  		"INTERNAL",
    72  		"UNAVAILABLE",
    73  		"DATA_LOSS",
    74  		"UNAUTHENTICATED",
    75  	}
    76  )
    77  
    78  func canonicalCodeString(code int32) string {
    79  	if code < 0 || int(code) >= len(canonicalCodes) {
    80  		return "error code " + strconv.FormatInt(int64(code), 10)
    81  	}
    82  	return canonicalCodes[code]
    83  }
    84  
    85  func tracezHandler(w http.ResponseWriter, r *http.Request) {
    86  	r.ParseForm()
    87  	w.Header().Set("Content-Type", "text/html; charset=utf-8")
    88  	name := r.Form.Get(spanNameQueryField)
    89  	t, _ := strconv.Atoi(r.Form.Get(spanTypeQueryField))
    90  	st, _ := strconv.Atoi(r.Form.Get(spanSubtypeQueryField))
    91  	WriteHTMLTracezPage(w, name, t, st)
    92  }
    93  
    94  // WriteHTMLTracezPage writes an HTML document to w containing locally-sampled trace spans.
    95  func WriteHTMLTracezPage(w io.Writer, spanName string, spanType, spanSubtype int) {
    96  	if err := headerTemplate.Execute(w, headerData{Title: "Trace Spans"}); err != nil {
    97  		log.Printf("zpages: executing template: %v", err)
    98  	}
    99  	WriteHTMLTracezSummary(w)
   100  	WriteHTMLTracezSpans(w, spanName, spanType, spanSubtype)
   101  	if err := footerTemplate.Execute(w, nil); err != nil {
   102  		log.Printf("zpages: executing template: %v", err)
   103  	}
   104  }
   105  
   106  // WriteHTMLTracezSummary writes HTML to w containing a summary of locally-sampled trace spans.
   107  //
   108  // It includes neither a header nor footer, so you can embed this data in other pages.
   109  func WriteHTMLTracezSummary(w io.Writer) {
   110  	if err := summaryTableTemplate.Execute(w, getSummaryPageData()); err != nil {
   111  		log.Printf("zpages: executing template: %v", err)
   112  	}
   113  }
   114  
   115  // WriteHTMLTracezSpans writes HTML to w containing locally-sampled trace spans.
   116  //
   117  // It includes neither a header nor footer, so you can embed this data in other pages.
   118  func WriteHTMLTracezSpans(w io.Writer, spanName string, spanType, spanSubtype int) {
   119  	if spanName == "" {
   120  		return
   121  	}
   122  	if err := tracesTableTemplate.Execute(w, traceDataFromSpans(spanName, traceSpans(spanName, spanType, spanSubtype))); err != nil {
   123  		log.Printf("zpages: executing template: %v", err)
   124  	}
   125  }
   126  
   127  // WriteTextTracezSpans writes formatted text to w containing locally-sampled trace spans.
   128  func WriteTextTracezSpans(w io.Writer, spanName string, spanType, spanSubtype int) {
   129  	spans := traceSpans(spanName, spanType, spanSubtype)
   130  	data := traceDataFromSpans(spanName, spans)
   131  	writeTextTraces(w, data)
   132  }
   133  
   134  // WriteTextTracezSummary writes formatted text to w containing a summary of locally-sampled trace spans.
   135  func WriteTextTracezSummary(w io.Writer) {
   136  	w.Write([]byte("Locally sampled spans summary\n\n"))
   137  
   138  	data := getSummaryPageData()
   139  	if len(data.Rows) == 0 {
   140  		return
   141  	}
   142  
   143  	tw := tabwriter.NewWriter(w, 8, 8, 1, ' ', 0)
   144  
   145  	for i, s := range data.Header {
   146  		if i != 0 {
   147  			tw.Write([]byte("\t"))
   148  		}
   149  		tw.Write([]byte(s))
   150  	}
   151  	tw.Write([]byte("\n"))
   152  
   153  	put := func(x int) {
   154  		if x == 0 {
   155  			tw.Write([]byte(".\t"))
   156  			return
   157  		}
   158  		fmt.Fprintf(tw, "%d\t", x)
   159  	}
   160  	for _, r := range data.Rows {
   161  		tw.Write([]byte(r.Name))
   162  		tw.Write([]byte("\t"))
   163  		put(r.Active)
   164  		for _, l := range r.Latency {
   165  			put(l)
   166  		}
   167  		put(r.Errors)
   168  		tw.Write([]byte("\n"))
   169  	}
   170  	tw.Flush()
   171  }
   172  
   173  // traceData contains data for the trace data template.
   174  type traceData struct {
   175  	Name string
   176  	Num  int
   177  	Rows []traceRow
   178  }
   179  
   180  type traceRow struct {
   181  	Fields [3]string
   182  	trace.SpanContext
   183  	ParentSpanID trace.SpanID
   184  }
   185  
   186  type events []interface{}
   187  
   188  func (e events) Len() int { return len(e) }
   189  func (e events) Less(i, j int) bool {
   190  	var ti time.Time
   191  	switch x := e[i].(type) {
   192  	case *trace.Annotation:
   193  		ti = x.Time
   194  	case *trace.MessageEvent:
   195  		ti = x.Time
   196  	}
   197  	switch x := e[j].(type) {
   198  	case *trace.Annotation:
   199  		return ti.Before(x.Time)
   200  	case *trace.MessageEvent:
   201  		return ti.Before(x.Time)
   202  	}
   203  	return false
   204  }
   205  
   206  func (e events) Swap(i, j int) { e[i], e[j] = e[j], e[i] }
   207  
   208  func traceRows(s *trace.SpanData) []traceRow {
   209  	start := s.StartTime
   210  
   211  	lasty, lastm, lastd := start.Date()
   212  	wholeTime := func(t time.Time) string {
   213  		return t.Format("2006/01/02-15:04:05") + fmt.Sprintf(".%06d", t.Nanosecond()/1000)
   214  	}
   215  	formatTime := func(t time.Time) string {
   216  		y, m, d := t.Date()
   217  		if y == lasty && m == lastm && d == lastd {
   218  			return t.Format("           15:04:05") + fmt.Sprintf(".%06d", t.Nanosecond()/1000)
   219  		}
   220  		lasty, lastm, lastd = y, m, d
   221  		return wholeTime(t)
   222  	}
   223  
   224  	lastTime := start
   225  	formatElapsed := func(t time.Time) string {
   226  		d := t.Sub(lastTime)
   227  		lastTime = t
   228  		u := int64(d / 1000)
   229  		// There are five cases for duration printing:
   230  		// -1234567890s
   231  		// -1234.123456
   232  		//      .123456
   233  		// 12345.123456
   234  		// 12345678901s
   235  		switch {
   236  		case u < -9999999999:
   237  			return fmt.Sprintf("%11ds", u/1e6)
   238  		case u < 0:
   239  			sec := u / 1e6
   240  			u -= sec * 1e6
   241  			return fmt.Sprintf("%5d.%06d", sec, -u)
   242  		case u < 1e6:
   243  			return fmt.Sprintf("     .%6d", u)
   244  		case u <= 99999999999:
   245  			sec := u / 1e6
   246  			u -= sec * 1e6
   247  			return fmt.Sprintf("%5d.%06d", sec, u)
   248  		default:
   249  			return fmt.Sprintf("%11ds", u/1e6)
   250  		}
   251  	}
   252  
   253  	firstRow := traceRow{Fields: [3]string{wholeTime(start), "", ""}, SpanContext: s.SpanContext, ParentSpanID: s.ParentSpanID}
   254  	if s.EndTime.IsZero() {
   255  		firstRow.Fields[1] = "            "
   256  	} else {
   257  		firstRow.Fields[1] = formatElapsed(s.EndTime)
   258  		lastTime = start
   259  	}
   260  	out := []traceRow{firstRow}
   261  
   262  	formatAttributes := func(a map[string]interface{}) string {
   263  		if len(a) == 0 {
   264  			return ""
   265  		}
   266  		var keys []string
   267  		for key := range a {
   268  			keys = append(keys, key)
   269  		}
   270  		sort.Strings(keys)
   271  		var s []string
   272  		for _, key := range keys {
   273  			val := a[key]
   274  			switch val.(type) {
   275  			case string:
   276  				s = append(s, fmt.Sprintf("%s=%q", key, val))
   277  			default:
   278  				s = append(s, fmt.Sprintf("%s=%v", key, val))
   279  			}
   280  		}
   281  		return "Attributes:{" + strings.Join(s, ", ") + "}"
   282  	}
   283  
   284  	if s.Status != (trace.Status{}) {
   285  		msg := fmt.Sprintf("Status{canonicalCode=%s, description=%q}",
   286  			canonicalCodeString(s.Status.Code), s.Status.Message)
   287  		out = append(out, traceRow{Fields: [3]string{"", "", msg}})
   288  	}
   289  
   290  	if len(s.Attributes) != 0 {
   291  		out = append(out, traceRow{Fields: [3]string{"", "", formatAttributes(s.Attributes)}})
   292  	}
   293  
   294  	var es events
   295  	for i := range s.Annotations {
   296  		es = append(es, &s.Annotations[i])
   297  	}
   298  	for i := range s.MessageEvents {
   299  		es = append(es, &s.MessageEvents[i])
   300  	}
   301  	sort.Sort(es)
   302  	for _, e := range es {
   303  		switch e := e.(type) {
   304  		case *trace.Annotation:
   305  			msg := e.Message
   306  			if len(e.Attributes) != 0 {
   307  				msg = msg + "  " + formatAttributes(e.Attributes)
   308  			}
   309  			row := traceRow{Fields: [3]string{
   310  				formatTime(e.Time),
   311  				formatElapsed(e.Time),
   312  				msg,
   313  			}}
   314  			out = append(out, row)
   315  		case *trace.MessageEvent:
   316  			row := traceRow{Fields: [3]string{formatTime(e.Time), formatElapsed(e.Time)}}
   317  			switch e.EventType {
   318  			case trace.MessageEventTypeSent:
   319  				row.Fields[2] = fmt.Sprintf("sent message [%d bytes, %d compressed bytes]", e.UncompressedByteSize, e.CompressedByteSize)
   320  			case trace.MessageEventTypeRecv:
   321  				row.Fields[2] = fmt.Sprintf("received message [%d bytes, %d compressed bytes]", e.UncompressedByteSize, e.CompressedByteSize)
   322  			}
   323  			out = append(out, row)
   324  		}
   325  	}
   326  	for i := range out {
   327  		if len(out[i].Fields[2]) > maxTraceMessageLength {
   328  			out[i].Fields[2] = out[i].Fields[2][:maxTraceMessageLength]
   329  		}
   330  	}
   331  	return out
   332  }
   333  
   334  func traceSpans(spanName string, spanType, spanSubtype int) []*trace.SpanData {
   335  	internalTrace := internal.Trace.(interface {
   336  		ReportActiveSpans(name string) []*trace.SpanData
   337  		ReportSpansByError(name string, code int32) []*trace.SpanData
   338  		ReportSpansByLatency(name string, minLatency, maxLatency time.Duration) []*trace.SpanData
   339  	})
   340  	var spans []*trace.SpanData
   341  	switch spanType {
   342  	case 0: // active
   343  		spans = internalTrace.ReportActiveSpans(spanName)
   344  	case 1: // latency
   345  		var min, max time.Duration
   346  		n := len(defaultLatencies)
   347  		if spanSubtype == 0 {
   348  			max = defaultLatencies[0]
   349  		} else if spanSubtype == n {
   350  			min, max = defaultLatencies[spanSubtype-1], (1<<63)-1
   351  		} else if 0 < spanSubtype && spanSubtype < n {
   352  			min, max = defaultLatencies[spanSubtype-1], defaultLatencies[spanSubtype]
   353  		}
   354  		spans = internalTrace.ReportSpansByLatency(spanName, min, max)
   355  	case 2: // error
   356  		spans = internalTrace.ReportSpansByError(spanName, 0)
   357  	}
   358  	return spans
   359  }
   360  
   361  func traceDataFromSpans(name string, spans []*trace.SpanData) traceData {
   362  	data := traceData{
   363  		Name: name,
   364  		Num:  len(spans),
   365  	}
   366  	for _, s := range spans {
   367  		data.Rows = append(data.Rows, traceRows(s)...)
   368  	}
   369  	return data
   370  }
   371  
   372  func writeTextTraces(w io.Writer, data traceData) {
   373  	tw := tabwriter.NewWriter(w, 1, 8, 1, ' ', 0)
   374  	fmt.Fprint(tw, "When\tElapsed(s)\tType\n")
   375  	for _, r := range data.Rows {
   376  		tw.Write([]byte(r.Fields[0]))
   377  		tw.Write([]byte("\t"))
   378  		tw.Write([]byte(r.Fields[1]))
   379  		tw.Write([]byte("\t"))
   380  		tw.Write([]byte(r.Fields[2]))
   381  		if sc := r.SpanContext; sc != (trace.SpanContext{}) {
   382  			fmt.Fprintf(tw, "trace_id: %s span_id: %s", sc.TraceID, sc.SpanID)
   383  			if r.ParentSpanID != (trace.SpanID{}) {
   384  				fmt.Fprintf(tw, " parent_span_id: %s", r.ParentSpanID)
   385  			}
   386  		}
   387  		tw.Write([]byte("\n"))
   388  	}
   389  	tw.Flush()
   390  }
   391  
   392  type summaryPageData struct {
   393  	Header             []string
   394  	LatencyBucketNames []string
   395  	Links              bool
   396  	TracesEndpoint     string
   397  	Rows               []summaryPageRow
   398  }
   399  
   400  type summaryPageRow struct {
   401  	Name    string
   402  	Active  int
   403  	Latency []int
   404  	Errors  int
   405  }
   406  
   407  func getSummaryPageData() summaryPageData {
   408  	data := summaryPageData{
   409  		Links:          true,
   410  		TracesEndpoint: "tracez",
   411  	}
   412  	internalTrace := internal.Trace.(interface {
   413  		ReportSpansPerMethod() map[string]internal.PerMethodSummary
   414  	})
   415  	for name, s := range internalTrace.ReportSpansPerMethod() {
   416  		if len(data.Header) == 0 {
   417  			data.Header = []string{"Name", "Active"}
   418  			for _, b := range s.LatencyBuckets {
   419  				l := b.MinLatency
   420  				s := fmt.Sprintf(">%v", l)
   421  				if l == 100*time.Second {
   422  					s = ">100s"
   423  				}
   424  				data.Header = append(data.Header, s)
   425  				data.LatencyBucketNames = append(data.LatencyBucketNames, s)
   426  			}
   427  			data.Header = append(data.Header, "Errors")
   428  		}
   429  		row := summaryPageRow{Name: name, Active: s.Active}
   430  		for _, l := range s.LatencyBuckets {
   431  			row.Latency = append(row.Latency, l.Size)
   432  		}
   433  		for _, e := range s.ErrorBuckets {
   434  			row.Errors += e.Size
   435  		}
   436  		data.Rows = append(data.Rows, row)
   437  	}
   438  	sort.Slice(data.Rows, func(i, j int) bool {
   439  		return data.Rows[i].Name < data.Rows[j].Name
   440  	})
   441  	return data
   442  }
   443
View as plain text