Cocoapods: Slow dependency resolution

[yanzhiwei147]

Report

What did you do?

Use pod update --no-repo-update

What did you expected to happen?

Don't block at Resolving dependencies of Podfile

What happened instead?

I have a huge dependencies tree(about 15 depths),about 260 pcs(I use private pod repo in house).It use long time for resolving dependencies(taking up about 95% of the total time), about 35 minutes,i mind it's a problem.

Podfile

I use private pod repo in house,and i can't provide it.sorry.

[segiddins]

I don't really know what to do without a reproduction case, sorry. You'll either have to share one or investigate yourself.

[yanzhiwei147]

@segiddins OK,thank you very much.

[alloy]

@yanzhiwei147 The best course would be to run pod update through a profiler and figure out where the time is being spent and if that can be improved. E.g. like this person did https://github.com/CocoaPods/Molinillo/pull/39 with ruby-prof.

[jrafanie]

@yanzhiwei147 FYI, here's a intro to ruby-prof since I did the same in the linked CocoaPods/Molinillo#39.

I added gem 'ruby-prof' to my Gemfile and bundled...

Then ran a script like this:

def ruby_prof_block
  require 'ruby-prof'
  result = RubyProf.profile do
    yield
  end

  File.open("./graphs/callstack.html", "w") do |file|
    RubyProf::CallStackPrinter.new(result).print(file, :threshold => 0.5, :expansion => 1.0)
  end
end

ruby_prof_block { require 'bundler/setup'}  # whatever you want to profile in the block

See the output in the graphs directory.

[yanzhiwei147]

Let me try it now.

[yanzhiwei147]

Excuse me, i do not know how to run this ruby script,and it run before execute pod update? I hope to get your help. Thank you!

[jrafanie]

I assume you'll have to determine what pod update calls in ruby so you can do the same thing within the profiling block.

[alloy]

This is where the pod update CLI command lives: https://github.com/CocoaPods/CocoaPods/blob/242da6b56683dd173b1ab9f3c998308374c9415c/lib/cocoapods/command/update.rb

I _think_ you should be able to require that file into your profiling script and invoke it like so:

ruby_prof_block do
  require 'cocoapods'
  Pod::Command::Update.new(CLAide::ARGV.new([])).run
end

[jrafanie]

Thank you @alloy, that was the part I had no idea! ❤️

[yanzhiwei147]

@jrafanie @alloy I try to run this script today, but it seem block all day.

Update all pods
Updating local specs repositories

CocoaPods 1.0.0.beta.8 is available.
To update use: `gem install cocoapods --pre`
[!] This is a test version we'd love you to try.

For more information see http://blog.cocoapods.org
and the CHANGELOG for this version http://git.io/BaH8pQ.

Analyzing dependencies
Pre-downloading: `RATreeView` from `https://github.com/Augustyniak/RATreeView.git`, commit `5c08a85`
Fetching podspec for `LanguageImport` from `project/Resources/i18n`
Fetching podspec for `SkinImport` from `project/Resources/skin`

[jrafanie]

@yanzhiwei147 If it takes 35 minutes with no profiling, it may never finish under rubyprof. Sorry, I didn't think of that.

Perhaps there is a way to run it with a smaller number of your dependencies so it doesn't take forever?

I would do this if possible:

1. Time the pod update --no-repo-update with your current dependencies (with no profiling)
2. Remove one or more dependencies
3. Cleanup the environment so you can repeat step 1 until you get down to less than 3 minutes
4. Now, profile the subset of dependencies that take 3 minutes... I'd imagine it could still take 1 hour or more to run.

Also, stackprof block might also yield some useful information since it has a lot less overhead since it's a sampling profiler. Add gem 'stackprof' to your Gemfile (requires ruby 2.1+ I believe)

def stack_prof_block
  require 'stackprof'
  StackProf.run(:mode => :wall, :out => "tmp/stackprof.dump") do
    yield
  end
end

stack_prof_block do
  require 'cocoapods'
  Pod::Command::Update.new(CLAide::ARGV.new([])).run
end

Then run stackprof tmp/stackprof.dump

Note, my output for bundler looks like this:

