many magit operations are slowed by forge-get-repository when many forge topics

[aspiers]

I noticed that many magit and forge operations are slow (e.g. 1 or 2 seconds) when run on a repository which has a lot of forge topics in the emacsql database, such as the magit repo itself. This applies to magit-status, magit-commit-create, and others - in fact just pressing ' to trigger the forge transient is sufficient to trigger it. So I did some profiling via etrace:

(elp-restore-all)
(elp-instrument-package "magit")
(elp-instrument-package "forge")
(elp-instrument-package "emacsql")
(elp-instrument-package "closql")

(elp-reset-all)
(magit-status "/home/adam/.emacs.d/straight/repos/magit")
(etrace-write)

and loading the resulting etrace.json into https://www.speedscope.app/ revealed this:

So I added the following debug to emacsql-wait:

@@ -158,7 +158,9 @@ (defclass emacsql-connection ()
     (while (and (or (null real-timeout) (< (float-time) end))
                 (not (emacsql-waiting-p connection)))
       (save-match-data
+        (message "before accept-process-output %f" (float-time))
         (accept-process-output (emacsql-process connection) real-timeout)))
+        (message "after accept-process-output %f" (float-time))
     (unless (emacsql-waiting-p connection)
       (signal 'emacsql-timeout (list "Query timed out" real-timeout)))))

and sure enough, this confirms it:

before accept-process-output 1604262682.648445
after accept-process-output 1604262682.655656
before accept-process-output 1604262682.661547
after accept-process-output 1604262683.454592
before accept-process-output 1604262683.462395
after accept-process-output 1604262683.969285
before accept-process-output 1604262683.977087
after accept-process-output 1604262684.519352
before accept-process-output 1604262684.542023
after accept-process-output 1604262685.002909

This is with the latest master of magit, forge, emacsql, and closql (all installed via straight.el).

I haven't had time to build a reproducible test case yet, so it's possible that this is a local issue with my own ~/.emacs.d/forge-database.sqlite, but I thought I'd share now anyway in the hope that this might be useful.

[aspiers]

Edited to reflect that this problem affects many common operations, not just magit-status.

[aspiers]

M-x forge-remove-repository instantly eliminates the slowness, but of course that's not ideal because I really want to use forge ;-)

[tarsius]

If I interpret that image correctly (and then some) this means that (forge-get-repository 'full) is slow for you. You might want to time just that. However I don't see how the performance of that function could be affected by the number of topics.

and sure enough, this confirms it:

What does that confirm and how?

(Consider using durations like so):

(message "Stuff...done (%.3fs)"
         (float-time (time-subtract (current-time) before)))        

[aspiers]

(let ((before (float-time)))
  (forge-get-repository 'full)
  (message "forge-get-repository took %.3fs"
           (float-time (time-subtract (current-time) before))))

on a repo with no forge remote configured yields:

forge-get-repository took 0.008s

On the magit repo, it yields:

forge-get-repository took 1.030s

Maybe it's not the number of topics but something else; that was an (un)educated guess.

[tarsius]

On the magit repo, it yields 0.02 to 0.04 for me.

Maybe it's not the number of topics but something else; that was an (un)educated guess.

Try M-x forge-toggle-display-in-status-buffer.

[aspiers]

Thanks for the suggestion; unfortunately that toggle makes no difference. Given that most of the time is being spent when emacsql-wait invokes accept-process-output, doesn't that suggest this is an issue with emacs-sqlite, e.g. either the connection to the external process or perhaps an excessively slow query?

[aspiers]

Don't suppose you've had any ideas for anything else I could investigate on this issue? Forge is still quite painfully slow for me, unfortunately (although I still use it because I love it).

[tarsius]

I suspect you were right when you wrote

Given that most of the time is being spent when emacsql-wait invokes accept-process-output, doesn't that suggest this is an issue with emacs-sqlite, e.g. either the connection to the external process or perhaps an excessively slow query?

So it would be useful if you could try to figure out which of the two it is.

[aspiers]

I just changed emacsql to the following:

(cl-defmethod emacsql ((connection emacsql-connection) sql &rest args)
  "Send SQL s-expression to CONNECTION and return the results."
  (emacsql-clear connection)
  (let ((sql-string (apply #'emacsql-compile connection sql args))
        (before (float-time)))
    (emacsql-send-message connection sql-string)
    (emacsql-wait connection)
    (let* ((after (float-time))
           (elapsed (- after before)))
      (if (> elapsed 0.2)
          (message "emacsql: slow query (%fs): %s" elapsed sql-string)))
    (emacsql-parse connection)))

and immediately saw:

emacsql: slow query (0.459997s): UPDATE repository SET apihost = '"api.github.com"' WHERE id = '"Z2l0aHViLmNvbTowMTA6UmVwb3NpdG9yeTMyMjA3MzA0MQ=="';
emacsql: slow query (0.416893s): UPDATE repository SET githost = '"github.com"' WHERE id = '"Z2l0aHViLmNvbTowMTA6UmVwb3NpdG9yeTMyMjA3MzA0MQ=="';
emacsql: slow query (0.204041s): UPDATE repository SET remote = '"origin"' WHERE id = '"Z2l0aHViLmNvbTowMTA6UmVwb3NpdG9yeTMyMjA3MzA0MQ=="';
emacsql: slow query (0.202354s): UPDATE repository SET worktree = '"/home/adam/my/repo/"' WHERE id = '"Z2l0aHViLmNvbTowMTA6UmVwb3NpdG9yeTMyMjA3MzA0MQ=="';
emacsql: slow query (0.225668s): UPDATE repository SET apihost = '"api.github.com"' WHERE id = '"Z2l0aHViLmNvbTowMTA6UmVwb3NpdG9yeTMyMjA3MzA0MQ=="';

This seems insanely slow for such simple updates.

[aspiers]

Filed at magit/emacsql#81

[aspiers]

I notice that these slow queries are triggered when entering magit-log-mode:

  forge-bug-reference-setup()
  run-hooks(change-major-mode-after-body-hook special-mode-hook magit-section-mode-hook magit-mode-hook magit-log-mode-hook)
  apply(run-hooks (change-major-mode-after-body-hook special-mode-hook magit-section-mode-hook magit-mode-hook magit-log-mode-hook))
  run-mode-hooks(magit-log-mode-hook)
  magit-log-mode()

Is this correct that it is necessary to run forge-bug-reference-setup when viewing logs? I see that forge-bug-reference-setup is in magit-mode-hook, and also in other hooks like find-file-hook, so this performance issue ends up slowing down several commonly used operations. I'm not sure why scenarios involving essentially read-only operations such as viewing logs or opening files would need to trigger a whole load of UPDATE statements. For example, in the backtraces I see that UPDATE statements like the above are being triggered from frames like:

  forge-get-repository(("github.com" "skeeto" "emacsql") "origin" full)

That seems pretty strange to me, but I'm probably missing something?

[aspiers]

I'm trying this workaround to see if it breaks anything:

  (remove-hook 'find-file-hook 'forge-bug-reference-setup)
  (remove-hook 'magit-mode-hook 'forge-bug-reference-setup)

[tarsius]

That seems pretty strange to me, but I'm probably missing something?

worktree is set so that forge-visit-repository can now where the (or the last clone, or worktree) of a certain repository happens to reside in the local file-system. The others have to be set too but probably not again and again, I cannot quite wrap my head around it right now. The reasoning is "it is so cheap to set these values, whether doing so is a no-op or not, we might as well do that instead of determining whether we actually have to do it, which might be just as expensive, or more".

Of course if these actions turn out not to be cheap but excessively expensive, then that calculation changes. But we assume that some issue in emacsql causes the slowness, so the above reasoning is still sound, at least in theory.

Is this correct that it is necessary to run forge-bug-reference-setup when viewing logs?

It's not necessary but potentially useful. (Some commit messages mention an issue in its summary, and it might be convenient to visit that issue with one key press.)

I'm trying this workaround to see if it breaks anything:

It probably won't break anything but it almost certainly won't help. Calls to forge-get-repository are cached during a refresh. The one done by the bug-reference code happens to be the first, so nothing is cached yet and its value becomes the cached value. If that call is removed, then another becomes the first.

[aspiers]

@tarsius commented on September 12, 2021 8:17 AM:

That seems pretty strange to me, but I'm probably missing something?

worktree is set so that forge-visit-repository can now where the (or the last clone, or worktree) of a certain repository happens to reside in the local file-system. The others have to be set too but probably not again and again, I cannot quite wrap my head around it right now. The reasoning is "it is so cheap to set these values, whether doing so is a no-op or not, we might as well do that instead of determining whether we actually have to do it, which might be just as expensive, or more".

Of course if these actions turn out not to be cheap but excessively expensive, then that calculation changes. But we assume that some issue in emacsql causes the slowness, so the above reasoning is still sound, at least in theory.

I see - thanks for the explanation, and yes, that seems fair. Certainly I would have expected a single UPDATE to be extremely cheap too (and many of them are, BTW).

Is this correct that it is necessary to run forge-bug-reference-setup when viewing logs?

It's not necessary but potentially useful. (Some commit messages mention an issue in its summary, and it might be convenient to visit that issue with one key press.)

I'm trying this workaround to see if it breaks anything:

It probably won't break anything but it almost certainly won't help. Calls to forge-get-repository are cached during a refresh. The one done by the bug-reference code happens to be the first, so nothing is cached yet and its value becomes the cached value. If that call is removed, then another becomes the first.

Weirdly, it has helped; at least, find-file and viewing magit logs are now much nearer to instant, and don't trigger either of the slow query (plus edebug) or fast query messages below:

(cl-defmethod emacsql ((connection emacsql-connection) sql &rest args)
  "Send SQL s-expression to CONNECTION and return the results."
  (emacsql-clear connection)
  (let ((sql-string (apply #'emacsql-compile connection sql args))
        (before (float-time)))
    (emacsql-send-message connection sql-string)
    (emacsql-wait connection)
    (let* ((after (float-time))
           (elapsed (- after before)))
      (cond ((> elapsed 0.2)
             (message "emacsql: slow query (%fs): %s"
                      elapsed sql-string)
             (edebug))
            (t
             (message "emacsql: fast query (%fs): %s"
                      elapsed sql-string))))
    (emacsql-parse connection)))

I added

(remove-hook 'git-commit-setup-hook 'forge-bug-reference-setup)

too, since creating commits was experiencing the same issue.

[aspiers]

I should mention I also tried running VACUUM on the forge sqlite3 database, but it only shaved about 2MB off a ~90MB file (now 108MB due to fetching topics from emacs-lsp), and had no impact on performance.

[tarsius]

I've added optional support for using the sqlite library using a module instead of using a child process. Still highly experimental but it seems faster. To use it you have to:

1. Install emacsql-libsqlite3
2. Update closql and forge (and epkg if you use that)
3. (setq forge-database-connector 'libsqlite3) before loading forge

You can continue using the existing database.

[tarsius]

I've also tried psql but being another dialect that required translating some queries (not quite done but poc ready) and then it turned out this implemenation has issues communicating with the client that are worse than just being slow, so all in all not a win over emacsql-sqlite.

[tarsius]

I have now releases two new SQLite backends, both maintained at https://github.com/emacscollective/emacsql-sqlite-builtin. They are no longer considered experimental. Please give one of them a try.

[aspiers]

emacsql-sqlite-module seems to have fixed it - thank you so much!!

[whompyjaw]

I have now releases two new SQLite backends, both maintained at https://github.com/emacscollective/emacsql-sqlite-builtin. They are no longer considered experimental. Please give one of them a try.

I am experiencing a fairly slow magit experience since I added forge. Reading this it doesn't seem like it's an on-going issue (so it could just my network), but just wanted to add that this link goes to a 404. So was this merged into emacsql and is the default? I would like to try to speed up my magit experience back to its original. Sadly, I am not experienced enough in elisp to provide all the statistics that aspiers provided. I can only anecdotally say that the magit experience on a repo is significantly slower since I added forge.

@aspiers , if you happen to have any commands I can run to benchmark this, I would be thankful!

[whompyjaw]

Using this tutorial: https://jakemccrary.com/blog/2020/11/14/speeding-up-magit/

I was able to go from 9s:

Refreshing buffer ‘magit: memory-model’...
  magit-insert-error-header                          4.365e-06 
  magit-insert-diff-filter-header                    0.022676676 !
  magit-insert-head-branch-header                    0.064967722 !!
  magit-insert-upstream-branch-header                0.048609714 !!
  magit-insert-push-branch-header                    6.5858e-05 
  magit-insert-tags-header                           4.822492132 !!
  magit-insert-status-headers                        4.979219423 !!
  magit-insert-merge-log                             0.014104538 !
  magit-insert-rebase-sequence                       9.4305e-05 
  magit-insert-am-sequence                           5.5744e-05 
  magit-insert-sequencer-sequence                    0.000168177 
  magit-insert-bisect-output                         5.4311e-05 
  magit-insert-bisect-rest                           5.4868e-05 
  magit-insert-bisect-log                            5.3563e-05 
  magit-insert-untracked-files                       0.274922623 !!
  magit-insert-unstaged-changes                      0.041846209 !!
  magit-insert-staged-changes                        0.048330037 !!
  magit-insert-stashes                               0.090688758 !!
  magit-insert-unpushed-to-pushremote                5.1123e-05 
  magit-insert-unpushed-to-upstream-or-recent        2.008738283 !!
  magit-insert-unpulled-from-pushremote              5.509e-06 
  magit-insert-unpulled-from-upstream                1.901123775 !!
  forge-insert-pullreqs                              0.046931576 !!
  forge-insert-issues                                0.002156839 
Refreshing buffer ‘magit: memory-model’...done (9.771s)

To under a second:

Refreshing buffer ‘magit: memory-model’...
  magit-insert-merge-log                             0.013176462 !
  magit-insert-rebase-sequence                       0.000142693 
  magit-insert-am-sequence                           7.4905e-05 
  magit-insert-sequencer-sequence                    0.000389368 
  magit-insert-bisect-output                         5.4055e-05 
  magit-insert-bisect-rest                           5.3161e-05 
  magit-insert-bisect-log                            5.3745e-05 
  magit-insert-untracked-files                       0.299808431 !!
  magit-insert-unstaged-changes                      0.043206543 !!
  magit-insert-staged-changes                        0.039093796 !!
  magit-insert-stashes                               0.089974638 !!
  forge-insert-pullreqs                              0.048540768 !!
  forge-insert-issues                                0.002135291 
Refreshing buffer ‘magit: memory-model’...done (0.896s)

I do lose some status data, but I don't think it's really needed. I imagine it will be faster if I removed forge

But idk if I should post this here instead: magit/magit#2982