extrawurst
commented
1 year ago That’s an Intretesting observation. Gonna look into this
Closed MartinVincent closed 1 year ago
extrawurst
commented
1 year ago That’s an Intretesting observation. Gonna look into this
extrawurst
commented
1 year ago How did you make this exact measurement?
MartinVincent
commented
1 year ago 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
commented
1 year ago 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:
[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
commented
1 year ago 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:118the 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: 216fad3140d5923ef78b2e4484e35f57326b6eaf
extrawurst
commented
1 year ago 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
commented
1 year ago @alexmaco maybe you wanna clean that up? :)
MartinVincent
commented
1 year ago 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/github.com-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/github.com-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/github.com-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/github.com-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/github.com-1ecc6299db9ec823/asyncgit-0.22.0/src/tags.rs:67] request
5 02:19:15 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/github.com-1ecc6299db9ec823/gitui-0.22.0/src/app.rs:475] update
6 02:19:15 [TRACE] (1) asyncgit::tags: [<my home dir>/.cargo/registry/src/github.com-1ecc6299db9ec823/asyncgit-0.22.0/src/tags.rs:67] request
7 02:19:15 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/github.com-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/github.com-1ecc6299db9ec823/asyncgit-0.22.0/src/tags.rs:67] request
9 02:19:15 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/github.com-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/github.com-1ecc6299db9ec823/asyncgit-0.22.0/src/tags.rs:67] request
11 02:19:15 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/github.com-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/github.com-1ecc6299db9ec823/asyncgit-0.22.0/src/tags.rs:67] request
13 02:19:15 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/github.com-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/github.com-1ecc6299db9ec823/asyncgit-0.22.0/src/tags.rs:67] request
15 02:19:17 [TRACE] (1) gitui::app: [<my home dir>/.cargo/registry/src/github.com-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
commented
1 year ago no that is not a debug build, you can use make debug to build one
MartinVincent
commented
1 year ago Here are 2 trials:
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:
1 12:24:58 [TRACE] (6) mio::poll: [
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: "
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:
1 12:28:14 [TRACE] (6) mio::poll: [
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: "
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
commented
1 year ago 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
commented
1 year ago 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
commented
1 year ago 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
commented
1 year ago @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
commented
1 year ago 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/github.com-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/github.com-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/github.com-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/github.com-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/github.com-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/github.com-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/github.com-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 ok wow 600ms inside the appstart sequense. this is crazy.
can you please run make profile from current master. it should generate a flamegraph file.
extrawurst
commented
1 year ago new theory: cf9ce9d is the culprit and the filesystem watcher takes ages if there is a ton of files generated for this .virtualenv. newest master (8cdb023) has explicit scope timing in the logs for the watcher initialisation.
MartinVincent
commented
1 year ago Approx 40000 files in .virtualenv:
~/Code/gitui ❯ git pull
From https://github.com/extrawurst/gitui
3667db3..8cdb023 master -> origin/master
Updating 3667db3..8cdb023
Fast-forward
asyncgit/src/branches.rs | 77 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
asyncgit/src/lib.rs | 4 ++++
src/components/branchlist.rs | 2 +-
src/components/changes.rs | 14 ++++++++++++++
src/components/status_tree.rs | 2 ++
src/tabs/revlog.rs | 36 ++++++++++++++++++++++++++++--------
src/tabs/status.rs | 32 +++++++++++++++++++++++++-------
src/watcher.rs | 3 +++
8 files changed, 154 insertions(+), 16 deletions(-)
create mode 100644 asyncgit/src/branches.rs
~/Code/gitui ❯ make profile 
and make debug for 8cdb023:
44 16:15:04 [TRACE] (6) mio::poll: [<my home dir>/.cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(0), interests=READABLE
43 16:15:04 [TRACE] (6) mio::poll: [<my home dir>/.cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(1), interests=READABLE
42 16:15:04 [TRACE] (1) mio::poll: [<my home dir>/.cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.8.4/src/poll.rs:521] registering event source with poller: token=Token(0), interests=READABLE
41 16:15:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 2274 ms [gitui::watcher::RepoWatcher::new] @src/watcher.rs:20
40 16:15:06 [TRACE] (1) gitui::app: [src/app.rs:119] open repo at: RefCell { value: Path(".") }
39 16:15:06 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
38 16:15:06 [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
37 16:15:06 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request
36 16:15:06 [TRACE] (1) gitui: [src/main.rs:195] app start: 2299 ms
35 16:15:06 [TRACE] (1) gitui::app: [src/app.rs:475] update
34 16:15:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
33 16:15:06 [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
32 16:15:06 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [asyncgit::sync::tags::get_tags] @asyncgit/src/sync/tags.rs:58
31 16:15:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
30 16:15:06 [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
29 16:15:06 [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
28 16:15:06 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request
27 16:15:06 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::tags::get_tags] @asyncgit/src/sync/tags.rs:58
26 16:15:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 11 ms [gitui::loop] @src/main.rs:218
25 16:15:06 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Branches)
24 16:15:06 [INFO] branches: 1
23 16:15:06 [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
22 16:15:06 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request
21 16:15:06 [TRACE] (2) scopetime: [scopetime/src/lib.rs:41] scopetime: 2 ms [asyncgit::sync::branch::get_branches_info] @asyncgit/src/sync/branch/mod.rs:118
20 16:15:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [gitui::loop] @src/main.rs:218
19 16:15:06 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Tags)
18 16:15:06 [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
17 16:15:06 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request
16 16:15:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [gitui::loop] @src/main.rs:218
15 16:15:06 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Tags)
14 16:15:06 [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
13 16:15:06 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request
12 16:15:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 3 ms [gitui::loop] @src/main.rs:218
11 16:15:06 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Branches)
10 16:15:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:4] scopetime: 1 ms [gitui::loop] @src/main.rs:218
9 16:15:06 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Log)
8 16:15:06 [TRACE] (3) scopetime: [scopetime/src/lib.rs:41] scopetime: 40 ms [asyncgit::revlog::async::revlog] @asyncgit/src/revlog.rs:142
7 16:15:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 20 ms [asyncgit::sync::commits_info::get_commits_info] @asyncgit/src/sync/commits_info.rs:73
6 16:15:06 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request
5 16:15:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 41 ms [gitui::loop] @src/main.rs:218
4 16:15:06 [TRACE] (1) gitui::app: [src/app.rs:494] update_async: Git(Log)
3 16:15:06 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request
2 16:15:06 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 9 ms [gitui::loop] @src/main.rs:218
1 16:15:08 [DEBUG] (9) gitui::watcher: notify events: 1
45 16:15:08 [DEBUG] (9) gitui::watcher: notify [0]: DebouncedEvent { path: "<my home dir>/Code/gitui/.git/gitui", kind: Any }
1 16:15:08 [TRACE] (1) gitui::app: [src/app.rs:475] update
2 16:15:08 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
3 16:15:08 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 0 ms [asyncgit::sync::utils::get_head_repo] @asyncgit/src/sync/utils.rs:82
4 16:15:08 [TRACE] (1) asyncgit::tags: [asyncgit/src/tags.rs:67] request
5 16:15:08 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 9 ms [gitui::loop] @src/main.rs:218
6 16:15:08 [TRACE] (1) gitui::app: [src/app.rs:380] event: Input(Key(KeyEvent { code: Char('q'), modifiers: NONE, kind: Press, state: NONE }))
7 16:15:08 [TRACE] (1) scopetime: [scopetime/src/lib.rs:41] scopetime: 7 ms [gitui::loop] @src/main.rs:218
ok theory confirmed, its the file watcher initialisation - holy moly is that slow. enjoy recent master: bbcadcb - should fix the problem. please confirm
MartinVincent
commented
1 year ago it (following a make install) looks very good, in fact even faster than 0.21.0 :) according to my simple tests!
Thx!
(gitui:3.8.10) [master:bbcadcb ] ~/Code/gitui ❯ for i in $(seq 10) ; do time ~/bin/gitui_startup_test.scp 0.21.0 >/dev/null; done
delta: 0,042
delta: 0,045
delta: 0,043
delta: 0,043
delta: 0,043
delta: 0,042
delta: 0,043
delta: 0,043
delta: 0,043
delta: 0,040
(gitui:3.8.10) [master:bbcadcb ] ~/Code/gitui ❯ for i in $(seq 10) ; do time ~/bin/gitui_startup_test.scp 0.22.1_beta >/dev/null; done
delta: 0,038
delta: 0,037
delta: 0,038
delta: 0,038
delta: 0,034
delta: 0,039
delta: 0,033
delta: 0,035
delta: 0,034
delta: 0,035yeah lol I also cleaned up the slight delay that got introduced by #1371 in 92f63d1. so that shaved off a few ms aswell. consider this fixed then! thanks for all the support!
extrawurst
commented
1 year ago closed via bbcadcb
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! (https://github.com/extrawurst/gitui/pull/1371)), but I noticed that there is now a significant delay on startup for relatively small repos (1500 Commits):
0,094(v0.21) up to0,746(v0.22).Is that expected? (ie: the price to pay for the new features)
Thx!