Extremely slow when exiting?

[TannerYoung]

Runtime Environment

• Operating system and version: Ubuntu 18.04.3 LTS
• Terminal emulator and version: rxvt-unicode (urxvt) v9.22
• Python version: 2.7.17
• Ranger version/commit: ranger-stable 1.8.1 && HEAD (870435d)
• Locale: en_US.UTF-8

Current Behavior

Takes multiple seconds to exit if not more

Expected Behavior

Exits immediately

Context

I'm not sure when but it didn't used to be slow and now it is. This might be a problem with my shell environment, but I'm not sure how to diagnose it / where to find logs.

Possible Solutions

Steps to reproduce

1. Clone head
2. ./ranger.py
3. navigate and exit with q

Traceback

[toonn]

Check the task view right before exiting w. I suspect it's preview processes that are still running.

[TannerYoung]

It just said no tasks in queue. It looks like the problem was setting set vcs_aware true in my rc.conf:

set display_size_in_main_column true
set hidden_filter ^\.|~$|.meta$
set preview_images true
set preview_images_method urxvt
set vcs_aware true

Removing this immediately fixed the issue. Not sure if I should mark this as resolved, since I know the issue but it seems like this would be a bug somewhere. Is there another component I should file on?

[toonn]

This should probably be looked into but it's far from a priority tbh. It'd be great if you could do a deep dive, figuring out what code is causing this.

[kevinhwang91]

It just said no tasks in queue. It looks like the problem was setting set vcs_aware true in my rc.conf:

set display_size_in_main_column true
set hidden_filter ^\.|~$|.meta$
set preview_images true
set preview_images_method urxvt
set vcs_aware true

Removing this immediately fixed the issue. Not sure if I should mark this as resolved, since I know the issue but it seems like this would be a bug somewhere. Is there another component I should file on?

If you have a huge repository such as chromium or a slow CPU you will be easy to reproduce this issue caused by git status command.

Ranger will update the content of the directories including all parent's paths. After Enabling the vcs_aware, every time the directory is updated, it will send a directory object to a queue in vcs thread. When executing quit command, ranger will wait for all tasks are in queue in vsc thread for now.

I found that the vsc thread is already setup as a daemon, It's not necessary to wait for the tasks because no files were modified during the process of tasks.
From the previous commit core.main: Refactor exit handling, solve this issue only revert the code about vcs thread.

@toonn Here is my commit, If you think it's a good solution, I will pull request this commit.

[toonn]

Hmm, those changes had to do with logging. There must've been a reason for making thread destruction synchronous. Could you take another look at #717 to figure out what the reasoning was?

[kevinhwang91]

Hmm, those changes had to do with logging. There must've been a reason for making thread destruction synchronous. Could you take another look at #717 to figure out what the reasoning was?

His primary motivation is to refactor exit handling.
I assume that He wanted to shutdown vcs thread safely. Vcs thread already setup up as a daemon, when the main thread exit, it will destroy the resource all about vcs thread. The tasks run in vsc thread don't modify any files. So the files are always safe, although the process of vcs command may be interrupted.

Nowadays, PC almost have multiple core CPU, I think the code about vcs should use multiprocessing instead of thread because GIL will decrease the performance caused by walking directories.

[eMPee584]

⚠️ With fatrace it can also be seen the VCS thread scours through directory hierarchies explicitly gitignored ..

[mik13ST]

This is odd, it appears that checking if the VCS root is outdated takes longer than actually updating the root. See this line_profiler result.

Timer unit: 1e-06 s

