bug#72004: 30.0.50, master: 'erc--check-prompt-input-for-multiline-blanks' test fail

bug#72004: 30.0.50, master: 'erc--check-prompt-input-for-multiline-blanks' test fail

[Andrea Corallo]

Since few days I see 'erc--check-prompt-input-for-multiline-blanks'
failing.  I think the fail is intermittent and because of that I could
not determine the commit that introduced it.

I observe this both on emacs-30 both on master, the first commit in
emacs-30 where I observed it is 2fb6a98ecfa1579273a640e923f2e52f75e1f7ad
which seems unrelated (but I mention it so we have a point in time).

This is the output I see:

Test erc--check-prompt-input-for-multiline-blanks backtrace:
  user-error("Process not running")
  erc--run-input-validation-checks(#s(erc--input-split :string "a" :in
  run-hook-with-args(erc--run-input-validation-checks #s(erc--input-sp
  erc-send-current-line()
  #f(compiled-function (next) #<bytecode 0x1eab02298fb35043>)(#f(lambd
  funcall(#f(compiled-function (next) #<bytecode 0x1eab02298fb35043>)
  (progn (fset 'erc-server-buffer vnew) (fset 'erc-process-input-line
  (unwind-protect (progn (fset 'erc-server-buffer vnew) (fset 'erc-pro
  (let* ((vnew #'(lambda (&rest r) (setq calls (cons r calls)))) (vnew
  (let* ((erc--input-review-functions (remove 'erc-add-to-input-ring e
  (save-current-buffer (set-buffer (get-buffer-create "FakeNet")) (let
  erc-tests-common-with-process-input-spy(#f(compiled-function (next)
  #f(compiled-function () #<bytecode -0xaf493cb21b42d4b>)()
  #f(compiled-function () #<bytecode -0x1a6c2873f655e48c>)()
  handler-bind-1(#f(compiled-function () #<bytecode -0x1a6c2873f655e48
  ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
  ert-run-test(#s(ert-test :name erc--check-prompt-input-for-multiline
  ert-run-or-rerun-test(#s(ert--stats :selector ... :tests ... :test-m
  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 treesit-extra-l
  command-line()
  normal-top-level()
Test erc--check-prompt-input-for-multiline-blanks condition:
    Info: Opts: (+wb -sw), Input: "a", want: (a)
    (user-error "Process not running")
   FAILED   5/95  erc--check-prompt-input-for-multiline-blanks (10.525627 sec) at lisp/erc/erc-tests.el:1637


  Andrea

bug#72004: 30.0.50, master: 'erc--check-prompt-input-for-multiline-blanks' test fail

[Eli Zaretskii]

> From: Andrea Corallo <acorallo@gnu.org>
> Date: Tue, 09 Jul 2024 04:08:06 -0400
> 
> Since few days I see 'erc--check-prompt-input-for-multiline-blanks'
> failing.  I think the fail is intermittent and because of that I could
> not determine the commit that introduced it.
> 
> I observe this both on emacs-30 both on master, the first commit in
> emacs-30 where I observed it is 2fb6a98ecfa1579273a640e923f2e52f75e1f7ad
> which seems unrelated (but I mention it so we have a point in time).
> 
> This is the output I see:
> 
> Test erc--check-prompt-input-for-multiline-blanks backtrace:
>   user-error("Process not running")
>   erc--run-input-validation-checks(#s(erc--input-split :string "a" :in
>   run-hook-with-args(erc--run-input-validation-checks #s(erc--input-sp
>   erc-send-current-line()
>   #f(compiled-function (next) #<bytecode 0x1eab02298fb35043>)(#f(lambd
>   funcall(#f(compiled-function (next) #<bytecode 0x1eab02298fb35043>)
>   (progn (fset 'erc-server-buffer vnew) (fset 'erc-process-input-line
>   (unwind-protect (progn (fset 'erc-server-buffer vnew) (fset 'erc-pro
>   (let* ((vnew #'(lambda (&rest r) (setq calls (cons r calls)))) (vnew
>   (let* ((erc--input-review-functions (remove 'erc-add-to-input-ring e
>   (save-current-buffer (set-buffer (get-buffer-create "FakeNet")) (let
>   erc-tests-common-with-process-input-spy(#f(compiled-function (next)
>   #f(compiled-function () #<bytecode -0xaf493cb21b42d4b>)()
>   #f(compiled-function () #<bytecode -0x1a6c2873f655e48c>)()
>   handler-bind-1(#f(compiled-function () #<bytecode -0x1a6c2873f655e48
>   ert--run-test-internal(#s(ert--test-execution-info :test #s(ert-test
>   ert-run-test(#s(ert-test :name erc--check-prompt-input-for-multiline
>   ert-run-or-rerun-test(#s(ert--stats :selector ... :tests ... :test-m
>   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 treesit-extra-l
>   command-line()
>   normal-top-level()
> Test erc--check-prompt-input-for-multiline-blanks condition:
>     Info: Opts: (+wb -sw), Input: "a", want: (a)
>     (user-error "Process not running")
>    FAILED   5/95  erc--check-prompt-input-for-multiline-blanks (10.525627 sec) at lisp/erc/erc-tests.el:1637

Adding the ERC developer to the discussion.

bug#72004: 30.0.50, master: 'erc--check-prompt-input-for-multiline-blanks' test fail

[J.P.]

Hi Andrea,

Eli Zaretskii <eliz@gnu.org> writes:

>> From: Andrea Corallo <acorallo@gnu.org>
>> Date: Tue, 09 Jul 2024 04:08:06 -0400
>> 
>> Since few days I see 'erc--check-prompt-input-for-multiline-blanks'
>> failing.  I think the fail is intermittent and because of that I could
>> not determine the commit that introduced it.
>> 
>> I observe this both on emacs-30 both on master, the first commit in
>> emacs-30 where I observed it is 2fb6a98ecfa1579273a640e923f2e52f75e1f7ad
>> which seems unrelated (but I mention it so we have a point in time).

I've not yet witnessed the test in question fail, but I can definitely
imagine it doing so because it's rather flimsy, which is my bad. I've
therefore attempted a superficial fix on the release branch:

  ef3f26ec02d ; Tag ERC multiline blanks test as :expensive

Here's what (I think) is going on. That test relies on the macro
`ert-with-message-capture'. Because that macro advises a few primitive
functions, its first appearance in any make-check run exhibits a
trampoline penalty in terms of execution time (as I'm sure you, more
than anyone, are acutely aware). For example, if you put this at the
bottom of test/lisp/emacs-lisp/ert-x-tests.el

  (ert-deftest ert-with-message-capture/1 ()
    (ert-with-message-capture string (ignore string)))
  
  (ert-deftest ert-with-message-capture/2 ()
    (ert-with-message-capture string (ignore string)))

you'll notice the first takes upwards of a few seconds (when built with
debugging symbols), while subsequent occurrences are comparatively free:

  passed  21/30  ert-with-message-capture/1 (3.067526 sec)
  passed  22/30  ert-with-message-capture/2 (0.000396 sec)

I think it's possible that this phenomenon, combined with added CPU
pressure from unbounded "make -j" runs, may account for the intermittent
failures you've been seeing. And correct me if I'm wrong, but I'm
guessing that during parallel make-check runs, the first occurrence of
`ert-with-message-capture' in any one file always incurs such a penalty
because `ert-run-tests-batch-and-exit' deletes its .eln cache on exit
and "make -j" runs every test file in a separate process.

(Incidentally, I count eleven files in the suite currently using this
macro. Granted, none likely depends on a brittle hard timeout, like the
"sleep 10" in my test, so there's surely no risk of similar failures,
but if the mere appearance of that macro or ones like it translates to
noticeable overhead, perhaps it's worth looking into eventually.)

Anyway, thanks for bringing this to ERC's attention.

J.P.

bug#72004: 30.0.50, master: 'erc--check-prompt-input-for-multiline-blanks' test fail

[Andrea Corallo]

"J.P." <jp@neverwas.me> writes:

> Hi Andrea,
>
> Eli Zaretskii <eliz@gnu.org> writes:
>
>>> From: Andrea Corallo <acorallo@gnu.org>
>>> Date: Tue, 09 Jul 2024 04:08:06 -0400
>>> 
>>> Since few days I see 'erc--check-prompt-input-for-multiline-blanks'
>>> failing.  I think the fail is intermittent and because of that I could
>>> not determine the commit that introduced it.
>>> 
>>> I observe this both on emacs-30 both on master, the first commit in
>>> emacs-30 where I observed it is 2fb6a98ecfa1579273a640e923f2e52f75e1f7ad
>>> which seems unrelated (but I mention it so we have a point in time).
>
> I've not yet witnessed the test in question fail, but I can definitely
> imagine it doing so because it's rather flimsy, which is my bad. I've
> therefore attempted a superficial fix on the release branch:
>
>   ef3f26ec02d ; Tag ERC multiline blanks test as :expensive
>
> Here's what (I think) is going on. That test relies on the macro
> `ert-with-message-capture'. Because that macro advises a few primitive
> functions, its first appearance in any make-check run exhibits a
> trampoline penalty in terms of execution time (as I'm sure you, more
> than anyone, are acutely aware). For example, if you put this at the
> bottom of test/lisp/emacs-lisp/ert-x-tests.el
>
>   (ert-deftest ert-with-message-capture/1 ()
>     (ert-with-message-capture string (ignore string)))
>   
>   (ert-deftest ert-with-message-capture/2 ()
>     (ert-with-message-capture string (ignore string)))
>
> you'll notice the first takes upwards of a few seconds (when built with
> debugging symbols), while subsequent occurrences are comparatively free:
>
>   passed  21/30  ert-with-message-capture/1 (3.067526 sec)
>   passed  22/30  ert-with-message-capture/2 (0.000396 sec)
>
> I think it's possible that this phenomenon, combined with added CPU
> pressure from unbounded "make -j" runs, may account for the intermittent
> failures you've been seeing. And correct me if I'm wrong, but I'm
> guessing that during parallel make-check runs, the first occurrence of
> `ert-with-message-capture' in any one file always incurs such a penalty
> because `ert-run-tests-batch-and-exit' deletes its .eln cache on exit
> and "make -j" runs every test file in a separate process.
>
> (Incidentally, I count eleven files in the suite currently using this
> macro. Granted, none likely depends on a brittle hard timeout, like the
> "sleep 10" in my test, so there's surely no risk of similar failures,
> but if the mere appearance of that macro or ones like it translates to
> noticeable overhead, perhaps it's worth looking into eventually.)
>
> Anyway, thanks for bringing this to ERC's attention.

Hi J.P.,

I buy the theory of this being related to trampoline generation under
high system load, looking at my logs I see this test failing only with
native compilation an passing without.

I'm wondering if we could work around the issue somehow 🤔

Also I'm not sure the right tag is :expensive, shouldn't be :unstable?

Thanks!

  Andrea

bug#72004: 30.0.50, master: 'erc--check-prompt-input-for-multiline-blanks' test fail

[J.P.]

Andrea Corallo <acorallo@gnu.org> writes:

> I buy the theory of this being related to trampoline generation under
> high system load, looking at my logs I see this test failing only with
> native compilation an passing without.
>
> I'm wondering if we could work around the issue somehow 🤔

I'm afraid I can offer next to nothing when it comes to serious insights
about Emacs internals and related magic 😞

>
> Also I'm not sure the right tag is :expensive, shouldn't be :unstable?

If we want to prevent the test from running completely (at least on
EMBA), then :unstable would indeed make sense. However, if we'd like the
test to run on the 3x daily expensive pipelines, I'm fairly confident my
latest change sidesteps the issue. It now waits to start the subprocess,
which was previously too short-lived, until after the macro has done its
(potentially time-consuming) advising. Thus, the liveliness check that
was signaling the error should now always find a running process.
(Although, for good measure, I also lengthened the timeout from 10s to
5m.) All this said, I'm happy to change it to :unstable or try a safer
approach, such as mocking `process-status'. Thanks.

bug#72004: 30.0.50, master: 'erc--check-prompt-input-for-multiline-blanks' test fail

[Andrea Corallo]

"J.P." <jp@neverwas.me> writes:

> Andrea Corallo <acorallo@gnu.org> writes:
>
>> I buy the theory of this being related to trampoline generation under
>> high system load, looking at my logs I see this test failing only with
>> native compilation an passing without.
>>
>> I'm wondering if we could work around the issue somehow 🤔
>
> I'm afraid I can offer next to nothing when it comes to serious insights
> about Emacs internals and related magic 😞
>
>>
>> Also I'm not sure the right tag is :expensive, shouldn't be :unstable?
>
> If we want to prevent the test from running completely (at least on
> EMBA), then :unstable would indeed make sense. However, if we'd like the
> test to run on the 3x daily expensive pipelines, I'm fairly confident my
> latest change sidesteps the issue. It now waits to start the subprocess,
> which was previously too short-lived, until after the macro has done its
> (potentially time-consuming) advising. Thus, the liveliness check that
> was signaling the error should now always find a running process.
> (Although, for good measure, I also lengthened the timeout from 10s to
> 5m.) All this said, I'm happy to change it to :unstable or try a safer
> approach, such as mocking `process-status'. Thanks.

Generally speaking I think we should flag tests for what they are and
then tune the EMBA testing strategy to our needs afterward.  That said
with a 5m timeout the test is now probably more expansive than unstable
so I think the classificaiton it's fine :)

Thanks closing this.

  Andrea