1
// Copyright 2006 The Closure Library Authors. 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
/**
16
 * @fileoverview Definition of the Tracer class and associated classes.
17
 *
18
 * @see ../demos/tracer.html
19
 */
20

21
goog.provide('goog.debug.Trace');
22

23
goog.require('goog.array');
24
goog.require('goog.debug.Logger');
25
goog.require('goog.iter');
26
goog.require('goog.log');
27
goog.require('goog.structs.Map');
28
goog.require('goog.structs.SimplePool');
29

30

31

32
/**
33
 * Class used for singleton goog.debug.Trace.  Used for timing slow points in
34
 * the code. Based on the java Tracer class but optimized for javascript.
35
 * See com.google.common.tracing.Tracer.
36
 * @constructor
37
 * @private
38
 */
39
goog.debug.Trace_ = function() {
40

41
  /**
42
   * Events in order.
43
   * @type {Array<goog.debug.Trace_.Event_>}
44
   * @private
45
   */
46
  this.events_ = [];
47

48
  /**
49
   * Outstanding events that have started but haven't yet ended. The keys are
50
   * numeric ids and the values are goog.debug.Trace_.Event_ objects.
51
   * @type {goog.structs.Map}
52
   * @private
53
   */
54
  this.outstandingEvents_ = new goog.structs.Map();
55

56
  /**
57
   * Start time of the event trace
58
   * @type {number}
59
   * @private
60
   */
61
  this.startTime_ = 0;
62

63
  /**
64
   * Cummulative overhead of calls to startTracer
65
   * @type {number}
66
   * @private
67
   */
68
  this.tracerOverheadStart_ = 0;
69

70
  /**
71
   * Cummulative overhead of calls to endTracer
72
   * @type {number}
73
   * @private
74
   */
75
  this.tracerOverheadEnd_ = 0;
76

77
  /**
78
   * Cummulative overhead of calls to addComment
79
   * @type {number}
80
   * @private
81
   */
82
  this.tracerOverheadComment_ = 0;
83

84
  /**
85
   * Keeps stats on different types of tracers. The keys are strings and the
86
   * values are goog.debug.Stat
87
   * @type {goog.structs.Map}
88
   * @private
89
   */
90
  this.stats_ = new goog.structs.Map();
91

92
  /**
93
   * Total number of traces created in the trace.
94
   * @type {number}
95
   * @private
96
   */
97
  this.tracerCount_ = 0;
98

99
  /**
100
   * Total number of comments created in the trace.
101
   * @type {number}
102
   * @private
103
   */
104
  this.commentCount_ = 0;
105

106
  /**
107
   * Next id to use for the trace.
108
   * @type {number}
109
   * @private
110
   */
111
  this.nextId_ = 1;
112

113
  /**
114
   * A pool for goog.debug.Trace_.Event_ objects so we don't keep creating and
115
   * garbage collecting these (which is very expensive in IE6).
116
   * @private {!goog.structs.SimplePool}
117
   */
118
  this.eventPool_ = new goog.structs.SimplePool(0, 4000);
119
  this.eventPool_.createObject = function() {
120
    return new goog.debug.Trace_.Event_();
121
  };
122

123

124
  /**
125
   * A pool for goog.debug.Trace_.Stat_ objects so we don't keep creating and
126
   * garbage collecting these (which is very expensive in IE6).
127
   * @private {!goog.structs.SimplePool}
128
   */
129
  this.statPool_ = new goog.structs.SimplePool(0, 50);
130
  this.statPool_.createObject = function() {
131
    return new goog.debug.Trace_.Stat_();
132
  };
133

134
  var self = this;
135

136
  /** @private {!goog.structs.SimplePool} */
137
  this.idPool_ = new goog.structs.SimplePool(0, 2000);
138

139
  // TODO(nicksantos): SimplePool is supposed to only return objects.
140
  // Reconcile this so that we don't have to cast to number below.
141
  this.idPool_.createObject = function() { return String(self.nextId_++); };
142
  this.idPool_.disposeObject = function(obj) {};
143

144
  /**
145
   * Default threshold below which a tracer shouldn't be reported
146
   * @type {number}
147
   * @private
148
   */
149
  this.defaultThreshold_ = 3;
150
};
151

152

153
/**
154
 * Logger for the tracer
155
 * @type {goog.log.Logger}
156
 * @private
157
 */
158
goog.debug.Trace_.prototype.logger_ = goog.log.getLogger('goog.debug.Trace');
159

160

161
/**
162
 * Maximum size of the trace before we discard events
163
 * @type {number}
164
 */
165
goog.debug.Trace_.prototype.MAX_TRACE_SIZE = 1000;
166

167

168
/**
169
 * Event type supported by tracer
170
 * @enum {number}
171
 */
172
goog.debug.Trace_.EventType = {
173
  /**
174
   * Start event type
175
   */
176
  START: 0,
177

178
  /**
179
   * Stop event type
180
   */
181
  STOP: 1,
182

183
  /**
184
   * Comment event type
185
   */
186
  COMMENT: 2
187
};
188

189

190

191
/**
192
 * Class to keep track of a stat of a single tracer type. Stores the count
193
 * and cumulative time.
194
 * @constructor
195
 * @private
196
 */
197
goog.debug.Trace_.Stat_ = function() {
198
  /**
199
   * Number of tracers
200
   * @type {number}
201
   */
202
  this.count = 0;
203

204
  /**
205
   * Cumulative time of traces
206
   * @type {number}
207
   */
208
  this.time = 0;
209

210
  /**
211
   * Total number of allocations for this tracer type
212
   * @type {number}
213
   */
214
  this.varAlloc = 0;
215
};
216

217

218
/**
219
 * @type {string|null|undefined}
220
 */
221
goog.debug.Trace_.Stat_.prototype.type;
222

223

224
/**
225
 * @return {string} A string describing the tracer stat.
226
 * @override
227
 */
228
goog.debug.Trace_.Stat_.prototype.toString = function() {
229
  var sb = [];
230
  sb.push(
231
      this.type, ' ', this.count, ' (', Math.round(this.time * 10) / 10,
232
      ' ms)');
233
  if (this.varAlloc) {
234
    sb.push(' [VarAlloc = ', this.varAlloc, ']');
235
  }
236
  return sb.join('');
237
};
238

239

240

241
/**
242
 * Private class used to encapsulate a single event, either the start or stop
243
 * of a tracer.
244
 * @constructor
245
 * @private
246
 */
247
goog.debug.Trace_.Event_ = function() {
248
  // the fields are different for different events - see usage in code
249
};
250

251

252
/**
253
 * @type {string|null|undefined}
254
 */
255
goog.debug.Trace_.Event_.prototype.type;
256

257

258
/**
259
 * Returns a formatted string for the event.
260
 * @param {number} startTime The start time of the trace to generate relative
261
 * times.
262
 * @param {number} prevTime The completion time of the previous event or -1.
263
 * @param {string} indent Extra indent for the message
264
 *     if there was no previous event.
265
 * @return {string} The formatted tracer string.
266
 */
267
goog.debug.Trace_.Event_.prototype.toTraceString = function(
268
    startTime, prevTime, indent) {
269
  var sb = [];
270

271
  if (prevTime == -1) {
272
    sb.push('    ');
273
  } else {
274
    sb.push(goog.debug.Trace_.longToPaddedString_(this.eventTime - prevTime));
275
  }
276

277
  sb.push(' ', goog.debug.Trace_.formatTime_(this.eventTime - startTime));
278
  if (this.eventType == goog.debug.Trace_.EventType.START) {
279
    sb.push(' Start        ');
280
  } else if (this.eventType == goog.debug.Trace_.EventType.STOP) {
281
    sb.push(' Done ');
282
    var delta = this.stopTime - this.startTime;
283
    sb.push(goog.debug.Trace_.longToPaddedString_(delta), ' ms ');
284
  } else {
285
    sb.push(' Comment      ');
286
  }
287

288
  sb.push(indent, this);
289
  if (this.totalVarAlloc > 0) {
290
    sb.push('[VarAlloc ', this.totalVarAlloc, '] ');
291
  }
292
  return sb.join('');
293
};
294

