Forum: Ruby-core [ruby-trunk - Bug #7500][Open] Improve GC profiler timings on linux

Issue #7500 has been reported by tmm1 (Aman Gupta).

----------------------------------------
Bug #7500: Improve GC profiler timings on linux
https://bugs.ruby-lang.org/issues/7500

Author: tmm1 (Aman Gupta)
Status: Open
Priority: Normal
Assignee:
Category:
Target version: 2.0.0
ruby -v: ruby 2.0.0dev (2012-12-03 trunk 38149) [x86_64-darwin12.2.0]


On linux kernels, getrusage()'s precision depends on the value of HZ 
when the kernel was compiled. By default, HZ=250 provides a 4ms 
granularity.

This patch uses clock_gettime() with CLOCK_PROCESS_CPUTIME_ID when 
available, which provides a 1ns precision on linux.

Issue #7500 has been updated by authorNari (Narihiro Nakamura).

Category set to core
Assignee set to authorNari (Narihiro Nakamura)


----------------------------------------
Bug #7500: Improve GC profiler timings on linux
https://bugs.ruby-lang.org/issues/7500#change-34340

Author: tmm1 (Aman Gupta)
Status: Open
Priority: Normal
Assignee: authorNari (Narihiro Nakamura)
Category: core
Target version: 2.0.0
ruby -v: ruby 2.0.0dev (2012-12-03 trunk 38149) [x86_64-darwin12.2.0]


On linux kernels, getrusage()'s precision depends on the value of HZ 
when the kernel was compiled. By default, HZ=250 provides a 4ms 
granularity.

This patch uses clock_gettime() with CLOCK_PROCESS_CPUTIME_ID when 
available, which provides a 1ns precision on linux.

Issue #7500 has been updated by kosaki (Motohiro KOSAKI).


AFAIK, clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &ts) return time included 
kernel running. So, clock_gettime() and ru_utime of getrusage() aren't 
equivalent.

----------------------------------------
Bug #7500: Improve GC profiler timings on linux
https://bugs.ruby-lang.org/issues/7500#change-34341

Author: tmm1 (Aman Gupta)
Status: Open
Priority: Normal
Assignee: authorNari (Narihiro Nakamura)
Category: core
Target version: 2.0.0
ruby -v: ruby 2.0.0dev (2012-12-03 trunk 38149) [x86_64-darwin12.2.0]


On linux kernels, getrusage()'s precision depends on the value of HZ 
when the kernel was compiled. By default, HZ=250 provides a 4ms 
granularity.

This patch uses clock_gettime() with CLOCK_PROCESS_CPUTIME_ID when 
available, which provides a 1ns precision on linux.

Issue #7500 has been updated by kosaki (Motohiro KOSAKI).


And, if i understand the kernel source correctly, getrusage() and 
get_time(CLOCK_PROCESS_CPUTIME_ID) use the same clock source. So, I 
doubt this patch improve time accuracy.

Do anyone have a test result?
----------------------------------------
Bug #7500: Improve GC profiler timings on linux
https://bugs.ruby-lang.org/issues/7500#change-34342

Author: tmm1 (Aman Gupta)
Status: Open
Priority: Normal
Assignee: authorNari (Narihiro Nakamura)
Category: core
Target version: 2.0.0
ruby -v: ruby 2.0.0dev (2012-12-03 trunk 38149) [x86_64-darwin12.2.0]


On linux kernels, getrusage()'s precision depends on the value of HZ 
when the kernel was compiled. By default, HZ=250 provides a 4ms 
granularity.

This patch uses clock_gettime() with CLOCK_PROCESS_CPUTIME_ID when 
available, which provides a 1ns precision on linux.

Issue #7500 has been updated by tmm1 (Aman Gupta).


 tmm1@fe19:~$ uname -a
 Linux fe19.rs.github.com 3.5.0-17-generic #28-Ubuntu SMP Tue Oct 9 
19:31:23 UTC 2012 x86_64 GNU/Linux

 tmm1@fe19:~$ cat timings.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;
 }

 double clock_time() {
 struct timespec ts;

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

 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("clock_gettime() before: %f\n", clock_time());
 for (n=0; n<10000; n++) pow(2, 2048);
 printf("clock_gettime() after: %f\n", clock_time());
 }

 tmm1@fe19:~$ gcc -o timings timings.c -lrt

 tmm1@fe19:~$ ./timings
 getrusage() before: 0.000000
 getrusage() after: 0.000000
 clock_gettime() before: 0.001244
 clock_gettime() after: 0.001358

----------------------------------------
Bug #7500: Improve GC profiler timings on linux
https://bugs.ruby-lang.org/issues/7500#change-34386

Author: tmm1 (Aman Gupta)
Status: Open
Priority: Normal
Assignee: authorNari (Narihiro Nakamura)
Category: core
Target version: 2.0.0
ruby -v: ruby 2.0.0dev (2012-12-03 trunk 38149) [x86_64-darwin12.2.0]


On linux kernels, getrusage()'s precision depends on the value of HZ 
when the kernel was compiled. By default, HZ=250 provides a 4ms 
granularity.

This patch uses clock_gettime() with CLOCK_PROCESS_CPUTIME_ID when 
available, which provides a 1ns precision on linux.

Issue #7500 has been updated by tmm1 (Aman Gupta).


Increasing the number of iterations shows the 4ms granularity.

  tmm1@fe19:~$ grep loops timings.c
  int loops = 1000000;
      for (n=0; n<loops; n++) pow(2, 2048);
      for (n=0; n<loops; n++) pow(2, 2048);

  tmm1@fe19:~$ gcc -o timings timings.c -lrt && ./timings
  getrusage() before: 0.000000
  getrusage() after: 0.004000
  clock_gettime() before: 0.006966
  clock_gettime() after: 0.010733

----------------------------------------
Bug #7500: Improve GC profiler timings on linux
https://bugs.ruby-lang.org/issues/7500#change-34387

Author: tmm1 (Aman Gupta)
Status: Open
Priority: Normal
Assignee: authorNari (Narihiro Nakamura)
Category: core
Target version: 2.0.0
ruby -v: ruby 2.0.0dev (2012-12-03 trunk 38149) [x86_64-darwin12.2.0]


On linux kernels, getrusage()'s precision depends on the value of HZ 
when the kernel was compiled. By default, HZ=250 provides a 4ms 
granularity.

This patch uses clock_gettime() with CLOCK_PROCESS_CPUTIME_ID when 
available, which provides a 1ns precision on linux.