Re: Stream of kernel messages: pid <n> is killed: exceeded RLIMIT_CPU

[Jarle Greipsland <jarle%uninett.no@localhost>]

christos%zoulas.com@localhost (Christos Zoulas) writes:
> On Nov 13,  4:55pm, jarle%uninett.no@localhost (Jarle Greipsland) wrote:
> -- Subject: Re: Stream of kernel messages: pid <n> is killed: exceeded RLIMIT
> 
> | Also, this time the log messages seems to have stopped after just
> | these three messages, and no other processes than pid 0 seem to
> | have been affected.  Slightly suspicious that
> |  9223372036854775807==0x7FFFFFFFFFFFFFFF, and
> | 18446744073709551615==0xFFFFFFFFFFFFFFFF....
> |                                     -jarle
> | 
> check if in the update_rtime now is always greater than l->l_stime, if not,
> complain.
With the attached patch applied, the kernel now prints:

updatertime: now (6,13082990375156292405) < &l->l_stime->sec 
(7,2696175004034666709)
pid 0 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
WARNING: negative runtime; monotonic clock has gone backwards
updatertime: now (6,16614217696894460111) < &l->l_stime->sec 
(7,6227415493056243927)
updatertime: now (7,1062082572521342241) < &l->l_stime->sec 
(7,9122070055515699413)
updatertime: now (7,12178466383987892079) < &l->l_stime->sec 
(8,1499692050621368511)
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
stray isa irq 4
pid 0 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551614 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
stray isa irq 4
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
stray isa irq 4
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
stray isa irq 4
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807
pid 9 is killed: exceeded RLIMIT_CPU, runtm=18446744073709551615 
rlim_cur=9223372036854775807 rlim_max=9223372036854775807

Note, I'm not sure the comparision of the two bintime values is
done correctly, but it still produced some results.

                                        -jarle

Index: kern_synch.c
===================================================================
RCS file: /cvsroot/src/sys/kern/kern_synch.c,v
retrieving revision 1.296
diff -u -r1.296 kern_synch.c
--- kern_synch.c        6 Nov 2011 14:11:00 -0000       1.296
+++ kern_synch.c        13 Nov 2011 16:35:19 -0000
@@ -524,10 +524,14 @@
 void
 updatertime(lwp_t *l, const struct bintime *now)
 {
+       struct bintime *stime;
 
        if (__predict_false(l->l_flag & LW_IDLE))
                return;
-
+       stime = &l->l_stime;
+       if ((now->sec == stime->sec && now->frac < stime->frac) ||
+           now->sec < stime->sec)
+               log(LOG_NOTICE, "updatertime: now (%lu,%lu) < &l->l_stime->sec 
(%lu,%lu)\n", now->sec, now->frac, stime->sec, stime->frac);
        /* rtime += now - stime */
        bintime_add(&l->l_rtime, now);
        bintime_sub(&l->l_rtime, &l->l_stime);
@@ -1255,8 +1259,9 @@
                if (__predict_false(runtm >= rlim->rlim_cur)) {
                        if (runtm >= rlim->rlim_max) {
                                sig = SIGKILL;
-                               log(LOG_NOTICE, "pid %d is killed: %s\n",
-                                       p->p_pid, "exceeded RLIMIT_CPU");
+                               log(LOG_NOTICE, "pid %d is killed: %s, 
runtm=%lu rlim_cur=%lu rlim_max=%lu\n",
+                                       p->p_pid, "exceeded RLIMIT_CPU",
+                                       (unsigned long)runtm, (unsigned 
long)rlim->rlim_cur, (unsigned long)rlim->rlim_max);
                                uprintf("pid %d, command %s, is killed: %s\n",
                                        p->p_pid, p->p_comm,
                                        "exceeded RLIMIT_CPU");