295

296
/**
297
 * @return {string} A string describing the tracer event.
298
 * @override
299
 */
300
goog.debug.Trace_.Event_.prototype.toString = function() {
301
  if (this.type == null) {
302
    return this.comment;
303
  } else {
304
    return '[' + this.type + '] ' + this.comment;
305
  }
306
};
307

308

309
/**
310
 * Add the ability to explicitly set the start time. This is useful for example
311
 * for measuring initial load time where you can set a variable as soon as the
312
 * main page of the app is loaded and then later call this function when the
313
 * Tracer code has been loaded.
314
 * @param {number} startTime The start time to set.
315
 */
316
goog.debug.Trace_.prototype.setStartTime = function(startTime) {
317
  this.startTime_ = startTime;
318
};
319

320

321
/**
322
 * Initializes and resets the current trace
323
 * @param {number} defaultThreshold The default threshold below which the
324
 * tracer output will be suppressed. Can be overridden on a per-Tracer basis.
325
 */
326
goog.debug.Trace_.prototype.initCurrentTrace = function(defaultThreshold) {
327
  this.reset(defaultThreshold);
328
};
329

330

331
/**
332
 * Clears the current trace
333
 */
334
goog.debug.Trace_.prototype.clearCurrentTrace = function() {
335
  this.reset(0);
336
};
337

338

339
/**
340
 * Resets the trace.
341
 * @param {number} defaultThreshold The default threshold below which the
342
 * tracer output will be suppressed. Can be overridden on a per-Tracer basis.
343
 */
344
goog.debug.Trace_.prototype.reset = function(defaultThreshold) {
345
  this.defaultThreshold_ = defaultThreshold;
346

347
  this.releaseEvents_();
348
  this.outstandingEvents_.clear();
349
  this.startTime_ = goog.debug.Trace_.now();
350
  this.tracerOverheadStart_ = 0;
351
  this.tracerOverheadEnd_ = 0;
352
  this.tracerOverheadComment_ = 0;
353
  this.tracerCount_ = 0;
354
  this.commentCount_ = 0;
355

356
  var keys = this.stats_.getKeys();
357
  for (var i = 0; i < keys.length; i++) {
358
    var key = keys[i];
359
    var stat = this.stats_.get(key);
360
    stat.count = 0;
361
    stat.time = 0;
362
    stat.varAlloc = 0;
363
    this.statPool_.releaseObject(/** @type {Object} */ (stat));
364
  }
365
  this.stats_.clear();
366
};
367

368

369
/**
370
 * @private
371
 */
372
goog.debug.Trace_.prototype.releaseEvents_ = function() {
373
  for (var i = 0; i < this.events_.length; i++) {
374
    var event = this.events_[i];
375
    if (event.id) {
376
      this.idPool_.releaseObject(event.id);
377
    }
378
    this.eventPool_.releaseObject(event);
379
  }
380
  this.events_.length = 0;
381
};
382

383

384
/**
385
 * Starts a tracer
386
 * @param {string} comment A comment used to identify the tracer. Does not
387
 *     need to be unique.
388
 * @param {string=} opt_type Type used to identify the tracer. If a Trace is
389
 *     given a type (the first argument to the constructor) and multiple Traces
390
 *     are done on that type then a "TOTAL line will be produced showing the
391
 *     total number of traces and the sum of the time
392
 *     ("TOTAL Database 2 (37 ms)" in our example). These traces should be
393
 *     mutually exclusive or else the sum won't make sense (the time will
394
 *     be double counted if the second starts before the first ends).
395
 * @return {number} The identifier for the tracer that should be passed to the
396
 *     the stopTracer method.
397
 */
