v0.22.0 => increased app startup time

[MartinVincent]

Hi @extrawurst,

First, thanks for this great piece of software, it truly is the best of the CLI Git clients!

Just want to make an observation regarding the 0.22 release: I really appreciate the update with the great new features (yes! (#1371)), but I noticed that there is now a significant delay on startup for relatively small repos (1500 Commits):

• Launching gitui with an immediate quitting on that 1500 commit repo went from an average of : 0,094 (v0.21) up to 0,746 (v0.22).

Is that expected? (ie: the price to pay for the new features)

Thx!

[extrawurst]

That’s an Intretesting observation. Gonna look into this

[extrawurst]

How did you make this exact measurement?

[MartinVincent]

Answer: I quickly scripted the following and I ran it with both versions and averaged them out:

❯ cat ~/bin/gitui_test.scp
#!/usr/bin/expect
set version [lindex $argv 0];
spawn ~/bin/gitui_$version         # ie: symlinks to 0.21.0 or 0.22.0
expect "Status"
send "q\r";


# BTW no guarantee that this is a valid speed test

Now, your question above prompted me to rerun my script on a fresh clone of gitui's own repo (with its more than 1700 commits), and this time I did get satisfactory results:

[master:b495425  ] ~/Code/gitui ❯ TIMEFORMAT="delta: %E";
[master:b495425  ] ~/Code/gitui ❯ # for  0.21.0
[master:b495425  ] ~/Code/gitui ❯ for i in $(seq 10); do time ~/bin/gitui_test.scp  0.21.0  >/dev/null; done
delta: 0,072
delta: 0,033
delta: 0,032
delta: 0,032
delta: 0,032
delta: 0,032
delta: 0,032
delta: 0,035
delta: 0,032
delta: 0,032
[master:b495425  ] ~/Code/gitui ❯ # for  0.22.0
[master:b495425  ] ~/Code/gitui ❯ for i in $(seq 10); do time ~/bin/gitui_test.scp  0.22.0  >/dev/null; done
delta: 0,046
delta: 0,048
delta: 0,048
delta: 0,046
delta: 0,047
delta: 0,047
delta: 0,048
delta: 0,048
delta: 0,047
delta: 0,046

Update, I just redid the test on my own repo (fresh clone) and now I get similar satisfactory results to gitui's repo.

so... Conclusion: not sure what is the problem with my older perso repo, but it looks like a fresh clone fixes the issue in my case.

[MartinVincent]

Update: the issue appears to be reproducible (and caused by the presence of a python .virtualenv directory)

In the code block below, we can see that:

• test is started on a fresh clone of the gitui repo
• initial startup time difference between 0.21.0 and 0.22.0 is small
• the virtualenv is relatively small: only Ansible + its main dependencies are installed
  • (I can also confirm that installing more python wheels in the virtualenv, increases even more the startup time)
• the .virtualenv directory is correctly present in the .gitignore file
• post-virtualenv installation,
  • the startup time is constant for 0.21.0
  • the startup time is multiplied by ~ 4 for 0.22.0

 [master:b495425  ] /tmp/gitui ❯ g status
On branch master
Your branch is up to date with 'origin/master'.

nothing to commit, working tree clean

 [master:b495425  ] /tmp/gitui ❯ for i in $(seq 10) ; do time  ~/bin/gitui_startup_test.scp 0.21.0 >/dev/null; done
delta: 0,077
delta: 0,034
delta: 0,032
delta: 0,034
delta: 0,032
delta: 0,033
delta: 0,034
delta: 0,035
delta: 0,034
delta: 0,034

 [master:b495425  ] /tmp/gitui ❯ for i in $(seq 10) ; do time  ~/bin/gitui_startup_test.scp 0.22.0 >/dev/null; done
delta: 0,049
delta: 0,048
delta: 0,047
delta: 0,047
delta: 0,046
delta: 0,045
delta: 0,047
delta: 0,046
delta: 0,047
delta: 0,045

 [master:b495425  ] /tmp/gitui ❯ virtualenv --python python3.8 ./.virtualenv; source ./.virtualenv/bin/activate
created virtual environment CPython3.8.10.final.0-64 in 146ms
  creator CPython3Posix(dest=/tmp/gitui/.virtualenv, clear=False, global=False)
  seeder FromAppData(download=False, pip=latest, setuptools=latest, wheel=latest, pkg_resources=latest, via=copy, app_data_dir=<my home dir>/.local/share/virtualenv/seed-app-data/v1.0.1.debian.1)
  activators BashActivator,CShellActivator,FishActivator,PowerShellActivator,PythonActivator,XonshActivator
(gitui:)  [master:b495425  ] /tmp/gitui ❯ pip3 install ansible
Looking in indexes: http://pypi:3141/root/ax-focal/+simple/
Collecting ansible
  Downloading http://pypi:3141/root/pypi/%2Bf/3c6/812e9af1c243b/ansible-6.6.0-py3-none-any.whl (42.3 MB)
     |████████████████████████████████| 42.3 MB 1.2 MB/s 
Collecting ansible-core~=2.13.6
  Downloading http://pypi:3141/root/pypi/%2Bf/e31/fd550a5ea9423/ansible_core-2.13.6-py3-none-any.whl (2.1 MB)
     |████████████████████████████████| 2.1 MB 3.0 MB/s 
Collecting PyYAML>=5.1
  Downloading http://pypi:3141/root/pypi/%2Bf/277/a0ef2981ca405/PyYAML-6.0-cp38-cp38-manylinux_2_5_x86_64.manylinux1_x86_64.manylinux_2_12_x86_64.manylinux2010_x86_64.whl (701 kB)
     |████████████████████████████████| 701 kB 4.9 MB/s 
Collecting jinja2>=3.0.0
  Downloading http://pypi:3141/root/pypi/%2Bf/608/8930bfe239f0e/Jinja2-3.1.2-py3-none-any.whl (133 kB)
     |████████████████████████████████| 133 kB 5.0 MB/s 
Collecting packaging
  Downloading http://pypi:3141/root/pypi/%2Bf/ef1/03e05f519cdc7/packaging-21.3-py3-none-any.whl (40 kB)
     |████████████████████████████████| 40 kB 8.3 MB/s 
Collecting cryptography
  Downloading http://pypi:3141/root/pypi/%2Bf/b1b/52c9e5f8aa2b8/cryptography-38.0.3-cp36-abi3-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (4.2 MB)
     |████████████████████████████████| 4.2 MB 2.7 MB/s 
Collecting resolvelib<0.9.0,>=0.5.3
  Downloading http://pypi:3141/root/pypi/%2Bf/d9b/7907f055c3b3a/resolvelib-0.8.1-py2.py3-none-any.whl (16 kB)
Collecting MarkupSafe>=2.0
  Downloading http://pypi:3141/root/pypi/%2Bf/4b9/fe39a2ccc108a/MarkupSafe-2.1.1-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (25 kB)
Collecting pyparsing!=3.0.5,>=2.0.2
  Downloading http://pypi:3141/root/pypi/%2Bf/502/6bae9a10eeaef/pyparsing-3.0.9-py3-none-any.whl (98 kB)
     |████████████████████████████████| 98 kB 4.0 MB/s 
Collecting cffi>=1.12
  Downloading http://pypi:3141/root/pypi/%2Bf/4f2/c9f67e9821cad/cffi-1.15.1-cp38-cp38-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (442 kB)
     |████████████████████████████████| 442 kB 9.1 MB/s 
Collecting pycparser
  Downloading http://pypi:3141/root/pypi/%2Bf/8ee/45429555515e1/pycparser-2.21-py2.py3-none-any.whl (118 kB)
     |████████████████████████████████| 118 kB 3.6 MB/s 
Installing collected packages: PyYAML, MarkupSafe, jinja2, pyparsing, packaging, pycparser, cffi, cryptography, resolvelib, ansible-core, ansible
Successfully installed MarkupSafe-2.1.1 PyYAML-6.0 ansible-6.6.0 ansible-core-2.13.6 cffi-1.15.1 cryptography-38.0.3 jinja2-3.1.2 packaging-21.3 pycparser-2.21 pyparsing-3.0.9 resolvelib-0.8.1

(gitui:3.8.10)  [master:b495425 ∆  ] /tmp/gitui ❯ cat .gitignore  | grep virtual
.virtualenv


(gitui:3.8.10)  [master:b495425  ] /tmp/gitui ❯ for i in $(seq 10) ; do time  ~/bin/gitui_startup_test.scp 0.21.0 >/dev/null; done
delta: 0,050
delta: 0,035
delta: 0,034
delta: 0,036
delta: 0,032
delta: 0,034
delta: 0,037
delta: 0,034
delta: 0,035
delta: 0,034
(gitui:3.8.10)  [master:b495425  ] /tmp/gitui ❯ for i in $(seq 10) ; do time  ~/bin/gitui_startup_test.scp 0.22.0 >/dev/null; done
delta: 0,207
delta: 0,200
delta: 0,199
delta: 0,199
delta: 0,195
delta: 0,192
delta: 0,196
delta: 0,193
delta: 0,200
delta: 0,197

I hope this sheds some light on the issue.

[extrawurst]

can you do me a favour and compare this in a debug build and the -l arg to enable logging? this will generate entries in the log like these:

21:08:32 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118

the log on Mac can be found: ~/Library/Caches/gitui/gitui.log

my theory is that get_branches_info appears in there with the diff time while in 0.21 it does not on startup, can you verify?

if that's the case I assume the following commit is the offender: 216fad3

[extrawurst]

if we can validate that's the culprit we can fix it by making the waiting for the branches info async and have our fast(er) startup times again :)

[extrawurst]

@alexmaco maybe you wanna clean that up? :)

[MartinVincent]

Hum, I am no Rust programmer, but building (as per) [master:b495425], and then running the resulting binary with -l
yields:

 0 02:19:12 [TRACE] (6) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.5/src/poll.rs:532] registering event source with poller: token=Token(0), interests=READABLE                                                                                                                                                                                                                                                                                                  
 1 02:19:12 [TRACE] (6) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.5/src/poll.rs:532] registering event source with poller: token=Token(1), interests=READABLE
 2 02:19:12 [TRACE] (1) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.5/src/poll.rs:532] registering event source with poller: token=Token(0), interests=READABLE
 3 02:19:15 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/gitui-0.22.0/src/app.rs:119] open repo at: RefCell { value: Path(".") }
 4 02:19:15 [TRACE] (1) asyncgit::tags: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/asyncgit-0.22.0/src/tags.rs:67] request  
 5 02:19:15 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/gitui-0.22.0/src/app.rs:475] update          
 6 02:19:15 [TRACE] (1) asyncgit::tags: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/asyncgit-0.22.0/src/tags.rs:67] request  
 7 02:19:15 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/gitui-0.22.0/src/app.rs:494] update_async: Git(Tags)
 8 02:19:15 [TRACE] (1) asyncgit::tags: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/asyncgit-0.22.0/src/tags.rs:67] request  
 9 02:19:15 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/gitui-0.22.0/src/app.rs:494] update_async: Git(Log)
