Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PDE-2650 perf(core): improve logging performance #469

Merged
merged 7 commits into from
Feb 4, 2022

Conversation

eliangcs
Copy link
Member

@eliangcs eliangcs commented Jan 12, 2022

Improves z.console.log and HTTP logging performance. In this PR, we stream many logs in a single request to the /input endpoint on the log server. This reduces the overhead where the original /input endpoint only took one log in a request.

I used the following trigger code for benchmark:

const perform = async (z, bundle) => {
  const response = await z.request('https://httpbin.zapier-tooling.com/get');
  const requestId = response.data.headers['X-Request-Id'][0];

  for (let i = 0; i < 200; i++) {
    z.console.log(`hello ${i}`);
  }

  return [{ id: requestId }];
};

The above example code produces one HTTP log and 200 console logs. The old way (one log, one request) takes ~6.6 seconds to invoke the trigger. The new way (stream many logs in a request) takes ~3.5 seconds. I was expecting a bigger improvement but I think this is as good as it gets.

@@ -203,10 +204,10 @@ const createLambdaHandler = (appRawOrPath) => {

const { skipHttpPatch } = appRaw.flags || {};
// Adds logging for _all_ kinds of http(s) requests, no matter the library
if (!skipHttpPatch) {
if (!skipHttpPatch && !event.calledFromCli) {
Copy link
Member Author

Choose a reason for hiding this comment

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

I was running zapier push and found the CLI tool sent HTTP logs to the log server. So I added !event.calledFromCli to make sure we don't patch http when it was from CLI.

httpPatch(require('http'));
httpPatch(require('https')); // 'https' needs to be patched separately
httpPatch(require('http'), logger);
httpPatch(require('https'), logger); // 'https' needs to be patched separately
Copy link
Member Author

Choose a reason for hiding this comment

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

This ensures HTTP logs and console logs share the same logger instance created by createLogger(). In the old implementation, there's no difference because every log is a separate request. But in the new implementation, every time you call createLogger(), you create a new request, ready to stream logs. Here we want to reuse the same request as much as possible.

@eliangcs eliangcs marked this pull request as ready for review January 14, 2022 06:46
@eliangcs eliangcs requested a review from xavdid as a code owner January 14, 2022 06:46
@eliangcs eliangcs changed the title PDE-2650 pref(core): improve logging performance PDE-2650 perf(core): improve logging performance Jan 14, 2022
@eliangcs
Copy link
Member Author

@xavdid I found there's an issue with lost logs, which I'm still figuring out. So you don't have to review this PR just yet!

// Copy bundle environment into process.env *before* creating the logger and
// loading app code, so that the logger gets the endpoint from process.env,
// and top level app code can get bundle environment vars via process.env.
environmentTools.applyEnvironment(event);
Copy link
Member Author

@eliangcs eliangcs Feb 4, 2022

Choose a reason for hiding this comment

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

I moved applyEnvironment up because I found the logging endpoint could be different on the first invocation than it was on the subsequent invocations.

Here you can see the logging endpoint is either derived from the environment variable LOGGING_ENDPOINT or the constant DEFAULT_LOGGING_HTTP_ENDPOINT. But in the original (bad) code, we applyEnvironment AFTER createLogger. So on the first invocation, it would get the logging endpoint from the constant. But on the second or subsequent calls, since the environment variables have been loaded, it gets the logging endpoint from the environment variable.

We don't see any issues on production because the constant and the environment variables are the same (https://httplogger.zapier.com/input) on production.

To fix, we need to make sure we applyEnvironment BEFORE createLogger.

@eliangcs
Copy link
Member Author

eliangcs commented Feb 4, 2022

@xavdid this is ready for review!

@@ -65,7 +68,9 @@ const yarnInstall = (coreZipPath, workdir) => {
}
};

describe('smoke tests - setup will take some time', () => {
describe('smoke tests - setup will take some time', function () {
this.retries(3);
Copy link
Member Author

Choose a reason for hiding this comment

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

Hopefully this fixes the test timeout issue.

Copy link
Contributor

@xavdid xavdid left a comment

Choose a reason for hiding this comment

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

Very awesome! Looks great here.

@eliangcs eliangcs merged commit 9160d73 into master Feb 4, 2022
@eliangcs eliangcs deleted the PDE-2650-logging-performance branch February 4, 2022 09:01
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants