Skip to content
This repository has been archived by the owner on Dec 27, 2022. It is now read-only.

[DNM] Add logOperationTime util with implementation in protocol module #398

Draft
wants to merge 2 commits into
base: main
Choose a base branch
from

Conversation

jakekidd
Copy link
Contributor

The Problem

  • We need accurate logging to document time it's taking for methods to execute, starting with protocol module

The Solution

  • Implemented logOperationTime, a util method
  • Used at start and completion of a method to log start and time it took to execute, respectively
  • Used performance(.mark()) as opposed to Date.now() for accuracy

@@ -23,6 +23,5 @@
"eslint-plugin-import": "2.22.1",
"eslint-plugin-prettier": "3.1.4",
"pino-pretty": "4.3.0"
},
"dependencies": {}
}
Copy link
Contributor Author

@jakekidd jakekidd Feb 24, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure why this is getting removed for me - might be result of using later version of node. Can fix before I check in. Likely above package-lock.json diff is for same reason.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not really an issue, we can push this change. We will be updating to Node 14 soon anyways.

const stopLabel = `${label}-stop`;
const timestamp = performance.mark(stopLabel);
const diff = performance.measure(method, label, stopLabel);
const message = `${method} : finished @ ${timestamp}; took ${diff} ms`;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Probably only need the diff here since pino adds timestamps

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep, this is from earlier iteration, good catch

/// time method took to execute in ms).
export const logOperationTime = (log: pino.BaseLogger, method: string, label?: string): string => {
if (label) {
const stopLabel = `${label}-stop`;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What would happen if there are label collisions?

Copy link
Contributor Author

@jakekidd jakekidd Feb 24, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Currently using a unique identifier below as part of generated label to prevent that, but this will be replaced by passed in methodId

EDIT: But to answer question, yeah, if there are label collisions, it would overwrite the prev mark. Which would be bad, bc an async method of same name could be called twice

@@ -199,7 +201,7 @@ export class Vector implements IVectorProtocol {
}
const method = "onReceiveProtocolMessage";
const methodId = getRandomBytes32();
this.logger.debug({ method, methodId }, "Method start");
const label = logOperationTime(this.logger, method);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We will likely want to keep the methodId to log throughout the other parts of the method so the logs are easily searchable. Maybe we should use the label as the methodId instead.

General purpose of the methodId is to get a unique strings so that you can easily identify all logs that came from a given method when searching in log dna or whatever other log parser

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sure. This functionality is already internal to the logOperationTime method. I actually had it like that at first, but worried that not all methods would follow this standard of generating a methodId. Will add this back tho, thanks

@rhlsthrm
Copy link
Contributor

We should make this time logging part of the "debug" log config. IMO it should be in the code and be able to be enabled with a "switch flip" of sorts.

@jakekidd
Copy link
Contributor Author

We should make this time logging part of the "debug" log config. IMO it should be in the code and be able to be enabled with a "switch flip" of sorts.

Can you clarify what you mean by "debug" log config? Is there a configuration somewhere I should be aware of? The way it is currently, unless the method takes an inordinate amount of time to execute, it will always log it on debug level. Takes too long and it logs it as info, then warning

@rhlsthrm
Copy link
Contributor

Can you clarify what you mean by "debug" log config? Is there a configuration somewhere I should be aware of? The way it is currently, unless the method takes an inordinate amount of time to execute, it will always log it on debug level. Takes too long and it logs it as info, then warning

https://docs.connext.network/configuring-a-router here's the config.

Your implementation sounds good. The main thing I was trying to get at is we should have the ability to turn this on/off in the config. So as part of this PR I think we should add a config item called enableTimestampLogging or something which can turn the whole thing on/off.

@jakekidd
Copy link
Contributor Author

jakekidd commented Feb 25, 2021

https://docs.connext.network/configuring-a-router

Ah, I misread your first comment. I thought you said it should NOT be able to be enabled by switch flip of sorts , haha.

Yes, agreed. I will target that functionality for this PR, thanks. (Meaning I will include addition of this config item)

EDIT: I'm going to go out on a limb and assume the responsibility to 'check' the switch should be relegated to the method itself (meaning I'll check the enableTimestampLogging config setting within the logOperationTime method)

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants