Closed mgalgs closed 9 years ago
tarsius
commented
9 years ago This happens in magit-status-refresh-buffer:
(magit-git-exit-code "update-index" "--refresh")That has been there (will in some equivalent place) since before my times. I always wondered whether that is really necessary. It might not be, but if that turns out to be untrue, then just removing it would be have quite negative consequences. We should check when Git itself does the equivalent and when not.
holocronweaver
commented
9 years ago I can confirm that stashing files on a large multi-GB repo is extremely slow since Magit 2.1, taking ~30 seconds, whereas it was almost instantaneous before. Is this the culprit, or am I describing a separate bug?
tarsius
commented
9 years ago Are you using the -u and -a switches?
holocronweaver
commented
9 years ago No, neither.
mgalgs
commented
9 years ago @holocronweaver can you do a ps -ef | grep git during the hang to see if it matches what I'm seeing (git update-index on every file in the repo)?
tarsius
commented
9 years ago In the repository where you see that large delay, how long does (benchmark-run '(magit-git-exit-code "update-index" "--refresh")) take? Then also create a stash. If the first thing takes almost no time and the second still takes very long, then we at least know we don't have to worry about doing the former in magit-status-refresh-buffer, because even if it should happen to be unnecessary, at least it is inexpensive.
tarsius
commented
9 years ago Actually run all of these:
time git update-index --refresh
time git diff --name-only HEAD
time git update-index --add --remove -- $(git diff --name-only HEAD)
time git ls-files --full-name --other
time git update-index --add --remove -- $(git ls-files --full-name --other)
time git ls-files --full-name --other --exclude-standard
time git update-index --add --remove -- $(git ls-files --full-name --other --exclude-standard)After creating the stash what does git log --oneline --name-status -n 5 --graph refs/stash print?
holocronweaver
commented
9 years ago @mgalgs When I run that command I get
4638 83 13:38 ? 00:00:19 /usr/bin/git -c commit.gpgsign=false --no-pager --literal-pathspecs -c core.preloadindex=true diff -z --name-only HEAD@tarsius Here are the commands and timings.
| command | time (s) |
|---|---|
| time git update-index --refresh | 0.07 |
| time git diff --name-only HEAD | 0.10 |
| time git update-index --add --remove -- $(git diff --name-only HEAD) | 0.04 |
| time git ls-files --full-name --other | 0.22 |
| time git update-index --add --remove -- $(git ls-files --full-name --other) | 33.61 |
| time git ls-files --full-name --other --exclude-standard | 0.18 |
| time git update-index --add --remove -- $(git ls-files --full-name --other --exclude-standard) | 0.04 |
After creating the stash brb and running the log command, I get:
* 53a1495 On rism-periodic-dev: brb
|\
| * 31a9583 index on rism-periodic-dev: b88bf9d Merge branch 'master' into rism-periodic
|/
| A AmberTools/test/rism3d.periodic/summary.org
| A test/rism3d/ala/Run.ala.min.pme.ortho
| A test/rism3d/ala/Run.ala.min.pme.tri
| A test/rism3d/ala/ala.min.pme.ortho.out.save
* b88bf9d Merge branch 'master' into rism-periodic
|\
| * 7dcb764 [rism] Add non-periodic force debug test.
| | M test/Makefile
| | A test/rism3d/dev/ala/Run.ala.min.debug
| | A test/rism3d/dev/ala/ala.min.debug.out.save
| * a441479 [rism] Update sander.RISM.OIN test for new output format.
| | M test/sander_rism3d_asfe_oin/ala.out.saveExcept for the first, these are all commands that may be run by magit-stash-create. But the slow one should not run unless the -a switch is used. Insert this at the beginning of this command: (message "--- %s %s %s" index worktree untracked), it should print --- t t nil when creating a stash using z z and without -a.
holocronweaver
commented
9 years ago That is indeed the output I received upon stashing.
BTW, good thing I stashed before issuing those timing commands. Every uncommitted file was staged for commit. There were tens of thousands.
tarsius
commented
9 years ago Let's narrow it down a little more. Please sprinkle a few messages across magit-stash-create to find out where it spends the time. I would expect inside (and untracked ...) except that's not possible because untracked is nil.
diff --git a/lisp/magit-stash.el b/lisp/magit-stash.el
index 9c85810..80b43a8 100644
--- a/lisp/magit-stash.el
+++ b/lisp/magit-stash.el
@@ -231,22 +231,27 @@ (defun magit-stash-store (message ref commit)
(error "Cannot update %s with %s" ref commit)))
(defun magit-stash-create (message index worktree untracked)
+ (message "A...")
(unless (magit-rev-parse "--verify" "HEAD")
(error "You do not have the initial commit yet"))
+ (message "B...")
(let ((magit-git-global-arguments (nconc (list "-c" "commit.gpgsign=false")
magit-git-global-arguments))
(default-directory (magit-toplevel))
(conflicts (magit-anything-unmerged-p))
(summary (magit-stash-summary))
(head "HEAD"))
+ (message "C...")
(when (and worktree (not index) (not conflicts))
(setq head (magit-commit-tree "pre-stash index" nil "HEAD")))
+ (message "D...")
(or (setq index (if conflicts
(magit-commit-tree (concat "index on " summary)
"HEAD^{tree}" "HEAD")
(magit-commit-tree (concat "index on " summary)
nil head)))
(error "Cannot save the current index state"))
+ (message "E...")
(and untracked
(setq untracked (magit-untracked-files (eq untracked 'all)))
(setq untracked (magit-with-temp-index nil
@@ -254,12 +259,14 @@ (defun magit-stash-create (message index worktree untracked)
(magit-commit-tree
(concat "untracked files on " summary)))
(error "Cannot save the untracked files")))))
+ (message "F...")
(magit-with-temp-index index
(when worktree
(or (magit-update-files (magit-git-items "diff" "-z" "--name-only" head))
(error "Cannot save the current worktree state")))
(or (magit-commit-tree message nil head index untracked)
- (error "Cannot save the current worktree state")))))
+ (error "Cannot save the current worktree state")))
+ (message "G...")))
(defun magit-stash-summary ()
(concat (or (magit-get-current-branch) "(no branch)")Does Emacs have a line-by-line elisp profiler?
Ok, I narrowed it down to (magit-git-items "diff" "-z" "--name-only" head) as the troublemaker. I verified that it is NOT the git call itself calling the problem, but rather the (apply #'process-file magit-git-executable nil (list t nil) nil args) line at the end of magit-git-insert.
When I run the git command itself (-c commit.gpgsign=false --no-pager --literal-pathspecs -c core.preloadindex=true diff -z --name-only HEAD) it returns instantly.
I guess the problem is somehow related to process-file? I am not familiar with that function.
tarsius
commented
9 years ago I think there's nothing in process-file (unless when using tramp) that could affect performance in this case. So we might end up narrowing it down to call-process having issues with a loooong line with null characters in it. Lets hope that's not the issue.
Are you sure it's not (split-string (buffer-string) "\0" t)?
I hope it's that. Then we would have to implement magit-git-lines and magit-git-items more like process-lines. I think the issue is that we do a regex search (even though it is a very simple regexp).
tarsius
commented
9 years ago Does this help?:
(defun magit-git-items (&rest args)
"Execute Git with ARGS, returning its null-separated output as a list.
Empty items anywhere in the output are omitted.
If Git exits with a non-zero exit status, then show a message
and add a section in the respective process buffer."
(with-temp-buffer
(apply #'magit-git-insert args)
(goto-char (point-min))
(let (items)
(while (not (eobp))
(let ((beg (point))
(end (--if-let (search-forward "\0" nil 'max)
(1- it)
(point-max))))
(unless (= beg end)
(setq items (cons (buffer-substring-no-properties beg end)
items)))))
(nreverse items))))Are you sure it's not (split-string (buffer-string) "\0" t)?
I narrowed it down to a single like like so:
(message "1...")
(apply #'process-file magit-git-executable nil (list t nil) nil args)
(message "2...")I see the message 1... and Emacs ignores normal user input for about 20 seconds before 2... finally appears and I regain control. Thus I am very confident it is that line.
Does this help?
Unfortunately no.
tarsius
commented
9 years ago Please print the args so we are sure it's really the call you think it is. Or in other words isolate the code and the particular arguments you have determined to be the cause, combine them, and run them separately. As I understand it you are talking about:
(benchmark-run 1
'(process-file "git" nil (list t nil) nil
"-c" "commit.gpgsign=false" "--no-pager"
"--literal-pathspecs" "-c" "core.preloadindex=true"
"diff" "-z" "--name-only" "HEAD"))Or when going less low-level:
(benchmark-run 1
'(magit-git-items "diff" "-z" "--name-only" "HEAD"))For me both take a tiny fraction of a second, even with more than four thousand modified files.
tarsius
commented
9 years ago Are you using MS Windows? (Well @mgalgs probably is not, since he mentions the Linux kernel. :-)
holocronweaver
commented
9 years ago Please print the args
args: (-c commit.gpgsign=false --no-pager --literal-pathspecs -c core.preloadindex=true diff -z --name-only HEAD)
To reiterate, I have run this exact call manually in a terminal and it completes almost instantly.
Are you using MS Windows?
I am experiencing this problem on Linux, but I use Emacs on all 3 major OS.
tarsius
commented
9 years ago I have a hard time believing your conclusion, as I can see no reason why this command would take much less than on the command line (and for me also when using process-line or call-process) than when called by Magit.
You said:
Thus I am very confident it is that line.
Later I said:
Or in other words isolate the code and the particular arguments you have determined to be the cause, combine them, and run them separately. [emacs lisp code]
To which you replied
To reiterate, I have run this exact call manually in a terminal and it completes almost instantly.
That's not what I asked you to do. What I asked you to do is run the elisp code that I posted, so that we know it is that code, not some other part of magit (or some unrelated timer).
holocronweaver
commented
9 years ago Or in other words isolate the code and the particular arguments you have determined to be the cause, combine them, and run them separately. [emacs lisp code]
Sorry for the confusion, the must have been a mixup as the e-mail I got of your message did not include any elisp, nor was there any when I visited the Github page to make my reply. Maybe you were editing while I was writing my reply?
Those benchmarks complete nearly instantly for me as well. Hm....
I switched to using edebug and that made things much easier. Stepping through every call to magit-git-items, I found the problem line is indeed (apply #'process-file magit-git-executable nil (list t nil) nil args) called by (apply #'magit-git-insert args) with args ("-c" "commit.gpgsign=false" "--no-pager" "--literal-pathspecs" "-c" "core.preloadindex=true" "diff" "-z" "--name-only" "HEAD"). Stepping through that particular line takes ~30 secs. Unless edebug cannot be trusted or you know of a better way, I think this is as close as I can get to proving that this line is the slowdown.
However, that doesn't solve WHY it is slow. My guess is it has to do with the particular set git commands being used back to back. I noticed that during stashing, magit-git-insert is called a number of times with a variety of arguments. I have created a gist which contains an edebug backtrace of the problem location and the messages edebug produced just before the problem: https://gist.github.com/holocronweaver/e088d3b13e608c23e89a
Hopefully this will offer some clue as to what is going on.
liujoey
commented
9 years ago experienced the same. Working on a 2.4GB repo, stashing a small txt file, it spent 30 seconds to finish the z z command.
tarsius
commented
9 years ago experienced the same
Could you please be more specific? Above you find two theories why this is slow. Did you try to verify/falsify them?
tarsius
commented
9 years ago I am considering closing this.
What @holocronweaver is saying is either correct or it is not.
holocronweaver
commented
9 years ago @tarsius I will look into to creating a reproducible test case.
tarsius
commented
9 years ago @holocronweaver yes please do that
@liujoey @vjohansen Please help me help you by trying to narrow the issue down to the cause identified by @mgalgs or the one identified by @holocronweaver. Or something else. Above you find instructions which could be useful in the process.
vjohansen
commented
9 years ago My investigation show the same as @holocronweaver.
All the time is spent in
(apply #'process-file magit-git-executable nil (list t nil) nil args)If I run
(apply #'process-file magit-git-executable nil (list t nil) nil '("-c" "commit.gpgsign=false"
"--no-pager"
"--literal-pathspecs" "-c"
"core.preloadindex=true"
"diff" "-z" "--name-only"
"HEAD"))inside Emacs (in a file in the top-level git folder) it returns instantly with the result.
I have big repo (a few GBs) and try to stash one file. it outputs the one file I have changed and a ^@ at the end.
I am on Windows 7.
bsuh
commented
9 years ago I noticed that it is actually git taking up a long time, and also using quite a bit of CPU. Since using the same command on the terminal takes no time, I looked at the environment variables for the long running git process and noticed that GIT_INDEX_FILE is set.
I commented out the code for setting that environment variable in magit-stash.el like so
;(magit-with-temp-index index
(when worktree
(or (magit-update-files (magit-git-items "diff" "-z" "--name-only" head))
(error "Cannot save the current worktree state")))
(or (magit-commit-tree message nil head index untracked)
(error "Cannot save the current worktree state"))));)And recompiled and things run much faster now. I'm not familiar with the low level commands like git write-tree and git commit-tree, so not sure how to fix properly. Use at your own risk. I'm sure @tarsius can comment.
Update: Now I'm using
(let ((changed (magit-git-items "diff" "-z" "--name-only" head)))
(magit-with-temp-index index
(when worktree
(or (magit-update-files changed)
(error "Cannot save the current worktree state")))
(or (magit-commit-tree message nil head index untracked)
(error "Cannot save the current worktree state"))))))That's interesting. I will look into that, but I suspect that your fix results in a stash that is different from what you would get otherwise.
bsuh
commented
9 years ago (magit-git-items "diff" "-z" "--name-only" head) is diffing a head tree-ish with the working directory. The index shouldn't affect that comparison, no? Therefore hoisting it out of the magit-with-temp-index macro should be fine. That is the simple conclusion I have come after much head scratching considering all the branch paths taken with different values of the boolean variables worktree, index, conflicts through magit-stash-create.
bsuh
commented
9 years ago I have created a reproducible repository
#!/bin/sh
cd
mkdir magit_2049
cd magit_2049
# create zeroed out file sized 1GB
dd if=/dev/zero of=test bs=1024 count=1048576
echo "hello" > hmm
git init
git add test
git add hmm
git commit -m "first commit!"
echo "hello2" >> hmmTry stashing the change to the hmm file. And have top running. git takes 100% cpu.
holocronweaver
commented
9 years ago I can confirm that this test repo reproduces the issue, including the fact that stashing outside of Magit causes no similar slowdown.
Thanks for the work, @bsuh. Any ideas for a fix?
bsuh
commented
9 years ago @holocronweaver See #2253
tarsius
commented
9 years ago Okay this is quite embarrassing. The issue was that magit-with-temp-index evaluated the TREE form at compile time.
tarsius
commented
9 years ago Note that you need to recompile carefully because this changes a macro. Use make clean-lisp lisp. If you use package.el and you (or your starter-kit) haven't done anything to undo the "compile in another emacs instance" hack, then you should be safe too.
holocronweaver
commented
9 years ago So the ,@ was the culprit? If you don't mind, could you explain what that means in elisp?
tarsius
commented
9 years ago It is similar to ``, but "splices" the evaluated value into the resulting list. See http://www.gnu.org/software/emacs/manual/html_node/elisp/Backquote.html. But that wasn't really the issue; if I had used,(--when-let tree (or ... the result would have been the same with regards to when things get evaluated. (In case TREE literally is nil we would have gotten (progn nil ... instead of (progn ... without the additional nil.)
bsuh
commented
9 years ago Unfortunately this is still a problem for me. I created a screencast using the script I posted earlier to create a repository to reproduce the problem, to reproduce the problem with the latest magit-with-temp-index.
holocronweaver
commented
9 years ago The issue does not appear to be resolved for me either. I cleared my elpa folder before updating, so I assume there are no stale compiled elisp files anywhere.
tarsius
commented
9 years ago I used the provided steps to get to af85aea181242b7bcf462035f22f73e113f2ac47. Will look into that.
bsuh
commented
9 years ago This issue is fixed for me after 59e43cb! :+1:
holocronweaver
commented
9 years ago YAAAAAAAAAAAAAY! Hats off to @bsuh and @tarsius for getting this fixed. I am spared the pain of venturing from my posh Emacs environment to venture into the terminal stone age.
tarsius
commented
9 years ago This time I tested after all the changes, so I was fairly confident, but waited for you to confirm.
It looks like magit is calling
git update-index, passing what appears to be every file in my repository. Based on some observations of the offending sub-processes being created (see below) the offending code appears to be(magit-update-files). While working on the Linux kernel this completely hangs emacs for up to a minute.I've noticed this while staging changes after resolving merge conflicts and also while stashing. Looking at the call sites for
(magit-update-files)I don't see how this can possibly happen... Any ideas?Here's the (truncated) command line scraped from
psduring one such hang while trying to stage a file where I had just finished resolving some merge conflicts: