bug#15561: Timer can miss its SIGALRM

bug#15561: Timer can miss its SIGALRM

[Barry OReilly]

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

Looking over the timer code, the do_pending_atimers function does:

      block_atimers ();
      run_timers ();
      unblock_atimers ();

The last line of run_timers is:

  set_alarm ();

But what happens if the next timer happens to be soon, and Emacs
receives SIGALRM inbetween set_alarm and unblock_timers?

What is the purpose of sigmasking SIGALRM anyway? If it means to block
SIGALRM during timers, that doesn't always happen because timers run
within timers. The end of an inner timer would unblock SIGALRM and
the outer timer would finish with the sigmask unblocked.

[-- Attachment #2: Type: text/html, Size: 663 bytes --]

bug#15561: periodic timer stops running

[Barry OReilly]

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

> Are you talking about a SIGALRM received during the execution of
> do_pending_atimers, between run_timer's call to set_alarm and
> do_pending_atimers's call to unblock_atimers? If so, the SIGALRM
> should be held by the operating system during that period, and Emacs
> won't be informed of the SIGALRM until unblock_atimers does its
> thing. Sorry, I don't see how this would cause a timer to stop.

I see you're right, because SIGALRM isn't specified with SIG_IGN at
any point.

While verifying that, I found in sys_subshell:

  struct save_signal saved_handlers[5];
  [...]
#ifdef USABLE_SIGIO
  saved_handlers[3].code = SIGIO;
  saved_handlers[4].code = 0;
#else
  saved_handlers[3].code = 0;
#endif

Shouldn't the else case initialize saved_handlers[4]? On the off
chance it is garbage valued coincidentally as SIGALRM, the subsequent
SIG_IGN could drop a pending SIGALRM.

Peter, which OS do you run? What is USABLE_SIGIO in your src/config.h?

[-- Attachment #2: Type: text/html, Size: 1110 bytes --]

bug#15561: periodic timer stops running

[Barry OReilly]

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

save_signal_handlers (struct save_signal *saved_handlers)
{
  while (saved_handlers->code)

Nevermind, it short circuits at the first 0.

[-- Attachment #2: Type: text/html, Size: 182 bytes --]

bug#15561: periodic timer stops running

[Peter Münster]

On Fri, Feb 28 2014, Barry OReilly wrote:

> Peter, which OS do you run?

Hi,

GNU/Linux (openSUSE-12.3).


> What is USABLE_SIGIO in your src/config.h?

It's 1.


The patch did not help.


Very probably a timer stops running just after system wake-up (after
suspend to ram), because at that moment several timers are triggered at
the same time.

Thanks for your efforts,
-- 
           Peter

bug#15561: periodic timer stops running

[Barry OReilly]

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

> Very probably a timer stops running just after system wake-up (after
> suspend to ram), because at that moment several timers are triggered
> at the same time.

I tried testing several timers going off at once, but reproduced no
problem.

;;; -*- lexical-binding:t -*-
(require 'cl-lib)
(let ((noninteractive nil))
  (cl-dotimes (timer-id 8)
    (run-at-time '(0 0 0 0)
                 0.1
                 (lambda ()
                   (message "%s DEBUG: Timer ID=%s" (current-time)
timer-id)
                   (sit-for 0 t)))))

All 8 fire without stopping.

Is it always the same timer that stops running, or have you seen
different timers in Emacs stop?

Could you come up with a recipe that allows us to reproduce the bug?

[-- Attachment #2: Type: text/html, Size: 863 bytes --]

bug#15561: periodic timer stops running

[Peter Münster]

On Tue, Mar 04 2014, Barry OReilly wrote:

> Is it always the same timer that stops running, or have you seen
> different timers in Emacs stop?

Hi Barry,

Different timers.


> Could you come up with a recipe that allows us to reproduce the bug?

I don't know. It would be difficult:
- in happens only once or twice per day
- the timers depend on my personal environment: checking email, news,
  Bitcoin value, the todo-list of my org-file and so on
- some timers depend on idle-time

Would it help, if I a add some code to the start and to the end of each
timer function, that prints interesting information to the *Messages*
buffer? And when it happens again, we would get some trace?

-- 
           Peter

bug#15561: periodic timer stops running

[Peter Münster]

Perhaps related:

The following function make some beeps for some seconds. It is called
from a timer. Sometimes, the `cancel-timer' does not work, and emacs
continues to beep.

--8<---------------cut here---------------start------------->8---
(defun org-notify-action-ding (plist)
  "Make noise."
  (let ((timer (run-with-timer 0 1 'ding)))
    (run-with-timer (or (plist-get plist :duration) 3) nil
                    'cancel-timer timer)))
--8<---------------cut here---------------end--------------->8---

Or is this another problem/bug?

TIA for any help,
-- 
           Peter

bug#15561: periodic timer stops running

[Barry OReilly]

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

> I don't know. It would be difficult:
> - in happens only once or twice per day
> - the timers depend on my personal environment: checking email,
>   news, Bitcoin value, the todo-list of my org-file and so on
> - some timers depend on idle-time

> Would it help, if I a add some code to the start and to the end of
> each timer function, that prints interesting information to the
> *Messages* buffer? And when it happens again, we would get some
> trace?

After the timers stop, do they start up again when you 'kill -s ALRM'
the Emacs process?

Maybe you could put a print statement in the handle_alarm_signal
function to confirm you get the signal. If you do, then perhaps start
debugging at the do_pending_atimers function.

If the problem is that you're not getting the signal, write a small
program that implements a simple timer using SIGALRM, run it
continuously, and see if it stops too under the same conditions.

[-- Attachment #2: Type: text/html, Size: 1066 bytes --]

bug#15561: periodic timer stops running

[Peter Münster]

On Wed, Mar 12 2014, Barry OReilly wrote:

> After the timers stop, do they start up again when you 'kill -s ALRM'
> the Emacs process?

The timers don't stop anymore since my distribution upgrade from
opensuse-12.3 to 13.1. Very odd...

I don't understand why, but the problem seems to be solved.

-- 
           Peter

bug#15561: periodic timer stops running

[Barry OReilly]

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

I think applying Paul Eggert's patch is all that's left to this bug
report then. Since it solves a theoretical flaw rather than one
witnessed, maybe it's appropriate for trunk?

[-- Attachment #2: Type: text/html, Size: 224 bytes --]

bug#15561: periodic timer stops running

[Paul Eggert]

Barry OReilly wrote:
> I think applying Paul Eggert's patch is all that's left to this bug
> report then. Since it solves a theoretical flaw rather than one
> witnessed, maybe it's appropriate for trunk?

Sounds good; done as trunk bzr 116018.

bug#15561: periodic timer stops running

[Peter Münster]

Hi,

It happened again: 2 periodic timers have stopped running.


On Wed, Mar 12 2014, Barry OReilly wrote:

> After the timers stop, do they start up again when you 'kill -s ALRM'
> the Emacs process?

No.


> Maybe you could put a print statement in the handle_alarm_signal
> function to confirm you get the signal.

Emacs goes into the handle_alarm_signal function when sending the
signal.


> If you do, then perhaps start debugging at the do_pending_atimers
> function.

I've tried, but I don't really know, where to look...

Here the value of my timer-list:

--8<---------------cut here---------------start------------->8---
Value: ([t 21335 18354 590042 20 org-notify-process nil nil 953248]
 [t 21335 20714 647433 9000 gnus-demon-run-callback
    (pm/rescan-news 900 9000)
    nil 138000]
 [nil 21336 7511 917609 300 savehist-autosave nil nil 848940]
 [nil 21336 7547 595349 300 gnus-demon-run-callback
      (gnus-group-save-newsrc 120 300)
      nil 925000]
 [nil 21336 7547 880984 60 pm/newmail-update nil nil 696000]
 [nil 21336 7641 823147 900 gnus-demon-run-callback
      (pm/btc-checker 60 900)
      nil 609000]
 [nil 21336 7727 644172 420 gnus-demon-run-callback
      (gnus-delay-send-queue 180 420)
      nil 412000]
 [nil 21336 7947 507382 3600 url-cookie-write-file nil nil 982000]
 [nil 21336 10875 981456 nil password-cache-remove
      ("auth-source-magic (:max 1 :host (\"news.gmane.org\" \"news.gmane.org\") :port (\"119\" \"nntp\" \"nntp\" \"563\" \"nntps\" \"snews\"))")
      nil 731000]
 [nil 21336 13307 647529 6000 gnus-demon-run-callback
      (pm/check-mail 180 6000)
      nil 832000])
--8<---------------cut here---------------end--------------->8---

What does the first entry in the vector mean (t or nil)? The 2 first
entries have stopped.

What could I do to debug this?

TIA for any hints,
-- 
           Peter