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