Total time: 30.3792 s
File: /home/mik/src/ranger/ranger/ext/vcs/vcs.py
Function: check_outdated at line 328

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   328                                               @profile
   329                                               def check_outdated(self):
   330                                                   """Check if root is outdated"""
   331         5          7.0      1.4      0.0          if self.updatetime is None:
   332         1          1.0      1.0      0.0              return True
   333                                           
   334    120328    8446549.0     70.2     27.8          for wroot, wdirs, _ in os.walk(self.path):
   335    120324   10152376.0     84.4     33.4              wrootobj = self.obj.fm.get_directory(wroot)
   336    120324    2194831.0     18.2      7.2              wrootobj.load_if_outdated()
   337    120324    9331848.0     77.6     30.7              if wroot != self.path and wrootobj.vcs.is_root_pointer:
   338        68        180.0      2.6      0.0                  wdirs[:] = []
   339        68         34.0      0.5      0.0                  continue
   340                                           
   341    120256     162943.0      1.4      0.5              if wrootobj.stat and self.updatetime < wrootobj.stat.st_mtime:
   342                                                           return True
   343    120256      89578.0      0.7      0.3              if wrootobj.files_all:
   344       384        261.0      0.7      0.0                  for wfile in wrootobj.files_all:
   345       364        546.0      1.5      0.0                      if wfile.stat and self.updatetime < wfile.stat.st_mtime:
   346                                                                   return True
   347         4          4.0      1.0      0.0          return False

Total time: 31.346 s
File: /home/mik/src/ranger/ranger/ext/vcs/vcs.py
Function: _queue_process at line 425

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   425                                               @profile
   426                                               def _queue_process(self):  # pylint: disable=too-many-branches
   427                                                   """Process queue"""
   428         2         24.0     12.0      0.0          dirobjs = []
   429         2         10.0      5.0      0.0          paths = set()
   430         2         15.0      7.5      0.0          self._roots.clear()
   431                                           
   432                                                   while True:
   433        12         10.0      0.8      0.0              try:
   434        12        167.0     13.9      0.0                  dirobjs.append(self._queue.get(block=False))
   435         2          4.0      2.0      0.0              except queue.Empty:
   436         2          3.0      1.5      0.0                  break
   437                                           
   438        12         14.0      1.2      0.0          for dirobj in dirobjs:
   439        10         18.0      1.8      0.0              if dirobj.path in paths:
   440                                                           continue
   441        10         13.0      1.3      0.0              paths.add(dirobj.path)
   442                                           
   443        10        940.0     94.0      0.0              dirobj.vcs.reinit()
   444        10         19.0      1.9      0.0              if dirobj.vcs.track:
   445         5         14.0      2.8      0.0                  rootvcs = dirobj.vcs.rootvcs
   446         5   30970932.0 6194186.4     98.8                  if rootvcs.path not in self._roots and rootvcs.check_outdated():
   447         1          1.0      1.0      0.0                      self._roots.add(rootvcs.path)
   448         1     339232.0 339232.0      1.1                      if rootvcs.update_root():
   449         1      34285.0  34285.0      0.1                          rootvcs.update_tree()
   450                                                               else:
   451                                                                   rootvcs.update_tree(purge=True)
   452         1          7.0      7.0      0.0                      self._redraw = True
   453                                           
   454        10        279.0     27.9      0.0              has_vcschild = self._update_subroots(dirobj.files_all)
   455                                           
   456        10          9.0      0.9      0.0              if dirobj.has_vcschild != has_vcschild:
   457                                                           dirobj.has_vcschild = has_vcschild
   458                                                           self._redraw = True

Skipping the check (updating root always) makes both opening a file right after ranger starts and quitting ranger right after ranger starts instant-ish.

Is skipping the check the solution? Or should checking Git ignored files be prevented? Or both?

[toonn]

Is that branch on line 446 taking so much time because of "check_outdated"? We should definitely respect gitignores either way imo.

[mik13ST]

Is that branch on line 446 taking so much time because of "check_outdated"? We should definitely respect gitignores either way imo.

Yes it is. See the Total time: 30.3792 s in the header of the first section. I confirmed this by placing return True to the first row of check_outdated() (appended after line 330).

[mik13ST]

There actually are two similar VCS performance related problems:

1. Degraded performance caused by repo size,
2. Degraded performance caused by check_outdated().

It's quite difficult to draw the line between them. Being familiar with the line_profiler allows me to get an insight into what's happening, allow me to explain.

1. Degraded performance caused by repo size

Manifests itself when quitting.

Steps to replicate:

1. clone chromium (as suggested by @kevinhwang91)
2. launch ranger somewhere deep in the repository e.g. ./ranger.py ~/src/chromium/android_webview/browser/tracing/
3. wait for VCS status marks to appear
4. immediately quit ranger (press the q key), this will take a few seconds, but less than 10

Most of the time here (almost 99%) is spent on actually refreshing the VCS root on line number 447. See the profile.

Profile of problem No.1 in the chromium repo

Timer unit: 1e-06 s

Total time: 4.29596 s
File: /home/mik/src/ranger/ranger/ext/vcs/vcs.py
Function: _queue_process at line 424

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   424                                               @profile
   425                                               def _queue_process(self):  # pylint: disable=too-many-branches
   426                                                   """Process queue"""
   427         2          9.0      4.5      0.0          dirobjs = []
   428         2          7.0      3.5      0.0          paths = set()
   429         2         12.0      6.0      0.0          self._roots.clear()
   430                                           
   431                                                   while True:
   432        11          9.0      0.8      0.0              try:
   433        11        171.0     15.5      0.0                  dirobjs.append(self._queue.get(block=False))
   434         2          3.0      1.5      0.0              except queue.Empty:
   435         2          2.0      1.0      0.0                  break
   436                                           
   437         3          3.0      1.0      0.0          for dirobj in dirobjs:
   438         2          2.0      1.0      0.0              if dirobj.path in paths:
   439                                                           continue
   440         2          3.0      1.5      0.0              paths.add(dirobj.path)
   441                                           
   442         2        166.0     83.0      0.0              dirobj.vcs.reinit()
   443         2          3.0      1.5      0.0              if dirobj.vcs.track:
   444         2          1.0      0.5      0.0                  rootvcs = dirobj.vcs.rootvcs
   445         1         11.0     11.0      0.0                  if rootvcs.path not in self._roots and rootvcs.check_outdated():
   446         1          1.0      1.0      0.0                      self._roots.add(rootvcs.path)
   447         1    4245495.0 4245495.0     98.8                      if rootvcs.update_root():
   448         1      49974.0  49974.0      1.2                          rootvcs.update_tree()
   449                                                               else:
   450                                                                   rootvcs.update_tree(purge=True)
   451         1          6.0      6.0      0.0                      self._redraw = True
   452                                           
   453         1         77.0     77.0      0.0              has_vcschild = self._update_subroots(dirobj.files_all)
   454                                           
   455         1          1.0      1.0      0.0              if dirobj.has_vcschild != has_vcschild:
   456                                                           dirobj.has_vcschild = has_vcschild
   457                                                           self._redraw = True

I believe most people are actually talking about this problem.

If you are having trouble isolating this problem, make sure you don't run into the problem No.2 by temporarily "fixing" it (as suggested in my previous comment) like this. This is not necessary though.

Suggested "fix" of problem No.2

--- a/ranger/ext/vcs/vcs.py
+++ b/ranger/ext/vcs/vcs.py
@@ -327,6 +327,7 @@ class VcsRoot(Vcs):  # pylint: disable=abstract-method
 
     def check_outdated(self):
         """Check if root is outdated"""
+        return True
         if self.updatetime is None:
             return True

2. Degraded performance caused by check_outdated()

Manifests itself both when quitting and opening a file and is only present for a limited time. When you start ranger, it starts updating the VCS status. After a short while something probably triggers another update of VCS and it ends up os.walking all files in the repository (including ignored files). If you wait a minute or two, this settles down in the background and you can no longer experience this problem. This has a big impact if somebody uses ranger as a file picker (e.g. in Vim using a vim script from ranger examples).

Steps to replicate:

1. clone chromium
2. launch ranger somewhere deep in the repository e.g. ./ranger.py ~/src/chromium/android_webview/browser/tracing/
3. wait for VCS status marks to appear but not much longer
4. open the file under cursor in editor (press l key), this will take ages (e.g. 25 seconds)
5. immediately quit editor
6. immediately quit ranger (press the q key), this will take about half a second

This is different. Most of the time here (85%) is spent on the check_outdated() call on line number 445. It also takes much longer (Total time: 29.2101 s instead of Total time: 4.29596 s in problem No.1). See the profile.

Profile of problem No.2 in the chromium repo

Timer unit: 1e-06 s

