bug#30807: Tramp tests take waaayyy too long and refuse to exit

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Paul Eggert]

For the past few weeks "make check" has been taking a looooong time on 
Emacs master on my Fedora 27 desktop (AMD Phenom II X4 910e). The first 
line of "make" output that causes a long delay is:

   GEN      lisp/net/tramp-tests.log

and some of the tests in the corresponding script look to be very slow. 
Can this be sped up? Let's mark the slow tests to be expensive, so that 
they are run only if one executes "make check-expensive".

Worse, there's another long wait here:

   GEN      lisp/net/tramp-archive-tests.log

after this line is output:

    passed  20/22  tramp-archive-test40-file-system-info

and here the wait is so long that I gave up trying to run the tests and 
typed control-C to exit them. Presumably the semi-inflooping test is 
tramp-archive-test42-auto-load. (Why is it 42 and not 41? Why are there 
two test42s? I don't know.)

Worse yet, after I control-C out of "make check" and get a shell prompt 
back, a subsidiary Emacs that is running the Tramp test refuses to exit 
and continues to chew up CPU time in the background until I use "kill 
3304" (or whatever) to kill it. This really needs to get fixed.

Because of these problems I no longer routinely run "make check".

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Glenn Morris]

Paul Eggert wrote:

> For the past few weeks "make check" has been taking a looooong time on
> Emacs master on my Fedora 27 desktop (AMD Phenom II X4 910e). The
> first line of "make" output that causes a long delay is:
>
>   GEN      lisp/net/tramp-tests.log
>
> and some of the tests in the corresponding script look to be very
> slow. Can this be sped up? Let's mark the slow tests to be expensive,
> so that they are run only if one executes "make check-expensive".

I also find it problematically slow. Recently I identified these
particularly slow tests:

tramp-test11-copy-file 11s
tramp-test12-rename-file 13s
tramp-test21-file-links 24s
tramp-test38-special-characters 9s

Things are much faster for me with TEST_LOAD_EL=no (35s v 1m35s). 
I wonder about the utility of that setting being yes by default.
For me, faster, more frequent testing, with the option to re-run and get
more details from failures if they occur, is better than than the
current default.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Michael Albinus]

Glenn Morris <rgm@gnu.org> writes:

Hi Glenn,

> I also find it problematically slow. Recently I identified these
> particularly slow tests:
>
> tramp-test11-copy-file 11s
> tramp-test12-rename-file 13s
> tramp-test21-file-links 24s
> tramp-test38-special-characters 9s
>
> Things are much faster for me with TEST_LOAD_EL=no (35s v 1m35s). 
> I wonder about the utility of that setting being yes by default.
> For me, faster, more frequent testing, with the option to re-run and get
> more details from failures if they occur, is better than than the
> current default.

This explains indeed the differences between Emacs 26 and 27. I agree
with you, for default runs like a simple "make check", TEST_LOAD_EL
shall be set to "no". If there's a problem, one runs "make -C test <file>"
anyway, which should use an unset TEST_LOAD_EL per default.

Anyway, I will continue to analyze what makes the tests so slow.

Best regards, Michael.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Glenn Morris]

Michael Albinus wrote:

>> Things are much faster for me with TEST_LOAD_EL=no (35s v 1m35s). 
[...]
> This explains indeed the differences between Emacs 26 and 27.

No it doesn't, because that setting is the same in both branches?
Some individual tramp tests are just much slower than they used to be.

# test                                       emacs-26  master     ratio
tramp-test38-special-characters              6.894584  7.764409   1.12616
tramp-test15-copy-directory                  1.457630  2.458257   1.68648
tramp-test09-insert-file-contents            0.663612  1.775478   2.67548
tramp-test10-write-region                    1.338635  4.284001   3.20028
tramp-test08-file-local-copy                 0.442265  1.634770   3.69636
tramp-test14-delete-directory                0.327652  1.631007   4.97786
tramp-test12-rename-file                     2.129018  12.651678  5.94249
tramp-test11-copy-file                       1.838603  11.472515  6.2398
tramp-test13-make-directory                  0.234813  1.559038   6.63949
tramp-test21-file-links                      2.930289  21.953540  7.49194

> I agree with you, for default runs like a simple "make check",
> TEST_LOAD_EL shall be set to "no". If there's a problem, one runs
> "make -C test <file>" anyway, which should use an unset TEST_LOAD_EL
> per default.

Sounds good to me.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Michael Albinus]

Glenn Morris <rgm@gnu.org> writes:

