Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Performance Problems for magithub-issue-insert-section #152

Open
jgkamat opened this issue Oct 24, 2017 · 10 comments
Open

Performance Problems for magithub-issue-insert-section #152

jgkamat opened this issue Oct 24, 2017 · 10 comments
Assignees
Labels
performance concerned with efficiency or response times
Milestone

Comments

@jgkamat
Copy link
Contributor

jgkamat commented Oct 24, 2017

I always noticed on semi-large repostiories, magithub would slow down magit-status a lot. After seeing this in offline mode, I realized this is actually mostly performance problems, and not waiting for api calls.

I took a stacktrace of magit-status called repeatedly for qutebrowser/qutebrowser (with 400 issues, and about 20 prs)`

- command-execute                                                9119  93%
 - call-interactively                                            9119  93%
  - apply                                                        9119  93%
   - call-interactively@ido-cr+-record-current-command               9119  93%
    - apply                                                      9119  93%
     - #<subr call-interactively>                                9119  93%
      - funcall-interactively                                    9103  93%
       - magit-status                                            8574  88%
        - magit-status-internal                                  8574  88%
         - magit-mode-setup                                      8574  88%
          - magit-mode-setup-internal                            8574  88%
           - magit-refresh-buffer                                8423  86%
            - apply                                              8376  85%
             - magit-status-refresh-buffer                       8112  83%
              - magit-run-section-hook                           8032  82%
               - run-hooks                                       8032  82%
                - magithub-issue--insert-issue-section               7346  75%
                 - magithub-issue-insert-sections                7332  75%
                  - mapcar                                       7332  75%
                   - #<compiled 0x30199e9>                       7332  75%
                    - magithub-issue-insert-section               7300  74%
                     - run-hook-with-args                        6616  67%
                      - magithub-issue-detail-insert-body-preview               1432  14%
                       + s-word-wrap                             1220  12%
                       + #<compiled 0x1fbe465>                     56   0%
                         generate-new-buffer                       36   0%
                       + s-trim                                    32   0%
                         replace-regexp-in-string                   8   0%
                      + magithub-issue-detail-insert-labels                331   3%
                      + magithub-issue-detail-insert-assignees                190   1%
                      + magithub-issue-detail-insert-author                145   1%
                       magit-get-section                           32   0%
                     + magit-insert-heading                        20   0%
                     + run-hook-with-args-until-success                  8   0%
                 + magithub-issues                                  6   0%
                + magithub-issue--insert-pr-section                260   2%
                + magit-insert-status-headers                     131   1%
                + magit-insert-merge-log                           11   0%
                + magit-insert-unpulled-from-upstream                  4   0%
                + magit-insert-unpulled-from-pushremote                  4   0%
                + magit-insert-staged-changes                       4   0%
              + magit-section-show                                 68   0%
           + magit-display-buffer                                  53   0%
           + magit-status-mode                                     41   0%
           + run-hooks                                             20   0%
       + smex                                                     529   5%
      + byte-code                                                  16   0%
+ ...                                                             558   5%
+ redisplay_internal (C function)                                  44   0%
+ timer-event-handler                                               8   0%
+ sp--save-pre-command-state                                        5   0%
+ evil-repeat-pre-hook                                              4   0%
+ erc-server-filter-function                                        4   0%

It turns out 75% of time is spent generating the details for issues (which I feel can be optimized down).

Right away I saw a possible improvement where we can trim the string description before wrapping it (rather than after), as 12% of time is spent wrapping long descriptions (that are never used later)

run-hook-with-args seems to be taking a huge chunk of time itself, I'm not entirely sure why. I'm going to play with making that hook a function instead, and seeing if that improves performance (or gives me a better profile to look at).

I'm more than happy to work on this, because I like this kind of thing a lot :). It might be a while before I can work on it though.

@vermiculus vermiculus added the performance concerned with efficiency or response times label Oct 24, 2017
@vermiculus vermiculus self-assigned this Oct 24, 2017
@vermiculus
Copy link
Owner

vermiculus commented Oct 24, 2017

Can I ask how exactly you got that output? I used to know, but I can't seem to place my finger on the function.

We might try something like magit-log does: if there are going to be many child sections, have a 'more' button that will load the remaining ones. (We can set the section-data to the remaining sections or even a form to execute to do the job.)

Otherwise I made the change you suggested and don't notice much of an improvement:

(defun magithub-issue-detail-insert-body-preview (issue fmt)
  "Insert a preview of ISSUE's body using FMT."
  (let-alist issue
    (let* ((label-string (format fmt "Preview:"))
           (label-len (length label-string))
           (prefix (make-string label-len ?\ ))
           did-cut)
      (insert label-string
              (if (or (null .body) (string= .body ""))
                  (concat (propertize "none" 'face 'magit-dimmed))
                (concat
                 (s-trim
                  (with-temp-buffer
                    (insert (replace-regexp-in-string "^M" "" .body)) ;; todo: use actual control character
                    (goto-char (* 3 (- fill-column label-len)))
                    (forward-line 3)
                    (unless (eobp)
                      (setq did-cut t)
                      (backward-char 3))
                    (delete-region (point) (point-max))
                    (let ((text (buffer-string)))
                      (erase-buffer)
                      (insert (s-word-wrap (- fill-column label-len) text)))
                    (goto-char 0)
                    (let ((lines 0))
                      (while (and (not (eobp))
                                  (< (setq lines (1+ lines)) 4))
                        (insert prefix)
                        (forward-line))
                      (unless (= (point) (point-max))
                        (delete-region (point) (point-max))
                        (setq did-cut t)))
                 (when did-cut
                   (propertize "..." 'face 'magit-dimmed))))
              "\n"))))

@jgkamat
Copy link
Contributor Author

jgkamat commented Oct 25, 2017

Ah, that's the output of the builtin emacs profiler, see profiler-start (cpu) profiler-report and profiler-stop. I'm not sure how reliable it is though.

We might try something like magit-log does: if there are going to be many child sections, have a 'more' button that will load the remaining ones. (We can set the section-data to the remaining sections or even a form to execute to do the job.)

That would be really neat! After looking at this a bit, I'm starting to think the majority of the lag is coming from inserting magit entries, so paginating the log list would help a lot if that's the case. I'm probably still going to see if I can get some more concrete information, because it is very nice to have all the issues in one drawer.

I'm going to try profiling that implementation of the function when I get some free time, but at a first glance I don't like it because it:

  1. Inserts (possibly) long issues descriptions in a buffer
  2. Runs a regexp on the entire buffer (I'm not sure exactly what that is, though)

I don't know too much about emacs performance, so I could be wrong about those though (I'll let you know what I find out).

Just a heads up about profiling, don't compare byte-compiled code to evaluated code (I made the mistake of evaluating my modifications, and have them always be slower).

@vermiculus
Copy link
Owner

vermiculus commented Oct 25, 2017

Here's an updated definition based on your comments. It's a little wordier, but hopefully faster.

(defun magithub-issue-detail-insert-body-preview (issue fmt)
  "Insert a preview of ISSUE's body using FMT."
  (let-alist issue
    (let* ((label-string (format fmt "Preview:"))
           (label-len (length label-string))
           (prefix (make-string label-len ?\ ))
           (width (- fill-column label-len))
           (maxchar (* 3 width))
           (did-cut (< maxchar (length .body)))
           (maxchar (if did-cut (- maxchar 3) maxchar))
           (text (if did-cut (substring .body 0 maxchar) .body))
           (text (replace-regexp-in-string "^M" "" text))
           (text (s-word-wrap width (s-trim text))))
      (insert label-string
              (if (or (null .body) (string= .body ""))
                  (concat (propertize "none" 'face 'magit-dimmed))
                (concat
                 (s-trim
                  (with-temp-buffer
                    (insert text)
                    (goto-char 0)
                    (forward-line)
                    (let ((lines 1))
                      (while (and (not (eobp))
                                  (< (setq lines (1+ lines)) 4))
                        (insert prefix)
                        (forward-line))
                      (unless (eobp)
                        (delete-region (point) (point-max))
                        (setq did-cut t)))
                    (buffer-string)))
                 (when did-cut
                   (propertize "..." 'face 'magit-dimmed))))
              "\n"))))

I'll try to get the profiler up and running.

@jgkamat
Copy link
Contributor Author

jgkamat commented Oct 25, 2017

Yup, that definition seems a little bit faster to me (when comparing the previous definition)!

I still have no idea why run-hook-with-args or the let form is taking so much time though (and figuring out why that's happening is probably a bigger fix), I'm going to see if I can figure out whats going on there. Interestingly the entire function looks like it's taking up more time (from the let?) but I think that might be me not byte compiling the files this time, maybe.

Also, when profiling, you have to run profiler-report before stopping the profile, I'm not sure why.

- command-execute                                               13413  93%
 - call-interactively                                           13413  93%
  - apply                                                       13413  93%
   - call-interactively@ido-cr+-record-current-command              13413  93%
    - apply                                                     13413  93%
     - #<subr call-interactively>                               13413  93%
      - funcall-interactively                                   13408  93%
       - magit-status                                           11536  80%
        - magit-status-internal                                 11536  80%
         - magit-mode-setup                                     11536  80%
          - magit-mode-setup-internal                           11536  80%
           - magit-refresh-buffer                               11349  78%
            - apply                                             11325  78%
             - magit-status-refresh-buffer                      11057  76%
              - magit-run-section-hook                          11049  76%
               - run-hooks                                      11049  76%
                - magithub-issue--insert-issue-section              10371  71%
                 - magithub-issue-insert-sections               10347  71%
                  - mapcar                                      10347  71%
                   - #<compiled 0x26face5>                      10347  71%
                    - magithub-issue-insert-section              10347  71%
                     - if                                       10347  71%
                      - progn                                   10347  71%
                       - let*                                   10347  71%
                        - let                                   10191  70%
                         - catch                                10191  70%
                          - let                                 10071  69%
                           - let                                10067  69%
                            - run-hook-with-args                 9191  63%
                             - magithub-issue-detail-insert-body-preview               2396  16%
                              - let                              2392  16%
                               - let                             2392  16%
                                - let*                           2392  16%
                                 + s-word-wrap                    508   3%
                                 + insert                         224   1%
                                 + replace-regexp-in-string                 20   0%
                             + magithub-issue-detail-insert-author                628   4%
                             + magithub-issue-detail-insert-labels                392   2%
                             + magithub-issue-detail-insert-assignees                220   1%
                               magithub-issue-detail-insert-updated                  4   0%
                            + magit-insert-heading                 24   0%
                          + let*                                   60   0%
                          + if                                     40   0%
                        + progn                                   156   1%
                 + magithub-issues                                  4   0%
                   magit-insert-child-count                         4   0%
                + magithub-issue--insert-pr-section                261   1%
                + magit-insert-status-headers                     121   0%
                  magit-insert-unstaged-changes                     9   0%
                + magit-insert-unpulled-from-pushremote                  8   0%
                  magit-insert-unpulled-from-upstream                  8   0%
                + magit-insert-staged-changes                       7   0%
                + magit-insert-unpushed-to-upstream                  2   0%
                  magit-insert-merge-log                            2   0%
           + run-hooks                                             56   0%
           + magit-display-buffer                                  51   0%
           + magit-status-mode                                     37   0%
       + smex                                                    1862  12%
       + magit-mode-bury-buffer                                    10   0%
      + byte-code                                                   5   0%
+ ...                                                             894   6%
+ redisplay_internal (C function)                                  92   0%
+ timer-event-handler                                               9   0%

@vermiculus
Copy link
Owner

I'm guessing the profiler isn't smart enough to descend into the evaluation of the letbound forms. I'll see what I can do to figure how long those take.

@jgkamat
Copy link
Contributor Author

jgkamat commented Oct 26, 2017

I spent a bit of time working on this and I think the issue is in the usage of insert.

insert is a C function, so I don't think it gets profiled well by the lisp profiler. A way around this is to do something like:

(defalias 'jp-1 'progn)
(defalias 'jp-2 'progn)
(defalias 'jp-3 'progn)

Using the alias to surround suspcious parts helps pin down which forms are taking the most time.

I found that something like:

(dotimes (x 4000) (insert "Author: ") (insert (number-to-string x)) (insert "trailing\n"))

is much slower than inserting the entire text at once. Is it possible to build a string and then insert it, perhaps? (I'm not sure if string building is slower or not) I'm not too familiar with magit. If it isn't I think that it's probably best to limit the amount of stuff put into the magit buffer (my status buffer is over 3000 lines long).

@vermiculus
Copy link
Owner

I didn't find concatenating the string before insertion to be effective on my end – we might be hitting a low-level difference in our respective computers.

One workaround for you for now is to use magithub-issue-issue-filter-functions to limit what shows up – maybe only show issues assigned to you or something… :/

@tarsius Do you recall hitting a threshold like this with magit-log?

vermiculus added a commit that referenced this issue Oct 27, 2017
@tarsius
Copy link
Contributor

tarsius commented Oct 27, 2017

Do you recall hitting a threshold like this with magit-log?

No.

I didn't find concatenating the string before insertion to be effective on my end

I would expect that concatenating first would be less efficient. Edit: but thinking about it again - maybe not. Performing some benchmarks and/or asking Eli seems like a good idea.

vermiculus added a commit that referenced this issue Oct 28, 2017
@jgkamat
Copy link
Contributor Author

jgkamat commented Nov 1, 2017

I ended up solving this issue by filtering issues shown by magithub-status using this function:

(defun jay/mgh-filter-issues (issue)
    (let-alist issue
      (or
       (string= .user.login jay/github-user)
       (when .assignees
         (-first
          (lambda (assignees)
            (let-alist assignees
              (string= .login jay/github-user)))
          .assignees)))))

I think that there's probably nothing more we can do (from what I can see) so I'm fine with this being closed. Maybe it would be nice to provide sample filter functions to filter based on the current user (pulled from github token) but I don't mind if that's done or not.

@vermiculus
Copy link
Owner

vermiculus commented Nov 1, 2017

I'm a fan of some default filter functions. As a note to self, I'd want some way to advertise them in the customize interface.

Small note to make your coffeecode(autocorrect?) generalizable: you can use magithub-user-me to get the currently authenticated user.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
performance concerned with efficiency or response times
Projects
None yet
Development

No branches or pull requests

3 participants