Fetching changelog in monorepos: hundreds of requests for the same data resulting in timeouts. Can it be memoized/cached?

[dylang]

Type of discussion.

I'm proposing an idea

Tell us more.

Env:

Github Enterprise. Self hosted. latest build of Renovate.

What's going on:

1. We have a monorepo "product" with hundreds of packages in GHE.
2. Each package depends on the same "dx" packages, like React or Next.
3. All of those dev utility packages are from another single monorepo in GHE, so they will share the same changelog.
4. Renovate seems to request the same changelog hundreds of times.
5. This takes about an hour, and often times out, in which case we don't get any PR and it repeats the whole thing again next time it runs.

Details about the log:

• In this example, the "product" monorepo has 300 workspaces.
• The upgrade is for the "dx group" which has about 12 packages.
• 1 or 2 of those 12 packages are included in every workspace's devDependencies.

Our timeouts and limits are generous, for example:

        {
            matchHost: 'api.github.com',
            concurrentRequestLimit: 1,
            maxRequestsPerSecond: 1,
            // Renovate default timeout is 1 minute, our default is 10 minutes.
            timeout: 600000
        },
        {
            hostType: 'github-tags',
            concurrentRequestLimit: 1,
            maxRequestsPerSecond: 1,
            // Renovate default timeout is 1 minute, our default is 10 minutes.
            timeout: 600000
        },

Here's a snippet of the log:

-- starts off going well --

10:39:49  DEBUG: Ensuring PR (repository=product/product, branch=renovate/dx-packages)
10:39:49  DEBUG: There are 0 errors and 0 warnings (repository=product/product, branch=renovate/dx-packages)
10:39:49  DEBUG: getBranchPr(renovate/dx-packages) (repository=product/product, branch=renovate/dx-packages)
10:39:49  DEBUG: findPr(renovate/dx-packages, undefined, open) (repository=product/product, branch=renovate/dx-packages)
10:39:49  DEBUG: findPr(renovate/dx-packages, undefined, closed) (repository=product/product, branch=renovate/dx-packages)
10:39:49  DEBUG: Found PR #26024 (repository=product/product, branch=renovate/dx-packages)
10:39:49  DEBUG: getPrCache() (repository=product/product, branch=renovate/dx-packages)

-- Fetching changelog starts here --

10:39:49  DEBUG: Fetching changelog: https://github.company.com/DX/dx (40.10.0 -> 40.12.0) (repository=product/product, branch=renovate/dx-packages)
10:39:49  DEBUG: Fetching changelog: https://github.company.com/DX/dx (40.11.0 -> 40.12.0) (repository=product/product, branch=renovate/dx-packages)
10:39:49  DEBUG: Fetching changelog: https://github.company.com/DX/dx (40.11.0 -> 40.12.0) (repository=product/product, branch=renovate/dx-packages)

--------------------------------------------------
-- over 500 lines cut repeating the same thing ---
--------------------------------------------------

11:35:18  DEBUG: Fetching changelog: https://github.company.com/DX/dx (40.11.0 -> 40.12.0) (repository=product/product, branch=renovate/dx-packages)
11:35:33  DEBUG: Fetching changelog: https://github.company.com/DX/dx (40.11.0 -> 40.12.0) (repository=product/product, branch=renovate/dx-packages)
11:35:39  DEBUG: Fetching changelog: https://github.company.com/DX/dx (40.10.0 -> 40.12.0) (repository=product/product, branch=renovate/dx-packages)

-- Fetching changelog ends here, almost an hour later --

-- not sure if these timeouts immediately after the above are releated, a separate discussion? --

11:35:49  DEBUG: Found package lookup warnings (repository=product/product, branch=renovate/dx-packages)
11:35:49         "warnings": [
11:35:49           "Failed to look up npm package @company/dx-start",
11:35:49           "Failed to look up npm package @company/babel-preset-dx",
11:35:49           "Failed to look up npm package @company/dx-jenkins",
11:35:49           "Failed to look up npm package @company/dx-jest-config",
11:35:49           "Failed to look up npm package react-image"
11:35:49         ],
11:35:49         "warningFiles": ["package.json", "web/common/responses-common/package.json"]

-- pr is created this time, but often times out --

11:35:49  DEBUG: Creating PR (repository=product/product, branch=renovate/dx-packages)
11:35:49         "prTitle": "chore(deps): JIRA-1234 - minor - Update DX Packages to v40.12.0"

My guess is getChangeLogJSON should be cached or memoized, but I could be wrong.

Discussion: Can we cache or memoize this, or is something else causing this problem?

[viceice]

if the underlying http request is the same, then it's already cached per repo in memory. we've also some caching for github graphql post request. so only the log lines are duplicated per repo

[dylang]

That's what I expected too, but the long delay between log messages made me think something else was happening that's taking a long time, such as processing those already-downloaded changelog requests.

[rarkins]

We ideally should be de-duplicating at the "application" level, although http should still be an adequate fallback

[rarkins]

The concurrency limits on github are undesirable. I assume they were added due to some other problem, but otherwise this will really slow down Renovate and contribute to timeouts. Better to address the root cause of those than live with a permanently crippled fetching of one at a time

[dylang]

I added the concurrency limits to see if that would fix this problem. I thought maybe we were getting rate limited, even with the token being provided. Example:

22:04:42  + yarn renovate
22:04:48   INFO: Repository started (repository=product/product)
22:04:48         "renovateVersion": "35.57.4"
22:05:55   INFO: Dependency extraction complete (repository=product/product, baseBranch=main)
22:05:55         "stats": {
22:05:55           "managers": {
22:05:55             "cargo": {"fileCount": 1, "depCount": 8},
22:05:55             "docker-compose": {"fileCount": 1, "depCount": 3},
22:05:55             "dockerfile": {"fileCount": 2, "depCount": 2},
22:05:55             "npm": {"fileCount": 229, "depCount": 5256}
22:05:55           },
22:05:55           "total": {"fileCount": 233, "depCount": 5269}
22:05:55         }
23:19:51   WARN: Host error (repository=product/product)
23:19:51         "hostType": "github-tags",
23:19:51         "packageName": "nodejs/node",
23:19:51         "err": {
23:19:51           "name": "TimeoutError",
23:19:51           "code": "ETIMEDOUT",
23:19:51           "timings": {
23:19:51             "start": 1682390540392,
23:19:51             "socket": 1682390540392,
23:19:51             "lookup": 1682390540486,
23:19:51             "connect": 1682390540642,
23:19:51             "error": 1682390637363,
23:19:51             "phases": {"wait": 0, "dns": 94, "tcp": 156, "total": 96971}
23:19:51           },
23:19:51           "event": "request",
23:19:51           "message": "Timeout awaiting 'request' for 60000ms",
23:19:51           "stack": "RequestError: Timeout awaiting 'request' for 60000ms\n    at ClientRequest.<anonymous> (/home/jenkins/workspace/ia_org_renovate_PR-2133/node_modules/got/dist/source/core/index.js:970:65)\n    at Object.onceWrapper (node:events:628:26)\n    at ClientRequest.emit (node:events:525:35)\n    at ClientRequest.emit (node:domain:489:12)\n    at ClientRequest.origin.emit (/home/jenkins/workspace/ia_org_renovate_PR-2133/node_modules/@szmarczak/http-timer/dist/source/index.js:43:20)\n    at TLSSocket.socketErrorListener (node:_http_client:502:9)\n    at TLSSocket.emit (node:events:513:28)\n    at TLSSocket.emit (node:domain:489:12)\n    at emitErrorNT (node:internal/streams/destroy:151:8)\n    at emitErrorCloseNT (node:internal/streams/destroy:116:3)\n    at processTicksAndRejections (node:internal/process/task_queues:82:21)\n    at runNextTicks (node:internal/process/task_queues:64:3)\n    at listOnTimeout (node:internal/timers:538:9)\n    at Timeout.timeoutHandler [as _onTimeout] (/home/jenkins/workspace/ia_org_renovate_PR-2133/node_modules/got/dist/source/core/utils/timed-out.js:36:25)\n    at listOnTimeout (node:internal/timers:571:11)\n    at processTimers (node:internal/timers:512:7)",
23:19:51           "options": {
23:19:51             "headers": {
23:19:51               "user-agent": "RenovateBot/35.57.4 (https://github.com/renovatebot/renovate)",
23:19:51               "accept": "application/json, application/vnd.github.v3+json",
23:19:51               "authorization": "***********",
23:19:51               "content-type": "application/json",
23:19:51               "content-length": "872",
23:19:51               "accept-encoding": "gzip, deflate, br"
23:19:51             },
23:19:51             "url": "https://api.github.com/graphql",
23:19:51             "hostType": "github-tags",
23:19:51             "username": "",
23:19:51             "password": "",
23:19:51             "method": "POST",
23:19:51             "http2": false
23:19:51           }
23:19:51         }
23:19:51   INFO: External host error causing abort - skipping (repository=product/product)
23:19:51   INFO: Repository finished (repository=product/product)
23:19:51         "cloned": true,
23:19:51         "durationMs": 4502933

[rarkins]

The github-tags limit will apply to any fetched from your own github too. I'm not sure if it has any effect on release notes though

[dylang]

It did increase the queue, but it might have helped reduce the timeouts that were happening at 10 minutes.

11:36:11           "api.github.com": {
11:36:11             "requestCount": 15,
11:36:11             "requestAvgMs": 182567,
11:36:11             "queueAvgMs": 29081
11:36:11           }

No issues with GHE, not even a queue.

11:36:11           "github.company.com": {
11:36:11             "requestCount": 38,
11:36:11             "requestAvgMs": 836,
11:36:11             "queueAvgMs": 0
11:36:11           

This is interesting too:

11:36:11  DEBUG: Repository timing splits (milliseconds) (repository=product/product)
11:36:11         "splits": {
11:36:11           "init": 31824,
11:36:11           "extract": 38563,
11:36:11           "lookup": 5118551,
11:36:11           "onboarding": 2,
11:36:11           "update": 3883625
11:36:11         },
11:36:11         "total": 9087182
11:36:11  DEBUG: Package cache statistics (repository=product/product)
11:36:11         "get": {"count": 419, "avgMs": 8394, "medianMs": 7, "maxMs": 383277},
11:36:11         "set": {"count": 73, "avgMs": 402563, "medianMs": 43659, "maxMs": 1856067}

And those 2 github tags were really slow, I'll try to figure out what they were:

11:36:11  DEBUG: Package lookup durations (repository=product/product)
11:36:11         "docker": {"count": 5, "averageMs": 6607, "totalMs": 33036, "maximumMs": 11164},
11:36:11         "npm": {"count": 2889, "averageMs": 19583, "totalMs": 56573976, "maximumMs": 3271078},
11:36:11         "crate": {"count": 8, "averageMs": 683, "totalMs": 5466, "maximumMs": 1124},
11:36:11         "github-tags": {"count": 2, "averageMs": 1587677, "totalMs": 3175353, "maximumMs": 3157159}

It looks like they are to https://api.github.com/graphql, it times out, tries again with a smaller page size and gets socket hang up.