Installation of some libraries dramatically slower than alternative tooling

[nwoolls]

Functional impact

Does the bug result in any actual functional issue, if so, what?

If the library is cached, installation is quick enough. However, without libraries in cache, the performance of installing / restoring a library is dramatically slower than alternatives such as NPM and Bower.

Minimal repro steps

What is the smallest, simplest set of steps to reproduce the issue. If needed, provide a project that demonstrates the issue.

1. mkdir libman-speed-test
2. cd libman-speed-test/
3. npm cache clean --force
4. bower cache clean
5. libman cache clean
6. time npm install [email protected]
7. time bower install ckeditor#4.6.2 --save
8. time libman install [email protected] --provider cdnjs --destination libman_libs/ckeditor

Expected result

What would you expect to happen if there wasn't a bug

LibMan should install / restore the specified library in an amount of time comparable to alternatives such as NPM and Bower.

Actual result

What is actually happening

With the above steps, installing the specified library takes:

• NPM: 3.63s
• Bower: 8.49s
• LibMan: 2m47.92s

Further technical details

Optional, details of the root cause if known

[nwoolls]

FWIW jQuery UI is another package where this is reproducible:

• NPM: 3.57s
• Bower: 4.58s
• LibMan: 27.95s

[AdamWillden]

This is killing productivity because it restores client libraries after every c# code change, if it didn't take so long this wouldn't be such an issue.

1>Restore operation started...
1>Restoring library @fortawesome/[email protected]...
1>Restoring library [email protected]...
1>Restoring library [email protected]...
1>Restoring library [email protected]...
1>Restoring library [email protected]...
1>Restoring library [email protected]...
1>
1>6 libraries restored in 59.33 seconds

Is there a workaround? I'm using unpkg, would using a different provider help?

[nwoolls]

@AdamWillden IME the issue happens even with the CDNJS. That being said, IME UnPkg is even worse, including random timeout errors trying to restore packages (on a different file each time). The issue(s) with UnPkg are being discussed to some degree here: https://github.com/aspnet/LibraryManager/issues/344

[AdamWillden]

@nwoolls thanks for the info, I appreciate it. I'll subscribe there too 👍

[Casimodo72]

I'm trying to use libman since yesterday and I would say that my 16 seconds are also too much for every build at development time. Could a cache be added to libman, or did I miss something?

I can't resist to add: I didn't notice this at first because I'm currently migrating from ASP MVC 5, so I thought "ok, so the startup time has not improved in ASP .NET Core" :-D

1>Restore operation started... 1>Restoring library @types/[email protected]... 1>Restoring library @types/[email protected]... 1>Restoring library @types/[email protected]... 1>Restoring library @types/[email protected]... 1>Restoring library @types/[email protected]... 1>Restoring library @types/[email protected]... 1>Restoring library [email protected]... 1>Restoring library [email protected]... 1>Restoring library [email protected]... 1>Restoring library [email protected]... 1>Restoring library [email protected]... 1>Restoring library [email protected]... 1> 1>12 libraries restored in 16,29 seconds

[Braytiner]

material-design-icons is another package with the same problem

[Casimodo72]

A local cache would really be usefull. I'm mobile on a laptop and I can't build when I'm offline. I'm getting build errors like the following: "The "@types/[email protected]" library could not be resolved by the "unpkg" provider" I'm switching back to npm. Dunno for which scenario Libman was created. Obviously it's not mine (yet?).

[jimmylewis]

I played around with this a little bit, adding some details to the thread in case I don't have time to come back to a fix soon.

For my testing I was doing a libman restore with this manifest:

{
  "version": "1.0",
  "defaultProvider": "cdnjs",
  "libraries": [
    {
      "library": "[email protected]",
      "destination": "ckeditor"
    }
  ]
}

Restore ran in about 55 seconds, with an empty cache. It took 15 seconds when the cache was populated (i.e. this is just local file copy time).

I noticed that when we populate the local cache, we are currently downloading the files in serial order, not in parallel. See: https://github.com/aspnet/LibraryManager/blob/7446121b01aac63ca3e10114981508965c81822e/src/LibraryManager/CacheService/CacheService.cs#L92-L102

Basically, we await the download of each file in the loop, then do a Task.WaitAll(...) after we've already awaited each one. Probably an oversight.

If we were to just remove the await on line 97, we would create as many tasks as there are files in the library (200+ for something like ckeditor), which seems bad. I tweaked it to do 10 downloads in parallel, and the total install time went down to 24 seconds.

Next, I found where we copy the files from the cache to the local project. This is a provider specific implementation, and also depends on the host (CLI vs. VS vs. MSBuild; VS is probably even slower as it handles source control integration and adding files into the project where applicable). I tweaked the cdnjs provider to also do these copies in parallel, and it brought the overall time down to around 14 seconds.

It's still a little slower than other tools, but I haven't yet spent any time tweaking with the parallelism factor or looking beyond those two bottlenecks.

TL;DR: there's a lot of improvement to be had by doing I/O operations in parallel.

[AdamWillden]

Thanks for taking a look a this! <3

Heres the same code fixed as you suggested but with some linq and clean coding practices applied (written without a compiler). Note the reuse of the new DoesNotExistOrHasExpired function within GetResourceAsync

private async Task<string> GetResourceAsync(
    string url, 
    string localFile, 
    int expirationDays, 
    CancellationToken cancellationToken)
{
    cancellationToken.ThrowIfCancellationRequested();

    if (DoesNotExistOrHasExpired(localFile, expirationDays))
    {
        await DownloadToFileAsync(url, localFile, cancellationToken).ConfigureAwait(false);
    }

    return await FileHelpers.ReadFileAsTextAsync(localFile, cancellationToken).ConfigureAwait(false);
}

