###@###.### 2003-12-03

Legend
==============================================================
Attachment A below shows output of program "time.c" with
measurements which is subject of our consideration.

Attachment B below shows the current HotSpot implementation of
os::thread_cpu_time().

Attachment C below represents the program "time.c" used to
measure timing.

gethrvtime, gethrtime - Solaris Standard C Library Functions:
    gethrvtime() returns current high-resolution LWP virtual time.
    gethrtime() returns current high-resolution real time.

_lwp_info - Solaris System Call.
    _lwp_info() returns the time-accounting information of current LWP

thr_cpu_time - Copy of os::thread_cpu_time() implemented in HotSpot.
                It returns User + System CPU time of current LWP.
thr_cpu_utime - The same as thr_cpu_time but returns User CPU time only.

bratsk.sfbay - 2-cpu Ultra-60 sparc machine used for time measurements:
ss45998@bratsk uname -a
SunOS bratsk 5.9 Generic_112233-01 sun4u sparc SUNW,Ultra-60

==============================================================

In output below (Attachment A) we can see that thr_cpu_time()
consumes 220X CPU time of gethrvtime() to perform.
On Solaris Next x86 machine tomsk.sfbay this number is better: 66X.

This is a performance problem in JVMTI implementation of
GetCurrentThreadCpuTime() for Solaris.
It's because GetCurrentThreadCpuTime uses thread_cpu_time()
(see HS implementation of thread_cpu_time() in Attachment A below).
Measurements also show that it's better to use gethrvtime() instead.
The thread_cpu_time() returns time for any arbitrary thread (not current).
It'd be better to introduce a new function thread_current_cpu_time()
which should return CPU time for current thread.
The thread_current_cpu_time() should call gethrvtime() on Solaris.

There is some concern about turning On a Micro State Accounting
to make gethrvtime() to return nono-second accuracy. The ouput shows
that turning a Micro State Accounting On/Off effects both gethrvtime()
and thr_cpu_utime() in the same way. Also, the "time.c" program has
an example on how the user can turn On/Off a Micro State Accounting.

A similar performance problem may exist on Linux as well (worth to check).
It is because thread_cpu_time() on Linux is similar to that on Solaris.
(see it in the HotSpot os/linux/vm/os_linux.cpp).

Attachment A
============

ss45998@bratsk cc time.c
ss45998@bratsk a.out

Micro State Accounting: ON
--------------------------------------------------------
Timing using different approaches (write() in the loop):
gethrvtime (user only): 282427365 nsec
thr_cpu_utime (user only): 277559742 nsec
_lwp_info (user only): 280000000 nsec
thr_cpu_time (user + sys): 395032764 nsec
_lwp_info (user + sys): 370000000 nsec
gethrtime (wall clock): 2394217004 nsec

Time consumed by time measurement itself:
thr_cpu_time: 11767537862 nsec
_lwp_info: 500000000 nsec
gethrvtime: 51238103 nsec
gethrtime: 40828838 nsec

Comparison of current time stamps:
thr_cpu_utime: 4182836774 nsec
gethrvtime: 4182840990 nsec
lwp_info_utime: 3990000000 nsec
gethrvtime - thr_cpu_utime: 4216 nsec
gethrvtime - lwp_info_utime: 192840990 nsec
--------------------------------------------------------

Micro State Accounting: OFF
--------------------------------------------------------
Timing using different approaches (write() in the loop):
gethrvtime (user only): 190000000 nsec
thr_cpu_utime (user only): 240000000 nsec
_lwp_info (user only): 250000000 nsec
thr_cpu_time (user + sys): 310000000 nsec
_lwp_info (user + sys): 300000000 nsec
gethrtime (wall clock): 2319131609 nsec

Time consumed by time measurement itself:
thr_cpu_time: 11570000000 nsec
_lwp_info: 380000000 nsec
gethrvtime: 70000000 nsec
gethrtime: 42923640 nsec

Comparison of current time stamps:
thr_cpu_utime: 7640000000 nsec
gethrvtime: 7640000000 nsec
lwp_info_utime: 7640000000 nsec
gethrvtime - thr_cpu_utime: 0 nsec
gethrvtime - lwp_info_utime: 0 nsec
--------------------------------------------------------


Attachment B
============

Current HotSpot implementation of thread_cpu_time() in the file
os/solaris/vm/os_solaris.cpp (current sccs version: 1.302):

// thread_cpu_time(Thread *)
//
// Used by JVMPI and JVMTI code to get the user and system
// time of a thread. Returns elapsed time in nanoseconds or
// -1 on error.

const intptr_t thr_time_off = (intptr_t)(&((prusage_t *)(NULL))->pr_utime);
const intptr_t thr_time_size = (intptr_t)(&((prusage_t *)(NULL))->pr_ttime) -
                               (intptr_t)(&((prusage_t *)(NULL))->pr_utime);

jlong os::thread_cpu_time(Thread *thread) {
  char proc_name[64];
  int count;
  prusage_t prusage;
  jlong lwp_time;
  int fd;

  sprintf(proc_name, "/proc/%d/lwp/%d/lwpusage",
                     getpid(),
                     thread->osthread()->lwp_id());
  fd = open(proc_name, O_RDONLY);
  if ( fd == -1 ) return -1;

  do {
    count = pread(fd,
                  (void *)&prusage.pr_utime,
                  thr_time_size,
                  thr_time_off);
  } while (count < 0 && errno == EINTR);
  close(fd);
  if ( count < 0 ) return -1;
  
  lwp_time = (((jlong)prusage.pr_stime.tv_sec +
               (jlong)prusage.pr_utime.tv_sec) * (jlong)1000000000) +
               (jlong)prusage.pr_stime.tv_nsec +
               (jlong)prusage.pr_utime.tv_nsec;

  return(lwp_time);
}


Attachment C
============

This is the program which was used for time measurements below:

ss45998@bratsk cat time.c
#include <sys/time.h>
#include <sys/lwp.h>
#include <stdlib.h>
#include <stdio.h>
#include <fcntl.h>
#include <errno.h>
#include <unistd.h>
#include <procfs.h>

#define ITER_CNT 150000
#define ITER_CNT1 200000

static int arr[4000] = {0};

static int tmp_file;
static int cnt;
#define ACTION if ((++cnt/100000)*100000 == cnt) (void) system("sleep 1"); else (void) write(tmp_file, arr, sizeof(arr));
/* #define ACTION system("sleep 1\n"); */

void micro_state_accounting(int on) {
     char proc_ctl_fn[48];
     int procfd;

     printf("\nMicro State Accounting: %s\n",
             (on) ? "ON" : "OFF");

     /* Turn on micro state accounting, once per process */
     procfd = open("/proc/self/ctl", O_WRONLY);

     if (procfd >= 0) {
long ctl_op[2];

ctl_op[0] = (on) ? PCSET : PCUNSET;
ctl_op[1] = PR_MSACCT;

(void)write(procfd, ctl_op, sizeof(ctl_op));
(void)close(procfd);
     }
}

hrtime_t lwp_info_time() {
  struct lwpinfo buf;
  _lwp_info(&buf);
  return 1000000000 * (hrtime_t) (buf.lwp_utime.tv_sec + buf.lwp_stime.tv_sec)
                    + (hrtime_t) (buf.lwp_utime.tv_nsec + buf.lwp_stime.tv_nsec);
}

hrtime_t lwp_info_utime() {
  struct lwpinfo buf;
  _lwp_info(&buf);
  return 1000000000 * (hrtime_t) buf.lwp_utime.tv_sec + (hrtime_t) buf.lwp_utime.tv_nsec;
}

const intptr_t thr_time_off = (intptr_t)(&((prusage_t *)(NULL))->pr_utime);
const intptr_t thr_time_size = (intptr_t)(&((prusage_t *)(NULL))->pr_ttime) -
                               (intptr_t)(&((prusage_t *)(NULL))->pr_utime);

/* Returns SYSTEM + USER time */
hrtime_t thread_cpu_time() {
  char proc_name[64];
  int count;
  prusage_t prusage;
  hrtime_t lwp_time;
  int fd;

  sprintf(proc_name, "/proc/self/lwp/%d/lwpusage", _lwp_self());
  fd = open(proc_name, O_RDONLY);
  if (fd == -1) return -1;

  do { count = pread(fd, (void *) &prusage.pr_utime,
                         thr_time_size, thr_time_off);
  } while (count < 0 && errno == EINTR);
  close(fd);
  if ( count < 0 ) return -1;
  
  lwp_time = (((hrtime_t)prusage.pr_stime.tv_sec +
               (hrtime_t)prusage.pr_utime.tv_sec) * 1000000000) +
               (hrtime_t)prusage.pr_stime.tv_nsec +
               (hrtime_t)prusage.pr_utime.tv_nsec;

  return(lwp_time);
}

/* Returns USER time only */
hrtime_t thread_cpu_utime() {
  char proc_name[64];
  int count;
  prusage_t prusage;
  hrtime_t lwp_time;
  int fd;

  sprintf(proc_name, "/proc/self/lwp/%d/lwpusage", _lwp_self());
  fd = open(proc_name, O_RDONLY);
  if (fd == -1) return -1;

  do { count = pread(fd, (void *) &prusage.pr_utime,
                         thr_time_size, thr_time_off);
  } while (count < 0 && errno == EINTR);
  close(fd);
  if ( count < 0 ) return -1;
  
  lwp_time = ((hrtime_t)prusage.pr_utime.tv_sec) * 1000000000 +
              (hrtime_t)prusage.pr_utime.tv_nsec;

  return(lwp_time);
}

hrtime_t gethr() {
  hrtime_t beg, end;
  int i;

  beg = gethrtime();
  for (i = 0; i < ITER_CNT; i++) {
          ACTION;
  }
  end = gethrtime();

  return (hrtime_t) (end - beg);
}

hrtime_t gethrv() {
  hrtime_t beg, end;
  int i;

  beg = gethrvtime();
  for (i = 0; i < ITER_CNT; i++) {
          ACTION;
  }
  end = gethrvtime();

  return (hrtime_t) (end - beg);
}

hrtime_t thr_utime() {
  hrtime_t beg, end;
  int i;

  beg = thread_cpu_utime();
  for (i = 0; i < ITER_CNT; i++) {
          ACTION;
  }
  end = thread_cpu_utime();
  return (hrtime_t) (end - beg);
}

hrtime_t thr_time() {
  hrtime_t beg, end;
  int i;

  beg = thread_cpu_time();
  for (i = 0; i < ITER_CNT; i++) {
          ACTION;
  }
  end = thread_cpu_time();
  return (hrtime_t) (end - beg);
}

hrtime_t lwp_inf() {
  time_t beg, end;
  int i;

  beg = lwp_info_time();
  for (i = 0; i < ITER_CNT; i++) {
          ACTION;
  }
  end = lwp_info_time();

  return (hrtime_t) (end - beg);
}

hrtime_t lwp_uinf() {
  time_t beg, end;
  int i;

  beg = lwp_info_utime();
  for (i = 0; i < ITER_CNT; i++) {
          ACTION;
  }
  end = lwp_info_utime();

  return (hrtime_t) (end - beg);
}

/*
 * Timing of time measurement
 */


hrtime_t thr_time_time() {
  hrtime_t beg, end;
  int i;

  beg = thread_cpu_time();
  for (i = 0; i < ITER_CNT1; i++) {
       end = thread_cpu_time();
  }
  return (hrtime_t) (end - beg);
}

hrtime_t gethr_time() {
  hrtime_t beg, end;
  int i;

  beg = gethrtime();
  for (i = 0; i < ITER_CNT1; i++) {
       end = gethrtime();
  }
  return (hrtime_t) (end - beg);
}

hrtime_t gethrv_time() {
  hrtime_t beg, end;
  int i;

  beg = gethrvtime();
  for (i = 0; i < ITER_CNT1; i++) {
       end = gethrvtime();
  }
  return (hrtime_t) (end - beg);
}

hrtime_t lwp_inf_time() {
  time_t beg, end;
  int i;

  beg = lwp_info_time();
  for (i = 0; i < ITER_CNT1; i++) {
       end = lwp_info_time();
  }
  return (hrtime_t) (end - beg);
}

void compare_time() {
  hrtime_t time1, time2, time3;
  int i;

  time1 = thread_cpu_utime();
  time2 = gethrvtime();
  time3 = lwp_info_utime();

  printf("\nComparison of current time stamps:\n");
  printf("thr_cpu_utime: %16llu nsec\n", time1);
  printf("gethrvtime: %16llu nsec\n", time2);
  printf("lwp_info_utime: %16llu nsec\n", time3);
  printf("gethrvtime - thr_cpu_utime: %16lld nsec\n", time2 - time1);
  printf("gethrvtime - lwp_info_utime: %16lld nsec\n", time2 - time3);
  return;
}

void timing() {
  printf("--------------------------------------------------------\n");
  printf("Timing using different approaches (write() in the loop):\n");
  printf("gethrvtime (user only): %16llu nsec\n", gethrv());
  printf("thr_cpu_utime (user only): %16llu nsec\n", thr_utime());
  printf("_lwp_info (user only): %16llu nsec\n", lwp_uinf());
  printf("thr_cpu_time (user + sys): %16llu nsec\n", thr_time());
  printf("_lwp_info (user + sys): %16llu nsec\n", lwp_inf());
  printf("gethrtime (wall clock): %16llu nsec\n", gethr());

  printf("\nTime consumed by time measurement itself:\n");
  printf("thr_cpu_time: %16llu nsec\n", thr_time_time());
  printf("_lwp_info: %16llu nsec\n", lwp_inf_time());
  printf("gethrvtime: %16llu nsec\n", gethrv_time());
  printf("gethrtime: %16llu nsec\n", gethr_time());

  compare_time();
  printf("--------------------------------------------------------\n");
}

void main() {
  char tmp_fname[48];
  
  sprintf(tmp_fname, "/tmp/tmp_file%d", getpid());
  tmp_file = open(tmp_fname, O_WRONLY);

  micro_state_accounting(1);
  timing();

  micro_state_accounting(0);
  timing();
  (void)close(tmp_file);
}