Drupal project dependabot runs are very slow

[driskell]

Package manager/ecosystem Composer v2

Manifest contents prior to update

{
    "name": "drupal/recommended-project",
    "description": "Project template for Drupal 8 projects with a relocated document root",
    "type": "project",
    "license": "GPL-2.0-or-later",
    "homepage": "https://www.drupal.org/project/drupal",
    "support": {
        "docs": "https://www.drupal.org/docs/user_guide/en/index.html",
        "chat": "https://www.drupal.org/node/314178"
    },
    "repositories": [
        {
            "type": "composer",
            "url": "https://packages.drupal.org/8"
        }
    ],
    "require": {
        "composer/installers": "^1.2",
        "drupal/block_permissions": "1.0.0",
        "drupal/core-composer-scaffold": "^8.8",
        "drupal/core-project-message": "^8.8",
        "drupal/core-recommended": "^8.8"
    },
    "require-dev": {
        "drupal/core-dev": "^8.8"
    },
    "conflict": {
        "drupal/drupal": "*"
    },
    "minimum-stability": "dev",
    "prefer-stable": true,
    "config": {
        "sort-packages": true
    },
    "extra": {
        "drupal-scaffold": {
            "locations": {
                "web-root": "web/"
            }
        },
        "installer-paths": {
            "web/core": [
                "type:drupal-core"
            ],
            "web/libraries/{$name}": [
                "type:drupal-library"
            ],
            "web/modules/contrib/{$name}": [
                "type:drupal-module"
            ],
            "web/profiles/contrib/{$name}": [
                "type:drupal-profile"
            ],
            "web/themes/contrib/{$name}": [
                "type:drupal-theme"
            ],
            "drush/Commands/contrib/{$name}": [
                "type:drupal-drush"
            ],
            "web/modules/custom/{$name}": [
                "type:drupal-custom-module"
            ],
            "web/themes/custom/{$name}": [
                "type:drupal-custom-theme"
            ]
        },
        "drupal-core-project-message": {
            "include-keys": [
                "homepage",
                "support"
            ],
            "post-create-project-cmd-message": [
                "<bg=blue;fg=white>                                                         </>",
                "<bg=blue;fg=white>  Congratulations, you’ve installed the Drupal codebase  </>",
                "<bg=blue;fg=white>  from the drupal/recommended-project template!          </>",
                "<bg=blue;fg=white>                                                         </>",
                "",
                "<bg=yellow;fg=black>Next steps</>:",
                "  * Install the site: https://www.drupal.org/docs/8/install",
                "  * Read the user guide: https://www.drupal.org/docs/user_guide/en/index.html",
                "  * Get support: https://www.drupal.org/support",
                "  * Get involved with the Drupal community:",
                "      https://www.drupal.org/getting-involved",
                "  * Remove the plugin that prints this message:",
                "      composer remove drupal/core-project-message"
            ]
        }
    }
}

Updated dependency drupal/block_permissions 1.1.0 is available

What you expected to see, versus what you actually saw Fast check and update

Images of the diff or a link to the PR, issue or logs Actual result is extremely slow. It takes upwards of 30 seconds to process the update.

Across our main project where we have MANY Drupal modules, it easily takes the dependabot run to approximately 75 minutes. This is beyond the timeout set in GitHub so we can't use GitHub to do this currently due to issue #2416

In #2416 I started some investigations and came to the below conclusions. Some are not fixable by dependabot but I wanted to raise them here so the team is aware and could follow the issues / PR at the composer side if they wanted to.

1. -If a Drupal module depends on drupal/core in a large range, such as ^8 || ^9, it can cause composer to add all versions of drupal/core to its pool of packages that it uses to resolve updates. It causes hundreds of thousands of conflict rules to need to be generated and processed. Although processing is fast, generating them is not. It adds many seconds to a run.- Update: Fixed in 2.2 now that composer/composer#9261 and composer/composer#9620 are merged.
2. drupal/core has many replace entries for core modules. Because it's rarely a root requirement and is brought in by drupal/core-recommended, during an update when the module that needs updated depends on drupal/core it unlocks it, and then begins to attempt to download package information for it's replaces. This generates a lot of network activity, mostly 404s because these packages do not exist. Update: Waiting on composer/composer#9619 but it is highly complex.
3. Packages are actually downloaded and installed once the update is processed by dependabot, which seems largely unnecessary as they don't really impact the update run. Composer plugin packages might as they could hook into events etc. but not general libraries. So unnecessary bandwidth usage too. Update: I raised a PR at #2998 but abandoned it originally as https://github.com/wikimedia/composer-merge-plugin wasn't working, but I did realise this doesn't work anyway. So I have raised a new PR at #4635 for discussion.