Hi Glenn

>> I agree with you, for default runs like a simple "make check",
>> TEST_LOAD_EL shall be set to "no". If there's a problem, one runs
>> "make -C test <file>" anyway, which should use an unset TEST_LOAD_EL
>> per default.
>
> Sounds good to me.

I've committed a patch, fixing this for "make check" and "make
check-maybe". This should improve the situation, for example for Paul.

Next step will be to review the Tramp tests.

Best regards, Michael.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Michael Albinus]

Paul Eggert <eggert@cs.ucla.edu> writes:

Hi Paul,

> For the past few weeks "make check" has been taking a looooong time on
> Emacs master on my Fedora 27 desktop (AMD Phenom II X4 910e).

All following timings are performed on my 8-years old ThinkPad T500 (Intel
Core2 Duo T9550, 4MB RAM).

Yes, something is wrong. In the emacs-26 branch, I see

--8<---------------cut here---------------start------------->8---
$ time make -C test tramp-tests SELECTOR='$(SELECTOR_DEFAULT)'
28.902u 4.947s 0:36.09 93.7%	0+0k 4448+4568io 0pf+0w
--8<---------------cut here---------------end--------------->8---

The same call in master yields

--8<---------------cut here---------------start------------->8---
$ time make -C test tramp-tests SELECTOR='$(SELECTOR_DEFAULT)'
228.608u 7.401s 4:08.63 94.9%	0+0k 8064+8784io 8pf+0w
--8<---------------cut here---------------end--------------->8---

Up to eight time slower. I will check what's up. (Usually, I run only
the expensive Tramp tests, so I haven't seen this yet)

> and some of the tests in the corresponding script look to be very
> slow. Can this be sped up? Let's mark the slow tests to be expensive,
> so that they are run only if one executes "make check-expensive".

This is already the case. I guess you've uncovered an error, which must
be fixed.

> Worse, there's another long wait here:
>
>   GEN      lisp/net/tramp-archive-tests.log
>
> after this line is output:
>
>    passed  20/22  tramp-archive-test40-file-system-info

I don't see an error here. I get

--8<---------------cut here---------------start------------->8---
$ time make -C test tramp-archive-tests SELECTOR='$(SELECTOR_DEFAULT)'
11.131u 0.678s 0:17.43 67.6%	0+0k 0+104io 0pf+0w
--8<---------------cut here---------------end--------------->8---

This is not superfast (17s duration), but maybe acceptable.