398
goog.debug.Trace_.prototype.startTracer = function(comment, opt_type) {
399
  var tracerStartTime = goog.debug.Trace_.now();
400
  var varAlloc = this.getTotalVarAlloc();
401
  var outstandingEventCount = this.outstandingEvents_.getCount();
402
  if (this.events_.length + outstandingEventCount > this.MAX_TRACE_SIZE) {
403
    goog.log.warning(
404
        this.logger_, 'Giant thread trace. Clearing to avoid memory leak.');
405
    // This is the more likely case. This usually means that we
406
    // either forgot to clear the trace or else we are performing a
407
    // very large number of events
408
    if (this.events_.length > this.MAX_TRACE_SIZE / 2) {
409
      this.releaseEvents_();
410
    }
411

412
    // This is less likely and probably indicates that a lot of traces
413
    // aren't being closed. We want to avoid unnecessarily clearing
414
    // this though in case the events do eventually finish.
415
    if (outstandingEventCount > this.MAX_TRACE_SIZE / 2) {
416
      this.outstandingEvents_.clear();
417
    }
418
  }
419

420
  goog.debug.Logger.logToProfilers('Start : ' + comment);
421

422
  /** @const */
423
  var event =
424
      /** @type {!goog.debug.Trace_.Event_} */ (this.eventPool_.getObject());
425
  event.totalVarAlloc = varAlloc;
426
  event.eventType = goog.debug.Trace_.EventType.START;
427
  event.id = Number(this.idPool_.getObject());
428
  event.comment = comment;
429
  event.type = opt_type;
430
  this.events_.push(event);
431
  this.outstandingEvents_.set(String(event.id), event);
432
  this.tracerCount_++;
433
  var now = goog.debug.Trace_.now();
434
  event.startTime = event.eventTime = now;
435
  this.tracerOverheadStart_ += now - tracerStartTime;
436
  return event.id;
437
};
438

439

440
/**
441
 * Stops a tracer
442
 * @param {number|undefined|null} id The id of the tracer that is ending.
443
 * @param {number=} opt_silenceThreshold Threshold below which the tracer is
444
 *    silenced.
445
 * @return {?number} The elapsed time for the tracer or null if the tracer
446
 *    identitifer was not recognized.
447
 */
448
goog.debug.Trace_.prototype.stopTracer = function(id, opt_silenceThreshold) {
449
  // this used to call goog.isDef(opt_silenceThreshold) but that causes an
450
  // object allocation in IE for some reason (doh!). The following code doesn't
451
  // cause an allocation
452
  var now = goog.debug.Trace_.now();
453
  var silenceThreshold;
454
  if (opt_silenceThreshold === 0) {
455
    silenceThreshold = 0;
456
  } else if (opt_silenceThreshold) {
457
    silenceThreshold = opt_silenceThreshold;
458
  } else {
459
    silenceThreshold = this.defaultThreshold_;
460
  }
461

462
  var startEvent = this.outstandingEvents_.get(String(id));
463
  if (startEvent == null) {
464
    return null;
465
  }
466

467
  this.outstandingEvents_.remove(String(id));
468

469
  var stopEvent;
470
  var elapsed = now - startEvent.startTime;
471
  if (elapsed < silenceThreshold) {
472
    var count = this.events_.length;
473
    for (var i = count - 1; i >= 0; i--) {
474
      var nextEvent = this.events_[i];
475
      if (nextEvent == startEvent) {
476
        this.events_.splice(i, 1);
477
        this.idPool_.releaseObject(startEvent.id);
478
        this.eventPool_.releaseObject(/** @type {Object} */ (startEvent));
479
        break;
480
      }
481
    }
482

483
  } else {
484
    stopEvent =
485
        /** @type {goog.debug.Trace_.Event_} */ (this.eventPool_.getObject());
486
    stopEvent.eventType = goog.debug.Trace_.EventType.STOP;
487
    stopEvent.startTime = startEvent.startTime;
488
    stopEvent.comment = startEvent.comment;
489
    stopEvent.type = startEvent.type;
490
    stopEvent.stopTime = stopEvent.eventTime = now;
491

492
    this.events_.push(stopEvent);
493
  }
494

495
  var type = startEvent.type;
496
  var stat = null;
497
  if (type) {
498
    stat = this.getStat_(type);
499
    stat.count++;
500
    stat.time += elapsed;
501
  }
502
  if (stopEvent) {
503
    goog.debug.Logger.logToProfilers('Stop : ' + stopEvent.comment);
504

505
    stopEvent.totalVarAlloc = this.getTotalVarAlloc();
506

507
    if (stat) {
508
      stat.varAlloc += (stopEvent.totalVarAlloc - startEvent.totalVarAlloc);
509
    }
510
  }
511
  var tracerFinishTime = goog.debug.Trace_.now();
512
  this.tracerOverheadEnd_ += tracerFinishTime - now;
513
  return elapsed;
514
};
515

