Re: emacs slow on dired renaming

[Robert Marshall <spam@capuchin.co.uk>]

On Sat, Apr 05 2014, Eli Zaretskii <eliz@gnu.org> wrote:

>> From: Robert Marshall <spam@capuchin.co.uk>
>> Date: Sat, 05 Apr 2014 09:50:09 +0100
>> 
>> > If you try renaming a single file with "M-x rename-file RET", does it
>> > also take 2 sec?
>> >
>> There's no apparent delay
>
> On a restart or in a session where moving from Dired is already very
> slow?  If the latter, then the actual file I/O is not the reason for
> the slowdown, and I suggest to selectively disable portions of your
> ~/.emacs to find out what causes this.

In the session which is slow when using dired to rename

> It could be frequent GC, for
> example (set garbage-collection-messages non-nil to see if it is), or
> something else that causes excessive processing.  Or maybe you have a
> lot of buffers visiting files in a directory being renamed, in which
> case Dired will loop over all those files and rename their
> default-directory, which could be expensive for a very large number of
> such buffers.

The files which I'm renaming are all jpg's so there's no directories at
all in the file moving operation, could a soft link to that directory
have an effect (though in that case why doesn't it happen when emacs is
first started)?

>
> Btw, I don't understand this part of your profile:
>
> 	- dired-in-this-tree                     10841  38%
> 	 + let                                      23   0%
>
> This says that dired-in-this-tree takes 1/3rd of the run time.  But
> dired-in-this-tree is just this:
>
>   (defun dired-in-this-tree (file dir)
>     ;;"Is FILE part of the directory tree starting at DIR?"
>     (let (case-fold-search)
>       (string-match-p (concat "^" (regexp-quote dir)) file)))
>
> So I wonder how come it takes such a large proportion of the time.
>
> As another possible hint, does the number of times dired-create-files
> is called (26704) make sense?  Do you really have such a large number
> of files in the tree you are moving?  Can you produce a profile for
> moving a single file (which you say takes about 2 sec)?
>

This then (26704) - as you see from my comment about the jpg's which are
the only files being moved - doesn't appear to make any sense - I didn't
realise that number was the number of times the function was called. 10
files only are being moved none of which are directories, none of them
are links to other files

Here's moving a single file (using 'R' in a dired buffer) - the full trace rather than just a
selection from the report (again a jpg) from ~/Pictures to
~/Pictures/yy; 1083 calls to dired-do-rename(!). Could there be some
recursive calls somehow, why is command-execute being called 1227 times?!

- command-execute                                                1227  97%
 - call-interactively                                            1227  97%
  - dired-do-rename                                              1083  86%
   - dired-do-create-files                                       1083  86%
    - dired-create-files                                          962  76%
     - byte-code                                                  952  75%
      - dired-rename-file                                         766  61%
       - dired-rename-subdir                                      568  45%
        - dired-fun-in-all-buffers                                180  14%
           dired-buffers-for-dir                                  180  14%
       - dired-remove-file                                        194  15%
        - dired-fun-in-all-buffers                                194  15%
           dired-buffers-for-dir                                  186  14%
         - apply                                                    8   0%
          + dired-remove-entry                                      8   0%
      - dired-add-file                                            182  14%
       - dired-fun-in-all-buffers                                 182  14%
          dired-buffers-for-dir                                   178  14%
        - apply                                                     4   0%
         + dired-add-entry                                          4   0%
     + dired-file-marker                                           10   0%
    - dired-mark-read-file-name                                   107   8%
     - dired-mark-pop-up                                          107   8%
      - apply                                                     107   8%
       - read-file-name                                           107   8%
        - read-file-name-default                                  107   8%
         - completing-read                                         99   7%
          - completing-read-default                                99   7%
           - read-from-minibuffer                                  96   7%
            + timer-event-handler                                   1   0%
      dired-get-marked-files                                        4   0%
  - byte-code                                                     123   9%
   - read-extended-command                                        123   9%
    - completing-read                                             123   9%
     - completing-read-default                                    123   9%
      - read-from-minibuffer                                      108   8%
       - timer-event-handler                                        3   0%
        - byte-code                                                 3   0%
         - apply                                                    3   0%
            jit-lock-context-fontify                                2   0%
  + minibuffer-complete                                            15   1%
  + execute-extended-command                                        6   0%
- timer-event-handler                                              20   1%
 - byte-code                                                       13   1%
  - apply                                                          13   1%
   - which-func-update                                             12   0%
    - which-func-update-1                                          12   0%
     - byte-code                                                   12   0%
      - which-function                                             12   0%
       - add-log-current-defun                                     12   0%
          byte-code                                                 4   0%
   timer-activate                                                   3   0%
- redisplay_internal (C function)                                   7   0%
 - jit-lock-function                                                7   0%
  - jit-lock-fontify-now                                            7   0%
   - funcall                                                        7   0%
    - #<compiled 0xb436117>                                         7   0%
     - run-hook-with-args                                           7   0%
      - font-lock-fontify-region                                    7   0%
         font-lock-default-fontify-region                           7   0%
- ...                                                               0   0%
   Automatic GC                                                     0   0%

I've looked at pre-command-hook and post-command-hook and there doesn't
appear to be anything suspicious there (tooltip-hide and font-lock- fns)

In a session with no apparent slowdown, on a single dired-do-rename,
the function dired-do-rename gets called 42 times

Robert
-- 
La grenouille songe..dans son château d'eau
Links and things http://rmstar.blogspot.com/