> and here the wait is so long that I gave up trying to run the tests
> and typed control-C to exit them. Presumably the semi-inflooping test
> is tramp-archive-test42-auto-load. (Why is it 42 and not 41? Why are
> there two test42s? I don't know.)

No problem here:

--8<---------------cut here---------------start------------->8---
$ time make -C test tramp-archive-tests SELECTOR='\"tramp-archive-test42-auto-load\"'
1.505u 0.256s 0:02.64 66.2%	0+0k 0+0io 0pf+0w
--8<---------------cut here---------------end--------------->8---

The reasoning for the test numbering is explained in the comment of
tramp-archive-tests.el:

;; The `tramp-archive-testnn-*' tests correspond to the respective
;; tests in tramp-tests.el.

> Worse yet, after I control-C out of "make check" and get a shell
> prompt back, a subsidiary Emacs that is running the Tramp test refuses
> to exit and continues to chew up CPU time in the background until I
> use "kill 3304" (or whatever) to kill it. This really needs to get
> fixed.

I will try to produce some instrumentation for tramp-archive-test42-auto-load
in order to catch your problem.

> Because of these problems I no longer routinely run "make check".

This is bad, and we shall fix it.

Best regards, Michael.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Michael Albinus]

Michael Albinus <michael.albinus@gmx.de> writes:

Hi Paul,

>> Because of these problems I no longer routinely run "make check".
>
> This is bad, and we shall fix it.

As a first step, I have extended ert to print the duration time of single
tests in batch mode. This is disabled by default, you can enable it via

    make TEST_PRINT_TEST_DURATION=1 ...

Pushed to master.

If you run ert interactively, there is already the almost unknown key
"T" in the *ert* buffer, which gives a nice, sorted overview of the
duration times.

Best regards, Michael.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Paul Eggert]

On 03/14/2018 08:36 AM, Michael Albinus wrote:
> As a first step, I have extended ert to print the duration time of single
> tests in batch mode. This is disabled by default, you can enable it via
>
>      make TEST_PRINT_TEST_DURATION=1 ...

tramp-archive-test42-auto-load still takes so long that I kill it. 
Here's the relevant part of the output of "make 
TEST_PRINT_TEST_DURATION=1 check" at the top level. I manually killed 
the seemingly-runaway Emacs test process.

    passed  19/22  tramp-archive-test37-make-nearby-temp-file (0.005722 sec)
    passed  20/22  tramp-archive-test40-file-system-info (0.000921 sec)
Test tramp-archive-test42-auto-load backtrace:
   signal(ert-test-failed (((should (string-match (format "tramp-archiv
   ert-fail(((should (string-match (format "tramp-archive loaded: nil n
   (if (unwind-protect (setq value-886 (apply fn-884 args-885)) (setq f
   (let (form-description-888) (if (unwind-protect (setq value-886 (app
   (let ((value-886 'ert-form-evaluation-aborted-887)) (let (form-descr
   (let* ((fn-884 (function string-match)) (args-885 (condition-case er
   (let ((file (car --dolist-tail--))) (let* ((fn-884 (function string-
   (while --dolist-tail-- (let ((file (car --dolist-tail--))) (let* ((f
   (let ((--dolist-tail-- (list "/ssh::foo" (concat tramp-archive-test-
   (let ((default-directory (expand-file-name temporary-file-directory)
   (closure (t) nil (let ((value-877 (gensym "ert-form-evaluation-abort
   ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
   ert-run-test(#s(ert-test :name tramp-archive-test42-auto-load :docum
   ert-run-or-rerun-test(#s(ert--stats :selector (not (or (tag :expensi
   ert-run-tests((not (or (tag :expensive-test) (tag :unstable))) #f(co
   ert-run-tests-batch((not (or (tag :expensive-test) (tag :unstable)))
   ert-run-tests-batch-and-exit((not (or (tag :expensive-test) (tag :un
   eval((ert-run-tests-batch-and-exit '(not (or (tag :expensive-test) (
   command-line-1(("-L" ":." "-l" "ert" "--eval" "(setq ert-batch-print
   command-line()
   normal-top-level()
Test tramp-archive-test42-auto-load condition:
     (ert-test-failed
      ((should
        (string-match
     (format "tramp-archive loaded: nil nil[[:ascii:]]+tramp-archive 
loaded: t %s" ...)
     (shell-command-to-string ...)))
       :form
       (string-match "tramp-archive loaded: nil 
nil[[:ascii:]]+tramp-archive loaded: t nil" "tramp-archive loaded: nil nil
Are you sure you want to continue connecting (yes/no)? (yes or no) ")
       :value nil))
    FAILED  21/22  tramp-archive-test42-auto-load (2307.384644 sec)
    passed  22/22  tramp-archive-test42-delay-load (1.367596 sec)

Ran 22 tests, 21 results as expected, 1 unexpected (2018-03-14 
17:10:25-0700)

1 unexpected results:
    FAILED  tramp-archive-test42-auto-load

make[3]: *** [Makefile:173: lisp/net/tramp-archive-tests.log] Error 1

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Michael Albinus]

Paul Eggert <eggert@cs.ucla.edu> writes:

Hi Paul,

> I manually killed the seemingly-runaway Emacs test process.

--8<---------------cut here---------------start------------->8---
"tramp-archive loaded: nil
nil
Are you sure you want to continue connecting (yes/no)? (yes or no) "
--8<---------------cut here---------------end--------------->8---

This is the *Messages* buffer of the "seemingly-runaway Emacs test
process" you've killed. Obviously, it is waiting for an answer to that
question.

OMG, I'm using "/ssh::" as test directory here. I shouldn't. Pushed a
fix to the master branch; could you check tramp-archive-tests.el again?

Best regards, Michael.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Paul Eggert]

On 03/15/2018 03:36 AM, Michael Albinus wrote:
> OMG, I'm using "/ssh::" as test directory here. I shouldn't. Pushed a
> fix to the master branch; could you check tramp-archive-tests.el again?

Thanks, the test now succeeds for me. The output now says:

    passed  21/22  tramp-archive-test42-auto-load (1.405318 sec)

On my host the top four tests by time are now the following: could they 
be sped up or marked expensive?

test/lisp/net/tramp-tests.log:44:   passed  36/42 
tramp-test38-special-characters (13.277773 sec)
test/lisp/net/tramp-tests.log:21:   passed  13/42 tramp-test11-copy-file 
(23.924346 sec)
test/lisp/net/tramp-tests.log:22:   passed  14/42 
tramp-test12-rename-file (25.823506 sec)
test/lisp/net/tramp-tests.log:33:   passed  25/42 
tramp-test21-file-links (47.680492 sec)

Also, why not make the TEST_PRINT_TEST_DURATION=1 the default? It's a 
minor hassle to remember to type "make TEST_PRINT_TEST_DURATION=1".

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Michael Albinus]

Paul Eggert <eggert@cs.ucla.edu> writes:

Hi Paul,

> On my host the top four tests by time are now the following: could
> they be sped up or marked expensive?
>
> test/lisp/net/tramp-tests.log:44:   passed  36/42
> tramp-test38-special-characters (13.277773 sec)
> test/lisp/net/tramp-tests.log:21:   passed  13/42
> tramp-test11-copy-file (23.924346 sec)
> test/lisp/net/tramp-tests.log:22:   passed  14/42
> tramp-test12-rename-file (25.823506 sec)
> test/lisp/net/tramp-tests.log:33:   passed  25/42
> tramp-test21-file-links (47.680492 sec)

This are times counted with TEST_LOAD_EL=yes. I've committed
2d0853f62ac65f974f25887f69506bfe923bf14b, which changes the defaults
(see also README). Rerunning the tests shall show improved timings.

I don't want to set these tests as expensive, because they check
essential Tramp features. But as said the other message, I will work to
make them slimmer.

> Also, why not make the TEST_PRINT_TEST_DURATION=1 the default? It's a
> minor hassle to remember to type "make TEST_PRINT_TEST_DURATION=1".

I have no opinion on this. Glenn? Eli?

Best regards, Michael.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Glenn Morris]

>> Also, why not make the TEST_PRINT_TEST_DURATION=1 the default? It's a
>> minor hassle to remember to type "make TEST_PRINT_TEST_DURATION=1".

I can't think of a reason not to print the timing information.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Paul Eggert]

On 03/16/2018 09:41 AM, Michael Albinus wrote:
>> On my host the top four tests by time are now the following: could
>> they be sped up or marked expensive?
>>
>> test/lisp/net/tramp-tests.log:44:   passed  36/42
>> tramp-test38-special-characters (13.277773 sec)
>> test/lisp/net/tramp-tests.log:21:   passed  13/42
>> tramp-test11-copy-file (23.924346 sec)
>> test/lisp/net/tramp-tests.log:22:   passed  14/42
>> tramp-test12-rename-file (25.823506 sec)
>> test/lisp/net/tramp-tests.log:33:   passed  25/42
>> tramp-test21-file-links (47.680492 sec)
> This are times counted with TEST_LOAD_EL=yes. I've committed
> 2d0853f62ac65f974f25887f69506bfe923bf14b, which changes the defaults
> (see also README). Rerunning the tests shall show improved timings.


Thanks, I did a 'git pull' and a 'make bootstrap' followed by a 'make 
check' and got better numbers. Here are the top four now:

test/lisp/net/tramp-tests.log:33:   passed  25/42 
tramp-test21-file-links (9.909445 sec)
test/lisp/emacs-lisp/cl-seq-tests.log:13:   passed  12/13 
cl-seq-test-bug24264 (12.105374 sec)
test/lisp/net/tramp-tests.log:44:   passed  36/42 
tramp-test38-special-characters (13.106871 sec)
test/lisp/autorevert-tests.log:3:   passed  1/3 
auto-revert-test00-auto-revert-mode (13.113220 sec)

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Michael Albinus]

Paul Eggert <eggert@cs.ucla.edu> writes:

Hi Paul,

> Thanks, I did a 'git pull' and a 'make bootstrap' followed by a 'make
> check' and got better numbers. Here are the top four now:
>
> tramp-test21-file-links (9.909445 sec)
> cl-seq-test-bug24264 (12.105374 sec)
> tramp-test38-special-characters (13.106871 sec)
> auto-revert-test00-auto-revert-mode (13.113220 sec)

I've profiled tramp-tests.el, and could optimize some of the
tests. Surprisingly, should-error clauses take much more time than other
forms.

Furthermore, there was an error in how tramp-tests determine whether
expensive tests run. This I've fixed as well.

As a result, I have now

   passed  13/42  tramp-test11-copy-file (1.050841 sec)
   passed  14/42  tramp-test12-rename-file (1.175471 sec)
   passed  25/42  tramp-test21-file-links (0.606194 sec)
   passed  36/42  tramp-test38-special-characters (0.535814 sec)

Ran 42 tests, 41 results as expected, 1 skipped (2018-03-17 15:49:10+0100, 13.198513 sec)

The high runners take less time, and the whole duration for tramp-tests
is 13 sec. This is acceptable, isn't it?

I will continue to analyze other long-running tests I feel responsible
(autorevert-tests, filenotify-tests), but for this bug report I believe
we could close it.

Best regards, Michael.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Noam Postavsky]

Michael Albinus <michael.albinus@gmx.de> writes:

> I've profiled tramp-tests.el, and could optimize some of the
> tests. Surprisingly, should-error clauses take much more time than other
> forms.

The ert machinery for should-* forms is pretty hairy, we'll probably
have to overhaul it to solve Bug#30745 anyway.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Paul Eggert]

Michael Albinus wrote:
> The high runners take less time, and the whole duration for tramp-tests
> is 13 sec. This is acceptable, isn't it?

Sounds good to me, and thanks. Closing.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Glenn Morris]

With current master, tramp-archive-tests are very slow.
My time to run "make -j8 check" is 3 minutes.
If I remove tramp-archive-tests.el, it changes to 30 seconds.

Here are the slowest tests. Perhaps anything that takes more than 10
seconds should be tagged expensive?


LONG-RUNNING TESTS
------------------
   passed  10/22  tramp-archive-test11-copy-file (30.784306 sec)
   passed  11/22  tramp-archive-test15-copy-directory (20.679223 sec)
   passed  12/13  cl-seq-test-bug24264 (15.896021 sec)
   passed  1/3  auto-revert-test00-auto-revert-mode (13.111064 sec)
   passed  22/22  tramp-archive-test43-delay-load (11.372054 sec)
   passed  21/22  tramp-archive-test43-auto-load (11.365802 sec)
   passed  14/22  tramp-archive-test18-file-attributes (10.369735 sec)
   passed   8/22  tramp-archive-test08-file-local-copy (10.309309 sec)
   passed  13/22  tramp-archive-test17-insert-directory (10.301208 sec)
   passed  17/22  tramp-archive-test21-file-links (10.298635 sec)
   passed  18/22  tramp-archive-test26-file-name-completion (10.280112 sec)
   passed  16/22  tramp-archive-test20-file-modes (10.269900 sec)
   passed  15/22  tramp-archive-test19-directory-files-and-attributes (10.256971 sec)
   passed  12/22  tramp-archive-test16-directory-files (10.250864 sec)
   passed   7/22  tramp-archive-test07-file-exists-p (10.171281 sec)
   passed   9/22  tramp-archive-test09-insert-file-contents (10.160516 sec)
   passed  3/3  auto-revert-test04-auto-revert-mode-dired (6.042494 sec)
   passed  5/8  file-notify-test04-autorevert (6.017824 sec)
   passed  1/2  inotify-file-watch-simple (5.002061 sec)

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Michael Albinus]

Glenn Morris <rgm@gnu.org> writes:

Hi Glenn,

> With current master, tramp-archive-tests are very slow.
> My time to run "make -j8 check" is 3 minutes.
> If I remove tramp-archive-tests.el, it changes to 30 seconds.
>
> Here are the slowest tests. Perhaps anything that takes more than 10
> seconds should be tagged expensive?

Will check. This week I'm almost ooo, due to vacation.

Best regards, Michael.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Michael Albinus]

Glenn Morris <rgm@gnu.org> writes:

Hi Glenn,

> With current master, tramp-archive-tests are very slow.
> My time to run "make -j8 check" is 3 minutes.
> If I remove tramp-archive-tests.el, it changes to 30 seconds.
>
> Here are the slowest tests. Perhaps anything that takes more than 10
> seconds should be tagged expensive?

Done. Could you, pls, check?

Best regards, Michael.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Glenn Morris]

Michael Albinus wrote:

> Done. Could you, pls, check?

Works for me, thanks.

Running 8 tests (2018-08-10 11:41:04-0700, selector `(not (or (tag :expensive-te st) (tag :unstable)))')
   passed  1/8  tramp-archive-test00-availability (0.000178 sec)
   passed  2/8  tramp-archive-test01-file-name-syntax (0.000153 sec)
   passed  3/8  tramp-archive-test02-file-name-dissect (0.584458 sec)
   passed  4/8  tramp-archive-test05-expand-file-name (0.000156 sec)
   passed  5/8 tramp-archive-test05-expand-file-name-non-archive-directory (0.0 00284 sec)
   passed  6/8  tramp-archive-test06-directory-file-name (0.000503 sec)
   passed  7/8  tramp-archive-test38-make-nearby-temp-file (0.004607
   sec)
   passed  8/8  tramp-archive-test41-file-system-info (0.000852 sec)

Ran 8 tests, 8 results as expected (2018-08-10 11:41:04-0700, 0.591774
sec)

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Eli Zaretskii]

> From: Michael Albinus <michael.albinus@gmx.de>
> Date: Fri, 16 Mar 2018 17:41:16 +0100
> Cc: 30807@debbugs.gnu.org
> 
> > Also, why not make the TEST_PRINT_TEST_DURATION=1 the default? It's a
> > minor hassle to remember to type "make TEST_PRINT_TEST_DURATION=1".
> 
> I have no opinion on this. Glenn? Eli?

If tests becoming slow is something that happens a lot, and we want to
keep track of that, then indeed it sounds like a good idea.
Otherwise, it's just useless clutter.

Alternatively, maybe we should do this only for certain parts of the
suite, where this issue pops frequently.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Michael Albinus]

Eli Zaretskii <eliz@gnu.org> writes:

Hi Eli,

>> > Also, why not make the TEST_PRINT_TEST_DURATION=1 the default? It's a
>> > minor hassle to remember to type "make TEST_PRINT_TEST_DURATION=1".
>> 
>> I have no opinion on this. Glenn? Eli?
>
> If tests becoming slow is something that happens a lot, and we want to
> keep track of that, then indeed it sounds like a good idea.
> Otherwise, it's just useless clutter.
>
> Alternatively, maybe we should do this only for certain parts of the
> suite, where this issue pops frequently.

Your message arrived me 5 minutes too late; I've just committed a patch
as proposed by Paul and Glenn.