516

517
/**
518
 * Sets the ActiveX object that can be used to get GC tracing in IE6.
519
 * @param {Object} gcTracer GCTracer ActiveX object.
520
 */
521
goog.debug.Trace_.prototype.setGcTracer = function(gcTracer) {
522
  this.gcTracer_ = gcTracer;
523
};
524

525

526
/**
527
 * Returns the total number of allocations since the GC stats were reset. Only
528
 * works in IE.
529
 * @return {number} The number of allocaitons or -1 if not supported.
530
 */
531
goog.debug.Trace_.prototype.getTotalVarAlloc = function() {
532
  var gcTracer = this.gcTracer_;
533
  // isTracing is defined on the ActiveX object.
534
  if (gcTracer && gcTracer['isTracing']()) {
535
    return gcTracer['totalVarAlloc'];
536
  }
537
  return -1;
538
};
539

540

541
/**
542
 * Adds a comment to the trace. Makes it possible to see when a specific event
543
 * happened in relation to the traces.
544
 * @param {string} comment A comment that is inserted into the trace.
545
 * @param {?string=} opt_type Type used to identify the tracer. If a comment is
546
 *     given a type and multiple comments are done on that type then a "TOTAL
547
 *     line will be produced showing the total number of comments of that type.
548
 * @param {?number=} opt_timeStamp The timestamp to insert the comment. If not
549
 *    specified, the current time wil be used.
550
 */
551
goog.debug.Trace_.prototype.addComment = function(
552
    comment, opt_type, opt_timeStamp) {
553
  var now = goog.debug.Trace_.now();
554
  var timeStamp = opt_timeStamp ? opt_timeStamp : now;
555

556
  var eventComment =
557
      /** @type {goog.debug.Trace_.Event_} */ (this.eventPool_.getObject());
558
  eventComment.eventType = goog.debug.Trace_.EventType.COMMENT;
559
  eventComment.eventTime = timeStamp;
560
  eventComment.type = opt_type;
561
  eventComment.comment = comment;
562
  eventComment.totalVarAlloc = this.getTotalVarAlloc();
563
  this.commentCount_++;
564

565
  if (opt_timeStamp) {
566
    var numEvents = this.events_.length;
567
    for (var i = 0; i < numEvents; i++) {
568
      var event = this.events_[i];
569
      var eventTime = event.eventTime;
570

571
      if (eventTime > timeStamp) {
572
        goog.array.insertAt(this.events_, eventComment, i);
573
        break;
574
      }
575
    }
576
    if (i == numEvents) {
577
      this.events_.push(eventComment);
578
    }
579
  } else {
580
    this.events_.push(eventComment);
581
  }
582

583
  var type = eventComment.type;
584
  if (type) {
585
    var stat = this.getStat_(type);
586
    stat.count++;
587
  }
588

589
  this.tracerOverheadComment_ += goog.debug.Trace_.now() - now;
590
};
591

592

593
/**
594
 * Gets a stat object for a particular type. The stat object is created if it
595
 * hasn't yet been.
596
 * @param {string} type The type of stat.
597
 * @return {goog.debug.Trace_.Stat_} The stat object.
598
 * @private
599
 */
600
goog.debug.Trace_.prototype.getStat_ = function(type) {
601
  var stat = this.stats_.get(type);
602
  if (!stat) {
603
    stat = /** @type {goog.debug.Trace_.Event_} */ (this.statPool_.getObject());
604
    stat.type = type;
605
    this.stats_.set(type, stat);
606
  }
607
  return /** @type {goog.debug.Trace_.Stat_} */ (stat);
608
};
609

610

611
/**
612
 * Returns a formatted string for the current trace
613
 * @return {string} A formatted string that shows the timings of the current
614
 *     trace.
615
 */
616
goog.debug.Trace_.prototype.getFormattedTrace = function() {
617
  return this.toString();
618
};
619

620

621
/**
622
 * Returns a formatted string that describes the thread trace.
623
 * @return {string} A formatted string.
624
 * @override
625
 */
626
goog.debug.Trace_.prototype.toString = function() {
627
  var sb = [];
628
  var etime = -1;
629
  var indent = [];
630
  for (var i = 0; i < this.events_.length; i++) {
631
    var e = this.events_[i];
632
    if (e.eventType == goog.debug.Trace_.EventType.STOP) {
633
      indent.pop();
634
    }
635
    sb.push(' ', e.toTraceString(this.startTime_, etime, indent.join('')));
636
    etime = e.eventTime;
637
    sb.push('\n');
638
    if (e.eventType == goog.debug.Trace_.EventType.START) {
639
      indent.push('|  ');
640
    }
641
  }
642

643
  if (this.outstandingEvents_.getCount() != 0) {
644
    var now = goog.debug.Trace_.now();
645

646
    sb.push(' Unstopped timers:\n');
647
    goog.iter.forEach(this.outstandingEvents_, function(startEvent) {
648
      sb.push(
649
          '  ', startEvent, ' (', now - startEvent.startTime,
650
          ' ms, started at ',
651
          goog.debug.Trace_.formatTime_(startEvent.startTime), ')\n');
652
    });
653
  }
654

655
  var statKeys = this.stats_.getKeys();
656
  for (var i = 0; i < statKeys.length; i++) {
657
    var stat = this.stats_.get(statKeys[i]);
658
    if (stat.count > 1) {
659
      sb.push(' TOTAL ', stat, '\n');
660
    }
661
  }
662

663
  sb.push(
664
      'Total tracers created ', this.tracerCount_, '\n',
665
      'Total comments created ', this.commentCount_, '\n', 'Overhead start: ',
666
      this.tracerOverheadStart_, ' ms\n', 'Overhead end: ',
667
      this.tracerOverheadEnd_, ' ms\n', 'Overhead comment: ',
668
      this.tracerOverheadComment_, ' ms\n');
669

670
  return sb.join('');
671
};
672

673

674
/**
675
 * Converts 'v' to a string and pads it with up to 3 spaces for
676
 * improved alignment. TODO there must be a better way
677
 * @param {number} v A number.
678
 * @return {string} A padded string.
679
 * @private
680
 */
681
goog.debug.Trace_.longToPaddedString_ = function(v) {
682
  v = Math.round(v);
683
  // todo (pupius) - there should be a generic string in goog.string for this
684
  var space = '';
685
  if (v < 1000) space = ' ';
686
  if (v < 100) space = '  ';
687
  if (v < 10) space = '   ';
688
  return space + v;
689
};
690

691

692
/**
693
 * Return the sec.ms part of time (if time = "20:06:11.566",  "11.566
694
 * @param {number} time The time in MS.
695
 * @return {string} A formatted string as sec.ms'.
696
 * @private
697
 */
698
goog.debug.Trace_.formatTime_ = function(time) {
699
  time = Math.round(time);
700
  var sec = (time / 1000) % 60;
701
  var ms = time % 1000;
702

703
  // TODO their must be a nicer way to get zero padded integers
704
  return String(100 + sec).substring(1, 3) + '.' +
705
      String(1000 + ms).substring(1, 4);
706
};
707

708

709
/**
710
 * Returns the current time. Done through a wrapper function so it can be
711
 * overridden by application code. Gmail has an ActiveX extension that provides
712
 * higher precision timing info.
713
 * @return {number} The current time in milliseconds.
714
 */
715
goog.debug.Trace_.now = function() {
716
  return goog.now();
717
};
718

719

720
/**
721
 * Singleton trace object
722
 * @type {goog.debug.Trace_}
723
 */
724
goog.debug.Trace = new goog.debug.Trace_();
725

726