[R-package] speed up installation with Visual Studio #2965

jameslamb · 2020-04-02T03:53:16Z

This is another PR that contributes to #2936 , but which I think has standalone value.

Right now on Windows, to figure out which version of Visual Studio is available we try to build lib_lightgbm by generating and executing the corresponding CMake Makefile for the 3 most recent versions of VS. This is pretty expensive, and means that you have to build lib_lightgbm .

I went into this thinking that this is why r-package CI builds on Azure Devops with Visual Studio take 20 minutes...and it seems like it! I tested merging these changes into #2936 on my fork, and it takes the build time down from 20 minutes to about 9 minutes.

StrikerRUS

Huh, fake project, nice hack!

R-package/src/install.libs.R

jameslamb · 2020-04-08T19:46:01Z

@Laurae2 @StrikerRUS could you have another look?

StrikerRUS

I don't see any issues in logic in this PR. But please wait for an approval of R-maintainers 🙂 .

R-package/src/install.libs.R

.vsts-ci.yml

jameslamb · 2020-04-19T17:36:19Z

note to self: per #2936 (comment), I think that in CI we need to add "$env:R_LIB_PATH/Rtools/mingw_64/bin; to $env:PATH, so that gendef and dlltool are found.

If it isn't in our installation instructions already, we should make it clear there that Rtools/mingw_*/ needs to be on your path for Visual Studio installation to work.

jameslamb · 2020-04-26T21:15:07Z

Now that #2936, I'll get this updated tonight and add CI support for Visual Studio builds. I'll request new reviews after that.

StrikerRUS · 2020-05-03T15:29:15Z