10 02:19:15 [TRACE] (1) asyncgit::tags: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/asyncgit-0.22.0/src/tags.rs:67] request  
11 02:19:15 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/gitui-0.22.0/src/app.rs:494] update_async: Git(Log)
12 02:19:15 [TRACE] (1) asyncgit::tags: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/asyncgit-0.22.0/src/tags.rs:67] request  
13 02:19:15 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/gitui-0.22.0/src/app.rs:494] update_async: Git(Tags)
14 02:19:15 [TRACE] (1) asyncgit::tags: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/asyncgit-0.22.0/src/tags.rs:67] request  
15 02:19:17 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/gitui-0.22.0/src/app.rs:380] event: Input(Key(KeyEvent { code: Char('q'), modifiers: NONE, kind: Press, state: NONE }))

Does this help?

[extrawurst]

no that is not a debug build, you can use make debug to build one

[MartinVincent]

Here are 2 trials:

• in gitui's own cloned repo, with a .virtualenv directory
• running :

 Running `target/debug/gitui -l`
(gitui:3.6.12)  [master:b495425  ] ~/Code/gitui ❯ make debug -l
RUST_BACKTRACE=true cargo run --features=timing -- -l
    Finished dev [unoptimized + debuginfo] target(s) in 0.06s
     Running `target/debug/gitui -l`

