bug#5833: 23.1.94; Opening files on network shares on w32 is slow

[Mathias Dahl]

> That's strange: I thought they would slash much more.
>
> How about insert-file-contents and insert-file-contents-literally --
> can you time those?

I changed the measure function to this:

(defun measure ()
  (dotimes (i 10)
    (let ((time1 (float-time))
          time2)
      (with-temp-buffer
        (insert-file-contents
"//corpnet/files/Archive/Archive75/docman/core/docman
5.11.0/docman/database/docman/refobj.apy"))
      (setq time2 (float-time))
      (message "Time elapsed for insert-file-contents: %s" (- time2 time1)))))

The results are very interesting:

emacs -Q
Time elapsed for insert-file-contents: 3.5160000324249268
Time elapsed for insert-file-contents: 0.6719999313354492
Time elapsed for insert-file-contents: 0.6410000324249268
Time elapsed for insert-file-contents: 0.6559998989105225
Time elapsed for insert-file-contents: 0.6089999675750732
Time elapsed for insert-file-contents: 0.6410000324249268
Time elapsed for insert-file-contents: 0.687000036239624
Time elapsed for insert-file-contents: 0.6719999313354492
Time elapsed for insert-file-contents: 0.5940001010894775
Time elapsed for insert-file-contents: 0.9689998626708984
(setq vc-handled-backends nil)
Time elapsed for insert-file-contents: 0.687000036239624
Time elapsed for insert-file-contents: 0.6100001335144043
Time elapsed for insert-file-contents: 0.6089999675750732 [2 times]
Time elapsed for insert-file-contents: 0.5940001010894775
Time elapsed for insert-file-contents: 2.984999895095825
Time elapsed for insert-file-contents: 0.7030000686645508
Time elapsed for insert-file-contents: 1.2339999675750732
Time elapsed for insert-file-contents: 0.625
Time elapsed for insert-file-contents: 0.6099998950958252
(setq locate-dominating-stop-dir-regexp "")
Time elapsed for insert-file-contents: 0.6089999675750732
Time elapsed for insert-file-contents: 0.625
Time elapsed for insert-file-contents: 0.6410000324249268
Time elapsed for insert-file-contents: 0.5930001735687256
Time elapsed for insert-file-contents: 0.5939998626708984
Time elapsed for insert-file-contents: 1.0160000324249268
Time elapsed for insert-file-contents: 0.6719999313354492
Time elapsed for insert-file-contents: 0.625
Time elapsed for insert-file-contents: 0.6089999675750732
Time elapsed for insert-file-contents: 0.6090002059936523

(This is for the larger of the two files)

Suddenly we get relatively good results.

> Another idea is to use elp.el to profile the various functions called
> by find-file.  At least for the Lisp level, we will see where's the
> bottleneck, and that might give some ideas.

This is my first attempt at using elp.el so I might not know what I am
doing :) I sucked out all function calls in find-file-noselect and got
this:

find-file-noselect                30          122.34599999  4.0782
find-file-noselect-1              30          85.545000000  2.8515000000
file-exists-p                     780         35.546999999  0.0455730769
file-truename                     63          30.012999999  0.4763968253
find-buffer-visiting              30          16.72         0.5573333333
file-attributes                   60          3.9890000000  0.0664833333
file-directory-p                  31          2.7210000000  0.0877741935
mapcar                            31          2.1270000000  0.0686129032
string-match                      8867        0.125         1.40...e-005
message                           35          0.031         0.0008857142
expand-file-name                  842         0.016         1.90...e-005
...

Digging further, instrumenting all functions in find-file-noselect-1
as well (the ones instrumented earlier is still instrumented):

find-file-noselect                30          119.71899999  3.9906333333
find-file-noselect-1              30          84.484000000  2.8161333333
insert-file-contents              30          42.253        1.4084333333
after-find-file                   30          42.230999999  1.4076999999
file-exists-p                     780         34.638999999  0.0444089743
file-truename                     60          29.048999999  0.4841499999
funcall                           40          21.326999999  0.533175
find-buffer-visiting              30          16.000999999  0.5333666666
file-attributes                   60          4.0619999999  0.0677
file-directory-p                  30          2.124         0.0708
mapcar                            25          2.045         0.0818
file-readable-p                   48          0.5800000000  0.0120833333
string-match                      8798        0.08          9.09...e-006
message                           33          0.064         0.0019393939
file-name-directory               890         0.048         5.39...e-005
expand-file-name                  841         0.0310000000  3.68...e-005
abbreviate-file-name              172         0.015         8.72...e-005
...

Does any figure above stand out to you?

/Mathias