I experimented with trying to get caching to work better but the modifications to composer are just not really acceptable to submit to them (in my opinion) so I dug further to work out real solutions. There's already a PR that helps with installs, composer/composer#9261, which hopefully hits Composer 2.1 but in my testing did not have a major impact. So I raised two new PR with composer/composer#9619 and composer/composer#9620 for discussion that significantly speed up the processing of updates by targeting items 1 and 2 above directly.

Overall got my full Drupal run time with all the above to 5 minutes.

[markdorison]

We are experiencing this issue on a couple of our Drupal codebases. I am monitoring all of the referenced issues and pull requests and I will add any additional clues that we uncover.

[markdorison]

We tested this again now that the below PRs have been merged into Composer but our Dependabot run is still timing out.

• https://github.com/composer/composer/pull/9620
• https://github.com/composer/composer/pull/9261

We attempted to ensure that Dependabot was using the latest version of Composer by requiring composer/composer:^2.2.3 in our project, but I am not 100% sure Dependabot will respect that.

[jurre]

I am not 100% sure Dependabot will respect that.

It won't, dependabot is on 2.1.14 of composer. There is an effort being made to upgrade though, you can follow along here: https://github.com/dependabot/dependabot-core/pull/4586.

[jurre]

I've rolled out a version of Dependabot that uses composer 2.2.4 for updates, have you seen any improvement in the time it takes for updates to complete for your projects @markdorison?

[markdorison]

We have two projects where this is occurring. Sadly, they are both still timing out. Is there any info from the Dependabot "update logs" I could provide that would be helpful?

[jurre]

I don't think so unfortunately, I think the problem is that we're configuring composer to download all the dependencies and we should just not. But the last time I tried doing that it broke a couple of our test scenarios and we haven't been able to prioritize digging into it deeper.

I'll make sure to raise it internally and see if we can get some performance work planned soon.

One thing that actually would help a bunch is a public test project that we can reproduce this against

[markdorison]

@jurre I created a public repo that reproduces the issue for us.

[driskell]

Worth noting that composer/composer#9619 is still outstanding and is a peculiar complex one - my last proposal was to not just delete the 1 line but every line in that block. All tests still pass. But it's a major enigma as it's a risky change and it's unclear if the code is there to do something that a test doesn't exist for... That PR will drop the time to process even further as it removes a significant amount of 404 requests to the Drupal repositories for replaced packages.

Just wanted to drop in here that I'm still monitoring that PR and hoping it will move but things take time. Definitely though it'll be super worth optimising elsewhere in the meantime if there's other places that can be optimised. Then if and when composer/composer#9619 lands it should mean extremely fast updates in comparison to when this ticket first opened! Definitely it's way faster in 2.2 though but yeh hopefully more to come.

[driskell]

@jurre I updated #2998 and took the setInstall(false) approach you recommended and got it working so all expected tests pass. There is some discussion to be had though as I think by not installing packages some dependabot code that turns install failures into exceptions is likely not necessary anymore as installs no longer happen.

Once that bit is done we are just waiting on composer/composer#9619 then and from my tests a Drupal run with lots of modules will complete in minutes.

[driskell]

I'm going to rest a bit from this - testing again with default I realise that the Wikimedia merge plugin issue is present even with dependabot currently without any changes, because of setRunScripts(false) - so perhaps the original PR was suitable as it was...

I will restore my branch to what it was and await a response here before I continue further into a rabbit hole!

[driskell]

I raised it again in #4635 for fresh discussion and cleaned it all up.

[jurre]

@driskell your changes should be live, have you noticed an improvement in performance on your projects? From our metrics I'm not seeing a big change, but there might be some outliers that I'm missing (which I can dig into separately using p50/p99 metrics etc, but good to get some anecdata also)