@jameslamb Please remove all speedups (ifs in CI scripts) for MSVC and run full --as-cran test according to our plan (#2936 (comment)), so that we will be able to check how much time it takes to run after all other fixes were merged.

jameslamb · 2020-05-03T17:36:08Z

@jameslamb Please remove all speedups (ifs in CI scripts) for MSVC and run full --as-cran test according to our plan (#2936 (comment)), so that we will be able to check how much time it takes to run after all other fixes were merged.

@StrikerRUS I will do that, but I'm pretty confident we're going to decide not to use --as-cran. Even with all the ifs, it's taking 26 minutes right now :/

https://dev.azure.com/lightgbm-ci/lightgbm-ci/_build/results?buildId=5994&view=logs&j=9f61088a-36ee-57e4-0947-03329fd6ee90&t=2528b315-ee14-54c7-8330-fcfcaf0cbb8e

Toggling the timestamps, I can see 22 minutes of that is just the install:

UPDATE: looking closer, it takes 10+ minutes between "build files have been written" and the first compilation log message

~~I really think it might be that /MP flag to MSVC isn't being used~~. UPDATE: ok no that isn't true, but trying some of these suggestions

I'm going to experiment a big on my fork to not take up our CI capacity. Will report back.

I'll keep updating this comment. Will let you know when I reach a conclusion.

This branch before I started testing on my fork
- commit: 832b643
- build (26m 38s)
adding /incremental to use incremental linking cut about a minute
- commit: jameslamb@67387ac
- build (25m 28s)
Running full build (--as-cran)
- commit: jameslamb@2050a2e
- build (28m 55s)

NOTE: I can see on the builds on my fork that we're now getting failures on non-Windows like this:

* checking compilation flags used ... WARNING
Compilation used the following non-portable flag(s):
  ‘-Wno-ignored-attributes’ ‘-Wno-return-type’ ‘-Wno-unknown-pragmas’
including flag(s) suppressing warnings

I think it's because I'm temporarily echoing CMAKE_CXX_FLAGS and R CMD check is checking if the build logs match a regular expression for flags like -Wno-unknown-pragmas 😂 . They can be safely ignored because I'll remove that debugging MESSAGE() call, and because I'll handle those flag things in the CRAN-toolchain build once we add that (jameslamb#15).

jameslamb · 2020-05-05T04:42:46Z

I have been trying on my fork and cannot get the build times for R + MSVC under 24 minutes. They run very fast (Rscript build_r.R runs in 1-2 minutes) on my laptop, where I have Visual Studio 16 2019 installed but I never actually use it as an IDE, so it still has all of the default settings.

I have narrowed down the slowness with a lot of print debugging...it takes 10 minutes between when this line appears in the log

Build files have been written to: C:/Users/VssAdministrator/AppData/Local/Temp/RtmpWAMlj1/R.INSTALL32c6d499da/lightgbm/src/build

and when compilation starts. Even for the test project that has no source files and whose CMakeLists.txt is just one PROJECT() call.

That means system(paste0(cmake_cmd, ..)) is taking 10 minutes to complete on Azure DevOps. That command is running the Visual Studio generator, e.g. cmake -G"Visual Studio 15 2017" ....

I've at least narrowed it down to that, which rules out build-time flags like /MP as a root cause.

Theories I tried which were not correct:

Adding an explicit timeout in system() calls from R
Setting CMAKE_BUILD_TYPE to "Release" (link 1 | link 2)

My last guess here is that because cmake -G writes a LOT of files, maybe disk I/O is really slow in whatever part of the file system I'm writing to on however Azure DevOps configures its build images. Tomorrow I'll see if I have better luck with MSVC builds on AppVeyor, but beyond that I'm out of ideas :/

StrikerRUS · 2020-05-05T13:29:02Z

@jameslamb

That means system(paste0(cmake_cmd, ..)) is taking 10 minutes to complete on Azure DevOps. That command is running the Visual Studio generator, e.g. cmake -G"Visual Studio 15 2017" ....
I've at least narrowed it down to that, which rules out build-time flags like /MP as a root cause.

What about --as-cran option? It adds ~4min to 24min build time, right?

StrikerRUS · 2020-05-05T13:38:02Z

Hmm, I've noticed that current R builds with MinGW on Windows have interesting variance:

jameslamb · 2020-05-05T19:52:25Z

Hmm, I've noticed that current R builds with MinGW on Windows have interesting variance:

18min https://lightgbm-ci.visualstudio.com/lightgbm-ci/_build/results?buildId=6004&view=results

13min https://lightgbm-ci.visualstudio.com/lightgbm-ci/_build/results?buildId=6003&view=results

22min https://lightgbm-ci.visualstudio.com/lightgbm-ci/_build/results?buildId=5995&view=results

11min https://lightgbm-ci.visualstudio.com/lightgbm-ci/_build/results?buildId=5989&view=results

12min https://lightgbm-ci.visualstudio.com/lightgbm-ci/_build/results?buildId=5988&view=results

Taking a quick look at those, if you click Toggle Timestamps on the log, it seems like a lot of the variability is about installing MiKTeX and friends upstream of the actual build of the R package.

6004 (7 minutes):

6003 (3 minutes)

This is kind of a manual and painful process though, I'm sure if we looked across all builds we'd find other sources of variability. Maybe I'll try writing a script tonight that does that, so I know where to focus my effort.

StrikerRUS · 2020-05-05T22:56:34Z

Nice investigation! But I think that the main goal now is to try to minimize actual building time of R package.

Can you please clarify that?
#2965 (comment)

jameslamb · 2020-05-06T00:57:02Z

Nice investigation! But I think that the main goal now is to try to minimize actual building time of R package.

Can you please clarify that?
#2965 (comment)

right sorry, let me clarify:

The R package takes 1-2 minutes to build on my laptop with Visual Studio
The R package takes around 20 minutes to build in CI
I see in the logs that it takes 10 minutes for each call to system(cmake_cmd) to complete in the Azure CI environment, and that is unrelated to the LightGBM project specifically. Since it takes 10 minutes to build a fake project where the CMakeLists.txt file is just one PROJECT() call.
Removing --as-cran and ignoring all the documentation-related things in CI could save about 4 minutes.

Things I tried to fix this, which did not work:

Explicitly setting build type to Release so the other three types of Visual Studio builds would be ignored.
Putting a timeout on system()

Things I'm going to try next:

Running Visual Studio builds on AppVeyor instead
Finding a way to detect Visual Studio in install.libs.R that does not involve running cmake -G

jameslamb · 2020-05-06T01:28:17Z

There is a lot of information I'm reading through in this answer: https://stackoverflow.com/a/37327661

jameslamb · 2020-05-06T02:15:20Z

The situation looks even worse on AppVeyor. I cancelled this build after 34 minutes 😱

https://ci.appveyor.com/project/jameslamb/lightgbm/builds/32675576

I ran again with Rscript build_r.R (so we could directly see the logs instead of them being hidden in R CMD CHECK):

https://ci.appveyor.com/project/jameslamb/lightgbm/builds/32675702

You can see from the timestamps on the logs there that it takes about 2 and a half minutes to get to the point where install.libs.R is run....and then 25 minutes later the build hasn't progressed at all.

log (1).txt

jameslamb · 2020-05-06T03:18:30Z

Ok I might be making progress! To investigate my theory that this is about disk I/O (since cmake -G"Visual Studio..." writes a lot of files), I ran the following Powershell command:

Get-CimInstance Win32_PerfRawData_PerfDisk_LogicalDisk

environment	Disk	DiskWriteBytesPersec	DiskWritesPersec
AppVeyor	C:	208896	11
Azure	C:	565897728	8787
Azure	D:	43876352	1225
my laptop	C:	88364674560	3343288
my laptop	D:	364544	85

NOTE: There is no D: available on AppVeyor.

AppVeyor log: https://ci.appveyor.com/project/jameslamb/lightgbm/builds/32676579?fullLog=true

Azure DevOps log: https://dev.azure.com/JayLamb20/jameslamb-lightgbm/_build/results?buildId=421&view=logs&j=9f61088a-36ee-57e4-0947-03329fd6ee90&t=2528b315-ee14-54c7-8330-fcfcaf0cbb8e

This is exciting, and I think it's good evidence of what's happening!

D: on the VM we're getting from Azure DevOps is around 2000x slower than the C: disk on my laptop. That explains the difference in performance between my laptop and Azure DevOps. D: is where we install R and where the project build directory is by default on Azure DevOps.
C: on the VM we're getting for AppVeyor is around 210x slower than D: on Azure DevOps, which explains why the builds get stuck at cmake -G there and never even finish

I'm going to see if moving to C:\ on Azure DevOps is possible and if it's faster.

but wait...why hasn't this been a problem for Python builds?

I don't think we ever test using the Visual Studio generator (cmake -G"Visual Studio...") for the Python package! Our builds use the pre-made MSBuild solution file in https://github.com/microsoft/LightGBM/tree/master/windows

LightGBM/python-package/setup.py

Lines 136 to 148 in 18c706d

    
           if not any((use_gpu, use_mpi, use_hdfs, nomp, bit32)): 
        
               logger.info("Starting to compile with MSBuild from existing solution file.") 
        
               platform_toolsets = ("v142", "v141", "v140") 
        
               for pt in platform_toolsets: 
        
                   status = silent_call(["MSBuild", 
        
                                         os.path.join(CURRENT_DIR, "compile", "windows", "LightGBM.sln"), 
        
                                         "/p:Configuration=DLL", 
        
                                         "/p:Platform=x64", 
        
                                         "/p:PlatformToolset={0}".format(pt)]) 
        
                   if status == 0 and os.path.exists(lib_path): 
        
                       break 
        
                   else: 
        
                       clear_path(os.path.join(CURRENT_DIR, "compile", "windows", "x64"))

jameslamb · 2020-05-06T06:14:33Z

Short Summary

Disk throughput does the difference between install times on CI and my laptop, but moving from D:\ to C:\ on Azure DevOps builds doesn't help our build times.

How I reached this conclusion

Based on #2965 (comment), I tried adding some logic that says "if you are on Azure, work in C:\ not D:\". I expected a small speedup from this since any writes to disk should be 10x faster.

I tested on my fork. I tried 5 builds with copying to C:\ and 5 without. The times for the R package build are reported below.

All builds below are already using the configuration of R CMD check that skips all documentation.

Test Results

with (build link)

median: 26m22s

without

median: 25m53s

Conclusion

Yes, disk throughput is a lot lower in our CI environments than on my laptop (it is not a very good laptop, by the way), and that is causing cmake -G"Visual Studio..." to take around 10 minutes to run.
That command is run twice, once to figure out which version (if any) of Visual Studio is installed and once to actually build LightGBM. Because finding installed versions of Visual Studio has changed from version to version, I don't think it would be easy to eliminate the first cmake -G call used to determine if Visual Studio is working.
Moving all the files to C:\ at the beginning of an Azure builds doesn't improve the build times. That operation has a cost, and might even be slightly slowing down builds.

Next Step

It might be possible to cut one of the cmake -G calls, but it will increase the complexity of install.libs.R, which is already somewhat complex. If .find_vs_version() ran cmake -G on LightGBM itself (not a test project), we could skip running it again before building.

This is the only other idea I have, so I'll try that tomorrow. If it doesn't work or we decide it introduces too much complexity, I think 25-minute builds will be something we have to live with to prevent things like #2995 and #2997 from re-emerging.

jameslamb · 2020-05-06T07:03:43Z

Got it down to 16 minutes!

I know this PR has a lot of long comments, I apologize. Wanted to document the investigation as I went, since it reveals a lot about how we're building the R package and the project in general.

I now have the MSVC builds down to 16 minutes!

What Changed?

I tried this idea from #2965 (comment)

It might be possible to cut one of the cmake -G calls, but it will increase the complexity of install.libs.R, which is already somewhat complex. If .find_vs_version() ran cmake -G on LightGBM itself (not a test project), we could skip running it again before building.

I did 5 builds

median: 15m49s

StrikerRUS

Something went wrong during merging branches.

R-package/src/install.libs.R

jameslamb · 2020-05-13T18:05:08Z

Something went wrong during merging branches.

I'm very confused about what could have happened. Trying to figure it out. I don't understand why changes like #3078 are showing up in the diff, since they already exist on master

jameslamb · 2020-05-13T18:15:47Z

Ok I think I fixed the conflicts! I still have no idea how we got into this state...the danger of long-lived feature branches, I guess 😬

I am also very unsure how this PR only has one commit now. I only git reset back about 6 commits.

Either way, I think this PR is back to the state it was as of all previous reviews, including the most recent suggestion (#2965 (comment))

StrikerRUS

@jameslamb
Great improvement! Thanks a lot!
One comment for your consideration.

R-package/src/install.libs.R

jameslamb · 2020-05-13T19:00:16Z

Thanks for the reviews everyone! I'll merge this when it builds.

jameslamb · 2020-05-13T19:36:16Z

oh no 😱

link: https://dev.azure.com/lightgbm-ci/lightgbm-ci/_build/results?buildId=6128&view=results

jameslamb · 2020-05-13T22:46:16Z

Looks like Azure capacity problems to me:

jameslamb · 2020-05-14T00:29:44Z

Ok well now it's ✅ but I can see the linux sdist task never ran. Going to push an empty commit, just to be cautious

jameslamb · 2020-05-14T01:31:12Z

check-docs task is failing on one of our links 😬

this link is definitely valid though:

https://github.com/microsoft/LightGBM/blob/master/python-package/README.rst#build-from-sources

StrikerRUS · 2020-05-14T14:32:41Z

Seems that GitHub did something with their DOM / js (user-content- prefix)...

jameslamb · 2020-05-14T14:45:25Z

Seems that GitHub did something with their DOM / js (user-content- prefix)...

🤒 ok yeah, I agree. Very weird that it works from a curl request like my example above but fails linkchecker.

Either way, I think we need to update it to user-content. I'll push a PR right now.

StrikerRUS · 2020-05-14T15:26:38Z

Very weird that it works from a curl request like my example above but fails linkchecker.

I hope that with 10.0 release of linkchecker we will suffer a little bit less 😉 .

* fix conflicts * Update R-package/src/install.libs.R * empty commit

github-actions · 2023-08-24T13:07:30Z

This pull request has been automatically locked since there has not been any recent activity since it was closed. To start a new related discussion, open a new issue at https://github.com/microsoft/LightGBM/issues including a reference to this.

jameslamb added the maintenance label Apr 2, 2020

jameslamb requested review from Laurae2, guolinke and StrikerRUS April 2, 2020 03:53

jameslamb mentioned this pull request Apr 2, 2020

[R-package] [ci] Add Windows CI for R package (fixes #2335) #2936

Merged

StrikerRUS reviewed Apr 2, 2020

View reviewed changes

R-package/src/install.libs.R Outdated Show resolved Hide resolved

R-package/src/install.libs.R Outdated Show resolved Hide resolved

jameslamb added the awaiting review label Apr 5, 2020

StrikerRUS reviewed Apr 8, 2020

View reviewed changes

R-package/src/install.libs.R Outdated Show resolved Hide resolved

R-package/src/install.libs.R Outdated Show resolved Hide resolved

jameslamb added in progress and removed awaiting review labels Apr 15, 2020

jameslamb commented Apr 15, 2020

View reviewed changes

.vsts-ci.yml Outdated Show resolved Hide resolved

jameslamb mentioned this pull request Apr 27, 2020

[R-package] CMake fixes to support MSVC #2963

Merged

jameslamb changed the title ~~[R-package] speed up installation with Visual Studio~~ [WIP] [R-package] speed up installation with Visual Studio May 3, 2020

jameslamb force-pushed the r/visual-studio-install branch from f9057c3 to 596b5ef Compare May 6, 2020 07:02

StrikerRUS requested changes May 13, 2020

View reviewed changes

R-package/src/install.libs.R Outdated Show resolved Hide resolved

fix conflicts

ebfbacc

jameslamb force-pushed the r/visual-studio-install branch from 513684e to ebfbacc Compare May 13, 2020 18:12

StrikerRUS approved these changes May 13, 2020

View reviewed changes

R-package/src/install.libs.R Show resolved Hide resolved

Update R-package/src/install.libs.R

d7f3621

jameslamb removed the awaiting review label May 13, 2020

empty commit

621ed40

jameslamb mentioned this pull request May 14, 2020

[docs] update link to GitHub anchor conventions #3085

Merged

Merge branch 'master' into r/visual-studio-install

9ee636e

StrikerRUS merged commit 3caf359 into microsoft:master May 14, 2020

jameslamb mentioned this pull request May 14, 2020

R unit tests are not run in CI #2335

Closed

jameslamb deleted the r/visual-studio-install branch May 15, 2020 03:44

This was referenced May 16, 2020

[R-package] [docs] fix warnings in pkgdown site building #3086

Merged

[R-package] [ci] MacOS Travis builds timing out #3091

Closed

odimka pushed a commit to odimka/LightGBM that referenced this pull request May 17, 2020

[R-package] speed up installation with Visual Studio (microsoft#2965)

217a212

* fix conflicts * Update R-package/src/install.libs.R * empty commit

ChipKerchner pushed a commit to ChipKerchner/LightGBM that referenced this pull request Jun 10, 2020

[R-package] speed up installation with Visual Studio (microsoft#2965)

899d074

* fix conflicts * Update R-package/src/install.libs.R * empty commit

ChipKerchner pushed a commit to ChipKerchner/LightGBM that referenced this pull request Jun 11, 2020

[R-package] speed up installation with Visual Studio (microsoft#2965)

2e7b3d8

* fix conflicts * Update R-package/src/install.libs.R * empty commit

jameslamb mentioned this pull request Oct 26, 2020

[ci] [python] reduce unnecessary data loading in tests #3486

Merged

github-actions bot locked as resolved and limited conversation to collaborators Aug 24, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[R-package] speed up installation with Visual Studio #2965

[R-package] speed up installation with Visual Studio #2965

jameslamb commented Apr 2, 2020

StrikerRUS left a comment

jameslamb commented Apr 8, 2020

StrikerRUS left a comment

jameslamb commented Apr 19, 2020

jameslamb commented Apr 26, 2020

StrikerRUS commented May 3, 2020

jameslamb commented May 3, 2020 •

edited

Loading

jameslamb commented May 5, 2020 •

edited

Loading

StrikerRUS commented May 5, 2020

StrikerRUS commented May 5, 2020

jameslamb commented May 5, 2020

StrikerRUS commented May 5, 2020

jameslamb commented May 6, 2020

jameslamb commented May 6, 2020

jameslamb commented May 6, 2020

jameslamb commented May 6, 2020 •

edited

Loading

jameslamb commented May 6, 2020

jameslamb commented May 6, 2020

StrikerRUS left a comment

jameslamb commented May 13, 2020

jameslamb commented May 13, 2020

StrikerRUS left a comment

jameslamb commented May 13, 2020

jameslamb commented May 13, 2020

jameslamb commented May 13, 2020

jameslamb commented May 14, 2020

jameslamb commented May 14, 2020

StrikerRUS commented May 14, 2020

jameslamb commented May 14, 2020

StrikerRUS commented May 14, 2020

github-actions bot commented Aug 24, 2023

[R-package] speed up installation with Visual Studio #2965

[R-package] speed up installation with Visual Studio #2965

Conversation

jameslamb commented Apr 2, 2020

StrikerRUS left a comment

Choose a reason for hiding this comment

jameslamb commented Apr 8, 2020

StrikerRUS left a comment

Choose a reason for hiding this comment

jameslamb commented Apr 19, 2020

jameslamb commented Apr 26, 2020

StrikerRUS commented May 3, 2020

jameslamb commented May 3, 2020 • edited Loading

jameslamb commented May 5, 2020 • edited Loading

StrikerRUS commented May 5, 2020

StrikerRUS commented May 5, 2020

jameslamb commented May 5, 2020

StrikerRUS commented May 5, 2020

jameslamb commented May 6, 2020

jameslamb commented May 6, 2020

jameslamb commented May 6, 2020

jameslamb commented May 6, 2020 • edited Loading

jameslamb commented May 6, 2020

Short Summary

How I reached this conclusion

Test Results

Conclusion

Next Step

jameslamb commented May 6, 2020

Got it down to 16 minutes!

What Changed?

StrikerRUS left a comment

Choose a reason for hiding this comment

jameslamb commented May 13, 2020

jameslamb commented May 13, 2020

StrikerRUS left a comment

Choose a reason for hiding this comment

jameslamb commented May 13, 2020

jameslamb commented May 13, 2020

jameslamb commented May 13, 2020

jameslamb commented May 14, 2020

jameslamb commented May 14, 2020

StrikerRUS commented May 14, 2020

jameslamb commented May 14, 2020

StrikerRUS commented May 14, 2020

github-actions bot commented Aug 24, 2023

jameslamb commented May 3, 2020 •

edited

Loading

jameslamb commented May 5, 2020 •

edited

Loading

jameslamb commented May 6, 2020 •

edited

Loading