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 "android/soong/ui/status" 35) 36 37type Thread uint64 38 39const ( 40 MainThread = Thread(iota) 41 MaxInitThreads = Thread(iota) 42) 43 44type Tracer interface { 45 Begin(name string, thread Thread) 46 End(thread Thread) 47 Complete(name string, thread Thread, begin, end uint64) 48 49 ImportMicrofactoryLog(filename string) 50 51 StatusTracer() status.StatusOutput 52 53 NewThread(name string) Thread 54} 55 56type tracerImpl struct { 57 lock sync.Mutex 58 log logger.Logger 59 60 buf bytes.Buffer 61 file *os.File 62 w io.WriteCloser 63 64 firstEvent bool 65 nextTid uint64 66} 67 68var _ Tracer = &tracerImpl{} 69 70type viewerEvent struct { 71 Name string `json:"name,omitempty"` 72 Phase string `json:"ph"` 73 Scope string `json:"s,omitempty"` 74 Time uint64 `json:"ts"` 75 Dur uint64 `json:"dur,omitempty"` 76 Pid uint64 `json:"pid"` 77 Tid uint64 `json:"tid"` 78 ID uint64 `json:"id,omitempty"` 79 Arg interface{} `json:"args,omitempty"` 80} 81 82type nameArg struct { 83 Name string `json:"name"` 84} 85 86type nopCloser struct{ io.Writer } 87 88func (nopCloser) Close() error { return nil } 89 90// New creates a new Tracer, storing log in order to log errors later. 91// Events are buffered in memory until SetOutput is called. 92func New(log logger.Logger) *tracerImpl { 93 ret := &tracerImpl{ 94 log: log, 95 96 firstEvent: true, 97 nextTid: uint64(MaxInitThreads), 98 } 99 ret.startBuffer() 100 101 return ret 102} 103 104func (t *tracerImpl) startBuffer() { 105 t.w = nopCloser{&t.buf} 106 fmt.Fprintln(t.w, "[") 107 108 t.defineThread(MainThread, "main") 109} 110 111func (t *tracerImpl) close() { 112 if t.file != nil { 113 fmt.Fprintln(t.w, "]") 114 115 if err := t.w.Close(); err != nil { 116 t.log.Println("Error closing trace writer:", err) 117 } 118 119 if err := t.file.Close(); err != nil { 120 t.log.Println("Error closing trace file:", err) 121 } 122 t.file = nil 123 t.startBuffer() 124 } 125} 126 127// SetOutput creates the output file (rotating old files). 128func (t *tracerImpl) SetOutput(filename string) { 129 t.lock.Lock() 130 defer t.lock.Unlock() 131 132 t.close() 133 134 // chrome://tracing requires that compressed trace files end in .gz 135 if !strings.HasSuffix(filename, ".gz") { 136 filename += ".gz" 137 } 138 139 f, err := logger.CreateFileWithRotation(filename, 5) 140 if err != nil { 141 t.log.Println("Failed to create trace file:", err) 142 return 143 } 144 // Save the file, since closing the gzip Writer doesn't close the 145 // underlying file. 146 t.file = f 147 t.w = gzip.NewWriter(f) 148 149 // Write out everything that happened since the start 150 if _, err := io.Copy(t.w, &t.buf); err != nil { 151 t.log.Println("Failed to write trace buffer to file:", err) 152 } 153 t.buf = bytes.Buffer{} 154} 155 156// Close closes the output file. Any future events will be buffered until the 157// next call to SetOutput. 158func (t *tracerImpl) Close() { 159 t.lock.Lock() 160 defer t.lock.Unlock() 161 162 t.close() 163} 164 165func (t *tracerImpl) writeEvent(event *viewerEvent) { 166 t.lock.Lock() 167 defer t.lock.Unlock() 168 169 t.writeEventLocked(event) 170} 171 172func (t *tracerImpl) writeEventLocked(event *viewerEvent) { 173 bytes, err := json.Marshal(event) 174 if err != nil { 175 t.log.Println("Failed to marshal event:", err) 176 t.log.Verbosef("Event: %#v", event) 177 return 178 } 179 180 if !t.firstEvent { 181 fmt.Fprintln(t.w, ",") 182 } else { 183 t.firstEvent = false 184 } 185 186 if _, err = t.w.Write(bytes); err != nil { 187 t.log.Println("Trace write error:", err) 188 } 189} 190 191func (t *tracerImpl) defineThread(thread Thread, name string) { 192 t.writeEventLocked(&viewerEvent{ 193 Name: "thread_name", 194 Phase: "M", 195 Pid: 0, 196 Tid: uint64(thread), 197 Arg: &nameArg{ 198 Name: name, 199 }, 200 }) 201} 202 203// NewThread returns a new Thread with an unused tid, writing the name out to 204// the trace file. 205func (t *tracerImpl) NewThread(name string) Thread { 206 t.lock.Lock() 207 defer t.lock.Unlock() 208 209 ret := Thread(t.nextTid) 210 t.nextTid += 1 211 212 t.defineThread(ret, name) 213 return ret 214} 215 216// Begin starts a new Duration Event. More than one Duration Event may be active 217// at a time on each Thread, but they're nested. 218func (t *tracerImpl) Begin(name string, thread Thread) { 219 t.writeEvent(&viewerEvent{ 220 Name: name, 221 Phase: "B", 222 Time: uint64(time.Now().UnixNano()) / 1000, 223 Pid: 0, 224 Tid: uint64(thread), 225 }) 226} 227 228// End finishes the most recent active Duration Event on the thread. 229func (t *tracerImpl) End(thread Thread) { 230 t.writeEvent(&viewerEvent{ 231 Phase: "E", 232 Time: uint64(time.Now().UnixNano()) / 1000, 233 Pid: 0, 234 Tid: uint64(thread), 235 }) 236} 237 238// Complete writes a Complete Event, which are like Duration Events, but include 239// a begin and end timestamp in the same event. 240func (t *tracerImpl) Complete(name string, thread Thread, begin, end uint64) { 241 t.writeEvent(&viewerEvent{ 242 Name: name, 243 Phase: "X", 244 Time: begin / 1000, 245 Dur: (end - begin) / 1000, 246 Pid: 0, 247 Tid: uint64(thread), 248 }) 249} 250