Re: [Patch] Losing many samples when profiling multiple JVMs

Thanks, William,

I added ppc support in the test case and cleaned up the code a bit.

Your patch works for me, but I have one concern with this part;

>     && ((*it).second->pid && (*it).second->pid == event->mmap.pid)

(*it).second->pid is set to non zero only for vdso and anon,
so this code will prevent all_images_map from working for normal files.
Is it what you intended?


Rei Odaira


2015-07-07 15:31 GMT-05:00 William Cohen <[email protected]>:

> On 06/29/2015 01:10 PM, 大平怜 wrote:
> > Hello,
> >
> > I created a small test case (attached) to reproduce this problem.
> > This code assumes x86.
> >
> >> gcc -O2 -o oprofile_anon_remap_test oprofile_anon_remap_test.c
> >> operf ./oprofile_anon_remap_test 10000
> >> opreport
> >
> > opreport should print many samples hit at "anon".  However, it does not
> > in the current version, and if you look at
> oprofile_data/samples/operf.log,
> > many samples fall into "Nr. samples lost due to no permanent mapping".
> >
> >
> > Regards,
> > Rei Odaira
>
>
>
> Hi,
>
> Sorry, it has taken me a while to get back to this.
>
> I am including Andrew Haley on this email because he works on the JVM
> and has used oprofile to monitor performance of JVM generated code.
> He might be able to give some feedback this issue and whether the
> proposed fix is sufficient.
>
> Thanks for the reproducer code. It was very helpful.  I have modified the
> reproducer to be more portable to other machines and added support for
> arm and arm64.  It is trivial to add support for additional processors.
>
> Below is example compile and run of the code which exhibits the problem
> you observed.
>
>
> [wcohen@santana ~]$ gcc -g -o oprofile_anon_remap_testa
> oprofile_anon_remap_testa.c
> [wcohen@santana ~]$ operf ./oprofile_anon_remap_testa 10000
> operf: Profiler started
> * * * * WARNING: Profiling rate was throttled back by the kernel * * * *
> The number of samples actually recorded is less than expected, but is
> probably still statistically valid.  Decreasing the sampling rate is the
> best option if you want to avoid throttling.
>
> WARNING: Lost samples detected! See
> /home/wcohen/oprofile_data/samples/operf.log for details.
> Lowering the sampling rate may reduce or eliminate lost samples.
> See the '--events' option description in the operf man page for help.
>
> Profiling done.
> [wcohen@santana ~]$ opreport
> Using /home/wcohen/oprofile_data/samples/ for samples directory.
>
> WARNING! Some of the events were throttled. Throttling occurs when
> the initial sample rate is too high, causing an excessive number of
> interrupts.  Decrease the sampling frequency. Check the directory
> /home/wcohen/oprofile_data/samples/current/stats/throttled
> for the throttled event names.
>
>
> WARNING: Lost samples detected! See
> /home/wcohen/oprofile_data/samples/operf.log for details.
> CPU: Intel Ivy Bridge microarchitecture, speed 3300 MHz (estimated)
> Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit
> mask of 0x00 (No unit mask) count 100000
> CPU_CLK_UNHALT...|
>   samples|      %|
> ------------------
>       800 100.000 oprofile_anon_remap_testa
>         CPU_CLK_UNHALT...|
>           samples|      %|
>         ------------------
>               447 55.8750 oprofile_anon_remap_testa
>               207 25.8750 libc-2.21.so
>               141 17.6250 kallsyms
>                 3  0.3750 kvm
>                 2  0.2500 ld-2.21.so
>
>
> As mentioned in earlier email it looks like oprofile tracking of mmaps
> is getting confused by the large mmap getting carved into smaller
> mmaps.  The changes in the mmap are likely being done by the jvm to
> mark regions as executable.  For oprofile's purposes it is not that
> important to track changes on that level.  If a new mapping falls
> within an existing anon mapping, there is no need create a new
> mapping.  Attached is a patch that discards those mapping changes
> within existing mappings. I have also built a fedora 22 rpm with the
> git checkout and this patch
> at:http://koji.fedoraproject.org/koji/taskinfo?taskID=10313853.  It
> seems to provide saner output for the reproducer
>
>
> [wcohen@santana ~]$ operf ./oprofile_anon_remap_testa 10000
> operf: Profiler started
> * * * * WARNING: Profiling rate was throttled back by the kernel * * * *
> The number of samples actually recorded is less than expected, but is
> probably still statistically valid.  Decreasing the sampling rate is the
> best option if you want to avoid throttling.
>
> Profiling done.
> [wcohen@santana ~]$ opreport
> Using /home/wcohen/oprofile_data/samples/ for samples directory.
>
> WARNING! Some of the events were throttled. Throttling occurs when
> the initial sample rate is too high, causing an excessive number of
> interrupts.  Decrease the sampling frequency. Check the directory
> /home/wcohen/oprofile_data/samples/current/stats/throttled
> for the throttled event names.
>
> CPU: Intel Ivy Bridge microarchitecture, speed 3300 MHz (estimated)
> Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit
> mask of 0x00 (No unit mask) count 100000
> CPU_CLK_UNHALT...|
>   samples|      %|
> ------------------
>    394553 100.000 oprofile_anon_remap_testa
>         CPU_CLK_UNHALT...|
>           samples|      %|
>         ------------------
>            393758 99.7985 anon (tgid:16764
> range:0x7ffa7d680000-0x7ffa7ea81fff)
>               456  0.1156 oprofile_anon_remap_testa
>               185  0.0469 libc-2.21.so
>               152  0.0385 kallsyms
>                 1 2.5e-04 kvm
>                 1 2.5e-04 ld-2.21.so
>
>
>
> -Will
>
>

