2016-03-01 22:57:46 +00:00
// Copyright 2014 The Go Authors. All rights reserved.
2015-01-30 13:31:43 +03:00
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.
package main
import (
"encoding/json"
"fmt"
"internal/trace"
2018-02-06 14:34:32 -05:00
"io"
2015-07-02 20:33:30 +02:00
"log"
2018-02-06 14:34:32 -05:00
"math"
2015-01-30 13:31:43 +03:00
"net/http"
"path/filepath"
2015-08-12 21:26:25 +02:00
"runtime"
2018-02-06 14:56:30 -05:00
"runtime/debug"
2015-01-30 13:31:43 +03:00
"strconv"
"strings"
2016-05-03 16:44:25 +02:00
"time"
2015-01-30 13:31:43 +03:00
)
func init ( ) {
http . HandleFunc ( "/trace" , httpTrace )
http . HandleFunc ( "/jsontrace" , httpJsonTrace )
http . HandleFunc ( "/trace_viewer_html" , httpTraceViewerHTML )
}
// httpTrace serves either whole trace (goid==0) or trace for goid goroutine.
func httpTrace ( w http . ResponseWriter , r * http . Request ) {
2017-12-12 18:20:06 -05:00
_ , err := parseTrace ( )
2015-01-30 13:31:43 +03:00
if err != nil {
http . Error ( w , err . Error ( ) , http . StatusInternalServerError )
return
}
2016-05-03 16:44:25 +02:00
if err := r . ParseForm ( ) ; err != nil {
http . Error ( w , err . Error ( ) , http . StatusInternalServerError )
return
2015-01-30 13:31:43 +03:00
}
2016-05-03 16:44:25 +02:00
html := strings . Replace ( templTrace , "{{PARAMS}}" , r . Form . Encode ( ) , - 1 )
2015-01-30 13:31:43 +03:00
w . Write ( [ ] byte ( html ) )
}
2016-04-14 16:31:42 +02:00
// See https://github.com/catapult-project/catapult/blob/master/tracing/docs/embedding-trace-viewer.md
// This is almost verbatim copy of:
// https://github.com/catapult-project/catapult/blob/master/tracing/bin/index.html
2017-07-25 16:30:02 -04:00
// on revision 5f9e4c3eaa555bdef18218a89f38c768303b7b6e.
2015-01-30 13:31:43 +03:00
var templTrace = `
< html >
2016-04-14 16:31:42 +02:00
< head >
< link href = "/trace_viewer_html" rel = "import" >
2017-07-25 16:30:02 -04:00
< style type = "text/css" >
html , body {
box - sizing : border - box ;
overflow : hidden ;
margin : 0 px ;
padding : 0 ;
width : 100 % ;
height : 100 % ;
}
# trace - viewer {
width : 100 % ;
height : 100 % ;
}
# trace - viewer : focus {
outline : none ;
}
< / style >
2016-04-14 16:31:42 +02:00
< script >
2017-07-25 16:30:02 -04:00
' use strict ' ;
2016-04-14 16:31:42 +02:00
( function ( ) {
var viewer ;
var url ;
var model ;
function load ( ) {
var req = new XMLHttpRequest ( ) ;
var is_binary = / [ . ] gz $ / . test ( url ) || / [ . ] zip $ / . test ( url ) ;
req . overrideMimeType ( ' text / plain ; charset = x - user - defined ' ) ;
req . open ( ' GET ' , url , true ) ;
if ( is_binary )
req . responseType = ' arraybuffer ' ;
req . onreadystatechange = function ( event ) {
if ( req . readyState != = 4 )
return ;
window . setTimeout ( function ( ) {
if ( req . status == = 200 )
onResult ( is_binary ? req . response : req . responseText ) ;
else
onResultFail ( req . status ) ;
} , 0 ) ;
} ;
req . send ( null ) ;
}
function onResultFail ( err ) {
var overlay = new tr . ui . b . Overlay ( ) ;
overlay . textContent = err + ' : ' + url + ' could not be loaded ' ;
overlay . title = ' Failed to fetch data ' ;
overlay . visible = true ;
}
function onResult ( result ) {
model = new tr . Model ( ) ;
2017-07-25 16:38:39 -04:00
var opts = new tr . importer . ImportOptions ( ) ;
opts . shiftWorldToZero = false ;
var i = new tr . importer . Import ( model , opts ) ;
2016-04-14 16:31:42 +02:00
var p = i . importTracesWithProgressDialog ( [ result ] ) ;
p . then ( onModelLoaded , onImportFail ) ;
}
function onModelLoaded ( ) {
viewer . model = model ;
viewer . viewTitle = "trace" ;
2017-07-28 10:23:04 -04:00
if ( ! model || model . bounds . isEmpty )
return ;
var sel = window . location . hash . substr ( 1 ) ;
if ( sel == = ' ' )
return ;
var parts = sel . split ( ':' ) ;
var range = new ( tr . b . Range || tr . b . math . Range ) ( ) ;
range . addValue ( parseFloat ( parts [ 0 ] ) ) ;
range . addValue ( parseFloat ( parts [ 1 ] ) ) ;
viewer . trackView . viewport . interestRange . set ( range ) ;
2016-04-14 16:31:42 +02:00
}
2017-10-19 17:47:07 -04:00
function onImportFail ( err ) {
2016-04-14 16:31:42 +02:00
var overlay = new tr . ui . b . Overlay ( ) ;
overlay . textContent = tr . b . normalizeException ( err ) . message ;
overlay . title = ' Import error ' ;
overlay . visible = true ;
}
document . addEventListener ( ' DOMContentLoaded ' , function ( ) {
var container = document . createElement ( ' track - view - container ' ) ;
container . id = ' track_view_container ' ;
viewer = document . createElement ( ' tr - ui - timeline - view ' ) ;
viewer . track_view_container = container ;
viewer . appendChild ( container ) ;
viewer . id = ' trace - viewer ' ;
viewer . globalMode = true ;
document . body . appendChild ( viewer ) ;
2016-05-03 16:44:25 +02:00
url = ' / jsontrace ? { { PARAMS } } ' ;
2016-04-14 16:31:42 +02:00
load ( ) ;
} ) ;
} ( ) ) ;
< / script >
< / head >
< body >
< / body >
2015-01-30 13:31:43 +03:00
< / html >
`
// httpTraceViewerHTML serves static part of trace-viewer.
// This URL is queried from templTrace HTML.
func httpTraceViewerHTML ( w http . ResponseWriter , r * http . Request ) {
2017-08-24 16:32:54 -04:00
http . ServeFile ( w , r , filepath . Join ( runtime . GOROOT ( ) , "misc" , "trace" , "trace_viewer_full.html" ) )
2015-01-30 13:31:43 +03:00
}
// httpJsonTrace serves json trace, requested from within templTrace HTML.
func httpJsonTrace ( w http . ResponseWriter , r * http . Request ) {
2018-02-06 14:56:30 -05:00
defer debug . FreeOSMemory ( )
2018-02-06 13:21:39 -05:00
defer reportMemoryUsage ( "after httpJsonTrace" )
2015-07-02 20:33:30 +02:00
// This is an AJAX handler, so instead of http.Error we use log.Printf to log errors.
2017-12-12 18:20:06 -05:00
res , err := parseTrace ( )
2015-01-30 13:31:43 +03:00
if err != nil {
2015-07-02 20:33:30 +02:00
log . Printf ( "failed to parse trace: %v" , err )
2015-01-30 13:31:43 +03:00
return
}
params := & traceParams {
2017-12-12 18:20:06 -05:00
parsed : res ,
2018-02-06 14:34:32 -05:00
endTime : math . MaxInt64 ,
2015-01-30 13:31:43 +03:00
}
if goids := r . FormValue ( "goid" ) ; goids != "" {
2016-05-03 16:44:25 +02:00
// If goid argument is present, we are rendering a trace for this particular goroutine.
2015-01-30 13:31:43 +03:00
goid , err := strconv . ParseUint ( goids , 10 , 64 )
if err != nil {
2015-07-02 20:33:30 +02:00
log . Printf ( "failed to parse goid parameter '%v': %v" , goids , err )
2015-01-30 13:31:43 +03:00
return
}
2017-12-12 18:20:06 -05:00
analyzeGoroutines ( res . Events )
2015-01-30 13:31:43 +03:00
g := gs [ goid ]
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
params . mode = modeGoroutineOriented
2015-01-30 13:31:43 +03:00
params . startTime = g . StartTime
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if g . EndTime != 0 {
params . endTime = g . EndTime
} else { // The goroutine didn't end.
params . endTime = lastTimestamp ( )
}
2015-01-30 13:31:43 +03:00
params . maing = goid
2017-12-12 18:20:06 -05:00
params . gs = trace . RelatedGoroutines ( res . Events , goid )
2018-01-24 17:48:28 -05:00
} else if taskids := r . FormValue ( "taskid" ) ; taskids != "" {
taskid , err := strconv . ParseUint ( taskids , 10 , 64 )
if err != nil {
log . Printf ( "failed to parse taskid parameter %q: %v" , taskids , err )
return
}
2018-01-25 15:13:12 -05:00
annotRes , _ := analyzeAnnotations ( )
task , ok := annotRes . tasks [ taskid ]
2018-03-14 22:22:31 -04:00
if ! ok || len ( task . events ) == 0 {
2018-01-24 17:48:28 -05:00
log . Printf ( "failed to find task with id %d" , taskid )
return
}
goid := task . events [ 0 ] . G
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
params . mode = modeGoroutineOriented | modeTaskOriented
2018-01-24 17:48:28 -05:00
params . startTime = task . firstTimestamp ( ) - 1
params . endTime = task . lastTimestamp ( ) + 1
params . maing = goid
2018-01-25 15:13:12 -05:00
params . tasks = task . decendents ( )
gs := map [ uint64 ] bool { }
for _ , t := range params . tasks {
// find only directly involved goroutines
for k , v := range t . RelatedGoroutines ( res . Events , 0 ) {
gs [ k ] = v
}
}
params . gs = gs
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
} else if taskids := r . FormValue ( "focustask" ) ; taskids != "" {
taskid , err := strconv . ParseUint ( taskids , 10 , 64 )
if err != nil {
log . Printf ( "failed to parse focustask parameter %q: %v" , taskids , err )
return
}
annotRes , _ := analyzeAnnotations ( )
task , ok := annotRes . tasks [ taskid ]
if ! ok || len ( task . events ) == 0 {
log . Printf ( "failed to find task with id %d" , taskid )
return
}
params . mode = modeTaskOriented
params . startTime = task . firstTimestamp ( ) - 1
params . endTime = task . lastTimestamp ( ) + 1
params . tasks = task . decendents ( )
2015-01-30 13:31:43 +03:00
}
2018-02-06 14:34:32 -05:00
start := int64 ( 0 )
end := int64 ( math . MaxInt64 )
2016-05-03 16:44:25 +02:00
if startStr , endStr := r . FormValue ( "start" ) , r . FormValue ( "end" ) ; startStr != "" && endStr != "" {
// If start/end arguments are present, we are rendering a range of the trace.
2018-02-06 14:34:32 -05:00
start , err = strconv . ParseInt ( startStr , 10 , 64 )
2016-05-03 16:44:25 +02:00
if err != nil {
log . Printf ( "failed to parse start parameter '%v': %v" , startStr , err )
return
}
2018-02-06 14:34:32 -05:00
end , err = strconv . ParseInt ( endStr , 10 , 64 )
2016-05-03 16:44:25 +02:00
if err != nil {
log . Printf ( "failed to parse end parameter '%v': %v" , endStr , err )
return
}
}
2018-02-06 14:34:32 -05:00
c := viewerDataTraceConsumer ( w , start , end )
if err := generateTrace ( params , c ) ; err != nil {
log . Printf ( "failed to generate trace: %v" , err )
2015-01-30 13:31:43 +03:00
return
}
}
2016-05-03 16:44:25 +02:00
type Range struct {
Name string
Start int
End int
}
// splitTrace splits the trace into a number of ranges,
2018-02-06 14:34:32 -05:00
// each resulting in approx 100MB of json output
// (trace viewer can hardly handle more).
func splitTrace ( res trace . ParseResult ) [ ] Range {
params := & traceParams {
parsed : res ,
endTime : math . MaxInt64 ,
2016-05-03 16:44:25 +02:00
}
2018-02-06 14:34:32 -05:00
s , c := splittingTraceConsumer ( 100 << 20 ) // 100M
if err := generateTrace ( params , c ) ; err != nil {
dief ( "%v\n" , err )
}
return s . Ranges
}
type splitter struct {
Ranges [ ] Range
}
func splittingTraceConsumer ( max int ) ( * splitter , traceConsumer ) {
type eventSz struct {
Time float64
Sz int
}
var (
data = ViewerData { Frames : make ( map [ string ] ViewerFrame ) }
sizes [ ] eventSz
cw countingWriter
)
s := new ( splitter )
return s , traceConsumer {
consumeTimeUnit : func ( unit string ) {
data . TimeUnit = unit
} ,
consumeViewerEvent : func ( v * ViewerEvent , required bool ) {
if required {
// Store required events inside data
// so flush can include them in the required
// part of the trace.
data . Events = append ( data . Events , v )
2018-02-06 14:56:30 -05:00
return
2018-02-06 14:34:32 -05:00
}
enc := json . NewEncoder ( & cw )
enc . Encode ( v )
sizes = append ( sizes , eventSz { v . Time , cw . size + 1 } ) // +1 for ",".
cw . size = 0
} ,
consumeViewerFrame : func ( k string , v ViewerFrame ) {
data . Frames [ k ] = v
} ,
flush : func ( ) {
// Calculate size of the mandatory part of the trace.
// This includes stack traces and thread names.
cw . size = 0
enc := json . NewEncoder ( & cw )
enc . Encode ( data )
minSize := cw . size
// Then calculate size of each individual event
// and group them into ranges.
sum := minSize
start := 0
for i , ev := range sizes {
if sum + ev . Sz > max {
ranges = append ( ranges , Range {
Name : fmt . Sprintf ( "%v-%v" , time . Duration ( sizes [ start ] . Time * 1000 ) , time . Duration ( ev . Time * 1000 ) ) ,
Start : start ,
End : i + 1 ,
} )
start = i + 1
sum = minSize
} else {
sum += ev . Sz + 1
}
}
if len ( ranges ) <= 1 {
s . Ranges = nil
return
}
if end := len ( sizes ) - 1 ; start < end {
ranges = append ( ranges , Range {
Name : fmt . Sprintf ( "%v-%v" , time . Duration ( sizes [ start ] . Time * 1000 ) , time . Duration ( sizes [ end ] . Time * 1000 ) ) ,
Start : start ,
End : end ,
} )
}
s . Ranges = ranges
} ,
2016-05-03 16:44:25 +02:00
}
}
type countingWriter struct {
size int
}
func ( cw * countingWriter ) Write ( data [ ] byte ) ( int , error ) {
cw . size += len ( data )
return len ( data ) , nil
}
2015-01-30 13:31:43 +03:00
type traceParams struct {
2017-12-12 18:20:06 -05:00
parsed trace . ParseResult
2018-01-24 17:48:28 -05:00
mode traceviewMode
2015-01-30 13:31:43 +03:00
startTime int64
endTime int64
2018-01-24 17:48:28 -05:00
maing uint64 // for goroutine-oriented view, place this goroutine on the top row
gs map [ uint64 ] bool // Goroutines to be displayed for goroutine-oriented or task-oriented view
2018-01-25 15:13:12 -05:00
tasks [ ] * taskDesc // Tasks to be displayed. tasks[0] is the top-most task
2015-01-30 13:31:43 +03:00
}
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
type traceviewMode uint
2018-01-24 17:48:28 -05:00
const (
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
modeGoroutineOriented traceviewMode = 1 << iota
modeTaskOriented
2018-01-24 17:48:28 -05:00
)
2015-01-30 13:31:43 +03:00
type traceContext struct {
* traceParams
2018-02-06 14:34:32 -05:00
consumer traceConsumer
2015-01-30 13:31:43 +03:00
frameTree frameNode
frameSeq int
arrowSeq uint64
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
gcount uint64
heapStats , prevHeapStats heapStats
threadStats , prevThreadStats threadStats
2017-11-13 22:32:19 -05:00
gstates , prevGstates [ gStateCount ] int64
2018-04-12 17:06:33 -04:00
runtime/trace: rename "Span" with "Region"
"Span" is a commonly used term in many distributed tracing systems
(Dapper, OpenCensus, OpenTracing, ...). They use it to refer to a
period of time, not necessarily tied into execution of underlying
processor, thread, or goroutine, unlike the "Span" of runtime/trace
package.
Since distributed tracing and go runtime execution tracing are
already similar enough to cause confusion, this CL attempts to avoid
using the same word if possible.
"Region" is being used in a certain tracing system to refer to a code
region which is pretty close to what runtime/trace.Span currently
refers to. So, replace that.
https://software.intel.com/en-us/itc-user-and-reference-guide-defining-and-recording-functions-or-regions
This CL also tweaks APIs a bit based on jbd and heschi's comments:
NewContext -> NewTask
and it now returns a Task object that exports End method.
StartSpan -> StartRegion
and it now returns a Region object that exports End method.
Also, changed WithSpan to WithRegion and it now takes func() with no
context. Another thought is to get rid of WithRegion. It is a nice
concept but in practice, it seems problematic (a lot of code churn,
and polluting stack trace). Already, the tracing concept is very low
level, and we hope this API to be used with great care.
Recommended usage will be
defer trace.StartRegion(ctx, "someRegion").End()
Left old APIs untouched in this CL. Once the usage of them are cleaned
up, they will be removed in a separate CL.
Change-Id: I73880635e437f3aad51314331a035dd1459b9f3a
Reviewed-on: https://go-review.googlesource.com/108296
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: JBD <jbd@google.com>
2018-04-19 14:58:42 -04:00
regionID int // last emitted region id. incremented in each emitRegion call.
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
}
type heapStats struct {
2015-01-30 13:31:43 +03:00
heapAlloc uint64
nextGC uint64
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
}
type threadStats struct {
2017-11-30 18:51:04 -05:00
insyscallRuntime uint64 // system goroutine in syscall
insyscall uint64 // user goroutine in syscall
prunning uint64 // thread running P
2015-01-30 13:31:43 +03:00
}
type frameNode struct {
id int
children map [ uint64 ] frameNode
}
2016-10-08 17:35:27 -04:00
type gState int
const (
gDead gState = iota
gRunnable
gRunning
gWaiting
runtime, cmd/trace: track goroutines blocked on GC assists
Currently when a goroutine blocks on a GC assist, it emits a generic
EvGoBlock event. Since assist blocking events and, in particular, the
length of the blocked assist queue, are important for diagnosing GC
behavior, this commit adds a new EvGoBlockGC event for blocking on a
GC assist. The trace viewer uses this event to report a "waiting on
GC" count in the "Goroutines" row. This makes sense because, unlike
other blocked goroutines, these goroutines do have work to do, so
being blocked on a GC assist is quite similar to being in the
"runnable" state, which we also report in the trace viewer.
Change-Id: Ic21a326992606b121ea3d3d00110d8d1fdc7a5ef
Reviewed-on: https://go-review.googlesource.com/30704
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-10-08 18:38:35 -04:00
gWaitingGC
2016-10-08 17:35:27 -04:00
gStateCount
)
2017-01-31 14:09:14 -05:00
type gInfo struct {
2017-11-30 18:51:04 -05:00
state gState // current state
name string // name chosen for this goroutine at first EvGoStart
isSystemG bool
2017-01-31 14:09:14 -05:00
start * trace . Event // most recent EvGoStart
markAssist * trace . Event // if non-nil, the mark assist currently running.
}
2015-01-30 13:31:43 +03:00
type ViewerData struct {
2015-06-18 16:27:29 +02:00
Events [ ] * ViewerEvent ` json:"traceEvents" `
Frames map [ string ] ViewerFrame ` json:"stackFrames" `
TimeUnit string ` json:"displayTimeUnit" `
2016-05-03 16:44:25 +02:00
// This is where mandatory part of the trace starts (e.g. thread names)
footer int
2015-01-30 13:31:43 +03:00
}
type ViewerEvent struct {
Name string ` json:"name,omitempty" `
Phase string ` json:"ph" `
Scope string ` json:"s,omitempty" `
2015-06-18 16:27:29 +02:00
Time float64 ` json:"ts" `
Dur float64 ` json:"dur,omitempty" `
2015-01-30 13:31:43 +03:00
Pid uint64 ` json:"pid" `
Tid uint64 ` json:"tid" `
ID uint64 ` json:"id,omitempty" `
Stack int ` json:"sf,omitempty" `
EndStack int ` json:"esf,omitempty" `
Arg interface { } ` json:"args,omitempty" `
2018-01-24 17:48:28 -05:00
Cname string ` json:"cname,omitempty" `
Category string ` json:"cat,omitempty" `
2015-01-30 13:31:43 +03:00
}
type ViewerFrame struct {
Name string ` json:"name" `
Parent int ` json:"parent,omitempty" `
}
type NameArg struct {
Name string ` json:"name" `
}
type SortIndexArg struct {
Index int ` json:"sort_index" `
}
2018-02-06 14:34:32 -05:00
type traceConsumer struct {
consumeTimeUnit func ( unit string )
consumeViewerEvent func ( v * ViewerEvent , required bool )
consumeViewerFrame func ( key string , f ViewerFrame )
flush func ( )
}
2015-01-30 13:31:43 +03:00
// generateTrace generates json trace for trace-viewer:
// https://github.com/google/trace-viewer
// Trace format is described at:
// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/view
2018-01-24 17:48:28 -05:00
// If mode==goroutineMode, generate trace for goroutine goid, otherwise whole trace.
2015-01-30 13:31:43 +03:00
// startTime, endTime determine part of the trace that we are interested in.
// gset restricts goroutines that are included in the resulting trace.
2018-02-06 14:34:32 -05:00
func generateTrace ( params * traceParams , consumer traceConsumer ) error {
defer consumer . flush ( )
2015-01-30 13:31:43 +03:00
ctx := & traceContext { traceParams : params }
ctx . frameTree . children = make ( map [ uint64 ] frameNode )
2018-02-06 14:34:32 -05:00
ctx . consumer = consumer
ctx . consumer . consumeTimeUnit ( "ns" )
2015-01-30 13:31:43 +03:00
maxProc := 0
2017-01-31 14:09:14 -05:00
ginfos := make ( map [ uint64 ] * gInfo )
2017-12-12 18:20:06 -05:00
stacks := params . parsed . Stacks
2017-01-31 14:09:14 -05:00
getGInfo := func ( g uint64 ) * gInfo {
info , ok := ginfos [ g ]
if ! ok {
info = & gInfo { }
ginfos [ g ] = info
}
return info
}
2016-10-08 17:35:27 -04:00
// Since we make many calls to setGState, we record a sticky
// error in setGStateErr and check it after every event.
var setGStateErr error
setGState := func ( ev * trace . Event , g uint64 , oldState , newState gState ) {
2017-01-31 14:09:14 -05:00
info := getGInfo ( g )
if oldState == gWaiting && info . state == gWaitingGC {
runtime, cmd/trace: track goroutines blocked on GC assists
Currently when a goroutine blocks on a GC assist, it emits a generic
EvGoBlock event. Since assist blocking events and, in particular, the
length of the blocked assist queue, are important for diagnosing GC
behavior, this commit adds a new EvGoBlockGC event for blocking on a
GC assist. The trace viewer uses this event to report a "waiting on
GC" count in the "Goroutines" row. This makes sense because, unlike
other blocked goroutines, these goroutines do have work to do, so
being blocked on a GC assist is quite similar to being in the
"runnable" state, which we also report in the trace viewer.
Change-Id: Ic21a326992606b121ea3d3d00110d8d1fdc7a5ef
Reviewed-on: https://go-review.googlesource.com/30704
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-10-08 18:38:35 -04:00
// For checking, gWaiting counts as any gWaiting*.
2017-01-31 14:09:14 -05:00
oldState = info . state
runtime, cmd/trace: track goroutines blocked on GC assists
Currently when a goroutine blocks on a GC assist, it emits a generic
EvGoBlock event. Since assist blocking events and, in particular, the
length of the blocked assist queue, are important for diagnosing GC
behavior, this commit adds a new EvGoBlockGC event for blocking on a
GC assist. The trace viewer uses this event to report a "waiting on
GC" count in the "Goroutines" row. This makes sense because, unlike
other blocked goroutines, these goroutines do have work to do, so
being blocked on a GC assist is quite similar to being in the
"runnable" state, which we also report in the trace viewer.
Change-Id: Ic21a326992606b121ea3d3d00110d8d1fdc7a5ef
Reviewed-on: https://go-review.googlesource.com/30704
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-10-08 18:38:35 -04:00
}
2017-01-31 14:09:14 -05:00
if info . state != oldState && setGStateErr == nil {
2016-10-08 17:35:27 -04:00
setGStateErr = fmt . Errorf ( "expected G %d to be in state %d, but got state %d" , g , oldState , newState )
}
2017-01-31 14:09:14 -05:00
ctx . gstates [ info . state ] --
2016-10-08 17:35:27 -04:00
ctx . gstates [ newState ] ++
2017-01-31 14:09:14 -05:00
info . state = newState
2016-10-08 17:35:27 -04:00
}
2017-11-30 18:51:04 -05:00
2017-12-12 18:20:06 -05:00
for _ , ev := range ctx . parsed . Events {
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
// Handle state transitions before we filter out events.
switch ev . Type {
case trace . EvGoStart , trace . EvGoStartLabel :
setGState ( ev , ev . G , gRunnable , gRunning )
2017-01-31 14:09:14 -05:00
info := getGInfo ( ev . G )
info . start = ev
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
case trace . EvProcStart :
ctx . threadStats . prunning ++
case trace . EvProcStop :
ctx . threadStats . prunning --
case trace . EvGoCreate :
2017-12-12 18:20:06 -05:00
newG := ev . Args [ 0 ]
info := getGInfo ( newG )
if info . name != "" {
2018-02-06 14:34:32 -05:00
return fmt . Errorf ( "duplicate go create event for go id=%d detected at offset %d" , newG , ev . Off )
2017-12-12 18:20:06 -05:00
}
stk , ok := stacks [ ev . Args [ 1 ] ]
if ! ok || len ( stk ) == 0 {
2018-02-06 14:34:32 -05:00
return fmt . Errorf ( "invalid go create event: missing stack information for go id=%d at offset %d" , newG , ev . Off )
2017-12-12 18:20:06 -05:00
}
fname := stk [ 0 ] . Fn
info . name = fmt . Sprintf ( "G%v %s" , newG , fname )
info . isSystemG = strings . HasPrefix ( fname , "runtime." ) && fname != "runtime.main"
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
ctx . gcount ++
2017-12-12 18:20:06 -05:00
setGState ( ev , newG , gDead , gRunnable )
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
case trace . EvGoEnd :
ctx . gcount --
setGState ( ev , ev . G , gRunning , gDead )
case trace . EvGoUnblock :
setGState ( ev , ev . Args [ 0 ] , gWaiting , gRunnable )
case trace . EvGoSysExit :
setGState ( ev , ev . G , gWaiting , gRunnable )
2017-11-30 18:51:04 -05:00
if getGInfo ( ev . G ) . isSystemG {
ctx . threadStats . insyscallRuntime --
} else {
ctx . threadStats . insyscall --
}
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
case trace . EvGoSysBlock :
setGState ( ev , ev . G , gRunning , gWaiting )
2017-11-30 18:51:04 -05:00
if getGInfo ( ev . G ) . isSystemG {
ctx . threadStats . insyscallRuntime ++
} else {
ctx . threadStats . insyscall ++
}
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
case trace . EvGoSched , trace . EvGoPreempt :
setGState ( ev , ev . G , gRunning , gRunnable )
case trace . EvGoStop ,
trace . EvGoSleep , trace . EvGoBlock , trace . EvGoBlockSend , trace . EvGoBlockRecv ,
trace . EvGoBlockSelect , trace . EvGoBlockSync , trace . EvGoBlockCond , trace . EvGoBlockNet :
setGState ( ev , ev . G , gRunning , gWaiting )
case trace . EvGoBlockGC :
setGState ( ev , ev . G , gRunning , gWaitingGC )
2017-01-31 14:09:14 -05:00
case trace . EvGCMarkAssistStart :
getGInfo ( ev . G ) . markAssist = ev
case trace . EvGCMarkAssistDone :
getGInfo ( ev . G ) . markAssist = nil
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
case trace . EvGoWaiting :
setGState ( ev , ev . G , gRunnable , gWaiting )
case trace . EvGoInSyscall :
// Cancel out the effect of EvGoCreate at the beginning.
setGState ( ev , ev . G , gRunnable , gWaiting )
2017-11-30 18:51:04 -05:00
if getGInfo ( ev . G ) . isSystemG {
ctx . threadStats . insyscallRuntime ++
} else {
ctx . threadStats . insyscall ++
}
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
case trace . EvHeapAlloc :
ctx . heapStats . heapAlloc = ev . Args [ 0 ]
case trace . EvNextGC :
ctx . heapStats . nextGC = ev . Args [ 0 ]
}
if setGStateErr != nil {
2018-02-06 14:34:32 -05:00
return setGStateErr
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
}
2017-11-30 18:51:04 -05:00
if ctx . gstates [ gRunnable ] < 0 || ctx . gstates [ gRunning ] < 0 || ctx . threadStats . insyscall < 0 || ctx . threadStats . insyscallRuntime < 0 {
2018-02-06 14:34:32 -05:00
return fmt . Errorf ( "invalid state after processing %v: runnable=%d running=%d insyscall=%d insyscallRuntime=%d" , ev , ctx . gstates [ gRunnable ] , ctx . gstates [ gRunning ] , ctx . threadStats . insyscall , ctx . threadStats . insyscallRuntime )
2017-11-13 22:32:19 -05:00
}
2015-01-30 13:31:43 +03:00
// Ignore events that are from uninteresting goroutines
// or outside of the interesting timeframe.
if ctx . gs != nil && ev . P < trace . FakeP && ! ctx . gs [ ev . G ] {
continue
}
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if ! withinTimeRange ( ev , ctx . startTime , ctx . endTime ) {
2015-01-30 13:31:43 +03:00
continue
}
if ev . P < trace . FakeP && ev . P > maxProc {
maxProc = ev . P
}
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
// Emit trace objects.
2015-01-30 13:31:43 +03:00
switch ev . Type {
case trace . EvProcStart :
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if ctx . mode & modeGoroutineOriented != 0 {
2015-01-30 13:31:43 +03:00
continue
}
2018-01-26 10:18:16 -05:00
ctx . emitInstant ( ev , "proc start" , "" )
2015-01-30 13:31:43 +03:00
case trace . EvProcStop :
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if ctx . mode & modeGoroutineOriented != 0 {
2015-01-30 13:31:43 +03:00
continue
}
2018-01-26 10:18:16 -05:00
ctx . emitInstant ( ev , "proc stop" , "" )
2015-01-30 13:31:43 +03:00
case trace . EvGCStart :
ctx . emitSlice ( ev , "GC" )
case trace . EvGCDone :
2017-07-21 14:25:28 -04:00
case trace . EvGCSTWStart :
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if ctx . mode & modeGoroutineOriented != 0 {
2015-01-30 13:31:43 +03:00
continue
}
2017-07-21 14:25:28 -04:00
ctx . emitSlice ( ev , fmt . Sprintf ( "STW (%s)" , ev . SArgs [ 0 ] ) )
case trace . EvGCSTWDone :
2017-01-31 14:09:14 -05:00
case trace . EvGCMarkAssistStart :
// Mark assists can continue past preemptions, so truncate to the
// whichever comes first. We'll synthesize another slice if
// necessary in EvGoStart.
markFinish := ev . Link
goFinish := getGInfo ( ev . G ) . start . Link
fakeMarkStart := * ev
text := "MARK ASSIST"
2017-02-22 17:58:31 -05:00
if markFinish == nil || markFinish . Ts > goFinish . Ts {
2017-01-31 14:09:14 -05:00
fakeMarkStart . Link = goFinish
text = "MARK ASSIST (unfinished)"
}
ctx . emitSlice ( & fakeMarkStart , text )
2015-01-30 13:31:43 +03:00
case trace . EvGCSweepStart :
2017-04-14 14:53:09 -04:00
slice := ctx . emitSlice ( ev , "SWEEP" )
if done := ev . Link ; done != nil && done . Args [ 0 ] != 0 {
slice . Arg = struct {
Swept uint64 ` json:"Swept bytes" `
Reclaimed uint64 ` json:"Reclaimed bytes" `
} { done . Args [ 0 ] , done . Args [ 1 ] }
}
2017-01-31 14:09:14 -05:00
case trace . EvGoStart , trace . EvGoStartLabel :
info := getGInfo ( ev . G )
if ev . Type == trace . EvGoStartLabel {
ctx . emitSlice ( ev , ev . SArgs [ 0 ] )
} else {
ctx . emitSlice ( ev , info . name )
}
if info . markAssist != nil {
// If we're in a mark assist, synthesize a new slice, ending
// either when the mark assist ends or when we're descheduled.
markFinish := info . markAssist . Link
goFinish := ev . Link
fakeMarkStart := * ev
text := "MARK ASSIST (resumed, unfinished)"
2017-02-22 17:58:31 -05:00
if markFinish != nil && markFinish . Ts < goFinish . Ts {
2017-01-31 14:09:14 -05:00
fakeMarkStart . Link = markFinish
text = "MARK ASSIST (resumed)"
}
ctx . emitSlice ( & fakeMarkStart , text )
}
2015-01-30 13:31:43 +03:00
case trace . EvGoCreate :
ctx . emitArrow ( ev , "go" )
case trace . EvGoUnblock :
ctx . emitArrow ( ev , "unblock" )
case trace . EvGoSysCall :
2018-01-26 10:18:16 -05:00
ctx . emitInstant ( ev , "syscall" , "" )
2015-01-30 13:31:43 +03:00
case trace . EvGoSysExit :
ctx . emitArrow ( ev , "sysexit" )
2018-01-26 10:18:16 -05:00
case trace . EvUserLog :
ctx . emitInstant ( ev , formatUserLog ( ev ) , "user event" )
case trace . EvUserTaskCreate :
ctx . emitInstant ( ev , "task start" , "user event" )
case trace . EvUserTaskEnd :
ctx . emitInstant ( ev , "task end" , "user event" )
2016-08-08 17:24:07 -04:00
}
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
// Emit any counter updates.
ctx . emitThreadCounters ( ev )
ctx . emitHeapCounters ( ev )
ctx . emitGoroutineCounters ( ev )
2015-01-30 13:31:43 +03:00
}
2018-02-06 14:34:32 -05:00
ctx . emitFooter ( & ViewerEvent { Name : "process_name" , Phase : "M" , Pid : 0 , Arg : & NameArg { "PROCS" } } )
ctx . emitFooter ( & ViewerEvent { Name : "process_sort_index" , Phase : "M" , Pid : 0 , Arg : & SortIndexArg { 1 } } )
2015-01-30 13:31:43 +03:00
2018-02-06 14:34:32 -05:00
ctx . emitFooter ( & ViewerEvent { Name : "process_name" , Phase : "M" , Pid : 1 , Arg : & NameArg { "STATS" } } )
ctx . emitFooter ( & ViewerEvent { Name : "process_sort_index" , Phase : "M" , Pid : 1 , Arg : & SortIndexArg { 0 } } )
2015-01-30 13:31:43 +03:00
2018-02-06 14:34:32 -05:00
ctx . emitFooter ( & ViewerEvent { Name : "thread_name" , Phase : "M" , Pid : 0 , Tid : trace . GCP , Arg : & NameArg { "GC" } } )
ctx . emitFooter ( & ViewerEvent { Name : "thread_sort_index" , Phase : "M" , Pid : 0 , Tid : trace . GCP , Arg : & SortIndexArg { - 6 } } )
2016-09-29 11:53:42 -04:00
2018-02-06 14:34:32 -05:00
ctx . emitFooter ( & ViewerEvent { Name : "thread_name" , Phase : "M" , Pid : 0 , Tid : trace . NetpollP , Arg : & NameArg { "Network" } } )
ctx . emitFooter ( & ViewerEvent { Name : "thread_sort_index" , Phase : "M" , Pid : 0 , Tid : trace . NetpollP , Arg : & SortIndexArg { - 5 } } )
2015-01-30 13:31:43 +03:00
2018-02-06 14:34:32 -05:00
ctx . emitFooter ( & ViewerEvent { Name : "thread_name" , Phase : "M" , Pid : 0 , Tid : trace . TimerP , Arg : & NameArg { "Timers" } } )
ctx . emitFooter ( & ViewerEvent { Name : "thread_sort_index" , Phase : "M" , Pid : 0 , Tid : trace . TimerP , Arg : & SortIndexArg { - 4 } } )
2015-01-30 13:31:43 +03:00
2018-02-06 14:34:32 -05:00
ctx . emitFooter ( & ViewerEvent { Name : "thread_name" , Phase : "M" , Pid : 0 , Tid : trace . SyscallP , Arg : & NameArg { "Syscalls" } } )
ctx . emitFooter ( & ViewerEvent { Name : "thread_sort_index" , Phase : "M" , Pid : 0 , Tid : trace . SyscallP , Arg : & SortIndexArg { - 3 } } )
2015-01-30 13:31:43 +03:00
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
// Display rows for Ps if we are in the default trace view mode (not goroutine-oriented presentation)
if ctx . mode & modeGoroutineOriented != 0 {
2015-01-30 13:31:43 +03:00
for i := 0 ; i <= maxProc ; i ++ {
2018-02-06 14:34:32 -05:00
ctx . emitFooter ( & ViewerEvent { Name : "thread_name" , Phase : "M" , Pid : 0 , Tid : uint64 ( i ) , Arg : & NameArg { fmt . Sprintf ( "Proc %v" , i ) } } )
ctx . emitFooter ( & ViewerEvent { Name : "thread_sort_index" , Phase : "M" , Pid : 0 , Tid : uint64 ( i ) , Arg : & SortIndexArg { i } } )
2015-01-30 13:31:43 +03:00
}
}
runtime/trace: rename "Span" with "Region"
"Span" is a commonly used term in many distributed tracing systems
(Dapper, OpenCensus, OpenTracing, ...). They use it to refer to a
period of time, not necessarily tied into execution of underlying
processor, thread, or goroutine, unlike the "Span" of runtime/trace
package.
Since distributed tracing and go runtime execution tracing are
already similar enough to cause confusion, this CL attempts to avoid
using the same word if possible.
"Region" is being used in a certain tracing system to refer to a code
region which is pretty close to what runtime/trace.Span currently
refers to. So, replace that.
https://software.intel.com/en-us/itc-user-and-reference-guide-defining-and-recording-functions-or-regions
This CL also tweaks APIs a bit based on jbd and heschi's comments:
NewContext -> NewTask
and it now returns a Task object that exports End method.
StartSpan -> StartRegion
and it now returns a Region object that exports End method.
Also, changed WithSpan to WithRegion and it now takes func() with no
context. Another thought is to get rid of WithRegion. It is a nice
concept but in practice, it seems problematic (a lot of code churn,
and polluting stack trace). Already, the tracing concept is very low
level, and we hope this API to be used with great care.
Recommended usage will be
defer trace.StartRegion(ctx, "someRegion").End()
Left old APIs untouched in this CL. Once the usage of them are cleaned
up, they will be removed in a separate CL.
Change-Id: I73880635e437f3aad51314331a035dd1459b9f3a
Reviewed-on: https://go-review.googlesource.com/108296
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: JBD <jbd@google.com>
2018-04-19 14:58:42 -04:00
// Display task and its regions if we are in task-oriented presentation mode.
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if ctx . mode & modeTaskOriented != 0 {
2018-01-25 15:13:12 -05:00
taskRow := uint64 ( trace . GCP + 1 )
for _ , task := range ctx . tasks {
taskName := fmt . Sprintf ( "Task %s(%d)" , task . name , task . id )
ctx . emit ( & ViewerEvent { Name : "thread_name" , Phase : "M" , Pid : 0 , Tid : taskRow , Arg : & NameArg { "Tasks" } } )
ctx . emit ( & ViewerEvent { Name : "thread_sort_index" , Phase : "M" , Pid : 0 , Tid : taskRow , Arg : & SortIndexArg { - 3 } } )
2018-03-06 18:06:50 -05:00
tBegin := & ViewerEvent { Category : "task" , Name : taskName , Phase : "b" , Time : float64 ( task . firstTimestamp ( ) ) / 1e3 , Tid : taskRow , ID : task . id , Cname : colorBlue }
2018-01-26 10:18:16 -05:00
if task . create != nil {
tBegin . Stack = ctx . stack ( task . create . Stk )
}
ctx . emit ( tBegin )
2018-04-24 15:37:42 -04:00
tEnd := & ViewerEvent { Category : "task" , Name : taskName , Phase : "e" , Time : float64 ( task . endTimestamp ( ) ) / 1e3 , Tid : taskRow , ID : task . id , Cname : colorBlue }
2018-01-26 10:18:16 -05:00
if task . end != nil {
tEnd . Stack = ctx . stack ( task . end . Stk )
}
ctx . emit ( tEnd )
runtime/trace: rename "Span" with "Region"
"Span" is a commonly used term in many distributed tracing systems
(Dapper, OpenCensus, OpenTracing, ...). They use it to refer to a
period of time, not necessarily tied into execution of underlying
processor, thread, or goroutine, unlike the "Span" of runtime/trace
package.
Since distributed tracing and go runtime execution tracing are
already similar enough to cause confusion, this CL attempts to avoid
using the same word if possible.
"Region" is being used in a certain tracing system to refer to a code
region which is pretty close to what runtime/trace.Span currently
refers to. So, replace that.
https://software.intel.com/en-us/itc-user-and-reference-guide-defining-and-recording-functions-or-regions
This CL also tweaks APIs a bit based on jbd and heschi's comments:
NewContext -> NewTask
and it now returns a Task object that exports End method.
StartSpan -> StartRegion
and it now returns a Region object that exports End method.
Also, changed WithSpan to WithRegion and it now takes func() with no
context. Another thought is to get rid of WithRegion. It is a nice
concept but in practice, it seems problematic (a lot of code churn,
and polluting stack trace). Already, the tracing concept is very low
level, and we hope this API to be used with great care.
Recommended usage will be
defer trace.StartRegion(ctx, "someRegion").End()
Left old APIs untouched in this CL. Once the usage of them are cleaned
up, they will be removed in a separate CL.
Change-Id: I73880635e437f3aad51314331a035dd1459b9f3a
Reviewed-on: https://go-review.googlesource.com/108296
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: JBD <jbd@google.com>
2018-04-19 14:58:42 -04:00
// If we are in goroutine-oriented mode, we draw regions.
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
// TODO(hyangah): add this for task/P-oriented mode (i.e., focustask view) too.
if ctx . mode & modeGoroutineOriented != 0 {
runtime/trace: rename "Span" with "Region"
"Span" is a commonly used term in many distributed tracing systems
(Dapper, OpenCensus, OpenTracing, ...). They use it to refer to a
period of time, not necessarily tied into execution of underlying
processor, thread, or goroutine, unlike the "Span" of runtime/trace
package.
Since distributed tracing and go runtime execution tracing are
already similar enough to cause confusion, this CL attempts to avoid
using the same word if possible.
"Region" is being used in a certain tracing system to refer to a code
region which is pretty close to what runtime/trace.Span currently
refers to. So, replace that.
https://software.intel.com/en-us/itc-user-and-reference-guide-defining-and-recording-functions-or-regions
This CL also tweaks APIs a bit based on jbd and heschi's comments:
NewContext -> NewTask
and it now returns a Task object that exports End method.
StartSpan -> StartRegion
and it now returns a Region object that exports End method.
Also, changed WithSpan to WithRegion and it now takes func() with no
context. Another thought is to get rid of WithRegion. It is a nice
concept but in practice, it seems problematic (a lot of code churn,
and polluting stack trace). Already, the tracing concept is very low
level, and we hope this API to be used with great care.
Recommended usage will be
defer trace.StartRegion(ctx, "someRegion").End()
Left old APIs untouched in this CL. Once the usage of them are cleaned
up, they will be removed in a separate CL.
Change-Id: I73880635e437f3aad51314331a035dd1459b9f3a
Reviewed-on: https://go-review.googlesource.com/108296
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: JBD <jbd@google.com>
2018-04-19 14:58:42 -04:00
for _ , s := range task . regions {
ctx . emitRegion ( s )
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
}
2018-01-25 15:13:12 -05:00
}
2018-01-24 17:48:28 -05:00
}
}
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
// Display goroutine rows if we are either in goroutine-oriented mode.
if ctx . mode & modeGoroutineOriented != 0 {
2017-01-31 14:09:14 -05:00
for k , v := range ginfos {
2015-01-30 13:31:43 +03:00
if ! ctx . gs [ k ] {
continue
}
2018-02-06 14:34:32 -05:00
ctx . emitFooter ( & ViewerEvent { Name : "thread_name" , Phase : "M" , Pid : 0 , Tid : k , Arg : & NameArg { v . name } } )
2015-01-30 13:31:43 +03:00
}
2018-01-24 17:48:28 -05:00
// Row for the main goroutine (maing)
2018-02-06 14:34:32 -05:00
ctx . emitFooter ( & ViewerEvent { Name : "thread_sort_index" , Phase : "M" , Pid : 0 , Tid : ctx . maing , Arg : & SortIndexArg { - 2 } } )
2018-01-24 17:48:28 -05:00
// Row for GC or global state (specified with G=0)
2018-02-06 14:34:32 -05:00
ctx . emitFooter ( & ViewerEvent { Name : "thread_sort_index" , Phase : "M" , Pid : 0 , Tid : 0 , Arg : & SortIndexArg { - 1 } } )
2015-01-30 13:31:43 +03:00
}
2018-02-06 14:34:32 -05:00
return nil
2015-01-30 13:31:43 +03:00
}
func ( ctx * traceContext ) emit ( e * ViewerEvent ) {
2018-02-06 14:34:32 -05:00
ctx . consumer . consumeViewerEvent ( e , false )
}
func ( ctx * traceContext ) emitFooter ( e * ViewerEvent ) {
ctx . consumer . consumeViewerEvent ( e , true )
2015-01-30 13:31:43 +03:00
}
2015-06-18 16:27:29 +02:00
func ( ctx * traceContext ) time ( ev * trace . Event ) float64 {
// Trace viewer wants timestamps in microseconds.
2018-01-24 17:48:28 -05:00
return float64 ( ev . Ts ) / 1000
}
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
func withinTimeRange ( ev * trace . Event , s , e int64 ) bool {
2018-01-24 17:48:28 -05:00
if evEnd := ev . Link ; evEnd != nil {
return ev . Ts <= e && evEnd . Ts >= s
}
return ev . Ts >= s && ev . Ts <= e
2015-01-30 13:31:43 +03:00
}
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
func tsWithinRange ( ts , s , e int64 ) bool {
return s <= ts && ts <= e
}
2015-01-30 13:31:43 +03:00
func ( ctx * traceContext ) proc ( ev * trace . Event ) uint64 {
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if ctx . mode & modeGoroutineOriented != 0 && ev . P < trace . FakeP {
2015-01-30 13:31:43 +03:00
return ev . G
} else {
return uint64 ( ev . P )
}
}
2017-04-14 14:53:09 -04:00
func ( ctx * traceContext ) emitSlice ( ev * trace . Event , name string ) * ViewerEvent {
2018-04-04 13:47:53 -04:00
// If ViewerEvent.Dur is not a positive value,
// trace viewer handles it as a non-terminating time interval.
// Avoid it by setting the field with a small value.
durationUsec := ctx . time ( ev . Link ) - ctx . time ( ev )
if ev . Link . Ts - ev . Ts <= 0 {
durationUsec = 0.0001 // 0.1 nanoseconds
}
2017-04-14 14:53:09 -04:00
sl := & ViewerEvent {
2015-02-21 21:01:40 +03:00
Name : name ,
Phase : "X" ,
Time : ctx . time ( ev ) ,
2018-04-04 13:47:53 -04:00
Dur : durationUsec ,
2015-02-21 21:01:40 +03:00
Tid : ctx . proc ( ev ) ,
Stack : ctx . stack ( ev . Stk ) ,
2015-01-30 13:31:43 +03:00
EndStack : ctx . stack ( ev . Link . Stk ) ,
2017-04-14 14:53:09 -04:00
}
2018-01-26 10:28:10 -05:00
2018-01-25 15:38:09 -05:00
// grey out non-overlapping events if the event is not a global event (ev.G == 0)
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if ctx . mode & modeTaskOriented != 0 && ev . G != 0 {
2018-01-26 10:28:10 -05:00
// include P information.
if t := ev . Type ; t == trace . EvGoStart || t == trace . EvGoStartLabel {
type Arg struct {
P int
}
sl . Arg = & Arg { P : ev . P }
}
// grey out non-overlapping events.
2018-01-25 15:38:09 -05:00
overlapping := false
for _ , task := range ctx . tasks {
if _ , overlapped := task . overlappingDuration ( ev ) ; overlapped {
overlapping = true
break
}
}
if ! overlapping {
2018-03-06 18:06:50 -05:00
sl . Cname = colorLightGrey
2018-01-25 15:38:09 -05:00
}
}
2017-04-14 14:53:09 -04:00
ctx . emit ( sl )
return sl
2015-01-30 13:31:43 +03:00
}
runtime/trace: rename "Span" with "Region"
"Span" is a commonly used term in many distributed tracing systems
(Dapper, OpenCensus, OpenTracing, ...). They use it to refer to a
period of time, not necessarily tied into execution of underlying
processor, thread, or goroutine, unlike the "Span" of runtime/trace
package.
Since distributed tracing and go runtime execution tracing are
already similar enough to cause confusion, this CL attempts to avoid
using the same word if possible.
"Region" is being used in a certain tracing system to refer to a code
region which is pretty close to what runtime/trace.Span currently
refers to. So, replace that.
https://software.intel.com/en-us/itc-user-and-reference-guide-defining-and-recording-functions-or-regions
This CL also tweaks APIs a bit based on jbd and heschi's comments:
NewContext -> NewTask
and it now returns a Task object that exports End method.
StartSpan -> StartRegion
and it now returns a Region object that exports End method.
Also, changed WithSpan to WithRegion and it now takes func() with no
context. Another thought is to get rid of WithRegion. It is a nice
concept but in practice, it seems problematic (a lot of code churn,
and polluting stack trace). Already, the tracing concept is very low
level, and we hope this API to be used with great care.
Recommended usage will be
defer trace.StartRegion(ctx, "someRegion").End()
Left old APIs untouched in this CL. Once the usage of them are cleaned
up, they will be removed in a separate CL.
Change-Id: I73880635e437f3aad51314331a035dd1459b9f3a
Reviewed-on: https://go-review.googlesource.com/108296
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: JBD <jbd@google.com>
2018-04-19 14:58:42 -04:00
func ( ctx * traceContext ) emitRegion ( s regionDesc ) {
2018-03-14 22:22:31 -04:00
if s . Name == "" {
return
2018-01-24 17:48:28 -05:00
}
runtime/trace: rename "Span" with "Region"
"Span" is a commonly used term in many distributed tracing systems
(Dapper, OpenCensus, OpenTracing, ...). They use it to refer to a
period of time, not necessarily tied into execution of underlying
processor, thread, or goroutine, unlike the "Span" of runtime/trace
package.
Since distributed tracing and go runtime execution tracing are
already similar enough to cause confusion, this CL attempts to avoid
using the same word if possible.
"Region" is being used in a certain tracing system to refer to a code
region which is pretty close to what runtime/trace.Span currently
refers to. So, replace that.
https://software.intel.com/en-us/itc-user-and-reference-guide-defining-and-recording-functions-or-regions
This CL also tweaks APIs a bit based on jbd and heschi's comments:
NewContext -> NewTask
and it now returns a Task object that exports End method.
StartSpan -> StartRegion
and it now returns a Region object that exports End method.
Also, changed WithSpan to WithRegion and it now takes func() with no
context. Another thought is to get rid of WithRegion. It is a nice
concept but in practice, it seems problematic (a lot of code churn,
and polluting stack trace). Already, the tracing concept is very low
level, and we hope this API to be used with great care.
Recommended usage will be
defer trace.StartRegion(ctx, "someRegion").End()
Left old APIs untouched in this CL. Once the usage of them are cleaned
up, they will be removed in a separate CL.
Change-Id: I73880635e437f3aad51314331a035dd1459b9f3a
Reviewed-on: https://go-review.googlesource.com/108296
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: JBD <jbd@google.com>
2018-04-19 14:58:42 -04:00
ctx . regionID ++
regionID := ctx . regionID
2018-04-12 17:06:33 -04:00
2018-03-14 22:22:31 -04:00
id := s . TaskID
2018-01-24 17:48:28 -05:00
scopeID := fmt . Sprintf ( "%x" , id )
sl0 := & ViewerEvent {
runtime/trace: rename "Span" with "Region"
"Span" is a commonly used term in many distributed tracing systems
(Dapper, OpenCensus, OpenTracing, ...). They use it to refer to a
period of time, not necessarily tied into execution of underlying
processor, thread, or goroutine, unlike the "Span" of runtime/trace
package.
Since distributed tracing and go runtime execution tracing are
already similar enough to cause confusion, this CL attempts to avoid
using the same word if possible.
"Region" is being used in a certain tracing system to refer to a code
region which is pretty close to what runtime/trace.Span currently
refers to. So, replace that.
https://software.intel.com/en-us/itc-user-and-reference-guide-defining-and-recording-functions-or-regions
This CL also tweaks APIs a bit based on jbd and heschi's comments:
NewContext -> NewTask
and it now returns a Task object that exports End method.
StartSpan -> StartRegion
and it now returns a Region object that exports End method.
Also, changed WithSpan to WithRegion and it now takes func() with no
context. Another thought is to get rid of WithRegion. It is a nice
concept but in practice, it seems problematic (a lot of code churn,
and polluting stack trace). Already, the tracing concept is very low
level, and we hope this API to be used with great care.
Recommended usage will be
defer trace.StartRegion(ctx, "someRegion").End()
Left old APIs untouched in this CL. Once the usage of them are cleaned
up, they will be removed in a separate CL.
Change-Id: I73880635e437f3aad51314331a035dd1459b9f3a
Reviewed-on: https://go-review.googlesource.com/108296
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: JBD <jbd@google.com>
2018-04-19 14:58:42 -04:00
Category : "Region" ,
2018-03-14 22:22:31 -04:00
Name : s . Name ,
2018-01-24 17:48:28 -05:00
Phase : "b" ,
Time : float64 ( s . firstTimestamp ( ) ) / 1e3 ,
2018-03-15 11:28:07 -04:00
Tid : s . G ,
runtime/trace: rename "Span" with "Region"
"Span" is a commonly used term in many distributed tracing systems
(Dapper, OpenCensus, OpenTracing, ...). They use it to refer to a
period of time, not necessarily tied into execution of underlying
processor, thread, or goroutine, unlike the "Span" of runtime/trace
package.
Since distributed tracing and go runtime execution tracing are
already similar enough to cause confusion, this CL attempts to avoid
using the same word if possible.
"Region" is being used in a certain tracing system to refer to a code
region which is pretty close to what runtime/trace.Span currently
refers to. So, replace that.
https://software.intel.com/en-us/itc-user-and-reference-guide-defining-and-recording-functions-or-regions
This CL also tweaks APIs a bit based on jbd and heschi's comments:
NewContext -> NewTask
and it now returns a Task object that exports End method.
StartSpan -> StartRegion
and it now returns a Region object that exports End method.
Also, changed WithSpan to WithRegion and it now takes func() with no
context. Another thought is to get rid of WithRegion. It is a nice
concept but in practice, it seems problematic (a lot of code churn,
and polluting stack trace). Already, the tracing concept is very low
level, and we hope this API to be used with great care.
Recommended usage will be
defer trace.StartRegion(ctx, "someRegion").End()
Left old APIs untouched in this CL. Once the usage of them are cleaned
up, they will be removed in a separate CL.
Change-Id: I73880635e437f3aad51314331a035dd1459b9f3a
Reviewed-on: https://go-review.googlesource.com/108296
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: JBD <jbd@google.com>
2018-04-19 14:58:42 -04:00
ID : uint64 ( regionID ) ,
2018-01-24 17:48:28 -05:00
Scope : scopeID ,
2018-03-06 18:06:50 -05:00
Cname : colorDeepMagenta ,
2018-01-24 17:48:28 -05:00
}
2018-03-14 22:22:31 -04:00
if s . Start != nil {
sl0 . Stack = ctx . stack ( s . Start . Stk )
2018-01-24 17:48:28 -05:00
}
ctx . emit ( sl0 )
sl1 := & ViewerEvent {
runtime/trace: rename "Span" with "Region"
"Span" is a commonly used term in many distributed tracing systems
(Dapper, OpenCensus, OpenTracing, ...). They use it to refer to a
period of time, not necessarily tied into execution of underlying
processor, thread, or goroutine, unlike the "Span" of runtime/trace
package.
Since distributed tracing and go runtime execution tracing are
already similar enough to cause confusion, this CL attempts to avoid
using the same word if possible.
"Region" is being used in a certain tracing system to refer to a code
region which is pretty close to what runtime/trace.Span currently
refers to. So, replace that.
https://software.intel.com/en-us/itc-user-and-reference-guide-defining-and-recording-functions-or-regions
This CL also tweaks APIs a bit based on jbd and heschi's comments:
NewContext -> NewTask
and it now returns a Task object that exports End method.
StartSpan -> StartRegion
and it now returns a Region object that exports End method.
Also, changed WithSpan to WithRegion and it now takes func() with no
context. Another thought is to get rid of WithRegion. It is a nice
concept but in practice, it seems problematic (a lot of code churn,
and polluting stack trace). Already, the tracing concept is very low
level, and we hope this API to be used with great care.
Recommended usage will be
defer trace.StartRegion(ctx, "someRegion").End()
Left old APIs untouched in this CL. Once the usage of them are cleaned
up, they will be removed in a separate CL.
Change-Id: I73880635e437f3aad51314331a035dd1459b9f3a
Reviewed-on: https://go-review.googlesource.com/108296
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: JBD <jbd@google.com>
2018-04-19 14:58:42 -04:00
Category : "Region" ,
2018-03-14 22:22:31 -04:00
Name : s . Name ,
2018-01-24 17:48:28 -05:00
Phase : "e" ,
Time : float64 ( s . lastTimestamp ( ) ) / 1e3 ,
2018-03-15 11:28:07 -04:00
Tid : s . G ,
runtime/trace: rename "Span" with "Region"
"Span" is a commonly used term in many distributed tracing systems
(Dapper, OpenCensus, OpenTracing, ...). They use it to refer to a
period of time, not necessarily tied into execution of underlying
processor, thread, or goroutine, unlike the "Span" of runtime/trace
package.
Since distributed tracing and go runtime execution tracing are
already similar enough to cause confusion, this CL attempts to avoid
using the same word if possible.
"Region" is being used in a certain tracing system to refer to a code
region which is pretty close to what runtime/trace.Span currently
refers to. So, replace that.
https://software.intel.com/en-us/itc-user-and-reference-guide-defining-and-recording-functions-or-regions
This CL also tweaks APIs a bit based on jbd and heschi's comments:
NewContext -> NewTask
and it now returns a Task object that exports End method.
StartSpan -> StartRegion
and it now returns a Region object that exports End method.
Also, changed WithSpan to WithRegion and it now takes func() with no
context. Another thought is to get rid of WithRegion. It is a nice
concept but in practice, it seems problematic (a lot of code churn,
and polluting stack trace). Already, the tracing concept is very low
level, and we hope this API to be used with great care.
Recommended usage will be
defer trace.StartRegion(ctx, "someRegion").End()
Left old APIs untouched in this CL. Once the usage of them are cleaned
up, they will be removed in a separate CL.
Change-Id: I73880635e437f3aad51314331a035dd1459b9f3a
Reviewed-on: https://go-review.googlesource.com/108296
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: JBD <jbd@google.com>
2018-04-19 14:58:42 -04:00
ID : uint64 ( regionID ) ,
2018-01-24 17:48:28 -05:00
Scope : scopeID ,
2018-03-06 18:06:50 -05:00
Cname : colorDeepMagenta ,
2018-01-24 17:48:28 -05:00
}
2018-03-14 22:22:31 -04:00
if s . End != nil {
sl1 . Stack = ctx . stack ( s . End . Stk )
2018-01-24 17:48:28 -05:00
}
ctx . emit ( sl1 )
}
2016-08-08 17:24:07 -04:00
type heapCountersArg struct {
Allocated uint64
NextGC uint64
}
2015-01-30 13:31:43 +03:00
func ( ctx * traceContext ) emitHeapCounters ( ev * trace . Event ) {
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
if ctx . prevHeapStats == ctx . heapStats {
return
}
2015-01-30 13:31:43 +03:00
diff := uint64 ( 0 )
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
if ctx . heapStats . nextGC > ctx . heapStats . heapAlloc {
diff = ctx . heapStats . nextGC - ctx . heapStats . heapAlloc
2015-01-30 13:31:43 +03:00
}
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if tsWithinRange ( ev . Ts , ctx . startTime , ctx . endTime ) {
ctx . emit ( & ViewerEvent { Name : "Heap" , Phase : "C" , Time : ctx . time ( ev ) , Pid : 1 , Arg : & heapCountersArg { ctx . heapStats . heapAlloc , diff } } )
}
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
ctx . prevHeapStats = ctx . heapStats
2016-08-08 17:24:07 -04:00
}
type goroutineCountersArg struct {
runtime, cmd/trace: track goroutines blocked on GC assists
Currently when a goroutine blocks on a GC assist, it emits a generic
EvGoBlock event. Since assist blocking events and, in particular, the
length of the blocked assist queue, are important for diagnosing GC
behavior, this commit adds a new EvGoBlockGC event for blocking on a
GC assist. The trace viewer uses this event to report a "waiting on
GC" count in the "Goroutines" row. This makes sense because, unlike
other blocked goroutines, these goroutines do have work to do, so
being blocked on a GC assist is quite similar to being in the
"runnable" state, which we also report in the trace viewer.
Change-Id: Ic21a326992606b121ea3d3d00110d8d1fdc7a5ef
Reviewed-on: https://go-review.googlesource.com/30704
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-10-08 18:38:35 -04:00
Running uint64
Runnable uint64
GCWaiting uint64
2015-01-30 13:31:43 +03:00
}
func ( ctx * traceContext ) emitGoroutineCounters ( ev * trace . Event ) {
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
if ctx . prevGstates == ctx . gstates {
return
}
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if tsWithinRange ( ev . Ts , ctx . startTime , ctx . endTime ) {
ctx . emit ( & ViewerEvent { Name : "Goroutines" , Phase : "C" , Time : ctx . time ( ev ) , Pid : 1 , Arg : & goroutineCountersArg { uint64 ( ctx . gstates [ gRunning ] ) , uint64 ( ctx . gstates [ gRunnable ] ) , uint64 ( ctx . gstates [ gWaitingGC ] ) } } )
}
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
ctx . prevGstates = ctx . gstates
2016-08-08 17:24:07 -04:00
}
type threadCountersArg struct {
Running uint64
InSyscall uint64
2015-01-30 13:31:43 +03:00
}
func ( ctx * traceContext ) emitThreadCounters ( ev * trace . Event ) {
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
if ctx . prevThreadStats == ctx . threadStats {
return
}
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if tsWithinRange ( ev . Ts , ctx . startTime , ctx . endTime ) {
ctx . emit ( & ViewerEvent { Name : "Threads" , Phase : "C" , Time : ctx . time ( ev ) , Pid : 1 , Arg : & threadCountersArg {
Running : ctx . threadStats . prunning ,
InSyscall : ctx . threadStats . insyscall } } )
}
cmd/trace: fix goroutine view
Currently, trace processing interleaves state/statistics updates and
emitting trace viewer objects. As a result, if events are being
filtered, either by time or by goroutines, we'll miss those
state/statistics updates. At best, this leads to bad statistics;
however, since we're now strictly checking G state transitions, it
usually leads to a failure to process the trace if there is any
filtering.
Fix this by separating state updates from emitting trace object. State
updates are done before filtering, so we always have correct state
information and statistics. Trace objects are only emitted if we pass
the filter. To determine when we need to emit trace counters, rather
than duplicating the knowledge of which events might modify
statistics, we keep track of the previously emitted counters and emit
a trace counter object whenever these have changed.
Fixes #17719.
Change-Id: Ic66e3ddaef60d1acaaf2ff4c62baa5352799cf99
Reviewed-on: https://go-review.googlesource.com/32810
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>
2016-11-04 11:13:27 -04:00
ctx . prevThreadStats = ctx . threadStats
2015-01-30 13:31:43 +03:00
}
2018-01-26 10:18:16 -05:00
func ( ctx * traceContext ) emitInstant ( ev * trace . Event , name , category string ) {
2018-03-02 15:52:30 -05:00
cname := ""
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if ctx . mode & modeTaskOriented != 0 {
2018-04-24 15:37:42 -04:00
taskID , isUserAnnotation := isUserAnnotationEvent ( ev )
show := false
2018-03-02 15:52:30 -05:00
for _ , task := range ctx . tasks {
2018-04-24 15:37:42 -04:00
if isUserAnnotation && task . id == taskID || task . overlappingInstant ( ev ) {
show = true
2018-03-02 15:52:30 -05:00
break
}
}
// grey out or skip if non-overlapping instant.
2018-04-24 15:37:42 -04:00
if ! show {
if isUserAnnotation {
return // don't display unrelated user annotation events.
2018-03-02 15:52:30 -05:00
}
2018-03-06 18:06:50 -05:00
cname = colorLightGrey
2018-03-02 15:52:30 -05:00
}
}
2015-03-10 20:38:32 +03:00
var arg interface { }
if ev . Type == trace . EvProcStart {
type Arg struct {
ThreadID uint64
}
arg = & Arg { ev . Args [ 0 ] }
}
2018-01-26 10:18:16 -05:00
ctx . emit ( & ViewerEvent {
Name : name ,
Category : category ,
Phase : "I" ,
Scope : "t" ,
Time : ctx . time ( ev ) ,
Tid : ctx . proc ( ev ) ,
Stack : ctx . stack ( ev . Stk ) ,
2018-03-02 15:52:30 -05:00
Cname : cname ,
2018-01-26 10:18:16 -05:00
Arg : arg } )
2015-01-30 13:31:43 +03:00
}
func ( ctx * traceContext ) emitArrow ( ev * trace . Event , name string ) {
if ev . Link == nil {
// The other end of the arrow is not captured in the trace.
// For example, a goroutine was unblocked but was not scheduled before trace stop.
return
}
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
if ctx . mode & modeGoroutineOriented != 0 && ( ! ctx . gs [ ev . Link . G ] || ev . Link . Ts < ctx . startTime || ev . Link . Ts > ctx . endTime ) {
2015-01-30 13:31:43 +03:00
return
}
2015-06-18 16:27:29 +02:00
if ev . P == trace . NetpollP || ev . P == trace . TimerP || ev . P == trace . SyscallP {
// Trace-viewer discards arrows if they don't start/end inside of a slice or instant.
// So emit a fake instant at the start of the arrow.
2018-01-26 10:18:16 -05:00
ctx . emitInstant ( & trace . Event { P : ev . P , Ts : ev . Ts } , "unblock" , "" )
2015-06-18 16:27:29 +02:00
}
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
color := ""
if ctx . mode & modeTaskOriented != 0 {
2018-03-02 15:52:30 -05:00
overlapping := false
// skip non-overlapping arrows.
for _ , task := range ctx . tasks {
if _ , overlapped := task . overlappingDuration ( ev ) ; overlapped {
overlapping = true
break
}
}
if ! overlapping {
return
}
}
2015-01-30 13:31:43 +03:00
ctx . arrowSeq ++
cmd/trace: implement /trace?focustask=<taskid> mode
This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.
The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.
Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png
Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.
Also, it simplifies the traceview generation mode logic.
/trace ---> 0
/trace?goid ---> modeGoroutineOriented
/trace?taskid ---> modeGoroutineOriented|modeTaskOriented
/trace?focustask ---> modeTaskOriented
Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
2018-03-29 17:58:07 -04:00
ctx . emit ( & ViewerEvent { Name : name , Phase : "s" , Tid : ctx . proc ( ev ) , ID : ctx . arrowSeq , Time : ctx . time ( ev ) , Stack : ctx . stack ( ev . Stk ) , Cname : color } )
ctx . emit ( & ViewerEvent { Name : name , Phase : "t" , Tid : ctx . proc ( ev . Link ) , ID : ctx . arrowSeq , Time : ctx . time ( ev . Link ) , Cname : color } )
2015-01-30 13:31:43 +03:00
}
func ( ctx * traceContext ) stack ( stk [ ] * trace . Frame ) int {
return ctx . buildBranch ( ctx . frameTree , stk )
}
// buildBranch builds one branch in the prefix tree rooted at ctx.frameTree.
func ( ctx * traceContext ) buildBranch ( parent frameNode , stk [ ] * trace . Frame ) int {
if len ( stk ) == 0 {
return parent . id
}
last := len ( stk ) - 1
frame := stk [ last ]
stk = stk [ : last ]
node , ok := parent . children [ frame . PC ]
if ! ok {
ctx . frameSeq ++
node . id = ctx . frameSeq
node . children = make ( map [ uint64 ] frameNode )
parent . children [ frame . PC ] = node
2018-02-06 14:34:32 -05:00
ctx . consumer . consumeViewerFrame ( strconv . Itoa ( node . id ) , ViewerFrame { fmt . Sprintf ( "%v:%v" , frame . Fn , frame . Line ) , parent . id } )
2015-01-30 13:31:43 +03:00
}
return ctx . buildBranch ( node , stk )
}
2018-01-22 16:20:30 -05:00
// firstTimestamp returns the timestamp of the first event record.
func firstTimestamp ( ) int64 {
res , _ := parseTrace ( )
if len ( res . Events ) > 0 {
return res . Events [ 0 ] . Ts
}
return 0
}
// lastTimestamp returns the timestamp of the last event record.
func lastTimestamp ( ) int64 {
res , _ := parseTrace ( )
if n := len ( res . Events ) ; n > 1 {
return res . Events [ n - 1 ] . Ts
}
return 0
}
2018-02-06 14:34:32 -05:00
type jsonWriter struct {
w io . Writer
enc * json . Encoder
}
func viewerDataTraceConsumer ( w io . Writer , start , end int64 ) traceConsumer {
frames := make ( map [ string ] ViewerFrame )
enc := json . NewEncoder ( w )
written := 0
index := int64 ( - 1 )
io . WriteString ( w , "{" )
return traceConsumer {
consumeTimeUnit : func ( unit string ) {
io . WriteString ( w , ` "displayTimeUnit": ` )
enc . Encode ( unit )
io . WriteString ( w , "," )
} ,
consumeViewerEvent : func ( v * ViewerEvent , required bool ) {
index ++
if ! required && ( index < start || index > end ) {
// not in the range. Skip!
return
}
if written == 0 {
io . WriteString ( w , ` "traceEvents": [ ` )
}
if written > 0 {
io . WriteString ( w , "," )
}
enc . Encode ( v )
2018-02-06 14:56:30 -05:00
// TODO: get rid of the extra \n inserted by enc.Encode.
// Same should be applied to splittingTraceConsumer.
2018-02-06 14:34:32 -05:00
written ++
} ,
consumeViewerFrame : func ( k string , v ViewerFrame ) {
frames [ k ] = v
} ,
flush : func ( ) {
io . WriteString ( w , ` ], "stackFrames": ` )
enc . Encode ( frames )
io . WriteString ( w , ` } ` )
} ,
}
}
2018-03-06 18:06:50 -05:00
// Mapping from more reasonable color names to the reserved color names in
// https://github.com/catapult-project/catapult/blob/master/tracing/tracing/base/color_scheme.html#L50
// The chrome trace viewer allows only those as cname values.
const (
colorLightMauve string = "thread_state_uninterruptible" // 182, 125, 143
colorOrange = "thread_state_iowait" // 255, 140, 0
colorSeafoamGreen = "thread_state_running" // 126, 200, 148
colorVistaBlue = "thread_state_runnable" // 133, 160, 210
colorTan = "thread_state_unknown" // 199, 155, 125
colorIrisBlue = "background_memory_dump" // 0, 180, 180
colorMidnightBlue = "light_memory_dump" // 0, 0, 180
colorDeepMagenta = "detailed_memory_dump" // 180, 0, 180
colorBlue = "vsync_highlight_color" // 0, 0, 255
colorGrey = "generic_work" // 125, 125, 125
colorGreen = "good" // 0, 125, 0
colorDarkGoldenrod = "bad" // 180, 125, 0
colorPeach = "terrible" // 180, 0, 0
colorBlack = "black" // 0, 0, 0
colorLightGrey = "grey" // 221, 221, 221
colorWhite = "white" // 255, 255, 255
colorYellow = "yellow" // 255, 255, 0
colorOlive = "olive" // 100, 100, 0
colorCornflowerBlue = "rail_response" // 67, 135, 253
colorSunsetOrange = "rail_animation" // 244, 74, 63
colorTangerine = "rail_idle" // 238, 142, 0
colorShamrockGreen = "rail_load" // 13, 168, 97
colorGreenishYellow = "startup" // 230, 230, 0
colorDarkGrey = "heap_dump_stack_frame" // 128, 128, 128
colorTawny = "heap_dump_child_node_arrow" // 204, 102, 0
colorLemon = "cq_build_running" // 255, 255, 119
colorLime = "cq_build_passed" // 153, 238, 102
colorPink = "cq_build_failed" // 238, 136, 136
colorSilver = "cq_build_abandoned" // 187, 187, 187
colorManzGreen = "cq_build_attempt_running" // 222, 222, 75
colorKellyGreen = "cq_build_attempt_passed" // 108, 218, 35
colorFuzzyWuzzyBrown = "cq_build_attempt_failed" // 187, 187, 187
)
