From: "sax (Eric Saxby)" <sax@...>
Date: 2013-08-21T11:12:04+09:00
Subject: [ruby-core:56764] [ruby-trunk - Bug #8805] Ruby GC::Profiler	returns incorrect info on Solaris (and relatives)


Issue #8805 has been updated by sax (Eric Saxby).


I grabbed the c test code from the other ticket, and with some changes got these results:

> cat ./timing.c
#include <stdlib.h>
#include <stdio.h>
#include <sys/resource.h>
#include <time.h>
#include <math.h>

double getrusage_time() {
                struct rusage usage;
                struct timeval time;
                getrusage(RUSAGE_SELF, &usage);
                time = usage.ru_utime;
                return time.tv_sec + time.tv_usec * 1e-6;
}

void print_clock_res(clock_id) {
        int rc;
        struct timespec res;

        rc = clock_getres(clock_id, &res);
        if (rc == 0)
                printf("clock_res() for %d: %ldns\n", clock_id, res.tv_nsec);
}

double clock_time(clock_id) {
                struct timespec ts;

                if (clock_gettime(clock_id, &ts) == 0) {
                                return ts.tv_sec + ts.tv_nsec * 1e-9;
                }
                return 0.0;
}

void print_clock_time(clock_id) {
    int n;

                printf("clock_gettime() for %d before: %f\n", clock_id, clock_time(clock_id));
                for (n=0; n<10000; n++) pow(2, 2048);
                printf("clock_gettime() for %d after: %f\n", clock_id, clock_time(clock_id));
}

int main() {
                int n;

                printf("getrusage() before: %f\n", getrusage_time());
                for (n=0; n<10000; n++) pow(2, 2048);
                printf("getrusage() after: %f\n", getrusage_time());

    printf("\nclock_gettime() CLOCK_HIGHRES\n");

    print_clock_res(CLOCK_HIGHRES);
    print_clock_time(CLOCK_HIGHRES);

    printf("\nclock_gettime() CLOCK_PROCESS_CPUTIME_ID\n");

    print_clock_res(CLOCK_PROCESS_CPUTIME_ID);
    print_clock_time(CLOCK_PROCESS_CPUTIME_ID);

    printf("\nclock_gettime() CLOCK_THREAD_CPUTIME_ID\n");

    print_clock_res(CLOCK_THREAD_CPUTIME_ID);
    print_clock_time(CLOCK_THREAD_CPUTIME_ID);

    printf("\nclock_gettime() CLOCK_MONOTONIC\n");

    print_clock_res(CLOCK_MONOTONIC);
    print_clock_time(CLOCK_MONOTONIC);

}


> gcc -o timing timing.c -lrt

> ./timing
getrusage() before: 0.000382
getrusage() after: 0.000432

clock_gettime() CLOCK_HIGHRES
clock_res() for 4: 20ns
clock_gettime() for 4 before: 3140535.103844
clock_gettime() for 4 after: 3140535.103877

clock_gettime() CLOCK_PROCESS_CPUTIME_ID
clock_gettime() for 5 before: 0.000000
clock_gettime() for 5 after: 0.000000

clock_gettime() CLOCK_THREAD_CPUTIME_ID
clock_gettime() for 2 before: 0.000000
clock_gettime() for 2 after: 0.000000

clock_gettime() CLOCK_MONOTONIC
clock_res() for 4: 20ns
clock_gettime() for 4 before: 3140535.103960
clock_gettime() for 4 after: 3140535.103990
----------------------------------------
Bug #8805: Ruby GC::Profiler returns incorrect info on Solaris (and relatives)
https://bugs.ruby-lang.org/issues/8805#change-41307

Author: sax (Eric Saxby)
Status: Open
Priority: Normal
Assignee: 
Category: core
Target version: 
ruby -v: ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-solaris2.11]
Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN


We use SmartOS as our deployment platform, and noticed when attempting to roll out Ruby 2.0.0-p247 to some SmartOS hosts that garbage collection info is broken with integrations such as New Relic. Investigating further, we found that GC::Profiler.total_time always returns 0.0.

>> GC::Profiler.enable
=> nil
>> GC.start
=> nil
>> GC::Profiler.total_time
=> 0.0

It may be related to this issue: https://bugs.ruby-lang.org/issues/7500 where the mechanism by which the profiler gets timestamps from the OS.


-- 
http://bugs.ruby-lang.org/