Total time: 29.2101 s
File: /home/mik/src/ranger/ranger/ext/vcs/vcs.py
Function: _queue_process at line 424

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   424                                               @profile
   425                                               def _queue_process(self):  # pylint: disable=too-many-branches
   426                                                   """Process queue"""
   427         2          9.0      4.5      0.0          dirobjs = []
   428         2          8.0      4.0      0.0          paths = set()
   429         2          9.0      4.5      0.0          self._roots.clear()
   430                                           
   431                                                   while True:
   432        11          9.0      0.8      0.0              try:
   433        11        170.0     15.5      0.0                  dirobjs.append(self._queue.get(block=False))
   434         2          5.0      2.5      0.0              except queue.Empty:
   435         2          3.0      1.5      0.0                  break
   436                                           
   437        11         14.0      1.3      0.0          for dirobj in dirobjs:
   438         9         17.0      1.9      0.0              if dirobj.path in paths:
   439                                                           continue
   440         9         16.0      1.8      0.0              paths.add(dirobj.path)
   441                                           
   442         9       1114.0    123.8      0.0              dirobj.vcs.reinit()
   443         9         13.0      1.4      0.0              if dirobj.vcs.track:
   444         4          5.0      1.2      0.0                  rootvcs = dirobj.vcs.rootvcs
   445         4   24904002.0 6226000.5     85.3                  if rootvcs.path not in self._roots and rootvcs.check_outdated():
   446         1          1.0      1.0      0.0                      self._roots.add(rootvcs.path)
   447         1    3709632.0 3709632.0     12.7                      if rootvcs.update_root():
   448         1      49947.0  49947.0      0.2                          rootvcs.update_tree()
   449                                                               else:
   450                                                                   rootvcs.update_tree(purge=True)
   451         1          4.0      4.0      0.0                      self._redraw = True
   452                                           
   453         9     545080.0  60564.4      1.9              has_vcschild = self._update_subroots(dirobj.files_all)
   454                                           
   455         9         18.0      2.0      0.0              if dirobj.has_vcschild != has_vcschild:
   456                                                           dirobj.has_vcschild = has_vcschild
   457                                                           self._redraw = True

This problem is amplified by having many ignored files, but not necessarily caused by it, I believe.

This prolem is less known (so far mentioned only in #1904 and #902 (comment)) and I am more familiar with it since I was experiencing it myself (until switching to Netrw for Vim file picking).

---

Make sure to not measure the time on the first try because disk content might not be cached yet and that introduces inconsistency. Measure only the second or any subsequent attempt of replicating this.

Both of these problems could probably be solved by not waiting for VCS thread to exit (not acceptable).

Since No.2 is not mentioned anywhere in this GitHub issue, I suggest dedicating this GitHub issue to only No.1. That means my previous comment (#1841 (comment)) and the reactions to it, are irrelevant to the problem OP describes here. Please disregard that comment.

There is a similar GitHub issue (#902) with more mentions of "untracked files" and #902 (comment) specifically mentioning delay right after opening. So that GitHub issue is more suitable for dedicating to problem No.2. Right now these two GitHub issues are kind of blending in.

Can anybody confirm these are indeed distinct problems and that I have drawn the line correctly?

[kevinhwang91]

Problem 1: Caused by waiting for git process. If you want to "safely exit" ranger, you can't solve the waiting time.
Problem 2: The check_outdated solution is acceptable. Because vcs queue is activated by load_content, check_outdated is not necessary. I have already deleted the code about check_outdated in my fork.

To be honest, for now, the design of vcs is so bad, it will cause many problems such as death lock and other issues (#1871). No need to optimize it anymore, refactor the code is the only way to make all issues about vcs gone. I have a plan to refactor vcs using asyncio for my neovim plugin https://github.com/kevinhwang91/rnvimr. I don't desire it will be merged into the master branch of ranger, I just want to happy myself and other users using my plugin. (I am not an expert of python)

By the way, thank you for your profile, it inspires me a lots.

[bo5o]

What's the current status on this issue? Are there any workarounds other than setting 'vcs_aware false'? I am experiencing the same issue, even with medium-sized git repos.

[toonn]

The current status is we're stuck until someone finds the time to work on this.

[jakeschurch]

I had a similar issue and disabling vcs_aware true to vcs_aware false in rc.conf fixed this for me