Testing probot app significantly slower in v13

[askoufis]

Bug Report

Testing my probot app seems to have gotten significantly slower in probot v13.

I noticed when upgrading from probot v12 to v13, that my unit tests were taking nearly 10x longer to run (from ~5s to ~50s in our internal app). I though this could be due to swapping from nock to msw for mocking github API requests, but after reproducing the issue using just msw, I think the culprit is a change introduced in probot v13.

NOTE: I have not had a chance to test the real-world execution time of my app with probot v13, as I've been more concerned with the test time. As our internal app is not a critical app, we might just test it anyway and roll back if there are any issues. I will update this issue if we end up doing this and discovering anything.

Current Behavior

Tests run much slower in probot v13 compared to v12.

I have reproduced the issue in an example probot app that I created using npx create-probot-app my-first-app.

Reproduction repo

Steps to reproduce:

git clone https://github.com/askoufis/test-probot-app
cd test-probot-app
pnpm install
pnpm run test

The master version of the app is using probot v12 and msw. I replaced nock with msw because nock doesn't work with probot v13 since it now uses native fetch, and I didn't want to have both the probot version and msw migration influencing the reproduction.

You should observe that the 2 tests complete in ~1s (<1s on my M1 pro). Adding more tests does not significantly influence the test run time; each test only adds <100 ms.

Next steps:

git checkout probot-13
pnpm install
pnpm run test

This version of the app updates probot to 13.0.2, and that's it.

You should observe that the tests take significantly longer, ~4s on my machine. Adding more tests increases the test time by ~3s per test added.

Expected behavior/code
Test time should ideally be somewhat similar between major versions.

Environment

• Probot version(s): v13.0.2
• Node/npm version: 20.11.0
• OS: macOS 14.2.1

Possible Solution

Doing some rudimentary console.log timing, I can't see anything during the actual probot app execution that taking up lots of time. Interestingly, if you delete all but 1 test, it runs in ~1s, and jest indicates that it runs in <100ms on my machine. This leads me to believe that the culprit is potentially related to some kind of cleanup step that the probot app is doing.

[welcome]

Thanks for opening this issue. A contributor should be by to give feedback soon. In the meantime, please check out the contributing guidelines and explore other ways you can get involved.

[Uzlopak]

We benchmarked the runtime performance and it was 10x faster. But we removed alot of any typings in probot, so probably this is an issue of typescript transpilation performance.

We personally switched to vitest as jest is slow anyway

[askoufis]

We benchmarked the runtime performance and it was 10x faster. But we removed alot of any typings in probot, so probably this is an issue of typescript transpilation performance.

We personally switched to vitest as jest is slow anyway

My reproduction repo contains 0 typescript, and its jest setup isn't even configured to handle typescript at all. Additionally, the probot library is distributed as JS (with .d.ts types), so I doubt that typescript has anything to do with it.

Also, typescript transpilation wouldn't really explain why running a single test is fast (~50ms), but running a second test adds ~3s. I believe whatever transpilation setup you have, the file transpilation is at least cache between test runs, so I'd expect maybe the first test run to be slow, but subsequent test runs to be fast. Again, this is not observed.

[askoufis]

Just to be clear, I'm not claiming that runtime performance is an issue. I haven't even tested that claim, as I mentioned in the issue.

[travi]

have you disabled throttling and retry in the octokit instance used by your test probot instance, as shown in the docs about testing probot? if not disabled, that will add significant delay to your tests

[askoufis]

have you disabled throttling and retry in the octokit instance used by your test probot instance, as shown in the docs about testing probot? if not disabled, that will add significant delay to your tests

Yes, those settings are both disabled. Perhaps it's not clear in my issue (I've updated it just now), but I have a reproduction of the issue in a repo. Please take a look, it has had some minor adjustments made relative to the initial state from running npx create-probot-app my-first-app, which comes with a correct testing setup out of the box.

[gr2m]

I just ran into this. I disabled throttling like this

  probot = new Probot({
    id: 1,
    githubToken: "test",
    Octokit: ProbotOctokit.defaults({
      throttle: { enabled: false },
      retry: { enabled: false },
      log: pino(streamLogsToOutput),
    }),
    log: pino(streamLogsToOutput),
  });

and it no longer works since v13. I shortly looked into the ProbotOctoki.defaults() defaults callback and it never receives throttle: { enabled: false }. This might end up being a bug in @octokit/core's .defaults() implementation, Octokit was bumped a few versions between probot v12 and 13

I'll keep updating this comment with what else I find as I investigate

The code below works as expected, which now makes me think that ProbotOctokit works as designed, but the way Probot is instantiating it might have a bug

const { ProbotOctokit } = require("probot");

const MyOctokit = ProbotOctokit.defaults({
  throttle: { enabled: false },
});
const octokit = new MyOctokit({ auth: process.env.GITHUB_TOKEN });

octokit.request("GET /").then(() => {
  console.log("ok");
});

[gr2m]

Using a .defaults() callback works

const { Probot, ProbotOctokit } = require("probot");

const probot = new Probot({
  id: 1,
  githubToken: process.env.GITHUB_TOKEN,
  Octokit: ProbotOctokit.defaults((instanceOptions) => {
    return {
      ...instanceOptions,
      throttle: { enabled: false },
    };
  }),
});

probot.onAny(async ({ octokit }) => {
  await octokit.request("GET /");
  console.log("done!");
});

probot.receive({ id: "1", name: "test", payload: {} });

I agree it's not ideal, I'm not sure what exactly happened that changed the behavior, but my bet would be on @octokit/core. This should unblock folks to have their tests running again. I suggest we document this somewhere until someone brave figures out what happened.

[askoufis]

I agree it's not ideal, I'm not sure what exactly happened that changed the behavior, but my bet would be on @octokit/core. This should unblock folks to have their tests running again. I suggest we document this somewhere until someone brave figures out what happened.

The defaults implementation in @octokit/core doesn't look like it has changed in ~4 years, so it's strange that this has suddenly become an issue. This potentially indicates that it's coming from probot, rather than octokit.

It's clearly documented here that:

If you need a deep or conditional merge, you can pass a function instead.

This is necessary because Object.assign only does a shallow merge, and that's what they use in their implementation.

Doing some debugging, I can see other throttle options being passed in alongside defaults (specifically onSecondaryRateLimit and onRateLimit), but when defaults is just a plain object, the shallow merge occurs, overwriting the enabled: false. Perhaps defaulted instance of Octokit has moved around, such that the defaults are applying in a different order? That's my best guess right now, based on my 1 hour-old understanding of probot's call stack.