public Task RefreshCacheAsync(
    IEnumerable<CacheServiceMetadata> librariesCacheMetadata, 
    CancellationToken cancellationToken)
{
    cancellationToken.ThrowIfCancellationRequested();

    var refreshTasks = librariesCacheMetadata
        .Where(DoesNotExistOrHasExpired)
        .Select(x => DownloadToFileAsync(x, cancellationToken));

    return Task.WhenAll(refreshTasks).ConfigureAwait(false); 
}

private Task DownloadToFileAsync(
    CacheServiceMetadata metadata,
    CancellationToken cancellationToken)
{
    return DownloadToFileAsync(
        metadata.Source, 
        metadata.DestinationPath, 
        cancellationToken); 
}

private bool DoesNotExistOrHasExpired(CacheServiceMetadata metadata)
{
    return DoesNotExistOrHasExpired(metadata.DestinationPath, _libraryExpiresAfterDays);
}

private bool DoesNotExistOrHasExpired(string destinationPath, int expirationDays)
{
    return DoesNotExist(destinationPath) 
        || HasExpired(destinationPath, expirationDays);
}

private bool DoesNotExist(string destinationPath)
{
    return !File.Exists(destinationPath);
}

private bool HasExpired(string destinationPath, int expirationDays)
{
    return GetExpiry(destinationPath, expirationDays) < DateTime.Now;
}

private DateTime GetExpiry(string destinationPath, int expirationDays)
{
    return File.GetLastWriteTime(destinationPath).AddDays(expirationDays);
}

If you don't want clean code practices then please at least move the .AddDays(-_libraryExpiresAfterDays); to the other side of the expression with .AddDays(_libraryExpiresAfterDays); I couldn't tell if I was looking at a bug for a moment

Incidentally also if you have a method that returns a task but does not do any processing after after the completion of the task. When this is the case you do not need the async await keywords. async await do add a bit of overhead due to the state machine that is put in by the compiler. Thus the following methods can become:

public Task<string> GetCatalogAsync(string url, string cacheFile, CancellationToken cancellationToken)
{
    return GetResourceAsync(url, cacheFile, _catalogExpiresAfterDays, cancellationToken);
}

public Task<string> GetMetadataAsync(string url, string cacheFile, CancellationToken cancellationToken)
{
    return GetResourceAsync(url, cacheFile, _metadataExpiresAfterDays, cancellationToken);
}

[jimmylewis]

Revisiting this after #538 and #541. With the original repro (using [email protected]) from a clean directory and clean cache now took me 38 seconds. When the cache is populated it took 23 seconds.

When I added an anti-virus exclusion for the folder I was coping to, the first time still took about 20 seconds from cache. The second time took 4 seconds (as did a 3rd and 4th time).

Installing jqueryui from clean also took around 4 seconds including download (<1 sec from cache) after I was getting 4 sec times for ckeditor.

I'll take another swing at this soon to see if I can try to figure out why AV is getting in the way so harshly, but we're making progress on this.

[RobJohnston]

I'm hoping that what @Casimodo72 said in https://github.com/aspnet/LibraryManager/issues/389#issuecomment-449877677 also gets addressed as well. Use the local cache if all else fails.

Related to #370 and #234.

[jimmylewis]

We do have (and use) a local cache, but we don't cache library metadata for the Unpkg/JSDelivr providers yet. Basically, what happens is:

1. We try to resolve the package ID and request its metadata (e.g. is the version valid, what files are contained in the library, etc)
2. We calculate the list of files that we need to download/install into your project using this metadata (the glob expansion from #534), or to see if you've listed files that don't exist (which returns an error)
3. We check if the requested files are in the local cache for that library@version. If not, we download them.
   • We also used to have a 30-day cache life for downloaded files, but that will be gone in our next released version (part of #538). Seemed silly to re-download the same files every month.
4. We check if files in the cache are different from the files in your project (e.g. did you just upgrade to a newer version). If the files are different, we overwrite the file in your project with the one from the cache.

[BPA8]

I have been facing performance issues with libman for over 1.5 year now and nothing has changed on this front. below is the log from today

1>Build started 5/4/2020 11:32:31 AM. 1>Target LibraryManagerRestore: 1>
1> Restore operation started... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1> Restoring library [email protected]... 1>
1> 17 libraries restored in 1175.88 seconds

I am not sure why it takes so long to even enable connection, seems like once it establishes connection with unpkg, downloads happen quickly. Is obtaining connection an issue or downloading files in parallel?

every time we deploy this to our environments the build pipelines run for about 20-25 mins blocking other jobs. For local environment I always set restore option to false and enable to true only when I add a new package to list. Please share any workarounds if available any. much appreciated

[jimmylewis]

@BPA8 which version of the package are you using for restore? Libman does have a local cache, but that doesn't help if you're on a fresh build agent. Recent packages also now show an output message (MSBuild verbosity normal or higher) showing each file that is downloaded, which your sample doesn't have, so you might not have the latest improvements.

[BPA8]

@jimmylewis - thanks for pointing me to latest version of libman. I am on 2.1.76 version now. the time taken to download the files now came down by 10x times.

17 libraries restored in 172.86 seconds That is a huge performance boost. hopefully, its performance will improve much more in future

[purplepiranha]

I also have a similar problem when restoring fontawesome-free via libman (using the unpkg provider).

I don't have the problem on build (I haven't got restore on build enabled), but having just updated font awesome to the latest version in libman.json:

{
   "provider": "unpkg",
   "library": "@fortawesome/[email protected]",
   "destination": "wwwroot/lib/fortawesome/fontawesome-free/"
}

I have then had to wait 51 minutes on a gigabit connection for it to restore a package that's less that 17MB in size.

1 libraries restored in 3068.26 seconds

This is a regular occurrence and I can't really understand why it's so slow.