BTW: did you manage to reproduce the issue on your side?

1   tail: <my home dir>/.cache/gitui/gitui.log: file truncated                                                                                                                                                                                                                                                                                                                                                                                                                                          
  1 12:24:58 [TRACE] (6) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(0), interests=READABLE
  2 12:24:59 [TRACE] (6) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(1), interests=READABLE
  3 12:24:59 [TRACE] (1) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(0), interests=READABLE
  4 12:24:59 [TRACE] (1) gitui::app: [src/app.rs:119] open repo at: RefCell { value: Path(".") }                                                 
  5 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73
  6 12:24:59 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                       
  7 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
  8 12:24:59 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::tags::get_tags] @asyncgit/src/sync/tags.rs:58     
  9 12:24:59 [TRACE] (1) gitui::app: [src/app.rs:475] update                                                                                     
 10 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
 11 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::branch::get_branch_name_repo] @asyncgit/src/sync/branch/mod.rs:34
 12 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
 13 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::branch::get_branch_name_repo] @asyncgit/src/sync/branch/mod.rs:34
 14 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73
 15 12:24:59 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                       
 16 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 17 12:24:59 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::tags::get_tags] @asyncgit/src/sync/tags.rs:58     
 18 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 13 ms [gitui::loop] @src/main.rs:212                                    
 19 12:24:59 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Tags)                                                                    
 20 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 1 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73
 21 12:24:59 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                       
 22 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 23 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 5 ms [gitui::loop] @src/main.rs:212                                     
 24 12:24:59 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Tags)                                                                    
 25 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73
 26 12:24:59 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                       
 27 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 28 12:24:59 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 28 ms [asyncgit::revlog::async::revlog] @asyncgit/src/revlog.rs:142     
 29 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 5 ms [gitui::loop] @src/main.rs:212                                     
 30 12:24:59 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Log)                                                                     
 31 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 21 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73
 32 12:24:59 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                       
 33 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 34 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 44 ms [gitui::loop] @src/main.rs:212                                    
 35 12:24:59 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Log)                                                                     
 36 12:24:59 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                       
 37 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 38 12:24:59 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 9 ms [gitui::loop] @src/main.rs:212                                     
 39 12:25:02 [DEBUG] (9) gitui::watcher: notify events: 1                                                                                        
 40 12:25:02 [DEBUG] (9) gitui::watcher: notify [0]: DebouncedEvent { path: "<my home dir>/Code/gitui/.git/gitui", kind: Any }                   
 41 12:25:02 [TRACE] (1) gitui::app: [src/app.rs:475] update                                                                                     
 42 12:25:02 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
 43 12:25:02 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
 44 12:25:02 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                       
 45 12:25:02 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 46 12:25:02 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 15 ms [gitui::loop] @src/main.rs:212                                    
 47 12:25:06 [TRACE] (1) gitui::app: [src/app.rs:380] event: Input(Key(KeyEvent { code: Char('1'), modifiers: NONE, kind: Press, state: NONE })) 
 48 12:25:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 49 12:25:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
 50 12:25:06 [TRACE] (1) asyncgit::status: [asyncgit/src/status.rs:102] request: [hash: 8899781867415032480] (type: WorkingDir)                  
 51 12:25:06 [TRACE] (1) asyncgit::status: [asyncgit/src/status.rs:102] request: [hash: 6360984118397946275] (type: Stage)                       
 52 12:25:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::state::repo_state] @asyncgit/src/sync/state.rs:38 
 53 12:25:06 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::config::get_config_string_repo] @asyncgit/src/sync/config.rs:86
 54 12:25:06 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::config::get_config_string_repo] @asyncgit/src/sync/config.rs:86
 55 12:25:06 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::status::get_status] @asyncgit/src/sync/status.rs:135
 56 12:25:06 [TRACE] (3) asyncgit::status: [asyncgit/src/status.rs:160] status fetched: 6360984118397946275 (type: Stage)                        
 57 12:25:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 1 ms [asyncgit::sync::branch::branch_compare_upstream] @asyncgit/src/sync/branch/mod.rs:251
 58 12:25:06 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::status::get_status] @asyncgit/src/sync/status.rs:135
 59 12:25:06 [TRACE] (2) asyncgit::status: [asyncgit/src/status.rs:160] status fetched: 8899781867415032480 (type: WorkingDir)                   
 60 12:25:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 12 ms [gitui::loop] @src/main.rs:212                                    
 61 12:25:06 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Status)                                                                  
 62 12:25:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 63 12:25:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 4 ms [gitui::loop] @src/main.rs:212                                     
 64 12:25:06 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Status)                                                                  
 65 12:25:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 66 12:25:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 5 ms [gitui::loop] @src/main.rs:212                                     
 67 12:25:08 [TRACE] (1) gitui::app: [src/app.rs:380] event: Input(Key(KeyEvent { code: Char('q'), modifiers: NONE, kind: Press, state: NONE })) 
 68 12:25:08 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 1 ms [gitui::loop] @src/main.rs:212   

1   tail: <my home dir>/.cache/gitui/gitui.log: file truncated                                                                                                                                                                                                                                                                                                                                                                                                                                          
  1 12:28:14 [TRACE] (6) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(0), interests=READABLE
  2 12:28:14 [TRACE] (6) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(1), interests=READABLE
  3 12:28:14 [TRACE] (1) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(0), interests=READABLE
  4 12:28:14 [TRACE] (1) gitui::app: [src/app.rs:119] open repo at: RefCell { value: Path(".") }                                                 
  5 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
  6 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
  7 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::branch::get_branch_name_repo] @asyncgit/src/sync/branch/mod.rs:34
  8 12:28:14 [TRACE] (1) asyncgit::status: [asyncgit/src/status.rs:102] request: [hash: 16996878335589222437] (type: WorkingDir)                 
  9 12:28:14 [TRACE] (1) asyncgit::status: [asyncgit/src/status.rs:102] request: [hash: 175302263854643909] (type: Stage)                        
 10 12:28:14 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::config::get_config_string_repo] @asyncgit/src/sync/config.rs:86
 11 12:28:14 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::config::get_config_string_repo] @asyncgit/src/sync/config.rs:86
 12 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::state::repo_state] @asyncgit/src/sync/state.rs:38 
 13 12:28:14 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::status::get_status] @asyncgit/src/sync/status.rs:135
 14 12:28:14 [TRACE] (3) asyncgit::status: [asyncgit/src/status.rs:160] status fetched: 175302263854643909 (type: Stage)                         
 15 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 1 ms [asyncgit::sync::branch::branch_compare_upstream] @asyncgit/src/sync/branch/mod.rs:251
 16 12:28:14 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::status::get_status] @asyncgit/src/sync/status.rs:135
 17 12:28:14 [TRACE] (2) asyncgit::status: [asyncgit/src/status.rs:160] status fetched: 16996878335589222437 (type: WorkingDir)                  
 18 12:28:14 [TRACE] (1) gitui::app: [src/app.rs:475] update                                                                                     
 19 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
 20 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::branch::get_branch_name_repo] @asyncgit/src/sync/branch/mod.rs:34
 21 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
 22 12:28:14 [TRACE] (1) asyncgit::status: [asyncgit/src/status.rs:102] request: [hash: 16820291148087560183] (type: WorkingDir)                 
 23 12:28:14 [TRACE] (1) asyncgit::status: [asyncgit/src/status.rs:102] request: [hash: 11729092214781967683] (type: Stage)                      
 24 12:28:14 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::config::get_config_string_repo] @asyncgit/src/sync/config.rs:86
 25 12:28:14 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::config::get_config_string_repo] @asyncgit/src/sync/config.rs:86
 26 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::state::repo_state] @asyncgit/src/sync/state.rs:38 
 27 12:28:14 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::status::get_status] @asyncgit/src/sync/status.rs:135
 28 12:28:14 [TRACE] (3) asyncgit::status: [asyncgit/src/status.rs:160] status fetched: 11729092214781967683 (type: Stage)                       
 29 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 1 ms [asyncgit::sync::branch::branch_compare_upstream] @asyncgit/src/sync/branch/mod.rs:251
 30 12:28:14 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::status::get_status] @asyncgit/src/sync/status.rs:135
 31 12:28:14 [TRACE] (2) asyncgit::status: [asyncgit/src/status.rs:160] status fetched: 16820291148087560183 (type: WorkingDir)                  
 32 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 11 ms [gitui::loop] @src/main.rs:212                                    
 33 12:28:14 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Status)                                                                  
 34 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 35 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 4 ms [gitui::loop] @src/main.rs:212                                     
 36 12:28:14 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Status)                                                                  
 37 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 38 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 4 ms [gitui::loop] @src/main.rs:212                                     
 39 12:28:14 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Status)                                                                  
 40 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 41 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 4 ms [gitui::loop] @src/main.rs:212                                     
 42 12:28:14 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Status)                                                                  
 43 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 44 12:28:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 4 ms [gitui::loop] @src/main.rs:212                                     
 45 12:28:17 [DEBUG] (9) gitui::watcher: notify events: 1                                                                                        
 46 12:28:17 [DEBUG] (9) gitui::watcher: notify [0]: DebouncedEvent { path: "<my home dir>/Code/gitui/.git/gitui", kind: Any }                   
 47 12:28:17 [TRACE] (1) gitui::app: [src/app.rs:475] update                                                                                     
 48 12:28:17 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
 49 12:28:17 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
 50 12:28:17 [TRACE] (1) asyncgit::status: [asyncgit/src/status.rs:102] request: [hash: 10107808578477458434] (type: WorkingDir)                 
 51 12:28:17 [TRACE] (1) asyncgit::status: [asyncgit/src/status.rs:102] request: [hash: 14443303713589150085] (type: Stage)                      
 52 12:28:17 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::state::repo_state] @asyncgit/src/sync/state.rs:38 
 53 12:28:17 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::config::get_config_string_repo] @asyncgit/src/sync/config.rs:86
 54 12:28:17 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::config::get_config_string_repo] @asyncgit/src/sync/config.rs:86
 55 12:28:17 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::status::get_status] @asyncgit/src/sync/status.rs:135
 56 12:28:17 [TRACE] (3) asyncgit::status: [asyncgit/src/status.rs:160] status fetched: 14443303713589150085 (type: Stage)                       
 57 12:28:17 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 1 ms [asyncgit::sync::branch::branch_compare_upstream] @asyncgit/src/sync/branch/mod.rs:251
 58 12:28:17 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::status::get_status] @asyncgit/src/sync/status.rs:135
 59 12:28:17 [TRACE] (2) asyncgit::status: [asyncgit/src/status.rs:160] status fetched: 10107808578477458434 (type: WorkingDir)                  
 60 12:28:17 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 12 ms [gitui::loop] @src/main.rs:212                                    
 61 12:28:17 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Status)                                                                  
 62 12:28:17 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 63 12:28:17 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 4 ms [gitui::loop] @src/main.rs:212                                     
 64 12:28:17 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Status)                                                                  
 65 12:28:17 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
 66 12:28:17 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 4 ms [gitui::loop] @src/main.rs:212                                     
 67 12:28:23 [TRACE] (1) gitui::app: [src/app.rs:380] event: Input(Key(KeyEvent { code: Char('q'), modifiers: NONE, kind: Press, state: NONE })) 
 68 12:28:23 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 6 ms [gitui::loop] @src/main.rs:212  

[numToStr]

I am also getting consistent delay (1s - 3s) in startup. My work repository also have >2k commits. Although I didn't get chance to fully debug the behaviour.

[extrawurst]

1s is super long. Can you build with timing like I mentioned above and share the log to figure out where the culprit lies?

[numToStr]

Can you build with timing like I mentioned above and share the log to figure out where the culprit lies?

Sure. I'll paste the logs once done.

[extrawurst]

@MartinVincent can you do your checks again with current master (3fee481) and check if

1. the problem persists and
2. what the logs give us, because it logs out the exact startup times now into the logs (basically the duration of the first render)

[MartinVincent]

ok, so I did:

~/Code/gitui ❯ g pull                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
From https://github.com/extrawurst/gitui                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
   b495425..3667db3  master                             -> origin/master                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
 * [new branch]      dependabot/cargo/rayon-core-1.10.1 -> origin/dependabot/cargo/rayon-core-1.10.1                                                                                                                                                                                                                                                                                                                                                                                                                                                                                      
Updating b495425..3667db3                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
Fast-forward                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                              
 README.md   | 2 ++                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                       
 src/main.rs | 6 ++++++                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                   
 2 files changed, 8 insertions(+)                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         
Current branch master is up to date.  

then : make debug with the .virtualenv dir present:

14:24:53 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/gitui-0.22.0/src/app.rs:380] event: Input(Key(KeyEvent { code: Char('q'), modifiers: NONE, kind: Press, state: NONE }))                                                                                                                                                                                                                                                                                                                                                                  
tail: <my home dir>/.cache/gitui/gitui.log: file truncated                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               
14:25:11 [TRACE] (6) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(0), interests=READABLE                                                                                                                                                                                                                                                                                                                                                                                       
14:25:11 [TRACE] (6) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(1), interests=READABLE                                                                                                                                                                                                                                                                                                                                                                                       
14:25:11 [TRACE] (1) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(0), interests=READABLE                                                                                                                                                                                                                                                                                                                                                                                       
14:25:12 [TRACE] (1) gitui::app: [src/app.rs:119] open repo at: RefCell { value: Path(".") }                                                                                                                                                                                                                                                                                                                                                                                                                                                                                              
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 1 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73                                                                                                                                                                                                                                                                                                                                                                                                                          
14:25:12 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:25:12 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::tags::get_tags] @asyncgit/src/sync/tags.rs:58                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:25:12 [TRACE] (1) gitui: [src/main.rs:195] app start: 625 ms                                                <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<                                                                                                                                                                                                                                                                                                                                                                                                                                          
14:25:12 [TRACE] (1) gitui::app: [src/app.rs:475] update                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82                                                                                                                                                                                                                                                                                                                                                                                                                                           
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::branch::get_branch_name_repo] @asyncgit/src/sync/branch/mod.rs:34                                                                                                                                                                                                                                                                                                                                                                                                                              
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82                                                                                                                                                                                                                                                                                                                                                                                                                                           
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::branch::get_branch_name_repo] @asyncgit/src/sync/branch/mod.rs:34                                                                                                                                                                                                                                                                                                                                                                                                                              
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73                                                                                                                                                                                                                                                                                                                                                                                                                          
14:25:12 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:25:12 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::tags::get_tags] @asyncgit/src/sync/tags.rs:58                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 13 ms [gitui::loop] @src/main.rs:218                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
14:25:12 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Tags)                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 1 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73                                                                                                                                                                                                                                                                                                                                                                                                                          
14:25:12 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 6 ms [gitui::loop] @src/main.rs:218                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:25:12 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Tags)                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
14:25:12 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 28 ms [asyncgit::revlog::async::revlog] @asyncgit/src/revlog.rs:142                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 22 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73                                                                                                                                                                                                                                                                                                                                                                                                                         
14:25:12 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 43 ms [gitui::loop] @src/main.rs:218                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
14:25:12 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Log)                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:25:12 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 10 ms [gitui::loop] @src/main.rs:218                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
14:25:12 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Log)                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:25:12 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:25:12 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 8 ms [gitui::loop] @src/main.rs:218                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:25:14 [DEBUG] (9) gitui::watcher: notify events: 1                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                     
14:25:14 [DEBUG] (9) gitui::watcher: notify [0]: DebouncedEvent { path: "<my home dir>/Code/gitui/.git/gitui", kind: Any }                                                                                                                                                                                                                                                                                                                                                                                                                                                               
14:25:14 [TRACE] (1) gitui::app: [src/app.rs:475] update                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:25:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82                                                                                                                                                                                                                                                                                                                                                                                                                                           
14:25:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82                                                                                                                                                                                                                                                                                                                                                                                                                                           
14:25:14 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:25:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:25:14 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 19 ms [gitui::loop] @src/main.rs:218                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
14:25:25 [TRACE] (1) gitui::app: [src/app.rs:380] event: Input(Key(KeyEvent { code: Char('q'), modifiers: NONE, kind: Press, state: NONE }))                                                                                                                                                                                                                                                                                                                                                                                                                                              
14:25:25 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 7 ms [gitui::loop] @src/main.rs:218            

then : make debug with the .virtualenv dir absent:

tail: <my home dir>/.cache/gitui/gitui.log: file truncated                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                               
14:26:58 [TRACE] (6) mio::poll: [<my home dir>/.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(0), interests=READABLE                                                                                                                                                                                                                                                                                                                                                                                       
14:26:58 [TRACE] (6) mio::poll: [<my home dir>.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(1), interests=READABLE                                                                                                                                                                                                                                                                                                                                                                                       
14:26:58 [TRACE] (1) mio::poll: [<my home dir>.cargo/registry/src/proxy-git.cwkhome.fun-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(0), interests=READABLE                                                                                                                                                                                                                                                                                                                                                                                       
14:26:58 [TRACE] (1) gitui::app: [src/app.rs:119] open repo at: RefCell { value: Path(".") }                                                                                                                                                                                                                                                                                                                                                                                                                                                                                              
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73                                                                                                                                                                                                                                                                                                                                                                                                                          
14:26:58 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:26:58 [TRACE] (1) gitui: [src/main.rs:195] app start: 89 ms                               <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<                                                                  
14:26:58 [TRACE] (1) gitui::app: [src/app.rs:475] update                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:26:58 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 6 ms [asyncgit::sync::tags::get_tags] @asyncgit/src/sync/tags.rs:58                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82                                                                                                                                                                                                                                                                                                                                                                                                                                           
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::branch::get_branch_name_repo] @asyncgit/src/sync/branch/mod.rs:34                                                                                                                                                                                                                                                                                                                                                                                                                              
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82                                                                                                                                                                                                                                                                                                                                                                                                                                           
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::branch::get_branch_name_repo] @asyncgit/src/sync/branch/mod.rs:34                                                                                                                                                                                                                                                                                                                                                                                                                              
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73                                                                                                                                                                                                                                                                                                                                                                                                                          
14:26:58 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:26:58 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::tags::get_tags] @asyncgit/src/sync/tags.rs:58                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 14 ms [gitui::loop] @src/main.rs:218                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
14:26:58 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Tags)                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73                                                                                                                                                                                                                                                                                                                                                                                                                          
14:26:58 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 5 ms [gitui::loop] @src/main.rs:218                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:26:58 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Tags)                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73                                                                                                                                                                                                                                                                                                                                                                                                                          
14:26:58 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 4 ms [gitui::loop] @src/main.rs:218                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:26:58 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Log)                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:26:58 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 31 ms [asyncgit::revlog::async::revlog] @asyncgit/src/revlog.rs:142                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 21 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73                                                                                                                                                                                                                                                                                                                                                                                                                         
14:26:58 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 40 ms [gitui::loop] @src/main.rs:218                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
14:26:58 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Log)                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:26:58 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                                
14:26:58 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 9 ms [gitui::loop] @src/main.rs:218                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:27:01 [DEBUG] (9) gitui::watcher: notify events: 1                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                     
14:27:01 [DEBUG] (9) gitui::watcher: notify [0]: DebouncedEvent { path: "<my home dir>/Code/gitui/.git/gitui", kind: Any }                                                                                                                                                                                                                                                                                                                                                                                                                                                               
14:27:01 [TRACE] (1) gitui::app: [src/app.rs:475] update                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
14:27:01 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82                                                                                                                                                                                                                                                                                                                                                                                                                                           
14:27:01 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82                                                                                                                                                                                                                                                                                                                                                                                                                                           
14:27:01 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    
14:27:01 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 10 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118                                                                                                                                                                                                                                                                                                                                                                                                                               
14:27:01 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 40 ms [gitui::loop] @src/main.rs:218                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 
14:27:01 [TRACE] (1) gitui::app: [src/app.rs:380] event: Input(Key(KeyEvent { code: Char('q'), modifiers: NONE, kind: Press, state: NONE }))                                                                                                                                                                                                                                                                                                                                                                                                                                              
14:27:01 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 8 ms [gitui::loop] @src/main.rs:218