[markdorison]

Our affected projects (including the public repo) are still failing to complete.

[jeffwidman]

Per @driskell over in https://github.com/dependabot/dependabot-core/issues/2416#issuecomment-1246465434:

Drupal now removed the replaced declaration in 9.4.4 so I expect it to run much quicker as no 404 requests clogging the network per package. But I haven’t tested it.

So can this particular issue which is scoped to Drupal be closed?

I don't want this to become a catch-all issue for "composer is slow"... Unfortunately catch-call issues aren't really helpful because while the symptoms may be similar, the root cause may be entirely different.

@markdorison I really appreciate the hard work you did to create a public repo that repro's the issue in https://github.com/dependabot/dependabot-core/issues/2999#issuecomment-1013139098. I don't have time to look at it now, but hopefully we can get to that at some point... but if you're still seeing slowness even after bumping Drupal to 9.4.4 perhaps we should split your problem out as a separate issue?

[markdorison]

I updated the public example repo to require Drupal 9.4.4 and I am still seeing Dependabot errors.

[jeffwidman]

@markdorison thanks for circling back and spending time to put together the example public example. Since it's public, I was able to pull the job runs and it looks like it timed out a bunch of previous days, but the last two days it completed the job, taking ~34 mins the last time.

My guess is that you aren't seeing the job logs because there's 203,980 lines in this job log! 21MB!!

It hit a bunch of update_not_possible errors, which typically indicates the dependency has an updated version available, but that other requirements in the manifest file (both direct and indirect deps) specify requirements that conflict with the newer version... So it's impossible to bump to the newer version. This can often happen if several deps have to be bumped in lock-step, as Dependabot isn't smart enough for most ecosystems to bump multiple things at once.

Looking at the logs, I see 50 update_not_possible errors, so that's probably why things are slow... Because each time it's finding a new version of a dep, then making all the calls to walk the indirect dep tree only to get to the end and realize something conflicts and prevents the update. Versus an up-to-date dep it skips walking the dep tree once it realizes it's up to date. Sometimes Dependabot can complete all 50 in time, sometimes not. But even if we raised the timeout, that wouldn't solve the underlying problem of non-resolvable updates.

I wonder... if you updated a couple some of those manually such that there's only a handful of outdated deps which don't have to be raised in lock-step, would it then start working as expected, and much faster as well?

Given that you can't see the job logs, I'm checking if the job logs I can access are okay to post publicly (since this is a public repo)...

As a side note, if the logs are too big to display, it'd sure be nice if we returned a "the logs are too long" error rather than "unknown error"...

[driskell]

@jeffwidman

Looking at the logs, I see 50 update_not_possible errors, so that's probably why things are slow... Because each time it's finding a new version of a dep, then making all the calls to walk the indirect dep tree only to get to the end and realize something conflicts and prevents the update. Versus an up-to-date dep it skips walking the dep tree once it realizes it's up to date. Sometimes Dependabot can complete all 50 in time, sometimes not. But even if we raised the timeout, that wouldn't solve the underlying problem of non-resolvable updates.

Just to check - are you referring to Dependabot doing a walk or Composer? As I understood it, Dependabot runs Composer and Composer's Solver will decide if an update is possible or not. So the effort needed to improve this needs to be in Composer. It'll be worth someone taking the public repository and timing a composer update against individual packages to see what the slow down is.

[markdorison]

@driskell: Thanks for weighing in! You asked @jeffwidman, not me, but I will throw my .02 cents in here anyway. Feel free to take it with a grain of salt!

As I understood it, Dependabot runs Composer and Composer's Solver will decide if an update is possible or not. So the effort needed to improve this needs to be in Composer

Could this be a "yes and.."? I am following along on potential Composer performance improvements PRs (such as this one you created) and hoping something like that will make an impact. I want to note, though, that on the repos where we hit this issue, we are successfully using an alternative to Dependabot, which is working as expected. Obviously, I don't know how their approach might differ from Dependabot's.

Last but not least, any opportunity for a more descriptive error (as @jeffwidman noted), might give us a fighting chance to work around this issue in the meantime so I just wanted to give that a vigorous thumbs up! 😃