misc(logger): declaratively mark functions for timings #6515

connorjclark · 2018-11-10T01:42:38Z

Whew, this was a journey into TypeScript for me.

I also converted most usages of time/timeEnd. The ones remaining either 1) are around just part of a function, and I did not want to decompose it; 2) in a constructor, which cannot be decorated, nor decomposed without making TS very unhappy; 3) behind a conditional, so converting wouldn't be semantically equivalent.

I noticed that VSCode's TS language server can sometimes fail to identify the types. Requires restarting the language server, and also first viewing the type (you can hover over it) - otherwise it will identify as any. For example, the auditDefn parameter in runner.js.

After, follow up on #6410.

connorjclark · 2018-11-10T01:44:24Z

lighthouse-logger/index.js

+  /* eslint-disable no-invalid-this */
+  static timeDecorate(originalFn, opts) {
+    return function timeDecoratedFn(...args) {
+      const timeStartLogLevel = opts.timeStartLogLevel || 'log';


Maintaining the same feature set as before, with how messages are only logged w/ the proper verbosity level.

connorjclark · 2018-11-10T01:45:19Z

lighthouse-logger/index.js

+          Log.timeEnd(status, timeEndLogLevel);
+          return value;
+        }).catch(err => {
+          err.stack = err.stack.replace(/.* at timeDecoratedFn .*\n/, '');


wouldn't work if minified. Is just the viewer minified? is it mangled? I need to check.

IIRC our "minification" is just removing whitespace at the beginning of each line, but viewer might be special

what about packages that bundle lighthouse (and likely minify) themselves? AFAICT, minifiers like uglify-js do not support "do not mangle me" comment markers, which would be the only way to ensure timeDecoratedFn is always named as such.

Anyway, it's not a big deal. Even if this fails, that just means an extra stack in an already unreadable (minified) stack trace. Unless source maps are applied, then it would show up. Should only address it if anyone ever complains.

do we want to timeEnd in this .catch block too?

patrickhulce

I ❤️this! so much cleaner to read everything! :D

also encourages splitting off parts of functions into methods so double bonus 😉

patrickhulce · 2018-11-10T16:20:25Z

lighthouse-logger/index.js

+  static timeDecorate(originalFn, opts) {
+    return function timeDecoratedFn(...args) {
+      const timeStartLogLevel = opts.timeStartLogLevel || 'log';
+      const timeEndLogLevel = opts.timeStartLogLevel || 'verbose';


seems like this should be a different opt?

patrickhulce · 2018-11-10T16:20:58Z

lighthouse-logger/index.js

@@ -128,6 +128,72 @@ class Log {
    marky.stop(id);
  }

+  /* eslint-disable no-invalid-this */
+  static timeDecorate(originalFn, opts) {


typedefs here? :)

I made it happen, but had to type the entire file too :)

patrickhulce · 2018-11-10T16:22:05Z

lighthouse-logger/index.js

+      if (typeof opts.msg === 'string') {
+        msg = opts.msg;
+      } else if (typeof opts.msg === 'function') {
+        msg = opts.msg.bind(this)(...args);


Suggested change

msg = opts.msg.bind(this)(...args);

msg = opts.msg.apply(this, args);

patrickhulce · 2018-11-10T16:22:26Z

lighthouse-logger/index.js

+      if (typeof opts.id === 'string') {
+        id = opts.id;
+      } else if (typeof opts.id === 'function') {
+        id = opts.id.bind(this)(...args);


patrickhulce · 2018-11-10T16:22:59Z

lighthouse-logger/index.js

+
+      let result;
+      try {
+        result = originalFn.bind(this)(...args);


patrickhulce · 2018-11-10T16:24:49Z

lighthouse-logger/index.js

+  }
+  /* eslint-enable no-invalid-this */
+
+  static timeDecorateClass(klass, methods) {


typedefs :)

patrickhulce · 2018-11-10T16:25:12Z

lighthouse-logger/index.js

+  static timeDecorateClass(klass, methods) {
+    for (const [method, opts] of Object.entries(methods)) {
+      if (!opts.id) {
+        const className = (typeof klass === 'function' ? klass : klass.constructor).name;


maybe a quick note on why we need to handle both? seems like if this is always called on classes we shouldn't need the situation where it's not a function

It's called on classes and prototypes - the former are functions but the latter are objects. To decorate instance methods, the first arg should be the prototype. For static methods, it should be the class itself.

It's clearer w/ the comments in the .d.ts file. Should I just move those to the implementation file?

patrickhulce · 2018-11-10T16:25:56Z

lighthouse-logger/test/index-test.js

@@ -0,0 +1,152 @@
+/**
+ * @license Copyright 2016 Google Inc. All Rights Reserved.


patrickhulce · 2018-11-10T16:28:20Z

lighthouse-logger/test/index-test.js

+  });
+
+  it('accepts function template for msg and id', () => {
+    // eslint-disable-next-line no-unused-vars


maybe assert the values are what you expect them to be or just get rid of them if they're not important to the test?

the "retains parameters" test tests for parameters being passed correctly, so I didn't want to keep testing that in subsequent tests. Could remove the parameter list from the function, but it does better document exactly what "value1/value2" of the msg/id template functions are.

patrickhulce · 2018-11-10T16:29:32Z

typings/lighthouse-logger/index.d.ts

  export function time(status: Status, level?: string): void;
  export function timeEnd(status: Status, level?: string): void;
+
+  type ArgumentTypes<F extends Function> = F extends (...args: infer A) => any ? A : never;


oh here are the typedefs! very nice :)

connorjclark · 2018-11-12T01:51:19Z

I bit the bullet and moved all the typings for the logger to the .js file, instead of typings/lighthouse-logger.

I don't know how to generate a .d.ts from the Closure-typed comments, so my workaround was to create ./lib/log.js to reexport lighthouse-logger within the Closure/TS type system, and change all the logger requires to that instead.

connorjclark · 2018-11-12T22:58:02Z

Tests will fail until new version of lighthouse-logger is released. It's tricky to separate developing the changes to lighthouse-logger and usages, so after all comments are resolved in the PR I'll branch and send a PR w/ just the logger changes, followed by a PR for usage changes.

patrickhulce · 2018-11-29T19:24:41Z

docs/readme.md

@@ -74,7 +74,7 @@ and set an appropriate logging level in your code. You'll also need to pass
 the `logLevel` flag when calling `lighthouse`.

 ```javascript
-const log = require('lighthouse-logger');
+const log = require('../lib/log');


not sure we should be changing the public docs on how to use it though ;)

hahaha nice catch. got too global search-and-replace happy

patrickhulce · 2018-11-29T19:25:23Z

lighthouse-logger/index.js

+          Log.timeEnd(status, timeEndLogLevel);
+          return value;
+        }).catch(err => {
+          err.stack = err.stack.replace(/.* at timeDecoratedFn .*\n/, '');


IIRC our "minification" is just removing whitespace at the beginning of each line, but viewer might be special

patrickhulce

I think I'm happy enough with the API to move on to split landing 👍

Just the unresolved question about ditching lighthouse-logger that might make this easier for you before you jump on it :)

patrickhulce · 2018-11-29T19:30:03Z

clients/devtools-entry.js

@@ -7,7 +7,7 @@

 const lighthouse = require('../lighthouse-core/index.js');
 const RawProtocol = require('../lighthouse-core/gather/connections/raw.js');
-const log = require('lighthouse-logger');


if we're doing this it seems like we might as well just directly require in from ../lighthouse-logger and expose the logger object for setting level and whatnot at require('lighthouse'), then we wouldn't need to worry about this publish business.

honestly, the only reason it was separate package at all was so that ChromeLauncher could share the logging functions/levels but I'm thinking there are much better ways to go about sharing a log object with chrome launcher than to continue to jump through all these hoops. I realize this is a bit more than you probably wanted to chew on for this change 😆 but if we're rewriting all the logger require statements to make this work, it's worth discussing.

What's the better way to share this code with ChromeLauncher? I would very much like to pull this package back into core.

I was thinking ChromeLauncher could just accept a logger parameter as an option that conforms to the API we have and we can pass lighthouse-logger into, but we could use regular ol' debug by default

patrickhulce · 2018-11-29T19:36:14Z

lighthouse-logger/index.js

+      const timeStartLogLevel = opts.timeStartLogLevel || 'log';
+      const timeEndLogLevel = opts.timeEndLogLevel || 'verbose';
+
+      let msg;


Not a big deal, but it seems like msg and id could be turned into functions outside of the timeDecoratedFn so we could simplify what's going on inside each invocation a bit, i.e. line 212-234 becomes just const status = {msg: computeMsg(this, args), id: computeId(this, args)}

patrickhulce · 2018-11-29T19:37:35Z

lighthouse-logger/index.js

+          Log.timeEnd(status, timeEndLogLevel);
+          return value;
+        }).catch(err => {
+          err.stack = err.stack.replace(/.* at timeDecoratedFn .*\n/, '');


do we want to timeEnd in this .catch block too?

patrickhulce · 2018-11-29T19:40:29Z

lighthouse-logger/index.js

+   * @param {{[key in Prop]: TimeDecorateOpts<Class, ArgumentTypes<IsFunction<Class[key]>>>}} methods
+   */
+  static timeDecorateClass(klass, methods) {
+    for (const [method, opts] of Object.entries(methods)) {


I'm surprised this works with class prototypes, last time I dealt with this I feel like they weren't enumerable and I had to use getOwnPropertyNames for some reason. If you happened to run into some issues that you could share why I struggled last time I'd love to hear your insight :)

Ohhhhhh you're iterating over the methods that are manually specified, not the class members! 👍

yeah you got it. these are explicitly defined via an object literal when calling the function

patrickhulce · 2018-11-29T19:42:13Z

lighthouse-logger/index.js

+  static timeDecorateClass(klass, methods) {
+    for (const [method, opts] of Object.entries(methods)) {
+      if (!opts.id) {
+        const className = (typeof klass === 'function' ? klass : klass.constructor).name;


patrickhulce · 2018-11-29T19:43:08Z

lighthouse-logger/index.js

+        opts.id = `lh:${className}:${method}`;
+      }
+      /** @type {IsFunction<Class[typeof method]>} */
+      const original = klass[method];


maybe just do a quick spelling check here? if (!original) throw new Error('Cannot decorate non-existant method ${method}')

You mean existence check, yeah? :P

You mean existence check, yeah? :P

hey hey let's give ms. anonymous future coder the benefit of the doubt that the method does exist and it was just a typo 😆 😛

ahhh i see i see. misunderstood.

speaking of spelling mistakes; existent* haha

patrickhulce · 2018-11-29T19:43:52Z

lighthouse-logger/index.js

  static log(title, ...args) {
    Log.events.issueStatus(title, args);
-    return Log._logToStdErr(title, args);
+    Log._logToStdErr(title, args);


does this really change anything or was it just for ts?

yeah, changes nothing. The return value was void.

connorjclark · 2018-12-06T17:55:11Z

@patrickhulce how about this;

split logger changes in a separate PR, publish new version
update usages of it in another PR
open issue to discuss pulling the logger package into core

patrickhulce · 2018-12-06T18:11:32Z

Love it @hoten, let's make it happen!

connorjclark added 3 commits November 9, 2018 16:42

misc(logger): declaratively mark functions for timing (#6425)

c7d88f1

scrub stack trace

957ba26

comments

ec42ea0

connorjclark requested a review from brendankenny November 10, 2018 01:42

connorjclark requested review from patrickhulce and paulirish as code owners November 10, 2018 01:42

connorjclark commented Nov 10, 2018

View reviewed changes

patrickhulce suggested changes Nov 10, 2018

View reviewed changes

pr changes

ef0188d

connorjclark added 2 commits November 12, 2018 08:22

revise ts

7f11af4

delete typing file

1282d35

patrickhulce reviewed Nov 29, 2018

View reviewed changes

undo change to docs

9c5460f

patrickhulce reviewed Nov 29, 2018

View reviewed changes

connorjclark added 5 commits November 29, 2018 11:51

Merge branch 'master' into issue-6425-auto-mark

a181ebb

log time end in catch

4301102

refactor get msg/id

e0a915f

log time end in catch

14170a8

throw error if method no existy

919e5fe

connorjclark mentioned this pull request Dec 6, 2018

misc(logger): 1.3.0, package types, timeDecorate, add tests #6740

Closed

connorjclark closed this Dec 6, 2018

brendankenny deleted the issue-6425-auto-mark branch December 10, 2018 20:04

brendankenny restored the issue-6425-auto-mark branch December 10, 2018 20:04

brendankenny deleted the issue-6425-auto-mark branch December 12, 2018 01:41

connorjclark mentioned this pull request Jan 9, 2020

core: measure time for GatherRunner.runPass #10205

Merged

connorjclark mentioned this pull request Nov 16, 2020

core: add timing instrumentation for base artifacts #11672

Merged

	msg = opts.msg.bind(this)(...args);
	msg = opts.msg.apply(this, args);

		@@ -0,0 +1,152 @@
		/**
		* @license Copyright 2016 Google Inc. All Rights Reserved.

misc(logger): declaratively mark functions for timings #6515

misc(logger): declaratively mark functions for timings #6515

Conversation

connorjclark commented Nov 10, 2018

connorjclark Nov 10, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

patrickhulce left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

connorjclark commented Nov 12, 2018

connorjclark commented Nov 12, 2018 • edited Loading

patrickhulce Nov 29, 2018 • edited Loading

Choose a reason for hiding this comment

connorjclark Nov 29, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

patrickhulce left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

connorjclark Nov 29, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

connorjclark commented Dec 6, 2018

patrickhulce commented Dec 6, 2018

connorjclark Nov 10, 2018 •

edited

Loading

connorjclark commented Nov 12, 2018 •

edited

Loading

patrickhulce Nov 29, 2018 •

edited

Loading

connorjclark Nov 29, 2018 •

edited

Loading

connorjclark Nov 29, 2018 •

edited

Loading