[Bugme-janitors] [Bug 23652] New: procfs: /proc/<pid>/stat utime stops incrementing, stime starts incrementing

bugzilla-daemon at bugzilla.kernel.org bugzilla-daemon at bugzilla.kernel.org
Tue Nov 23 10:23:51 PST 2010


https://bugzilla.kernel.org/show_bug.cgi?id=23652

           Summary: procfs: /proc/<pid>/stat utime stops incrementing,
                    stime starts incrementing
           Product: File System
           Version: 2.5
    Kernel Version: 2.6.32-25-generic
          Platform: All
        OS/Version: Linux
              Tree: Mainline
            Status: NEW
          Severity: normal
          Priority: P1
         Component: Other
        AssignedTo: fs_other at kernel-bugs.osdl.org
        ReportedBy: mstemm at cloudmark.com
        Regression: No


I noticed that for a cpu-bound test program I had written,
getrusage(RUSAGE_SELF, ...)'s ru_utime would stop incrementing, reliably, after
between 261 and 262 seconds of cpu time.

Here is a simple test program that exhibits this behavior:

#include <stdio.h>
#include <assert.h>
#include <sys/time.h>
#include <sys/resource.h>

int main(int argc, char *argv[])
{
    struct rusage before;
    int count = 0;

    while(1) {
        count++;
        if (count > 5000000) {
            count=0;
            assert(getrusage(RUSAGE_SELF, &before)==0);
            printf("*****Before=%d sec %d usec\n", before.ru_utime.tv_sec,
before.ru_utime.tv_usec);
        }
    }
}

In the program's output, I see that ru_utime stops incrementing with sec=261,
and usec=some variable number, for example:

*****Before=261 sec 796361 usec
*****Before=261 sec 804361 usec
*****Before=261 sec 812362 usec
*****Before=261 sec 820362 usec
*****Before=261 sec 828363 usec
*****Before=261 sec 836363 usec
*****Before=261 sec 844364 usec
*****Before=261 sec 844364 usec
*****Before=261 sec 844364 usec
*****Before=261 sec 844364 usec
*****Before=261 sec 844364 usec
*****Before=261 sec 844364 usec


When I run this program and periodically cat /proc/<pid>/stat, what I see is
that utime stops incrementing and stime starts incrementing, for example:


$ while true; do sleep 1; cat /proc/5926/stat; done
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 25387 46 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513719 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 25487 46 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513719 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 25585 47 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513719 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 25684 48 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513720 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 25784 48 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513733 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 25884 48 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513719 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 25984 48 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513733 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 26085 48 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513719 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 26184 50 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513719 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 26184 149 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513719 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 26184 250 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513720 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 26184 350 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513733 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 26184 450 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513725 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 26184 550 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513733 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 26184 651 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513733 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 26184 751 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513733 0 0 0 0 0 0 0 17 1 0 0 0 0 0
5926 (foo) R 936 5926 936 34833 5926 4194304 163 0 0 0 26184 852 0 0 20 0 1 0
43456557 1679360 91 4294967295 134512640 134514112 3213945872 3213945600
134513719 0 0 0 0 0 0 0 17 1 0 0 0 0 0

This is the only major program running, and it's not swapping or anything.

My kernel information is:

$ cat /proc/version
Linux version 2.6.32-25-generic (buildd at palmer) (gcc version 4.4.3 (Ubuntu
4.4.3-4ubuntu5) ) #45-Ubuntu SMP Sat Oct 16 19:48:22 UTC 2010

This is not running as a virtual machine.

Let me know if you need more information, or if I'm misunderstanding the
allocation between user and system time, or if I should be filing this bug with
ubuntu instead.

-- 
Configure bugmail: https://bugzilla.kernel.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are watching the assignee of the bug.


More information about the Bugme-janitors mailing list