Skip to content

Commit

Permalink
feat: Add duration to logs
Browse files Browse the repository at this point in the history 
Some calls take time, especially asynchronous ones.  Logs now include
the duration of calls.

This also tweaks the HTML log formatting and moves some styles to CSS.

Change-Id: Ib9a3fc820bb62742ce1140300e76e73603381341
  • Loading branch information
@joeyparrish
joeyparrish committed Nov 8, 2021
1 parent d4007cf commit 6fe1aa6
Show file tree
Hide file tree
Showing 5 changed files with 79 additions and 11 deletions.
17 changes: 12 additions & 5 deletions log-window.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -123,27 +123,34 @@ class EmeLogWindow {
const heading = document.createElement('h3');
li.appendChild(heading);

const title = document.createElement('span');
const title = document.createElement('div');
title.classList.add('title');
title.style.color = 'blue';
heading.appendChild(title);
heading.appendChild(document.createTextNode(' '));

const time = document.createElement('div');
time.classList.add('time');
heading.appendChild(time);

const timestamp = new Date(log.timestamp);
// ISO date strings look like '2021-10-21T22:54:46.629Z', which is dense a
// little hard to read. Tweak the output a little into something more like
// '2021-10-21 22:54:46.629'.
const formattedTimestamp =
timestamp.toISOString().replace('T', ' ').replace('Z', '');
const time = document.createTextNode(' ' + formattedTimestamp);
heading.appendChild(time);

time.textContent = formattedTimestamp;
if (log.duration) {
time.textContent += ` - duration: ${log.duration.toFixed(1)} ms`;
}

const data = document.createElement('pre');
data.classList.add('data');
li.appendChild(data);

if (log.type == 'Warning') {
title.textContent = 'WARNING';
title.style.color = 'red';
title.classList.add('warning');
data.textContent = log.message;
}

Expand Down
14 changes: 14 additions & 0 deletions log.html
View file
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,20 @@
right: 10px;
display: none; /* initially hidden */
}

.title {
display: inline-block;
color: blue;
}

.title.warning {
color: red;
}

.time {
display: inline-block;
margin-left: 1em;
}
</style>
</head>
<body>
Expand Down
13 changes: 13 additions & 0 deletions spec/eme-trace-tests.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -53,6 +53,19 @@ describe('EME tracing', () => {
// A completely valid mp4 in a data URI (an audio init segment).
const tinyMp4 = 'data:audio/mp4;base64,AAAAGGZ0eXBkYXNoAAAAAGlzbzZtcDQxAAAC0W1vb3YAAABsbXZoZAAAAADTjyWa048lmgAAu4ACim4AAAEAAAEAAAAAAAAAAAAAAAABAAAAAAAAAAAAAAAAAAAAAQAAAAAAAAAAAAAAAAAAQAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAIAAACGbWV0YQAAAAAAAAAgaGRscgAAAAAAAAAASUQzMgAAAAAAAAAAAAAAAAAAAFpJRDMyAAAAABXHSUQzBAAAAAAAQlBSSVYAAAA4AABodHRwczovL2dpdGh1Yi5jb20vZ29vZ2xlL2VkYXNoLXBhY2thZ2VyAGZlNjc3NWEtcmVsZWFzZQAAADhtdmV4AAAAEG1laGQAAAAAAopuAAAAACB0cmV4AAAAAAAAAAEAAAABAAAEAAAAAAAAAAAAAAABn3RyYWsAAABcdGtoZAAAAAPTjyWa048lmgAAAAEAAAAAAopuAAAAAAAAAAAAAAAAAAEAAAAAAQAAAAAAAAAAAAAAAAAAAAEAAAAAAAAAAAAAAAAAAEAAAAAAAAAAAAAAAAAAATttZGlhAAAAIG1kaGQAAAAA048lmtOPJZoAALuAAopuABXHAAAAAAAtaGRscgAAAAAAAAAAc291bgAAAAAAAAAAAAAAAFNvdW5kSGFuZGxlcgAAAADmbWluZgAAACRkaW5mAAAAHGRyZWYAAAAAAAAAAQAAAAx1cmwgAAAAAQAAAKpzdGJsAAAAXnN0c2QAAAAAAAAAAQAAAE5tcDRhAAAAAAAAAAEAAAAAAAAAAAACABAAAAAAu4AAAAAAACplc2RzAAAAAAMcAAEABBRAFQAAAAAAAAAAAAAABQURkFblAAYBAgAAABBzdHRzAAAAAAAAAAAAAAAQc3RzYwAAAAAAAAAAAAAAFHN0c3oAAAAAAAAAAAAAAAAAAAAQc3RjbwAAAAAAAAAAAAAAEHNtaGQAAAAAAAAAAA==';

describe('timestamps and durations', () => {
it('are logged', async () => {
const mksa = await navigator.requestMediaKeySystemAccess(
keySystem, minimalConfigs);

expect(emeLogger).toHaveBeenCalledWith(
jasmine.objectContaining({
'timestamp': jasmine.any(Number),
'duration': jasmine.any(Number),
}));
});
});

describe('logs navigator object', () => {
it('requestMediaKeySystemAccess calls', async () => {
const mksa = await navigator.requestMediaKeySystemAccess(
Expand Down
14 changes: 12 additions & 2 deletions spec/log-window-tests.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -80,6 +80,16 @@ describe('Log window', () => {
.toContain('1969-07-20 12:34:56');
});

it('logs with durations', () => {
EmeLogWindow.instance.open();
EmeLogWindow.instance.appendLog({
timestamp: Date.now(),
duration: 15,
});
expect(mockLogElement.querySelector('h3').textContent)
.toContain('duration: 15.0 ms');
});

it('shows warnings', () => {
EmeLogWindow.instance.open();
EmeLogWindow.instance.appendLog({
Expand All @@ -90,8 +100,8 @@ describe('Log window', () => {

expect(mockLogElement.querySelector('.title').textContent)
.toContain('WARNING');
expect(mockLogElement.querySelector('.title').style.color)
.toBe('red');
expect(mockLogElement.querySelector('.title').classList.contains('warning'))
.toBe(true);
expect(mockLogElement.querySelector('.data').textContent)
.toContain('Oh no!');
});
Expand Down
32 changes: 28 additions & 4 deletions trace-anything.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -53,11 +53,13 @@ class TraceAnything {
try {
const original = new ctor(...args);
log.result = original;
log.duration = Date.now() - log.timestamp;
options.logger(log);

return TraceAnything.traceObject(original, options);
} catch (error) {
log.threw = error;
log.duration = Date.now() - log.timestamp;
options.logger(log);
throw error;
}
Expand Down Expand Up @@ -322,6 +324,7 @@ class TraceAnything {
try {
const returnValue = originalMethod.apply(this, args);
log.result = returnValue;
log.duration = Date.now() - log.timestamp;

if (returnValue == null) {
// If this is null, it's not a Promise. Return the value right away.
Expand All @@ -341,6 +344,7 @@ class TraceAnything {
returnValue.then((asyncValue) => {
if (!options.logAsyncResultsImmediately) {
log.result = asyncValue;
log.duration = Date.now() - log.timestamp;
options.logger(log);
}

Expand All @@ -349,6 +353,7 @@ class TraceAnything {
if (!options.logAsyncResultsImmediately) {
delete log.result;
log.threw = error;
log.duration = Date.now() - log.timestamp;
options.logger(log);
}

Expand All @@ -364,6 +369,7 @@ class TraceAnything {
} catch (error) {
delete log.result;
log.threw = error;
log.duration = Date.now() - log.timestamp;
options.logger(log);
throw error;
}
Expand Down Expand Up @@ -430,6 +436,7 @@ class TraceAnything {
if (options.inPlace && !originalDescriptor.configurable) {
options.logger({
timestamp: Date.now(),
duration: 0,
type: TraceAnything.LogTypes.Warning,
message: `Unable to trace ${k} on ${className} in-place!`,
});
Expand All @@ -455,6 +462,7 @@ class TraceAnything {
newDescriptor.set = (value) => {
options.logger({
timestamp: Date.now(),
duration: 0,
type: TraceAnything.LogTypes.Setter,
className,
memberName: k,
Expand All @@ -478,11 +486,13 @@ class TraceAnything {
try {
const value = originalDescriptor.get.call(this);
log.result = value;
log.duration = Date.now() - log.timestamp;
options.logger(log);

return value;
} catch (error) {
log.threw = error;
log.duration = Date.now() - log.timestamp;
options.logger(log);
throw error;
}
Expand All @@ -501,9 +511,11 @@ class TraceAnything {
try {
originalDescriptor.set.call(this, value);
log.value = value;
log.duration = Date.now() - log.timestamp;
options.logger(log);
} catch (error) {
log.threw = error;
log.duration = Date.now() - log.timestamp;
options.logger(log);
throw error;
}
Expand All @@ -530,6 +542,7 @@ class TraceAnything {
promise.then((result) => {
const log = {
timestamp: Date.now(),
duration: 0,
type: TraceAnything.LogTypes.Event,
className,
eventName: `${k} Promise resolved`,
Expand All @@ -541,6 +554,7 @@ class TraceAnything {
}, (error) => {
const log = {
timestamp: Date.now(),
duration: 0,
type: TraceAnything.LogTypes.Event,
className,
eventName: `${k} Promise rejected`,
Expand Down Expand Up @@ -673,6 +687,7 @@ class TraceAnything {
return function(event) {
const log = {
timestamp: Date.now(),
duration: 0,
type: TraceAnything.LogTypes.Event,
className,
eventName,
Expand Down Expand Up @@ -765,6 +780,7 @@ TraceAnything.LogTypes = {
/**
* @typedef {{
* timestamp: Number,
* duration: Number,
* type: TraceAnything.LogTypes,
* message: (string|undefined),
* className: (string|undefined),
Expand All @@ -777,8 +793,12 @@ TraceAnything.LogTypes = {
* value: (?|undefined)
* }}
* @property {Number} timestamp
* A timestamp in milliseconds since 1970, UTC. Suitable for use in the Date
* constructor in JavaScript.
* A timestamp of when the call was made, in milliseconds since 1970, UTC.
* Suitable for use in the Date constructor in JavaScript.
* @property {Number} duration
* The duration of this call in milliseconds. This is particularly useful
* information for async methods. The value may be 0 for some types, such as
* events or warnings.
* @property {TraceAnything.LogTypes} type
* The type of log.
* @property {(string|undefined)} message
Expand Down Expand Up @@ -945,10 +965,14 @@ TraceAnything.defaultLogger = (log) => {
* @property {boolean} logAsyncResultsImmediately
* If true, log the returned Promise from an async method immediately. This
* can be sensible when logging to a JavaScript console, as the live object
* can be inspected later when it has a value.
* can be inspected later when it has a value. This means that the duration
* of a log would only reflect the time spent getting a Promise back from the
* method.
* If false, wait for the Promise to be resolved or rejected before logging.
* This is more useful when logging pure text, since the output becomes
* static once logged.
* static once logged. This also makes the duration of a log reflect the time
* spent waiting for the Promise to be resolved or rejected.
* By default, true.
*/
TraceAnything.Options;

Expand Down

0 comments on commit 6fe1aa6

Please sign in to comment.