Skip to content

Commit 568ee13

Browse files
diemoldiemol
committed
Refactor logging to use Logger utility for error and debug messages
1 parent 1b2d600 commit 568ee13

14 files changed

Lines changed: 270 additions & 67 deletions

File tree

‎README.md‎

Lines changed: 54 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,59 @@ To install the package to your project, run:
1313
$ npm install --save tracelib
1414
```
1515

16+
# Debug Mode
17+
18+
Tracelib includes detailed logging for troubleshooting trace parsing and FPS calculation.
19+
Debug mode is **disabled by default** to keep console output clean.
20+
21+
## Enable Debug Logging
22+
23+
### Via Constructor Option
24+
25+
```js
26+
import Tracelib from 'tracelib'
27+
import TRACE_LOG from './trace.json'
28+
29+
const tasks = new Tracelib(TRACE_LOG, { debug: true })
30+
const fps = tasks.getFPS()
31+
// Debug output will be logged to console
32+
```
33+
34+
### Via Environment Variable
35+
36+
```bash
37+
# Using TRACELIB_DEBUG
38+
TRACELIB_DEBUG=true node your-script.js
39+
40+
# Or using DEBUG (if you use the debug pattern)
41+
DEBUG=tracelib node your-script.js
42+
```
43+
44+
### Programmatically
45+
46+
```js
47+
import Tracelib from 'tracelib'
48+
49+
// Enable debug mode globally
50+
Tracelib.setDebugMode(true)
51+
52+
const tasks = new Tracelib(TRACE_LOG)
53+
const fps = tasks.getFPS()
54+
55+
// Disable debug mode
56+
Tracelib.setDebugMode(false)
57+
```
58+
59+
### Check Debug Status
60+
61+
```js
62+
import Tracelib from 'tracelib'
63+
64+
if (Tracelib.isDebugEnabled()) {
65+
console.log('Debug mode is ON')
66+
}
67+
```
68+
1669
# Usage
1770

1871
## `getSummary`
@@ -219,7 +272,7 @@ console.log(detail)
219272
* times: [ 49970556.092, ..., 49972763.552 ],
220273
* values: [1, ..., 5]
221274
* },
222-
* range: {
275+
* range: {
223276
* times: [ 289959855.634, 289961229.717 ],
224277
* values: [ 289959855.634, 289961229.717 ]
225278
* }

‎devtools/cpuProfileDataModel/index.ts‎

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ import ProfileNode from '../profileTreeModel/profileNode'
33
import ProfileTreeModel from '../profileTreeModel'
44
import { lowerBound, stableSort } from '../utils'
55
import { Profile } from '../types'
6+
import Logger from '../../src/logger'
67

78
export default class CPUProfileDataModel extends ProfileTreeModel {
89
public profileStartTime: number
@@ -144,10 +145,9 @@ export default class CPUProfileDataModel extends ProfileTreeModel {
144145
return
145146
}
146147

147-
console.assert(
148-
Boolean(samples),
149-
'Error: Neither hitCount nor samples are present in profile.'
150-
)
148+
if (!samples) {
149+
Logger.error('CPUProfileDataModel', 'Error: Neither hitCount nor samples are present in profile.')
150+
}
151151
for (let i = 0; i < nodes.length; ++i) {
152152
nodes[i].hitCount = 0
153153
}
@@ -365,7 +365,7 @@ export default class CPUProfileDataModel extends ProfileTreeModel {
365365
}
366366

367367
if (count) {
368-
console.warn(`DevTools: CPU profile parser is fixing ${count} missing samples.`)
368+
Logger.debug('CPUProfileDataModel', `CPU profile parser is fixing ${count} missing samples.`)
369369
}
370370
}
371371

‎devtools/loader.ts‎

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
import TracingModel from './tracingModel/index'
22
import PerformanceModel from './timelineModel/performanceModel'
3+
import Logger from '../src/logger'
34

45
export default class TimelineLoader {
56
private _tracingModel: TracingModel
@@ -12,17 +13,20 @@ export default class TimelineLoader {
1213
}
1314

1415
/**
15-
* @param {string} data
16-
*/
16+
* @param {string} data
17+
*/
1718
public init(): void {
19+
Logger.debug('TimelineLoader', 'Initializing with trace log')
1820
try {
1921
this._tracingModel.addEvents(this._traceLog)
2022
} catch (e) {
2123
console.error('Malformed timeline data: %s', e.toString())
2224
return
2325
}
2426
this._tracingModel.tracingComplete()
27+
Logger.debug('TimelineLoader', 'TracingModel complete, creating PerformanceModel')
2528
this.performanceModel = new PerformanceModel()
2629
this.performanceModel.setTracingModel(this._tracingModel)
30+
Logger.debug('TimelineLoader', 'Initialization complete')
2731
}
28-
};
32+
}

‎devtools/timelineModel/index.ts‎

Lines changed: 11 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,7 @@ import {
2727
} from '../types'
2828

2929
import { upperBound, stableSort, pushAll, mergeOrIntersect, lowerBound } from '../utils'
30+
import Logger from '../../src/logger'
3031

3132
export const WorkerThreadName = 'DedicatedWorker thread'
3233
export const WorkerThreadNameLegacy = 'DedicatedWorker Thread'
@@ -494,7 +495,9 @@ export default class TimelineModel {
494495
} else if (event.name === DevToolsMetadataEvent.TracingSessionIdForWorker) {
495496
workersDevToolsMetadataEvents.push(event)
496497
} else if (event.name === DevToolsMetadataEvent.TracingStartedInBrowser) {
497-
console.assert(!this._mainFrameNodeId, 'Multiple sessions in trace')
498+
if (this._mainFrameNodeId) {
499+
Logger.error('TimelineModel', 'Multiple sessions in trace')
500+
}
498501
// TODO(Christian) fix typings
499502
this._mainFrameNodeId = event.args.frameTreeNodeId as any
500503
}
@@ -536,7 +539,8 @@ export default class TimelineModel {
536539
}
537540

538541
if (mismatchingIds.size) {
539-
console.error(
542+
Logger.error(
543+
'TimelineModel',
540544
'Timeline recording was started in more than one page simultaneously. Session id mismatch: ' +
541545
this._sessionId +
542546
' and ' +
@@ -624,7 +628,7 @@ export default class TimelineModel {
624628

625629
const profileGroup = tracingModel.profileGroup(cpuProfileEvent)
626630
if (!profileGroup) {
627-
console.error('Invalid CPU profile format.')
631+
Logger.error('TimelineModel', 'Invalid CPU profile format.')
628632
return null
629633
}
630634
cpuProfile = /** @type {!Protocol.Profiler.Profile} */ {
@@ -653,7 +657,7 @@ export default class TimelineModel {
653657
pushAll(cpuProfile.samples, samples)
654658
pushAll(cpuProfile.timeDeltas, eventData['timeDeltas'] || [])
655659
if (cpuProfile.samples.length !== cpuProfile.timeDeltas.length) {
656-
console.error('Failed to parse CPU profile.')
660+
Logger.error('TimelineModel', 'Failed to parse CPU profile.')
657661
return null
658662
}
659663
}
@@ -670,7 +674,7 @@ export default class TimelineModel {
670674
this._cpuProfiles.push(jsProfileModel)
671675
return jsProfileModel
672676
} catch (e) {
673-
console.error('Failed to parse CPU profile.')
677+
Logger.error('TimelineModel', 'Failed to parse CPU profile.')
674678
}
675679
return null
676680
}
@@ -800,7 +804,8 @@ export default class TimelineModel {
800804
private _fixNegativeDuration(event: Event, child: Event): void {
801805
const epsilon = 1e-3
802806
if (event.selfTime < -epsilon) {
803-
console.error(
807+
Logger.error(
808+
'TimelineModel',
804809
`Children are longer than parent at ${event.startTime} ` +
805810
`(${(child.startTime - this.minimumRecordTime()).toFixed(
806811
3

‎devtools/timelineModel/invalidationTracker.ts‎

Lines changed: 7 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
import Event from '../tracingModel/event'
22
import InvalidationTrackingEvent from './invalidationTrackingEvent'
33
import { InvalidationMap, RecordType } from '../types'
4+
import Logger from '../../src/logger'
45

56
export default class InvalidationTracker {
67
public static readonly invalidationTrackingEventsSymbol: unique symbol = Symbol(
@@ -34,8 +35,8 @@ export default class InvalidationTracker {
3435
this._startNewFrameIfNeeded()
3536

3637
if (!invalidation.nodeId) {
37-
console.error('Invalidation lacks node information.')
38-
console.error(invalidation)
38+
Logger.error('InvalidationTracker', 'Invalidation lacks node information.')
39+
Logger.error('InvalidationTracker', invalidation)
3940
return
4041
}
4142

@@ -159,8 +160,8 @@ export default class InvalidationTracker {
159160
}
160161

161162
if (!styleInvalidatorInvalidation.nodeId) {
162-
console.error('Invalidation lacks node information.')
163-
console.error(styleInvalidatorInvalidation)
163+
Logger.error('InvalidationTracker', 'Invalidation lacks node information.')
164+
Logger.error('InvalidationTracker', styleInvalidatorInvalidation)
164165
return
165166
}
166167

@@ -183,7 +184,8 @@ export default class InvalidationTracker {
183184
}
184185

185186
if (!lastScheduleStyleRecalculation) {
186-
console.error(
187+
Logger.error(
188+
'InvalidationTracker',
187189
'Failed to lookup the event that scheduled a style invalidator invalidation.'
188190
)
189191
continue

‎devtools/timelineModel/performanceModel.ts‎

Lines changed: 30 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -1,11 +1,11 @@
11
import TracingModel from '../tracingModel'
22
import TimelineModel from '.'
33
import TimelineFrameModel from './timelineFrameModel'
4-
import Track, { TrackType } from './track'
4+
import { TrackType } from './track'
55
import TimelineFrame from './timelineFrame/timelineFrame'
6-
import { ThreadData, WarningType, StatsObject } from '../types'
6+
import { ThreadData } from '../types'
77
import Event from '../tracingModel/event'
8-
import TimelineData from './timelineData'
8+
import Logger from '../../src/logger'
99

1010
interface ExtensionTracingModel {
1111
title: string
@@ -23,7 +23,7 @@ export default class PerformanceModel {
2323
public startTime: number
2424
public endTime: number
2525

26-
public constructor () {
26+
public constructor() {
2727
/** @type {?SDK.Target} */
2828
this._mainTarget = null
2929
/** @type {?SDK.TracingModel} */
@@ -70,16 +70,31 @@ export default class PerformanceModel {
7070

7171
const mainTracks = this._timelineModel
7272
.tracks()
73-
.filter((track): any => track.type === TrackType.MainThread && track.forMainFrame && track.events.length)
73+
.filter(
74+
(track): any =>
75+
track.type === TrackType.MainThread && track.forMainFrame && track.events.length
76+
)
7477
const threadData = mainTracks.map((track): ThreadData => {
7578
const event = track.events[0]
7679
return { thread: event.thread, time: event.startTime }
7780
})
78-
this._frameModel.addTraceEvents(this._mainTarget, this._timelineModel.inspectedTargetEvents(), threadData)
81+
Logger.debug('PerformanceModel', 'Adding trace events to frame model. Main tracks:', mainTracks.length, 'Thread data:', threadData.length)
82+
this._frameModel.addTraceEvents(
83+
this._mainTarget,
84+
this._timelineModel.inspectedTargetEvents(),
85+
threadData
86+
)
87+
Logger.debug('PerformanceModel', 'Trace events added to frame model')
88+
89+
// Finalize the frame model to flush any pending last frame
90+
this._frameModel.finalize(this._tracingModel.maximumRecordTime())
91+
Logger.debug('PerformanceModel', 'Frame model finalized')
7992

8093
for (const entry of this._extensionTracingModels) {
8194
entry.model.adjustTime(
82-
this._tracingModel.minimumRecordTime() + entry.timeOffset / 1000 - this._recordStartTime
95+
this._tracingModel.minimumRecordTime() +
96+
entry.timeOffset / 1000 -
97+
this._recordStartTime
8398
)
8499
}
85100
this._autoWindowTimes()
@@ -95,7 +110,9 @@ export default class PerformanceModel {
95110
if (!this._tracingModel) {
96111
return
97112
}
98-
model.adjustTime(this._tracingModel.minimumRecordTime() + timeOffset / 1000 - this._recordStartTime)
113+
model.adjustTime(
114+
this._tracingModel.minimumRecordTime() + timeOffset / 1000 - this._recordStartTime
115+
)
99116
}
100117

101118
/**
@@ -133,7 +150,7 @@ export default class PerformanceModel {
133150
* @param {!Timeline.PerformanceModel.Window} window
134151
* @param {boolean=} animate
135152
*/
136-
public setWindow(option: {left: number, right: number}) : void {
153+
public setWindow(option: { left: number; right: number }): void {
137154
this.startTime = option.left
138155
this.endTime = option.right
139156
}
@@ -148,7 +165,10 @@ export default class PerformanceModel {
148165
}
149166
}
150167
if (!tasks.length) {
151-
this.setWindow({ left: timelineModel.minimumRecordTime(), right: timelineModel.maximumRecordTime() })
168+
this.setWindow({
169+
left: timelineModel.minimumRecordTime(),
170+
right: timelineModel.maximumRecordTime(),
171+
})
152172
return
153173
}
154174

‎devtools/timelineModel/timelineJSProfileProcessor.ts‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@ import TracingModel, {
1010
import Runtime from '../runtime'
1111
import { TraceEvent, RecordType, EventData } from '../types'
1212
import Common from '../common/index'
13+
import Logger from '../../src/logger'
1314

1415
export enum NativeGroups {
1516
'Compile' = 'Compile',
@@ -39,7 +40,7 @@ export default class TimelineJSProfileProcessor {
3940
for (let i = 0; i < samples.length; ++i) {
4041
let node = jsProfileModel.nodeByIndex(i)
4142
if (!node) {
42-
console.error(`Node with unknown id ${samples[i]} at index ${i}`)
43+
Logger.error('TimelineJSProfileProcessor', `Node with unknown id ${samples[i]} at index ${i}`)
4344
continue
4445
}
4546
if (node === gcNode || node === idleNode) {
@@ -103,14 +104,15 @@ export default class TimelineJSProfileProcessor {
103104
if (lockedJsStackDepth.length) {
104105
const lockedDepth = lockedJsStackDepth[lockedJsStackDepth.length - 1]
105106
if (depth < lockedDepth) {
106-
console.error(
107+
Logger.error(
108+
'TimelineJSProfileProcessor',
107109
`Child stack is shallower (${depth}) than the parent stack (${lockedDepth}) at ${time}`
108110
)
109111
depth = lockedDepth
110112
}
111113
}
112114
if (jsFramesStack.length < depth) {
113-
console.error(`Trying to truncate higher than the current stack size at ${time}`)
115+
Logger.error('TimelineJSProfileProcessor', `Trying to truncate higher than the current stack size at ${time}`)
114116
depth = jsFramesStack.length
115117
}
116118
for (let k = 0; k < jsFramesStack.length; ++k) {

‎devtools/tracingModel/event.ts‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ import Thread from './thread'
33
import InvalidationTracker from '../timelineModel/invalidationTracker'
44
import InvalidationTrackingEvent from '../timelineModel/invalidationTrackingEvent'
55
import { TraceEvent, EventData } from '../types'
6+
import Logger from '../../src/logger'
67

78
export default class Event {
89
private _parsedCategories: Set<string>
@@ -109,7 +110,7 @@ export default class Event {
109110
*/
110111
public setEndTime(endTime: number): void {
111112
if (endTime < this.startTime) {
112-
console.assert(false, 'Event out of order: ' + this.name)
113+
Logger.error('TracingModel.Event', 'Event out of order:', this.name)
113114
return
114115
}
115116
this.endTime = endTime
@@ -125,7 +126,8 @@ export default class Event {
125126
*/
126127
for (const name in args) {
127128
if (name in this.args) {
128-
console.error(
129+
Logger.error(
130+
'TracingModel.Event',
129131
`Same argument name (${name}) is used for begin and end phases of ${this.name}`
130132
)
131133
}
@@ -141,7 +143,7 @@ export default class Event {
141143
if (endEvent.args) {
142144
this.addArgs(endEvent.args)
143145
} else {
144-
console.error(`Missing mandatory event argument 'args' at ${endEvent.startTime}`)
146+
Logger.error('TracingModel.Event', `Missing mandatory event argument 'args' at ${endEvent.startTime}`)
145147
}
146148

147149
this.setEndTime(endEvent.startTime)

0 commit comments

Comments
 (0)