stackprof graphs/stackprof_21689.dump
==================================
  Mode: wall(1000)
  Samples: 1266 (3.28% miss rate)
  GC: 168 (13.27%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       177  (14.0%)          94   (7.4%)     Bundler::Molinillo::DependencyGraph#add_vertex
        83   (6.6%)          83   (6.6%)     Bundler::Molinillo::DependencyGraph::Vertex#initialize
      1616 (127.6%)          72   (5.7%)     Kernel#require
        56   (4.4%)          56   (4.4%)     Gem::BasicSpecification#internal_init
       247  (19.5%)          39   (3.1%)     block in Bundler::Molinillo::DependencyGraph#initialize_copy
        38   (3.0%)          38   (3.0%)     block in Bundler::Runtime#setup_manpath
        37   (2.9%)          37   (2.9%)     Bundler::Molinillo::DependencyGraph#add_edge_no_circular
        34   (2.7%)          32   (2.5%)     block in Gem::Specification#initialize
        34   (2.7%)          31   (2.4%)     Set#add
        97   (7.7%)          25   (2.0%)     Bundler::Index#search_by_dependency
...

Note, there's other options for wall/cpu time, object counts, etc.

Another option I've used in the past is to run simplecov to get a code coverage report (since it also has less overhead to run)... It's been useful for me because it can show you which lines were executed and how many times. Sometimes, just seeing some lines run so frequently can help figure out problems.

[yanzhiwei147]

@jrafanie Sorry,i'm sick.The dump now available.you must change expand name to dump.

pod_update.dump.txt

[yanzhiwei147]

Below is after run stackprof tmp/stackprof.dump.

==================================
  Mode: wall(1000)
  Samples: 1058622 (0.31% miss rate)
  GC: 132838 (12.55%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
    193473  (18.3%)      193473  (18.3%)     Pod::Specification#platform_hash
    209329  (19.8%)       98023   (9.3%)     Pod::Platform#initialize
     90820   (8.6%)       57299   (5.4%)     Pod::Requirement#initialize
     54905   (5.2%)       54905   (5.2%)     Pod::Version.correct?
    104904   (9.9%)       49999   (4.7%)     Pod::Version#initialize
    146175  (13.8%)       30002   (2.8%)     Pod::Dependency#initialize
     59030   (5.6%)       27627   (2.6%)     Pod::Specification::DSL::RootAttributesAccessors#name
     27456   (2.6%)       27456   (2.6%)     Pod::Podfile::TargetDefinition#get_hash_value
    259925  (24.6%)       23473   (2.2%)     Pod::Specification#deployment_target
     33186   (3.1%)       20604   (1.9%)     Pod::Requirement.parse
     18480   (1.7%)       18480   (1.7%)     Pod::Specification::DSL::RootAttributesAccessors#base_name
    111307  (10.5%)       18248   (1.7%)     Pod::Vendor::Gem::Version.create
     28679   (2.7%)       18118   (1.7%)     Pod::Vendor::Gem::Version#segments
     20260   (1.9%)       15076   (1.4%)     Pod::Specification::Consumer#prepare_value
     63460   (6.0%)       14716   (1.4%)     Pod::Version#<=>
     14214   (1.3%)       14214   (1.3%)     block in #<Module:0x007fc10b282098>.popen3
     13208   (1.2%)       13208   (1.2%)     Molinillo::DependencyGraph::Vertex#hash
    103962   (9.8%)       13178   (1.2%)     Pod::Requirement.create
    196826  (18.6%)       12948   (1.2%)     Pod::Podfile::TargetDefinition#platform
     16929   (1.6%)       11286   (1.1%)     Pod::Source#search
    653955  (61.8%)       10788   (1.0%)     Pod::Resolver#edge_is_valid_for_target?
     10561   (1.0%)       10561   (1.0%)     block in Pod::Vendor::Gem::Version#segments
     11992   (1.1%)       10486   (1.0%)     Pod::Dependency#==
      9189   (0.9%)        9189   (0.9%)     Pod::Specification#root?
  11682347 (1103.5%)        7825   (0.7%)     Pod::Resolver#valid_dependencies_for_target_from_node
      7611   (0.7%)        7611   (0.7%)     block in Pod::Version#numeric_segments
      7383   (0.7%)        7383   (0.7%)     Pod::Specification#default_subspecs
      7316   (0.7%)        7316   (0.7%)     Pod::Vendor::Gem::Version#version
    249687  (23.6%)        7096   (0.7%)     Molinillo::DependencyGraph::Vertex#recursive_predecessors
      6508   (0.6%)        6508   (0.6%)     Pod::Platform#to_sym

[jrafanie]

@yanzhiwei147 I am not familiar with cocoapods but the first two (Pod::Specification#platform_hash, Pod::Platform#initialize) seem related... Maybe you can decrease the large number of dependencies locally so you can get it to run normally in 2-5 minutes where stackprof shows simular % as above. Then, try rubyprof with this reduced dependency tree as described above to see what that shows.

Being naive to the code base, these samples from above are very interesting since they seem to show up in similar number of TOTAL samples... Maybe they're called N times, where N is the size/complexity of the dependency tree:

    259925  (24.6%)       23473   (2.2%)     Pod::Specification#deployment_target
    196826  (18.6%)       12948   (1.2%)     Pod::Podfile::TargetDefinition#platform
    193473  (18.3%)      193473  (18.3%)     Pod::Specification#platform_hash
    209329  (19.8%)       98023   (9.3%)     Pod::Platform#initialize

https://github.com/CocoaPods/Core/blob/33d5fbcfb956cfef621bfb1b03e0880d6de4a546/lib/cocoapods-core/specification.rb#L405

I would wonder if you have dependencies that are specifying a large number of platforms in their specification.

If platform_hash is expensive, it's interesting that both deployment_target and supported_platform_names call platform_hash without caching the result here and here. I don't know if deployment_target and supported_platform_names are called multiple times per specification but caching/memoizing platform_hash (if it doesn't change) might help.

[segiddins]

Looks like we might want to cache creating of Dependency and Version objects like RubyGems does, and probably cache platform hashes by podspec in the resolver (that way they can be GC'ed after resolution is done)

[yanzhiwei147]

@segiddins What's the time to release it? I found the time is exponential order.

[segiddins]

To release what?

[jafara]

This might speed up our pod install/update as well. We have around 75 pods in our project.

I also wonder why installation of pods couldnt be parallelized?

[segiddins]

@jafara we tried parallelization but decided it wasn't worth the complexity

[jcampbell05]

Could some of the resolution results be baked into the Lockfile to speed it up ? I think having a more expensive hit on an update is acceptable since most of the time you only want to install.

[segiddins]

@jcampbell05 they already are entirely baked into the lockfile when possible

[jrafanie]

@segiddins What's the time to release it? I found the time is exponential order.

@yanzhiwei147 this project is open source so you could try fixing it based on @segiddins's description ☝️ above. Time is limited for everyone, especially project maintainers who donate their limited time, so it's very helpful to provide as much information as you can.

It would be helpful if we had a simplified set of recreation steps to demonstrate the slowness but within a reasonable time. Aim for less than 5 minutes without profiling. Then, verify the stackprof results for the simplified case looks very similar to your 35 minute scenario. I'd imagine you could start with some of the dependencies in your project and start adding/removing dependencies until you get to 2-5 minutes unprofiled resolution time. Of course if maintainers have other suggestions, listen to them.

With that minimal recreation case, we might have a shot at proposing solutions based on @segiddins suggestions... or provide enough direction that maintainers could fix up and get merged.

If this is that painful for you, see if you can provide the steps to reproduce it as described above. We all want painful slowness fixed.

[yanzhiwei147]

Thank you for your reply. I have 65 pods(At Podfile),but it have 1510 leafs in dependency tree(it can A->B, B->C. It's possible exist A->C).I do not know how to get back to you.

[segiddins]

@yanzhiwei147 the fastest way to get this improved will be for you to make a PR -- I don't know when I'll have time to look into performance improvements next

[wupher]

I recently came across the same situation, I have around 200 pods dependencies in our project. The CI compile process is long and painful, even with "--no-repo-update" options. The android project also got same dependencies number, but looks like Gradle and Maven works fine.

[jrafanie]

@wupher how does your stackprof output look compared to above? Where is your Podfile? How can I recreate it? What is your version or ruby version? We can't fix something we can't measure.

[wupher]

• the Podfile: http://dl.dropbox.com/u/1622618/Podfile
• the Podfile.lock: http://dl.dropbox.com/u/1622618/Podfile.lock
• Ruby Version: 2.2.2 / 2.0.0p645 2 Mac Pro as Jenkins Server
• Pod Version: 0.39.0 , I tried the Pod 1.0 but it's also slow

I try to find out what's wrong with it. It seems something wrong on molinillo's recursive_predecessors:

[yanzhiwei147]

@segiddins I'm sorry i can't fix it and make a PR. I have not learned Ruby,Otherwise i also hope that their contribution to a force. Your easy work for me is hard work.

[jkluolin3000]

http://stackoverflow.com/questions/23006683/cocoapods-staying-on-analyzing-dependencies

is like this problem?

[yanzhiwei147]

http://stackoverflow.com/questions/23006683/cocoapods-staying-on-analyzing-dependencies

is like this problem?

@jkluolin3000 No, it's complicated than you think.

[jrafanie]

@wupher thanks. The problem is it appears to be a specific dependency traversal problem, possibly due to cycles in the dependencies or many pods with many dependencies, but your Podfile doesn't appear to have public pods, so I can't run it. Is there open source app with a Podfile that you can recreate this issue on? Otherwise, we're guessing where the problem is.

If you can't provide a Podfile with public pods, you'll have to investigate the problem.

[orta]

Artsy/Eigen has a podfile with ~60 pods in it - but we don't see any of these problems alas

[wupher]

thank you guys, I'll try to recreate the issue with public pod dependencies.

[yanzhiwei147]

@jrafanie I move the private specs repo to github,now you can reappear this issue by yourself:

• use Cocoapods version 0.39.0
• use below Podfile content

source 'https://github.com/CocoaPods/Specs.git'
source 'https://github.com/SlowDepend/Specs.git'

pod 'MUIKit'
pod 'MUPFoundation'
pod 'BlocksKit'

#com.nd.sdp:uc_component:release


pod 'UCComponent', '0.2.107'
pod 'UCSDK','0.10.76'
pod 'VirtualOrgSDK','1.0.25'
pod 'UCExtend', '0.2.29'
pod 'ContentServiceSDK', '0.2.51'
pod 'CephS3SDK','1.3.0'



#com.nd.smartcan.appfactory:main_component:release


pod 'APFMainComponent', '0.2.67'
pod 'APFKit', '0.1.69'
pod 'MUPFoundationNetworking', '1.0.15'
pod 'SmartCan', '0.5.24'
pod 'APFWebKit', '1.0.25'
pod 'SMCDataLayer', '0.4.19'
pre_install do
    system("sed -i '' '/UITextField/d' Pods/BlocksKit/BlocksKit/BlocksKit+UIKit.h")
    system('rm Pods/BlocksKit/BlocksKit/UIKit/UITextField+BlocksKit.h')
    system('rm Pods/BlocksKit/BlocksKit/UIKit/UITextField+BlocksKit.m')
end



#com.nd.social:backpack:release


pod 'BackpackComponent', '6.5.1'



#com.nd.social:im:release


pod 'IMSComponent', '6.5.6'
pod 'IMSDK','6.5.6'
pod 'RATreeView', :git => 'https://github.com/kukushi/RATreeView.git', :commit => 'a4c96cb38bcd95f405b26d59363add1bd397d846'



#com.nd.social:voting:release


pod 'VotingComponent', '0.2.34'



#com.nd.social:notice:release


pod 'NoticeComponent', '0.3.45'



#com.nd.social:appbox:release


pod 'AppBoxComponent','6.3.0'



#com.nd.social:weibo:release


pod 'MicroBlogComponent','6.6.1'



#com.nd.social:lottery:release


pod 'LotteryComponent', '6.1.1'



#com.nd.social:appsetting:release


pod 'AppSettingComponent','6.5.0'



#com.nd.social:flower:release


pod 'SendFlowerComponent', '6.6.0'



#com.nd.social:ERP:release


pod 'ERPComponent','0.6.27'
pod 'CLOfficeSDK', '0.1.39'
pod 'COCommonUIKit', '0.1.55'



#com.nd.social:birthdaywishes:release


pod 'BirthdayWishesComponent', '0.4.4'



#com.nd.social:me:release


pod 'MeComponent','6.3.0'



#com.nd.social:greenhandguide:release


pod 'GreenHandGuideComponent','0.1.7'



#com.nd.social:netdisk:release

pod 'YunPanComponent', '0.4.15'


#com.nd.sdp:common_skin_component:release


pod 'CommonSkinComponent', ' 1.2.9'



#com.nd.social:forum:release


pod 'ForumComponent', '6.5.0'
pod 'RATreeView', :git => 'https://github.com/kukushi/RATreeView.git', :commit => 'a4c96cb38bcd95f405b26d59363add1bd397d846'



#com.nd.social:news:release


pod 'NewsComponent', '6.5.1'



#com.nd.erp:employee:release


pod 'ProfileComponent', '0.2.10'



#com.nd.erp:esop:release


pod 'ESOPComponent', '0.0.21'



#com.nd.erp:violation:release


#com.nd.erp:integral:release


#com.nd.erp:atnd:release


pod 'ATNDComponent','0.2.9'



#com.nd.social:qr-code:release


pod 'QRCodeComponent', '0.2.11'



#com.nd.social:activity:release


pod 'ActivityComponent','6.3.4'



#com.nd.hy:elearning:release


pod 'elearning2', '3.5.11'



#com.nd.sdp:data_analysis_component:release


pod 'DAComponent', '1.0.12'



#com.nd.erp:goods:release


#com.nd.sdp.component:crashreport:release


#com.nd.social:lbs:release


pod 'LBSComponent', '0.0.27'



#com.nd.social:vote:release


pod 'VoteComponent', '6.6.0'



#com.nd.oa:improve-info:release


pod 'ImproveInfoComponent', '0.0.6'



#com.nd.social:cloudalbum:release


pod 'CloudPhotoAlbumComponent', '0.1.15'



#com.nd.social:donatecomponent:release


pod 'SocialDonateComponent', '6.2.6'



#com.nd.social:collection:release


pod 'CollectionComponent', '0.4.9'



#com.nd.cloudoffice:sign:release


pod 'CloudSignInComponent', '1.1.54'



#com.nd.cloud:cloud-db:release


#com.nd.social:emotionmall:release


pod 'MUIExpressionMallComponent', '0.0.12'



#com.nd.sdp.component.cloudatlas:cloud-atlas-component-bussiness:release


pod 'cloudatlas_ios_component', '0.7.1'



#com.nd.social:appextention:release

• add private spec

$ pod repo add slow_dependency https://github.com/SlowDepend/Specs.git

• execute below command

$ pod update --verbose

• no more the steps, now you can found the miracle.

[yanzhiwei147]

@jrafanie It calculate too many times? Maybe We can get a good idea to solve this problem. thank you very much.

[jrafanie]

Thanks @yanzhiwei147. I'll try to run some tests the next few days.

Do you have a Podfile.lock before you run pod update --verbose?

[yanzhiwei147]

@jrafanie So what's the result to run this test case?

[jrafanie]

@yanzhiwei147 Thanks for providing a public set of pods to try this against. I'll try to get to it soon. My suggestions still stand above... Limit the podfile one dependency at a time until you get it to run in less than 5 minutes so you can profile it with ruby prof. Another option is to try running the same 5 minute run with simplecov (code coverage)... between stackprof, rubyprof and simplecov, we should be able to see if we have a really slow method, some method is run too often (same inputs, same outputs... it's not cached when it should be), etc.

I don't actually use cocoapods, only the shared resolver, Molinillo, with bundler so I can only test this in my free time.

[yanzhiwei147]

@jrafanie Thank you for you reply.I found this function can be optimized. It can be cached for follow up calc, now we run this command less than 40s. So should we make a PR to you?

[segiddins]

@yanzhiwei147 yes, a PR would be much appreciated 😄

[neonichu]

Fixed in #5578