New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 749229 link

Starred by 9 users

Issue metadata

Status: Duplicate
Merged: issue 764040
Owner: ----
Closed: Sep 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Windows
Pri: 1
Type: Bug



Sign in to add a comment

git cl upload takes minutes on Windows

Project Member Reported by gab@chromium.org, Jul 26 2017

Issue description

Forked from chromium-dev thread @ https://groups.google.com/a/chromium.org/d/msgid/chromium-dev/CAJTZ7LLeQqS9VOd9A47ZCAuD3OdG6-Fm6%3DsdFu482PbNtbu5TQ%40mail.gmail.com?utm_medium=email&utm_source=footer

Example (notice long periods between "Authorization: HIDDEN" blocks:

$git cl upload -vv -t "noop"
[D2017-07-26 15:09:13,792 17780 12040 subprocess2.py] git symbolic-ref HEAD
[D2017-07-26 15:09:13,838 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.git-cl-similarity
[D2017-07-26 15:09:13,894 17780 12040 subprocess2.py] git symbolic-ref HEAD
[D2017-07-26 15:09:13,930 17780 12040 subprocess2.py] git config --bool branch.2a3b_more_chrome/browser/printing_split.git-find-copies
[D2017-07-26 15:09:13,980 17780 12040 subprocess2.py] D:\src\depot_tools\win_tools-2_7_6_bin\git\mingw64\libexec\git-core\git.exe -c color.ui=never update-index --refresh -q
[D2017-07-26 15:09:15,020 17780 12040 subprocess2.py] D:\src\depot_tools\win_tools-2_7_6_bin\git\mingw64\libexec\git-core\git.exe -c color.ui=never diff-index --name-status HEAD
[D2017-07-26 15:09:16,469 17780 12040 subprocess2.py] git config rietveld.autoupdate
[D2017-07-26 15:09:16,499 17780 12040 git_cl.py] Failed running ['git', 'config', 'rietveld.autoupdate']
[D2017-07-26 15:09:16,500 17780 12040 subprocess2.py] git rev-parse --show-cdup
[D2017-07-26 15:09:16,532 17780 12040 subprocess2.py] git config rietveld.cc chromium-reviews@chromium.org
[D2017-07-26 15:09:16,562 17780 12040 subprocess2.py] git config --unset-all rietveld.private
[D2017-07-26 15:09:16,595 17780 12040 git_cl.py] Failed running ['git', 'config', '--unset-all', 'rietveld.private']
[D2017-07-26 15:09:16,596 17780 12040 subprocess2.py] git config rietveld.tree-status-url http://chromium-status.appspot.com/status
[D2017-07-26 15:09:16,630 17780 12040 subprocess2.py] git config rietveld.viewvc-url https://chromium.googlesource.com/chromium/src/+/
[D2017-07-26 15:09:16,664 17780 12040 subprocess2.py] git config --unset-all rietveld.bug-prefix
[D2017-07-26 15:09:16,694 17780 12040 git_cl.py] Failed running ['git', 'config', '--unset-all', 'rietveld.bug-prefix']
[D2017-07-26 15:09:16,697 17780 12040 subprocess2.py] git config --unset-all rietveld.cpplint-regex
[D2017-07-26 15:09:16,726 17780 12040 git_cl.py] Failed running ['git', 'config', '--unset-all', 'rietveld.cpplint-regex']
[D2017-07-26 15:09:16,730 17780 12040 subprocess2.py] git config rietveld.cpplint-ignore-regex webkit/api/.*
[D2017-07-26 15:09:16,760 17780 12040 subprocess2.py] git config rietveld.project chromium
[D2017-07-26 15:09:16,793 17780 12040 subprocess2.py] git config rietveld.run-post-upload-hook True
[D2017-07-26 15:09:16,825 17780 12040 subprocess2.py] git config gerrit.host True
[D2017-07-26 15:09:16,857 17780 12040 subprocess2.py] git config gerrit.host
[D2017-07-26 15:09:16,888 17780 12040 subprocess2.py] git symbolic-ref HEAD
[D2017-07-26 15:09:16,917 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.rietveldissue
[D2017-07-26 15:09:16,960 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.gerritissue
[D2017-07-26 15:09:17,000 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.merge
[D2017-07-26 15:09:17,040 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.remote
[D2017-07-26 15:09:17,082 17780 12040 subprocess2.py] git rev-parse --verify refs/heads/2a2_rm_messageloop_quit_simple
[D2017-07-26 15:09:17,164 17780 12040 subprocess2.py] D:\src\depot_tools\win_tools-2_7_6_bin\git\mingw64\libexec\git-core\git.exe -c color.ui=never config --get branch.2a3b_more_chrome/browser/printing_split.base
[D2017-07-26 15:09:17,213 17780 12040 subprocess2.py] D:\src\depot_tools\win_tools-2_7_6_bin\git\mingw64\libexec\git-core\git.exe -c color.ui=never config --get branch.2a3b_more_chrome/browser/printing_split.base-upstream
[D2017-07-26 15:09:17,253 17780 12040 subprocess2.py] D:\src\depot_tools\win_tools-2_7_6_bin\git\mingw64\libexec\git-core\git.exe -c color.ui=never merge-base refs/heads/2a2_rm_messageloop_quit_simple 2a3b_more_chrome/browser/printing_split
[D2017-07-26 15:09:17,325 17780 12040 subprocess2.py] git config --bool gerrit.skip-ensure-authenticated
[D2017-07-26 15:09:17,355 17780 12040 git_cl.py] Failed running ['git', 'config', '--bool', 'gerrit.skip-ensure-authenticated']
[D2017-07-26 15:09:17,549 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.gerritserver
[D2017-07-26 15:09:17,591 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.merge
[D2017-07-26 15:09:17,631 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.remote
[D2017-07-26 15:09:17,674 17780 12040 subprocess2.py] git config branch.2a2_rm_messageloop_quit_simple.merge
[D2017-07-26 15:09:17,717 17780 12040 subprocess2.py] git config branch.2a2_rm_messageloop_quit_simple.remote
[D2017-07-26 15:09:17,760 17780 12040 subprocess2.py] git config branch.2a1_runloopquitwhenidle.merge
[D2017-07-26 15:09:17,805 17780 12040 subprocess2.py] git config branch.2a1_runloopquitwhenidle.remote
[D2017-07-26 15:09:17,848 17780 12040 subprocess2.py] git config remote.origin.url
[D2017-07-26 15:09:17,903 17780 12040 gerrit_util.py] GET https://chromium-review.googlesource.com/a/changes/587050/detail?o=DETAILED_ACCOUNTS&o=CURRENT_REVISION&o=CURRENT_COMMIT
[D2017-07-26 15:09:17,908 17780 12040 gerrit_util.py] Authorization: HIDDEN
[D2017-07-26 15:09:42,762 17780 12040 gerrit_util.py] got response 200 for GET https://chromium-review.googlesource.com/a/changes/587050/detail?o=DETAILED_ACCOUNTS&o=CURRENT_REVISION&o=CURRENT_COMMIT
[D2017-07-26 15:09:42,778 17780 12040 subprocess2.py] git rev-parse --verify 7716ef06732e9da9499c0b1d7d792adab96b6038
[D2017-07-26 15:09:42,844 17780 12040 subprocess2.py] git merge-base 7716ef06732e9da9499c0b1d7d792adab96b6038 HEAD
[D2017-07-26 15:09:42,911 17780 12040 subprocess2.py] git rev-list ^7716ef06732e9da9499c0b1d7d792adab96b6038 HEAD
[D2017-07-26 15:09:42,980 17780 12040 subprocess2.py] git config gitcl.remotebranch
[D2017-07-26 15:09:43,025 17780 12040 subprocess2.py] git rev-list ^7716ef06732e9da9499c0b1d7d792adab96b6038 refs/remotes/origin/master
[D2017-07-26 15:09:43,095 17780 12040 subprocess2.py] git rev-parse --show-cdup
[D2017-07-26 15:09:43,124 17780 12040 subprocess2.py] git rev-parse HEAD
[D2017-07-26 15:09:43,200 17780 12040 subprocess2.py] git diff --name-status --no-renames -r 7716ef06732e9da9499c0b1d7d792adab96b6038... .;  cwd=.
[D2017-07-26 15:09:43,483 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.gerritpatchset
[D2017-07-26 15:09:43,523 17780 12040 subprocess2.py] git config user.email
[D2017-07-26 15:09:43,551 17780 12040 presubmit_support.py] GitAffectedFile(chrome/browser/printing/print_view_manager_base.cc)
Running presubmit upload checks ...
[D2017-07-26 15:09:43,680 17780 12040 presubmit_support.py] Presubmit files: D:\src\chrome2\src\PRESUBMIT.py,D:\src\chrome2\src\chrome\PRESUBMIT.py,D:\src\chrome2\src\chrome\browser\PRESUBMIT.py
Running D:\src\chrome2\src\PRESUBMIT.py
[D2017-07-26 15:09:43,835 17780 12040 presubmit_support.py] Running CheckChangeOnUpload in D:\src\chrome2\src\PRESUBMIT.py
[D2017-07-26 15:09:43,881 17780 12040 gerrit_util.py] GET https://chromium-review.googlesource.com/a/changes/587050/detail?o=ALL_REVISIONS&o=DETAILED_LABELS&o=ALL_COMMITS
[D2017-07-26 15:09:43,888 17780 12040 gerrit_util.py] Authorization: HIDDEN
[D2017-07-26 15:10:05,345 17780 12040 gerrit_util.py] got response 200 for GET https://chromium-review.googlesource.com/a/changes/587050/detail?o=ALL_REVISIONS&o=DETAILED_LABELS&o=ALL_COMMITS
[D2017-07-26 15:10:13,263 17780 12040 presubmit_canned_checks.py] owner: gab@chromium.org; approvals given by: scottbyer@chromium.org
  checking owners took a long time: 29425ms
[D2017-07-26 15:10:13,426 17780 12040 subprocess2.py] git diff -p --no-color --no-prefix --no-ext-diff 7716ef06732e9da9499c0b1d7d792adab96b6038...HEAD --no-renames;  cwd=D:\src\chrome2\src
[D2017-07-26 15:10:13,733 17780 12040 presubmit_support.py] LocalPaths: ['chrome\\browser\\printing\\print_view_manager_base.cc']
[D2017-07-26 15:10:13,750 17780 12040 subprocess2.py] git cl format --dry-run D:\src\chrome2\src
[D2017-07-26 15:10:16,592 17780 12040 presubmit_support.py] Running CheckChangeOnUpload done.
Running D:\src\chrome2\src\chrome\PRESUBMIT.py
[D2017-07-26 15:10:16,867 17780 12040 presubmit_support.py] Running CheckChangeOnUpload in D:\src\chrome2\src\chrome\PRESUBMIT.py
Done processing D:\src\chrome2\src\chrome\browser\printing\print_view_manager_base.cc
[D2017-07-26 15:10:17,338 17780 12040 presubmit_support.py] Running CheckChangeOnUpload done.
Running D:\src\chrome2\src\chrome\browser\PRESUBMIT.py
[D2017-07-26 15:10:17,813 17780 12040 presubmit_support.py] Running CheckChangeOnUpload in D:\src\chrome2\src\chrome\browser\PRESUBMIT.py
[D2017-07-26 15:10:17,834 17780 12040 presubmit_support.py] Running CheckChangeOnUpload done.

Presubmit checks took 34.8s to calculate.

Presubmit checks passed.
[D2017-07-26 15:10:18,476 17780 12040 subprocess2.py] git diff --no-ext-diff --stat -l100000 -C50 7716ef06732e9da9499c0b1d7d792adab96b6038 HEAD
 chrome/browser/printing/print_view_manager_base.cc | 9 +++++----
 1 file changed, 5 insertions(+), 4 deletions(-)
[D2017-07-26 15:10:18,753 17780 12040 subprocess2.py] git config --bool gerrit.override-squash-uploads
[D2017-07-26 15:10:18,802 17780 12040 git_cl.py] Failed running ['git', 'config', '--bool', 'gerrit.override-squash-uploads']
[D2017-07-26 15:10:18,805 17780 12040 subprocess2.py] git config --bool gerrit.squash-uploads
[D2017-07-26 15:10:18,842 17780 12040 git_cl.py] Failed running ['git', 'config', '--bool', 'gerrit.squash-uploads']
[D2017-07-26 15:10:18,845 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.merge
[D2017-07-26 15:10:18,895 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.remote
[D2017-07-26 15:10:18,944 17780 12040 subprocess2.py] git config branch.2a2_rm_messageloop_quit_simple.gerritsquashhash
[D2017-07-26 15:10:18,993 17780 12040 subprocess2.py] git rev-parse refs/heads/2a2_rm_messageloop_quit_simple:
[D2017-07-26 15:10:19,085 17780 12040 subprocess2.py] git rev-parse d5805905ee04404d11a492e877977a0cf49a2b8a:
[D2017-07-26 15:10:19,180 17780 12040 subprocess2.py] git rev-parse HEAD:
[D2017-07-26 15:10:19,253 17780 12040 subprocess2.py] git commit-tree 39c02f1d170ef94edce643d074a24306ce764391 -p d5805905ee04404d11a492e877977a0cf49a2b8a -m Manually migrate away from more deprecated MessageLoop::Quit*() methods in /chrome/browser/printing.

This follows an automated pass for simpler use cases @
https://chromium-review.googlesource.com/c/585732/.

Minimal cleanup was made when trivial.

(some calls were even removed as they merely added a redundant QuitWhenIdle()
to a RunLoop().RunUntilIdle() call)

When too complex I defaulted to the lesser bad alternative of
RunLoop::QuitCurrent*Deprecated() methods.

I will not engage in further cleanups as part of this massive
change -- owners are welcome to follow suit with better usage
of RunLoop if unsatisfied with this).

This CL was uploaded by git cl split.

R=scottbyer@chromium.org

Bug:  748715 
Change-Id: I89ee25215331f116bfdfe047c73e49dda00c1518
[D2017-07-26 15:10:19,364 17780 12040 subprocess2.py] git rev-list d5805905ee04404d11a492e877977a0cf49a2b8a..af4e8904595fef38a1bd29edf4e698c47c94797c
[D2017-07-26 15:10:19,460 17780 12040 subprocess2.py] git config remote.origin.url
[D2017-07-26 15:10:19,496 17780 12040 subprocess2.py] git push https://chromium.googlesource.com/chromium/src.git af4e8904595fef38a1bd29edf4e698c47c94797c:refs/for/refs/heads/master%notify=NONE,m=noop
remote: Processing changes: updated: 1, done
remote: (W) af4e890: commit subject >50 characters; use shorter first paragraph
remote: (W) No changes between prior commit 9528349 and new commit af4e890
remote:
remote: Updated Changes:
remote:   https://chromium-review.googlesource.com/587050 Manually migrate away from more deprecated MessageLoop::Quit*() methods in ...
remote:
To https://chromium.googlesource.com/chromium/src.git
 * [new branch]      af4e8904595fef38a1bd29edf4e698c47c94797c -> refs/for/refs/heads/master%notify=NONE,m=noop
[D2017-07-26 15:11:17,105 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.gerritissue 587050
[D2017-07-26 15:11:17,141 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.gerritserver https://chromium-review.googlesource.com
[D2017-07-26 15:11:17,177 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.gerritsquashhash af4e8904595fef38a1bd29edf4e698c47c94797c
[D2017-07-26 15:11:17,213 17780 12040 subprocess2.py] git config rietveld.cc
[D2017-07-26 15:11:17,256 17780 12040 gerrit_util.py] POST https://chromium-review.googlesource.com/a/changes/587050/revisions/current/review
[D2017-07-26 15:11:17,259 17780 12040 gerrit_util.py] Content-Type: application/json
[D2017-07-26 15:11:17,262 17780 12040 gerrit_util.py] Authorization: HIDDEN
[D2017-07-26 15:11:17,266 17780 12040 gerrit_util.py] {"reviewers": [{"reviewer": "chromium-reviews@chromium.org", "state": "CC", "notify": "NONE"}, {"reviewer": "scottbyer@chromium.org", "state": "REVIEWER", "notify": "NONE"}], "notify": "NONE"}
[D2017-07-26 15:11:19,668 17780 12040 gerrit_util.py] got response 200 for POST https://chromium-review.googlesource.com/a/changes/587050/revisions/current/review
[D2017-07-26 15:11:19,674 17780 12040 subprocess2.py] git rev-parse HEAD
[D2017-07-26 15:11:19,739 17780 12040 subprocess2.py] git symbolic-ref HEAD
[D2017-07-26 15:11:19,766 17780 12040 subprocess2.py] git config branch.2a3b_more_chrome/browser/printing_split.last-upload-hash 2158a95458af6752eee550153ff9ae1ffdd85dc6
[D2017-07-26 15:11:19,801 17780 12040 subprocess2.py] git config rietveld.run-post-upload-hook
[D2017-07-26 15:11:19,842 17780 12040 presubmit_support.py] Presubmit files: D:\src\chrome2\src\PRESUBMIT.py,D:\src\chrome2\src\chrome\PRESUBMIT.py,D:\src\chrome2\src\chrome\browser\PRESUBMIT.py
Running D:\src\chrome2\src\chrome\browser\PRESUBMIT.py
Running D:\src\chrome2\src\chrome\PRESUBMIT.py
Running D:\src\chrome2\src\PRESUBMIT.py
 

Comment 1 by mmenke@chromium.org, Jul 26 2017

Looks like two GETs took 25 and 18 seconds, and "git commit-tree" took 58 seconds.  Together those account for most of the time.

Comment 2 by aga...@chromium.org, Jul 26 2017

The GETs shouldn't have taken that long, but there was a temporary issue with latency this morning (b/64066979, internal only) which likely explains it.

git commit-tree is a purely local operation.

Comment 3 by gab@chromium.org, Jul 27 2017

It's usually slow but today was particularly bad so my usual issue is probably git commit-tree (Windows? maybe I need to git gc..? I share 3 git repos off of a single .git [1] and git gc does bad things to that so I've disabled it and usually run it manually but it's been a while...)

Today was likely made worse by the temporary latency issue.

[1] https://www.chromium.org/developers/how-tos/get-the-code/multiple-working-directories
Possibly related, but git cl patch also takes ~minutes :(
TL;DR - run "git cc".

I just tested on Linux and git cl upload took 29 s. That's still slow but a lot faster than Windows where it continues to take minutes (165-185 s on recent tests, with --bypass-hooks and --no-find-copies).

One issue is that this git process consumes 114s of CPU time, single threaded. It spends most of its time in NTFS.sys, ntoskrnl.exe, and ntdll.dll. It's hard to tell exactly what it's doing (no symbols for git.exe or, at the moment, KernelBase.dll) but it's spending a lot of time in ntdll.dll!ZwQueryDirectoryFile so clearly file-system scanning. Did our caching mechanism for fstat get broken? Can this be multi-threaded? This is the command-line it's running:

    git send-pack --stateless-rpc --helper-status --thin --no-progress https://chromium.googlesource.com/chromium/src.git/ --stdin

Towards the end this process goes idle for ~27 s while waiting on a network response, indirectly, through git-remote-https.exe. The time spent idle waiting on the network is almost as long as Linux takes to do the entire process. The original report suspected the "Authorization: HIDDEN" which may be the same problem. The command-line for that is:

    git-remote-https https://chromium.googlesource.com/chromium/src.git https://chromium.googlesource.com/chromium/src.git

> there was a temporary issue with latency this morning

The long delays for git cl upload have been going on for a while. Some network latency seems to continue to be a problem, although it isn't the main problem.

I've attached the output of a -vv run of git cl upload that took 171.45 seconds. 151 s of that was all inside "git push"

[D2017-09-01 16:29:40,417 16796 15144 subprocess2.py] git push https://chromium.googlesource.com/chromium/src.git 4dc7939f94ccfeb821994a50a08699514006635f:refs/for/refs/heads/master%notify=NONE,m=nop
remote: Processing changes: updated: 1, done
remote: (W) No changes between prior commit d8b5a39 and new commit 4dc7939
remote:
remote: Updated Changes:
remote:   https://chromium-review.googlesource.com/604810 Hacks to add ETW events to battor_agent
remote:
To https://chromium.googlesource.com/chromium/src.git
 * [new branch]                4dc7939f94ccfeb821994a50a08699514006635f -> refs/for/refs/heads/master%notify=NONE,m=nop
[D2017-09-01 16:32:11,167 16796 15144 subprocess2.py] git config branch.battor_etw_hack.gerritissue 604810


Knowing more about where the time was being spent I ran "git cc" and the next "git cl upload" took 53 seconds. Wow.

Still annoying slow, but *much* better.

gitclupload.txt
11.9 KB View Download
I'm seeing ~ten seconds of idle at the beginning of the process and ~seventeen seconds of idle towards the end of the trace (waiting on git-remote-https). If we could avoid most of those network delays then that would almost double the performance (halve the time) for git cl upload on Windows.

"git cc" seems to be a local alias, what's the full command?
Sorry, I meant "git gc" as in garbage-collect.

I turned off auto garbage collect a long time ago because it was triggering too often and takes a long time, but I need to remember to manually run garbage collection - weekly? monthly? Whenever git cl upload gets slow?
Thanks, that's what I thought :). I also always forget to run git gc
Mergedinto: 764040
Status: Duplicate (was: Untriaged)

Sign in to add a comment