1// Copyright 2017 Google Inc. All rights reserved. 2// 3// Licensed under the Apache License, Version 2.0 (the "License"); 4// you may not use this file except in compliance with the License. 5// You may obtain a copy of the License at 6// 7// http://www.apache.org/licenses/LICENSE-2.0 8// 9// Unless required by applicable law or agreed to in writing, software 10// distributed under the License is distributed on an "AS IS" BASIS, 11// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 12// See the License for the specific language governing permissions and 13// limitations under the License. 14 15// This package implements a trace file writer, whose files can be opened in 16// chrome://tracing. 17// 18// It implements the JSON Array Format defined here: 19// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit 20package tracer 21 22import ( 23 "bytes" 24 "compress/gzip" 25 "encoding/json" 26 "fmt" 27 "io" 28 "os" 29 "strings" 30 "sync" 31 "time" 32 33 "android/soong/ui/logger" 34) 35 36type Thread uint64 37 38const ( 39 MainThread = Thread(iota) 40 MaxInitThreads = Thread(iota) 41) 42 43type Tracer interface { 44 Begin(name string, thread Thread) 45 End(thread Thread) 46 Complete(name string, thread Thread, begin, end uint64) 47 48 ImportNinjaLog(thread Thread, filename string, startOffset time.Time) 49} 50 51type tracerImpl struct { 52 lock sync.Mutex 53 log logger.Logger 54 55 buf bytes.Buffer 56 file *os.File 57 w io.WriteCloser 58 59 firstEvent bool 60 nextTid uint64 61} 62 63var _ Tracer = &tracerImpl{} 64 65type viewerEvent struct { 66 Name string `json:"name,omitempty"` 67 Phase string `json:"ph"` 68 Scope string `json:"s,omitempty"` 69 Time uint64 `json:"ts"` 70 Dur uint64 `json:"dur,omitempty"` 71 Pid uint64 `json:"pid"` 72 Tid uint64 `json:"tid"` 73 ID uint64 `json:"id,omitempty"` 74 Arg interface{} `json:"args,omitempty"` 75} 76 77type nameArg struct { 78 Name string `json:"name"` 79} 80 81type nopCloser struct{ io.Writer } 82 83func (nopCloser) Close() error { return nil } 84 85// New creates a new Tracer, storing log in order to log errors later. 86// Events are buffered in memory until SetOutput is called. 87func New(log logger.Logger) *tracerImpl { 88 ret := &tracerImpl{ 89 log: log, 90 91 firstEvent: true, 92 nextTid: uint64(MaxInitThreads), 93 } 94 ret.startBuffer() 95 96 return ret 97} 98 99func (t *tracerImpl) startBuffer() { 100 t.w = nopCloser{&t.buf} 101 fmt.Fprintln(t.w, "[") 102 103 t.defineThread(MainThread, "main") 104} 105 106func (t *tracerImpl) close() { 107 if t.file != nil { 108 fmt.Fprintln(t.w, "]") 109 110 if err := t.w.Close(); err != nil { 111 t.log.Println("Error closing trace writer:", err) 112 } 113 114 if err := t.file.Close(); err != nil { 115 t.log.Println("Error closing trace file:", err) 116 } 117 t.file = nil 118 t.startBuffer() 119 } 120} 121 122// SetOutput creates the output file (rotating old files). 123func (t *tracerImpl) SetOutput(filename string) { 124 t.lock.Lock() 125 defer t.lock.Unlock() 126 127 t.close() 128 129 // chrome://tracing requires that compressed trace files end in .gz 130 if !strings.HasSuffix(filename, ".gz") { 131 filename += ".gz" 132 } 133 134 f, err := logger.CreateFileWithRotation(filename, 5) 135 if err != nil { 136 t.log.Println("Failed to create trace file:", err) 137 return 138 } 139 // Save the file, since closing the gzip Writer doesn't close the 140 // underlying file. 141 t.file = f 142 t.w = gzip.NewWriter(f) 143 144 // Write out everything that happened since the start 145 if _, err := io.Copy(t.w, &t.buf); err != nil { 146 t.log.Println("Failed to write trace buffer to file:", err) 147 } 148 t.buf = bytes.Buffer{} 149} 150 151// Close closes the output file. Any future events will be buffered until the 152// next call to SetOutput. 153func (t *tracerImpl) Close() { 154 t.lock.Lock() 155 defer t.lock.Unlock() 156 157 t.close() 158} 159 160func (t *tracerImpl) writeEvent(event *viewerEvent) { 161 t.lock.Lock() 162 defer t.lock.Unlock() 163 164 t.writeEventLocked(event) 165} 166 167func (t *tracerImpl) writeEventLocked(event *viewerEvent) { 168 bytes, err := json.Marshal(event) 169 if err != nil { 170 t.log.Println("Failed to marshal event:", err) 171 t.log.Verbosef("Event: %#v", event) 172 return 173 } 174 175 if !t.firstEvent { 176 fmt.Fprintln(t.w, ",") 177 } else { 178 t.firstEvent = false 179 } 180 181 if _, err = t.w.Write(bytes); err != nil { 182 t.log.Println("Trace write error:", err) 183 } 184} 185 186func (t *tracerImpl) defineThread(thread Thread, name string) { 187 t.writeEventLocked(&viewerEvent{ 188 Name: "thread_name", 189 Phase: "M", 190 Pid: 0, 191 Tid: uint64(thread), 192 Arg: &nameArg{ 193 Name: name, 194 }, 195 }) 196} 197 198// NewThread returns a new Thread with an unused tid, writing the name out to 199// the trace file. 200func (t *tracerImpl) NewThread(name string) Thread { 201 t.lock.Lock() 202 defer t.lock.Unlock() 203 204 ret := Thread(t.nextTid) 205 t.nextTid += 1 206 207 t.defineThread(ret, name) 208 return ret 209} 210 211// Begin starts a new Duration Event. More than one Duration Event may be active 212// at a time on each Thread, but they're nested. 213func (t *tracerImpl) Begin(name string, thread Thread) { 214 t.writeEvent(&viewerEvent{ 215 Name: name, 216 Phase: "B", 217 Time: uint64(time.Now().UnixNano()) / 1000, 218 Pid: 0, 219 Tid: uint64(thread), 220 }) 221} 222 223// End finishes the most recent active Duration Event on the thread. 224func (t *tracerImpl) End(thread Thread) { 225 t.writeEvent(&viewerEvent{ 226 Phase: "E", 227 Time: uint64(time.Now().UnixNano()) / 1000, 228 Pid: 0, 229 Tid: uint64(thread), 230 }) 231} 232 233// Complete writes a Complete Event, which are like Duration Events, but include 234// a begin and end timestamp in the same event. 235func (t *tracerImpl) Complete(name string, thread Thread, begin, end uint64) { 236 t.writeEvent(&viewerEvent{ 237 Name: name, 238 Phase: "X", 239 Time: begin / 1000, 240 Dur: (end - begin) / 1000, 241 Pid: 0, 242 Tid: uint64(thread), 243 }) 244} 245