Comment to task #5647 in hc-cron: hc-cron czasami odpala dwukrotnie zadania

Wed May 25 15:57:59 CEST 2005

Project: PLD 2.x (Ac)

  Package: hc-cron
  Summary: hc-cron czasami odpala dwukrotnie zadania
  Commented by: Marcin Kaminski (maxiu)
  Comment: Kolejny strace, tym razem z timestampami:

1117028160.621671 stat64("cron", {st_mode=S_IFDIR|S_ISVTX|0730,
st_size=6, ...}) = 0
[...]
1117028160.622872 time(NULL)            = 1117028160
1117028160.622911 time(NULL)            = 1117028160
1117028160.622951 clone(child_stack=0,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x40138708) = 5062
1117028160.623176 clone(child_stack=0,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x40138708) = 5063
1117028160.623440 time(NULL)            = 1117028160
1117028160.623772 nanosleep({60, 0}, 0xbfffd844) = ?
ERESTART_RESTARTBLOCK (To be restarted)
1117028160.629052 --- SIGCHLD (Child exited) @ 0 (0) ---
1117028160.629102 waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}],
WNOHANG) = 5062
1117028160.629179 waitpid(-1, 0xbfffd524, WNOHANG) = 0
1117028160.629230 sigreturn()           = ? (mask now [])
1117028160.629533 nanosleep({60, 0}, 0xbfffd844) = ?
ERESTART_RESTARTBLOCK (To be restarted)
1117028161.135012 --- SIGCHLD (Child exited) @ 0 (0) ---
1117028161.135060 waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}],
WNOHANG) = 5063
1117028161.135134 waitpid(-1, 0xbfffd524, WNOHANG) = 0
1117028161.135182 sigreturn()           = ? (mask now [])
1117028161.135547 nanosleep({59, 0},{59, 0}) = 0

1117028220.136696 stat64("cron", {st_mode=S_IFDIR|S_ISVTX|0730,
st_size=6, ...}) = 0
[...]
1117028220.138375 time(NULL)            = 1117028220
1117028220.138426 time(NULL)            = 1117028220
1117028220.138477 clone(child_stack=0,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x40138708) = 5462
1117028220.138912 clone(child_stack=0,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x40138708) = 5464
1117028220.139269 time(NULL)            = 1117028220
1117028220.139535 nanosleep({60, 0}, 0xbfffd844) = ?
ERESTART_RESTARTBLOCK (To be restarted)
1117028220.146077 --- SIGCHLD (Child exited) @ 0 (0) ---
1117028220.146166 waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}],
WNOHANG) = 5462
1117028220.146361 waitpid(-1, 0xbfffd524, WNOHANG) = 0
1117028220.146575 sigreturn()           = ? (mask now [])
1117028220.147538 nanosleep({60, 0}, 0xbfffd844) = ?
ERESTART_RESTARTBLOCK (To be restarted)
1117028220.650707 --- SIGCHLD (Child exited) @ 0 (0) ---
1117028220.650750 waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}],
WNOHANG) = 5464
1117028220.650811 waitpid(-1, 0xbfffd524, WNOHANG) = 0
1117028220.650845 sigreturn()           = ? (mask now [])
1117028220.651079 nanosleep({59, 0}, {59, 0}) = 0

1117028279.651581 stat64("cron", {st_mode=S_IFDIR|S_ISVTX|0730,
st_size=6, ...}) = 0

Pierwsza seria pokazuje prawidłowe zachowanie. W sekundzie 1117028161
został puszczony sleep na 59 sekund.
Druga seria pokazuje złe zachowane. W sekundzie 1117028220 został
puszczony sleep na 59 sekund, a więc za krótko!

Kod to obsługujący wygląda następująco:

        while (seconds_to_wait > 0) {
                Debug(DSCH, ("[%d] sleeping for %d secondsn",
                        getpid(), seconds_to_wait))
                seconds_to_wait = (int) sleep((unsigned int)
seconds_to_wait);
        }

A więc parametr do kolejnego sleepa jest pobierany z wyniku
poprzedniego. Powinna to być ilość sekund jaka pozostała do
wykonania pełnego sleepa. Niestety wychodzi na to że sleep wywołany
w momencie 1117028220.147538 zwrócił 59 w momencie 1117028220.650707,
a powinien zwrócić 60 (poprzedni wywołany w 1117028220.139535 tak
zrobił).
Tak na oko:
1117028220.146077 - 1117028220.139535 = 0.006542
1117028220.650707 - 1117028220.147538 = 0.503169
Wygląda na to że funkcja sleep() zaokrągla wynik i jeśli minęło
troche więcej niż półsekundy to w wyniku już pomija całą tą
sekundę.
W przypadku crona to jest zachowanie nieodpowiednie, gdyż on tylko
zmniejsza pozostały czas, więc zabrane pół sekundy już nie wróci
(chyba że wykonywanie kodu zajmie pół sekundy).

Muszę sprawdzić w specyfikacji funkcji sleep() jak ona ma się
zachowywać. Niestety zdanie z mana:
Zero if the requested time has elapsed, or the number of  seconds  left
to sleep.
Nic nie mówi o dokładności. Jeśli to jest ostateczna specyfikacja
to znaczy że błąd jest w hc-cron, gdyż powinien on uwzględniać te
błędy zaokrągleń.

Pytanie do operatorów bugs: czy kontynuować to na bugd.pld-linux.org,
czy skoro błąd występuje w orginalnym hc-cron to PLD się nim nie
zajmuje? Jeśli ostatecznym winowajcom okaże się hc-cron to mogę
stworzyć łatę i ją przesłać.

For more further see:
http://bugs.pld-linux.org/index.php?do=details&id=5647&area=comments#tabs}

------------------------------------------------------------------------
THIS IS AN AUTOMATICALLY GENERATED MESSAGE, DO NOT REPLY