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

Composer very slow to read & write cache files #6263

Closed
tnorthcutt opened this issue Mar 14, 2017 · 49 comments
Closed

Composer very slow to read & write cache files #6263

tnorthcutt opened this issue Mar 14, 2017 · 49 comments
Labels

Comments

@tnorthcutt
Copy link

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
Copy link
Member

alcohol commented Mar 15, 2017

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
Copy link
Contributor

curry684 commented Mar 15, 2017

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
Copy link
Author

@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
Copy link
Member

alcohol commented Mar 15, 2017

Does FileVault not encrypt your home directory by default?

@tnorthcutt
Copy link
Author

tnorthcutt commented Mar 15, 2017

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
Copy link
Member

alcohol commented Mar 15, 2017

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

@tnorthcutt
Copy link
Author

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

@alcohol
Copy link
Member

alcohol commented Mar 15, 2017

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
Copy link

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

@tnorthcutt
Copy link
Author

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

@tnorthcutt
Copy link
Author

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
Copy link
Author

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
Copy link
Member

Seldaek commented Mar 16, 2017

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
Copy link
Member

Seldaek commented Mar 16, 2017

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
Copy link
Author

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
Copy link
Member

@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
Copy link
Member

Seldaek commented Mar 16, 2017

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
Copy link
Author

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
Copy link
Member

@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
Copy link
Member

Seldaek commented Mar 16, 2017

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
Copy link
Author

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
Copy link
Member

@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
Copy link
Author

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

@Seldaek
Copy link
Member

Seldaek commented Mar 16, 2017

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
Copy link
Author

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

@Seldaek
Copy link
Member

Seldaek commented Mar 16, 2017

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
Copy link
Author

@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
Copy link
Member

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

@tnorthcutt
Copy link
Author

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
Copy link
Member

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

@tnorthcutt
Copy link
Author

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
Copy link
Author

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
Copy link
Member

Seldaek commented Mar 16, 2017

@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
Copy link
Member

Seldaek commented Mar 16, 2017

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

@Seldaek Seldaek closed this as completed Mar 16, 2017
@tnorthcutt
Copy link
Author

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

@hanoii
Copy link

hanoii commented May 23, 2017

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
Copy link
Contributor

stof commented May 23, 2017

@hanoii see #6342

@NabiKAZ
Copy link

NabiKAZ commented Dec 16, 2017

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

@angganegara
Copy link

angganegara commented Dec 19, 2017

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
Copy link

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

@davidjeddy
Copy link

@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
Copy link

@davidjeddy no, linux env.

@davidjeddy
Copy link

Ah, interesting; whats the output from a traceroute?

@pascal08
Copy link

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
Copy link

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

@svycka
Copy link

svycka commented Sep 20, 2018

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
Copy link

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
Copy link

svycka commented Sep 20, 2018

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
Copy link

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests