Composer: Composer very slow to read & write cache files

[tnorthcutt]

When I run

composer update --profile --vvv

I get the following output:
https://gist.github.com/tnorthcutt/770ba18a3f3f182354d85b7c80a91fe1

The dependency resolution itself is very fast, and (in this case) no packages are installed, updated, or removed (because I previously ran composer update). However, reading and writing the cache files seems _extremely_ slow.

Is there something I can do to speed this up, or to further debug?

My composer.json:

{
    "name": "laravel/laravel",
    "description": "The Laravel Framework.",
    "keywords": [
        "framework",
        "laravel"
    ],
    "license": "MIT",
    "type": "project",
    "require": {
        "php": ">=5.6.4",
        "laravel/framework": "5.3.*",
        "laravel/cashier": "~7.0",
        "laravel/spark": "*@dev",
        "yab/laracogs": "^1.9",
        "hashids/hashids": "^1.0",
        "barryvdh/laravel-cors": "^0.8.0",
        "barryvdh/laravel-debugbar": "^2.2",
        "barryvdh/laravel-ide-helper": "^2.1",
        "doctrine/dbal": "^2.5",
        "spatie/laravel-collection-macros": "^1.4",
        "league/csv": "^8.1",
        "guzzlehttp/guzzle": "^6.2"
    },
    "require-dev": {
        "fzaninotto/faker": "~1.4",
        "mockery/mockery": "0.9.*",
        "phpunit/phpunit": "~5.0",
        "symfony/css-selector": "3.1.*",
        "symfony/dom-crawler": "3.1.*",
        "phpmd/phpmd": "@stable",
        "spatie/laravel-migrate-fresh": "^1.3"
    },
    "autoload": {
        "classmap": [
            "database"
        ],
        "psr-4": {
            "App\\": "app/"
        }
    },
    "autoload-dev": {
        "classmap": [
            "tests/TestCase.php"
        ]
    },
    "scripts": {
        "post-root-package-install": [
            "php -r \"copy('.env.example', '.env');\""
        ],
        "post-create-project-cmd": [
            "php artisan key:generate"
        ],
        "post-install-cmd": [
            "Illuminate\\Foundation\\ComposerScripts::postInstall",
            "php artisan optimize"
        ],
        "post-update-cmd": [
            "Illuminate\\Foundation\\ComposerScripts::postUpdate",
            "php artisan ide-helper:generate",
            "php artisan optimize"
        ]
    },
    "config": {
        "preferred-install": "dist"
    },
    "repositories": [
        {
            "type": "path",
            "url": "./spark"
        }
    ]
}

Output of composer diagnose:

Checking composer.json: WARNING
require.laravel/spark : unbound version constraints (*@dev) should be avoided
Checking platform settings: OK
Checking git settings: OK
Checking http connectivity to packagist: OK
Checking https connectivity to packagist: OK
Checking github.com oauth access: OK
Checking disk free space: OK
Checking pubkeys: FAIL
Missing pubkey for tags verification
Missing pubkey for dev verification
Run composer self-update --update-keys to set them up
Checking composer version: OK

[alcohol]

Looks like an environment issue, not Composer related. Nothing I can further add to this without knowing more about your system setup (operating system, partitions, usage of VM yes/no, any symlinks in your path or not, encrypted home directory or not, etc).

[curry684]

For the record, I just tried your composer.json on a Westmere Xeon backed virtual server with SSD:

[269.9MB/5.05s] Resolving dependencies through SAT
[271.3MB/5.35s] Dependency resolution completed in 0.297 seconds

Note the 5 seconds, while that's fast on the other end of the scale, your 270 seconds are definitely a local issue.

Also: are you running the latest version of Composer, on PHP 7.x? You should realize that PHP 5.6 with Xdebug on an old Composer version may on its own already be 5+ times slower than a recent build that disables Xdebug, on PHP 7.1 which is frequently 2~3 times faster than PHP 5.6 on the kind of operations that happen during cache unserialization.

[tnorthcutt]

@curry684 thanks for the comparison. I am running Composer version 1.4.1 and PHP version 7.0.15.

@alcohol sorry, I should have thought to add more info. This is on:

• 2016 rMBP 13" touchbar, 3.1ghz processor
• macOS Sierra 10.12.3
• 512gb SSD, single partition
• No VM
• Symlinks in path: _maybe_, see below
• No encrypted home directory (though I do have FileVault turned on)

My $PATH:

/Users/travis/.phpbrew/bin:/Users/travis/go/bin:/usr/local/opt/php70/bin:/usr/local/opt/coreutils/libexec/gnubin:/Users/travis/.yarn/bin:/Users/travis/bin:/Users/travis/.composer/vendor/bin:/Users/travis/dotfiles/bin:/usr/local:/usr/local/sbin:/usr/bin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin

I do have symlinks in my home directory, but they point _to_ a directory in my path. The (maybe?) relevant one:

bin -> /Users/travis/dotfiles/bin

I did try a separate/fresh install of Composer from source following the directions in CONTRIBUTING.md, but that produced substantially identical times.

Any other suggestions on how to debug further?

[alcohol]

Does FileVault not encrypt your home directory by default?

[tnorthcutt]

I believe it does, but was under the impression that while logged in, it doesn't affect performance. I'm turning it off now to test.

_Edit: some quick searching reveals FileVault probably isn't the culprit, but I'll test anyway._

[alcohol]

You could also try moving the repository to a directory that is outside of any existing path, e.g. /code.

[tnorthcutt]

Do you mean the project I'm working on, or the Composer install?

[alcohol]

The project you are working on. You can also try creating /composer and then making sure your COMPOSER_HOME environment variable it set to point at /composer.

[davidjeddy]

@tnorthcutt Any chance you're running the example application in a container service?

[tnorthcutt]

@davidjeddy Do you mean something like Docker? If so, no.

[tnorthcutt]

Ok, new info to report. I:

1. Turned FileVault off
2. Installed Composer from source in /composer
3. Set COMPOSER_HOME to /composer
4. Ran /composer/composer global require franzl/studio -vvv --profile while in /composer
5. Ran '/composer/composer update -vvv --profilewhile in/composer (this package simply because I'd been looking at it recently)

Output from 4: https://gist.github.com/tnorthcutt/6b88fb29713baf9d425b626afafb73aa (528.28 seconds)
Output from 5: https://gist.github.com/tnorthcutt/1db9a4cbdeac8edfb2183b3ebb17a953 (196.55 seconds)

Am I correct that this seems _very_ slow?

[tnorthcutt]

Now it seems a lot of the slowness is in downloading files from packagist; others are reporting issues as well.

Anecdata:

If I wget https://packagist.org/p/provider-latest%242f333ec502b004ca61c6fb3bc4bc1190d623c76fe2ff036e7bd89effb214ca25.json, my speed is 19.3KB/s

If I wget https://gist.github.com/tnorthcutt/9cd436dda5a607cd994aaeff3d1ab318/raw/862e2ba6eb3e5fba571e4b7112929b2d12643a74/provider.json (the same file), my speed is 604KB/s.

I've confirmed similar ratios with people in other geographic locations. What seems odd to me is that my connection to Packagist is an order of magnitude slower than to Github, and it's the same case for others - but theirs are on the order of ~900KB/s from Packagist and ~3MB/s from Github. So it's not as if I'm maxing out the possible connection speed to Packagist right now.

[Seldaek]

Yup it seems like we have some bandwidth crunch at peak time when the US starts working. Working on improving things. Will get back to you later.

[Seldaek]

OK we'll see how things progress, but we have an mirror live now in North America. DNS propagation should kick in slowly, so I guess in a few hours once US is at work we can assess the situation a bit more in details. Please report any weirdness.

[tnorthcutt]

I'm not sure why, but sometimes /composer/composer update -vvv --profile results in downloading new files to cache, and other times it doesn't. Anyway, I executed that command just now, and it took 558.14 seconds to run, without downloading anything: https://gist.github.com/tnorthcutt/a9553be31e79af9e1cadeb59bc1e573e

I'm completely baffled as to why file reads & writes are taking so long. I'd love to be able to debug this more, but I'm not sure how at the moment. Any pointers would be very much appreciated.

[naderman]

@tnorthcutt I see you're using Loading plugin Hirak\Prestissimo\Plugin in there, can you profile the same without the plugin? Also can you tell us what IP your DNS resolves packagist.org to and where you're located?

[Seldaek]

One question is whether it goes better today than yesterday, but given you seem to be in Australia I guess it's not gonna help as much as it will people in the US and around.

[tnorthcutt]

I'm in Oklahoma, in the US.

traceroute packagist.org:

traceroute to packagist.org (87.98.253.214), 64 hops max, 52 byte packets
 1  dsldevice (192.168.1.254)  7.653 ms  11.825 ms  12.931 ms
 2  108-220-130-1.lightspeed.okcbok.sbcglobal.net (108.220.130.1)  49.499 ms  29.246 ms  30.032 ms
 3  71.147.108.64 (71.147.108.64)  30.002 ms  53.982 ms  32.427 ms
 4  * * *
 5  12.83.71.73 (12.83.71.73)  400.389 ms
    12.83.71.77 (12.83.71.77)  409.175 ms
    12.83.71.73 (12.83.71.73)  436.222 ms
 6  gar26.dlstx.ip.att.net (12.123.16.85)  431.853 ms  462.154 ms  474.891 ms
 7  * * *
 8  * * *
 9  be100-155.nwk-5-a9.nj.us (198.27.73.29)  98.558 ms  67.636 ms  99.753 ms
10  be100-1298.ldn-5-a9.uk.eu (192.99.146.132)  177.426 ms  204.570 ms
    be100-1295.ldn-1-a9.uk.eu (192.99.146.126)  204.755 ms
11  be10-1194.gra-g2-a9.fr.eu (91.121.128.92)  248.548 ms
    be10-1193.gra-g1-a9.fr.eu (91.121.128.90)  237.393 ms
    be10-1194.gra-g2-a9.fr.eu (91.121.128.92)  205.076 ms
12  vl21.gra-g1-a75.fr.eu (213.251.128.43)  204.071 ms  143.825 ms *
13  be50-7.gra-3a-a9.fr.eu (37.187.231.88)  181.233 ms  248.780 ms
    be50-7.gra-3b-a9.fr.eu (37.187.231.92)  201.475 ms
14  eu.packagist.org (87.98.253.214)  244.092 ms *  230.853 ms

[naderman]

@tnorthcutt ok you'll hopefully get better results once your dns cache is reloaded, that's the french packagist.org you're connecting to.

[Seldaek]

You can try to hardcode packagist.org to 144.217.203.53 in your hosts file to try it out now, but please make sure to remove it again later as the IP may change without warning.

[tnorthcutt]

Got it, I'll give it a shot hardcoded.

Any ideas on the super slow file reads & writes, though? An update is taking nearly 10 minutes without any downloads 😕

[naderman]

@tnorthcutt like i said, please try without the plugin, since I'm not sure it's accurately reporting what is taking long with the downloads happening in parallel.

[tnorthcutt]

@naderman oh sorry, I meant to mention that I'm trying it without that - it's just taking a while 😬

[Seldaek]

The slow cache reads/writes, most likely that's just an impression you have from the output, because it doesn't output when the CPU is crunching stuff.

[tnorthcutt]

@Seldaek Got it. Does that seem like a normal amount of time to you?

[Seldaek]

No 10min is definitely on the long side of things. I'm investigating other factors than network (which was definitely an issue, and I hope things will improve, but it may not be the only cause for you).

[tnorthcutt]

@naderman here's a re-run without Prestissimo: https://gist.github.com/tnorthcutt/2f41f421198b88329c64a52d0730a8b1

Total time 138.15s so that's a huge improvement. I also re-ran a traceroute right after and I'm still hitting 87.98.253.214.

[naderman]

@tnorthcutt TTL on that DNS record was a day, so may take a few hours

[tnorthcutt]

I just flushed my dns and now I'm getting 144.217.203.53.

Doesn't seem to be drastically improving download speeds, though (currently running composer udpate). For instance, wget http://packagist.org/p/provider-2015%2419f785235d2cb13e2b2aa2a23244e050b64cf79d7387d678b20088406c571053.json is still giving me ~13KB/s whereas a wget to a similar-sized file at Github gets ~1MB/s.

Besides the slow network speeds, is there some way I can further diagnose my local-only issues? I'm not sure how to proceed since I'm on a fresh install of Composer, new COMPOSER_HOME set, etc.

[naderman]

@tnorthcutt I don't see any local-only issues per-se in that log file anymore? Can you send another traceroute?

[tnorthcutt]

traceroute to packagist.org (144.217.203.53), 64 hops max, 52 byte packets
 1  dsldevice (192.168.1.254)  8.286 ms  8.449 ms  4.865 ms
 2  108-220-130-1.lightspeed.okcbok.sbcglobal.net (108.220.130.1)  89.297 ms  28.015 ms  28.277 ms
 3  71.147.108.64 (71.147.108.64)  34.490 ms  32.461 ms  33.858 ms
 4  * * *
 5  12.83.71.77 (12.83.71.77)  28.156 ms
    12.83.71.73 (12.83.71.73)  32.521 ms
    12.83.71.77 (12.83.71.77)  31.109 ms
 6  gar26.dlstx.ip.att.net (12.123.16.85)  37.299 ms  41.726 ms  38.924 ms
 7  * * *
 8  * * *
 9  be100-104.nwk-1-a9.nj.us (192.99.146.253)  567.632 ms
    be100-155.nwk-5-a9.nj.us (198.27.73.29)  542.429 ms  555.572 ms
10  be10-1037.bhs-g1-a9.qc.ca (192.99.146.99)  515.780 ms  569.876 ms  547.976 ms
11  * vl21.bhs-g1-a75.qc.ca (198.27.73.63)  137.918 ms
    vl21.bhs-g2-a75-lo2.qc.ca (198.27.73.91)  189.143 ms
12  be50-5.bhs-3a-a9.qc.ca (198.27.73.92)  464.066 ms  418.524 ms
    be50-7.bhs-3b-a9.qc.ca (198.27.73.98)  98.177 ms
13  ca.packagist.org (144.217.203.53)  86.854 ms  129.686 ms  183.286 ms

[tnorthcutt]

You're right, no local-only issues on the latest run: https://gist.github.com/tnorthcutt/538b77aa8bde471114686f074762a012

I may lack a fundamental understanding of how Composer works, but sometimes it downloads many files (as on that run) and other times it downloads almost nothing. I _think_ the pattern is that on the runs when it doesn't download much, the local reads/writes are very slow. I can't say that for sure though.

[Seldaek]

@tnorthcutt did some cleanup on the illuminate stuff.. won't go too much into details here but anyway that should speed things up further.

[Seldaek]

Seems everything is going well so far so closing this https://twitter.com/packagist/status/842441015839608833

[tnorthcutt]

@Seldaek thank you! Mirror is much, much faster.

[hanoii]

For me it's always very slow, I tried to search everywhere without much success. I can't pinpoint what's the culprit, the download is most of the time slow, but sometimes it doesn't seem to be any network activity or CPU for that matters and composer just stays there.

It's normally slow, today is super super slow.. maybe it's a temporary thing.

-v hangs on Writing /Users/ariel/.composer/cache/repo/https---packagist.org/packages.json into cache but that mustn't take that long.

I am running 1.4.2 and PHP 7.0.18, no container, OSX 10.12.5, SSD drive, FileVault enabled. Any help here?

[stof]

@hanoii see https://github.com/composer/composer/issues/6342

[NabiKAZ]

This problem still exists for me, and none of the issues raised in this issue, does not resolve my problem.

[angganegara]

Yeah composer has been super super slow nowadays :( what is actually happened here? here's some log when I tried to install a single package:

[6.5MB/394.61s] Downloading https://packagist.org/p/provider-2013%241e6878bf2b5d94a5e3cb2e852c378b6e41db311b4a339875ab02c22dedf4a221.json
[ErrorException] zlib_decode(): data error

EDIT: nevermind this was a connection issue. I changed my connection and it's working fine although still a bit slow.

[juanantoniomosquera]

same problem in docker arquitecture (php container 1GB ram and 4 cores)

[davidjeddy]

@juanantoniomosq you on OSX? If so the file read/write performance is a Docker issue.
https://blog.docker.com/2017/05/user-guided-caching-in-docker-for-mac/ for example.

[juanantoniomosquera]

@davidjeddy no, linux env.

[davidjeddy]

Ah, interesting; whats the output from a traceroute?

[pascal08]

I have been struggling with Composer's speed since a couple of weeks now. First I thought it had something to do with my environment, but today I've had speed issues on a completely different environment too. Running Composer using Docker or running it on Linux host makes no differences in terms of speed. If I run composer update it reads a ton of files from cache. Sometimes it downloads it and then writes it to the cache folder. Processing every 10 files or so takes about 1 or 2 seconds. Adding up to at least a minute. I've provided a log of composer update if that could be of any help.

https://gist.github.com/pascal08/c9cdfc476b09a468989e9b95f4831671

[juanantoniomosquera]

My problem solved using latest kernel of CentOS (before use elrepo kernel).

[svycka]

Slowness for me on docker
````
composer require zendframework/zend-inputfilter -vvv --profile

[7.7MB/0.00s] Loading composer repositories with package information
[7.9MB/0.01s] Downloading https://repo.packagist.org/packages.json
[7.9MB/0.20s] Writing /root/.composer/cache/repo/https---repo.packagist.org/packages.json into cache
[8.0MB/0.21s] Updating dependencies (including require-dev)
[8.1MB/0.21s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2013.json from cache
[12.1MB/1.01s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2014.json from cache
[20.3MB/4.37s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2015.json from cache
[33.3MB/12.09s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2016.json from cache
[52.6MB/25.94s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2017.json from cache
[69.9MB/35.49s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2017-10.json from cache
[76.4MB/40.08s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2018-01.json from cache
[91.4MB/47.77s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2018-04.json from cache
[102.3MB/56.47s] Downloading http://repo.packagist.org/p/provider-2018-07%24bd48a4a312894b4b8c944cab441fe479f3ce547c949cf6e4c22546ff6a399f90.json
[119.5MB/62.95s] Writing /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2018-07.json into cache
[115.8MB/63.43s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-archived.json from cache
[115.6MB/63.70s] Downloading http://repo.packagist.org/p/provider-latest%2486b0f858d808d6a10b6f375c1e3842bfce12a7b84ca118737c1bf77bbcd42d4f.json
[122.7MB/65.42s] Writing /root/.composer/cache/repo/https---repo.packagist.org/p-provider-latest.json into cache
.....
[448.1MB/271.58s] Memory usage: 448.11MB (peak: 498.2MB), time: 271.58s
````
also I am not sure how much memory composer should eat but 500MB sounds too mutch to install one dependancy.

[juanantoniomosquera]

Slowness for me on docker

composer require zendframework/zend-inputfilter -vvv --profile

[7.7MB/0.00s] Loading composer repositories with package information
[7.9MB/0.01s] Downloading https://repo.packagist.org/packages.json
[7.9MB/0.20s] Writing /root/.composer/cache/repo/https---repo.packagist.org/packages.json into cache
[8.0MB/0.21s] Updating dependencies (including require-dev)
[8.1MB/0.21s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2013.json from cache
[12.1MB/1.01s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2014.json from cache
[20.3MB/4.37s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2015.json from cache
[33.3MB/12.09s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2016.json from cache
[52.6MB/25.94s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2017.json from cache
[69.9MB/35.49s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2017-10.json from cache
[76.4MB/40.08s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2018-01.json from cache
[91.4MB/47.77s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2018-04.json from cache
[102.3MB/56.47s] Downloading http://repo.packagist.org/p/provider-2018-07%24bd48a4a312894b4b8c944cab441fe479f3ce547c949cf6e4c22546ff6a399f90.json
[119.5MB/62.95s] Writing /root/.composer/cache/repo/https---repo.packagist.org/p-provider-2018-07.json into cache
[115.8MB/63.43s] Reading /root/.composer/cache/repo/https---repo.packagist.org/p-provider-archived.json from cache
[115.6MB/63.70s] Downloading http://repo.packagist.org/p/provider-latest%2486b0f858d808d6a10b6f375c1e3842bfce12a7b84ca118737c1bf77bbcd42d4f.json
[122.7MB/65.42s] Writing /root/.composer/cache/repo/https---repo.packagist.org/p-provider-latest.json into cache
.....
[448.1MB/271.58s] Memory usage: 448.11MB (peak: 498.2MB), time: 271.58s

also I am not sure how much memory composer should eat but 500MB sounds too mutch to install one dependancy.

kernel host problem probably..

[svycka]

restarted pc and rebuild docker image now
[330.7MB/6.22s] Memory usage: 330.71MB (peak: 383.52MB), time: 6.22s
so maybe you were right

[rvitaliy]

@juanantoniomosquera @svycka thanks! you save my day!
same problem, reboot PC and it's work well again.