Let's see how this "clutter" is in the way. If people protest, we still
could apply what you have proposed (make it configurable, again; enable
it by default for suspicious test files; disable it by default for the
other tests).

Best regards, Michael.

bug#30807: Tramp tests take waaayyy too long and refuse to exit

[Glenn Morris]

[-- Attachment #1: Type: text/plain, Size: 2067 bytes --]

Michael Albinus wrote:

>>  Let's mark the slow tests to be expensive, so that they are run only
>> if one executes "make check-expensive".
>
> This is already the case. I guess you've uncovered an error, which must
> be fixed.

I think he meant that more tests should be marked expensive.
From the nice new timing feature that you added:

20 slowest non-expensive tests:
2.107192 auto-revert-test03-auto-revert-tail-mode
2.185436 included-c-header-files
2.478982 tramp-test09-insert-file-contents
2.539473 tramp-test39-utf8
2.541236 tramp-test15-copy-directory
2.641033 tramp-test08-file-local-copy
3.053811 file-notify-test05-file-validity
3.057267 file-notify-test08-backup
3.238807 file-notify-test03-events
3.453809 tramp-archive-test42-auto-load
5.005737 inotify-file-watch-simple
5.270187 tramp-test10-write-region
6.005597 file-notify-test04-autorevert
6.067378 auto-revert-test04-auto-revert-mode-dired
7.129754 cl-seq-test-bug24264
7.696874 tramp-test38-special-characters
12.318760 tramp-test12-rename-file
12.621092 tramp-test11-copy-file
13.105928 auto-revert-test00-auto-revert-mode
22.254235 tramp-test21-file-links

20 slowest expensive tests:
2.443189 file-notify-test06-dir-validity-remote
2.499095 tramp-test39-utf8-with-stat
2.581147 tramp-test39-utf8-with-ls
3.058655 tramp-test39-utf8-with-perl
3.140859 auto-revert-test01-auto-revert-several-files
3.741687 tramp-test41-asynchronous-requests
4.417266 file-notify-test05-file-validity-remote
4.454070 file-notify-test01-add-watch-remote
4.894808 file-notify-test08-backup-remote
4.983632 file-notify-test02-rm-watch-remote
7.111716 auto-revert-test02-auto-revert-deleted-file
7.502341 file-notify-test04-autorevert-remote
8.159349 tramp-test38-special-characters-with-stat
8.347577 tramp-test38-special-characters-with-ls
10.124505 tramp-test38-special-characters-with-perl
10.138312 file-notify-test09-watched-file-in-watched-dir
10.299857 file-notify-test03-events-remote
34.731760 ucs-normalize-part1
43.038078 file-notify-test07-many-events
579.167091 file-notify-test07-many-events-remote


[-- Attachment #2: times.png --]
[-- Type: image/png, Size: 24107 bytes --]