------------------------------------------------------------------------------
Don't Limit Your Business. Reach for the Cloud.
GigeNET's Cloud Solutions provide you with the tools and support that
you need to offload your IT needs and focus on growing your business.
Configured For All Businesses. Start Your Cloud Today.
https://www.gigenetcloud.com/

_______________________________________________
oprofile-list mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/oprofile-list

/*
 *  This test case is to make sure that oprofile collects the samples
 *  hit at the extended region of an anon buffer.
 */

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sys/mman.h>
#include <unistd.h>

typedef int (*func_t)(void);

/* If MINIMUM_BUFFER_SIZE is too small (like 4 KB), the anon buffer can
   overlap with the memory region of other library files such as ld-...,
   so any samples hit at the anon buffer are incorrectly attributed to
   the library files.  10 MB is large enough on Ubuntu 14.04/x86. */
#define MINIMUM_BUFFER_SIZE (10 * 1024 * 1024)

#if defined (__i386__) || defined (__x86_64__)
/* add $0x1,%eax */
char add_inst[3]={0x83, 0xc0, 0x01};
/* retq */
char ret_inst[1]={0xc3};
#elif defined(__arm__)
/* add r0, r0, #1 */
char add_inst[4]={0x01, 0x00, 0x80, 0xe2};
/* bx lr */
char ret_inst[4]={0x1e, 0xff, 0x2f, 0xe1};
#elif defined(__aarch64__)
/* add x0, x0, #1 */
char add_inst[4]={0x00, 0x04, 0x00, 0x91};
/* ret */
char ret_inst[4]={0xc0, 0x03, 0x5f, 0xd6};
#elif defined(__PPC__)
#if defined(__LITTLE_ENDIAN__)
/* addi r3,r3,1 */
char add_inst[4]={0x01, 0x00, 0x63, 0x38};
/* blr */
char ret_inst[4]={0x20, 0x00, 0x80, 0x4e};
#else
/* addi r3,r3,1 */
char add_inst[4]={0x38, 0x63, 0x00, 0x01};
/* blr */
char ret_inst[4]={0x4e, 0x80, 0x00, 0x20};
#endif
#else
  error unsupported architecture
#endif

/* Fill the extended region of the buffer with add and ret.

buffer                    func_start_addr
|                         |
v                         v
<-- initial_buffer_size -->
<-----            remapped_buffer_size                ----->
|.........................|add add add add add ... add ret|
 */
static func_t
initialize_anon_func(char *buffer, size_t initial_buffer_size, size_t remapped_buffer_size)
{
  char *func_start_addr = buffer + initial_buffer_size;
  char *func_end_addr = buffer + remapped_buffer_size;
  char *cursor;
  int add_size = sizeof(add_inst);
  int ret_size = sizeof(ret_inst);

  for (cursor = func_start_addr; cursor + add_size + ret_size <= func_end_addr; cursor += add_size) {
    memcpy(cursor, add_inst, add_size);
  }
  memcpy(cursor, ret_inst, ret_size);

  return (func_t)func_start_addr;
}

int
main(int argc, char *argv[])
{
  void *buffer;
  int ret;
  size_t page_size;
  size_t initial_buffer_size;
  size_t remapped_buffer_size;
  func_t anon_func;
  int iter;
  int iter_max;

  if (argc != 2) {
    fprintf(stderr, "Usage: oprofile_anon_remap_test <num iterations>\n");
    exit(1);
  }
  iter_max = atoi(argv[1]);

  page_size = (size_t)sysconf(_SC_PAGESIZE);
  initial_buffer_size = (MINIMUM_BUFFER_SIZE / page_size + 1) * page_size;
  /* remapped_buffer_size must be larger than initial_buffer_size */
  remapped_buffer_size = initial_buffer_size * 2;

  /* First, reserve remapped_buffer_size bytes of virtual memory.
     Don't specify PROT_EXEC. This mmap is to increase the chance of
     the following two mmap's to succeed. */
  buffer = mmap(NULL, remapped_buffer_size, PROT_NONE, MAP_PRIVATE | MAP_ANON | MAP_NORESERVE, 0, 0);
  if (buffer == MAP_FAILED) {
    perror("mmap");
    exit(1);
  }

  /* This munmap might be unnecessary. */
  ret = munmap(buffer, remapped_buffer_size);
  if (ret == -1) {
    perror("munmap");
    exit(1);
  }

  /* Next, mmap initial_buffer_size bytes from the "buffer" address
     with PROT_EXEC. The kernel will notify oprofile of the new
     executable mmap region.
  */
  buffer = mmap(buffer, initial_buffer_size, PROT_EXEC | PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANON | MAP_FIXED, 0, 0);
  if (buffer == MAP_FAILED) {
    perror("second mmap");
    exit(1);
  }

  /* Lastly, extend the buffer to remapped_buffer_size bytes with PROT_EXEC.
     The kernel will notify oprofile again.
     mremap(2) should be used instead? */
  buffer = mmap(buffer, remapped_buffer_size, PROT_EXEC | PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANON | MAP_FIXED, 0, 0);
  if (buffer == MAP_FAILED) {
    perror("third mmap");
    exit(1);
  }

  anon_func = initialize_anon_func(buffer, initial_buffer_size, remapped_buffer_size);

  /* Execute the function generated in the extended region of the buffer
     many times so that a number of samples hit there. */
  for (iter = 0; iter < iter_max; iter++) {
    anon_func();
  }
}