[Bug/Support]: Elpaca looks as if stuck while installing packages

[Martinsos]

Confirmation

• I have checked the documentation (README, Wiki, docstrings, etc)
• I am checking these without reading them.
• I have searched previous issues to see if my question is a duplicate.

Elpaca Version

Elpaca f83af38 grafted, HEAD -> master, origin/master, origin/HEAD
installer: 0.9
emacs-version: GNU Emacs 29.4 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.43, cairo version 1.18.2)
git --version: git version 2.47.0

Operating System

Archlinux

Description

When installing org, it gets stuck in this specific state for a quite long time (5 minutes I would guess, maybe even more. EDIT: logs say 15 minutes!). It gives impression that installation is permanently stuck, and I only figured out is it not because it started moving again at some point as I was writing this issue on github.

Is there any way to indicate progress in such situation in a better way?

Actually, here are the logs:

log:
  [2025-01-21 13:06:38] Package queued
  [2025-01-21 13:06:38] Continued by: elpaca--process
  [2025-01-21 13:06:38] Cloning
  [2025-01-21 13:06:38] $git clone --filter=tree:0 https://git.savannah.gnu.org/git/emacs/org-mode.git /home/martin/.emacs.d/elpaca/repos/org/
  [2025-01-21 13:06:38]   Cloning into '/home/martin/.emacs.d/elpaca/repos/org'...
  [2025-01-21 13:06:42]   warning: filtering not recognized by server, ignoring
  [2025-01-21 13:07:10]   remote: Enumerating objects: 149987, done.        
  [2025-01-21 13:07:10]   remote: Counting objects: 100% (149987/149987), done.        
  [2025-01-21 13:07:10]   remote: Compressing objects: 100% (36696/36696), done.        
  [2025-01-21 13:22:45]   remote: Total 149987 (delta 117689), reused 144194 (delta 113148), pack-reused 0        
  [2025-01-21 13:22:45]   Receiving objects: 100% (149987/149987), 102.92 MiB | 112.00 KiB/s, done.
  [2025-01-21 13:22:52]   Resolving deltas: 100% (117689/117689), done.
  [2025-01-21 13:22:52] Continued by: elpaca--clone-process-sentinel
  [2025-01-21 13:22:52] Continued by: elpaca--configure-remotes
  [2025-01-21 13:22:52] Continued by: elpaca--checkout-ref
  [2025-01-21 13:22:52] Running :pre-build commands

It seems like this big gap is happening between 13:07 and 13:22 -> so objects were compressed (that is git output if I am correct), and then it took 15 minutes for what hm, to download them?

[progfolio]

Thank you for the detailed report.

Is there any way to indicate progress in such situation in a better way?

There is some logic to mark a process as "busy" when it has been run but has not produced new output after the elpaca-busy-interval has passed. A face will be applied to the package's ID and it should be reflected in the status line package counts under "other".
However, there's also logic in the logging system to consolidate output which would normally clear the current line on a terminal (such as git's object compression logs). So my hunch is that the log was being updated, but overwritten here:

[2025-01-21 13:07:10] remote: Compressing objects: 100% (36696/36696), done.

The default recipe can be improved to use a shallow clone considering git.savannah.gnu does not support filtering:

[2025-01-21 13:06:42] warning: filtering not recognized by server, ignoring

That should speed things up considerably.
You should be able to see a difference after updating Elpaca the next time you install Org if you add :depth 1 to Org's declaration.
e.g.

1. M-x elpaca-update elpaca
2. M-x elpaca-delete org
3. M-x restart-emacs

[Martinsos]

Ok, so you are getting the logs without knowing their meaning, and here it happened that there was a big gap between the two. I get that logs are getting merged if they do \r, but just to be clear, for me it was stuck on 100% being printed there, for long time. So I doubt there were new logs comming during that time, unless I am getting something wrong here?
What sounds great to me is what you said there, showing some visual indicator of business on the specific line that is about package that is responsible for it, after some time delta of logs not coming, but that wasn't happening for me.

[progfolio]

I've reworked the logic to mark events in the log as "busy".
It should be more robust than the previous approach.
You can try it out with the following test case:

(elpaca-test
  :interactive t
  :init
  ;; Set intentionally low here for demonstration purposes
  (setq elpaca-busy-interval 2)
  (elpaca org))

Likewise, you should see the difference after an M-x elpaca-update elpaca followed by an M-x restart-emacs. Testing is appreciated.