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

On 07/09/2015 06:14 PM, 大平怜 wrote:
> Thanks, William,
> 
> I added ppc support in the test case and cleaned up the code a bit.

Hi,

Thanks for the addition to the test for ppc. Does that work for both 32-bit and 64-bit ppc compilation?  I added an explicit exit(EXIT_SUCCESS) at the end of main to make sure that the test doesn't pass some random value back on exit.

> 
> 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?

The previous code never recorded pid value.  This was to avoid having multiple copies of the same range for each process.  The patch attempted to preserve that behavior for regular file based memory maps, but for anon regions want to keep track of what process they were in because they are not shared across processes.  However, your analysis does point out a flaw with the conditional.  It looks like it should be:

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

Attached is a revised version of the patch.  Could you give that a try?

Thanks again.

-Will
> 
> 
> Rei Odaira
> 
> 
> 2015-07-07 15:31 GMT-05:00 William Cohen <[email protected] <mailto:[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 <http://libc-2.21.so>
>                   141 17.6250 kallsyms
>                     3  0.3750 kvm
>                     2  0.2500 ld-2.21.so <http://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 <http://libc-2.21.so>
>                   152  0.0385 kallsyms
>                     1 2.5e-04 kvm
>                     1 2.5e-04 ld-2.21.so <http://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
>

------------------------------------------------------------------------------
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

diff --git a/libperf_events/operf_process_info.h b/libperf_events/operf_process_info.h
index f98591f..3138ffb 100644
--- a/libperf_events/operf_process_info.h
+++ b/libperf_events/operf_process_info.h
@@ -25,6 +25,7 @@ struct operf_mmap {
 	u64 start_addr;
 	u64 end_addr;
 	u64 pgoff;
+	u32 pid;
 	bool is_anon_mapping;
 	bool is_hypervisor;
 	char filename[PATH_MAX];
diff --git a/libperf_events/operf_utils.cpp b/libperf_events/operf_utils.cpp
index 90a0765..7e6ed76 100644
--- a/libperf_events/operf_utils.cpp
+++ b/libperf_events/operf_utils.cpp
@@ -275,7 +275,10 @@ static void __handle_mmap_event(event_t * event)
 	range = all_images_map.equal_range(image_basename);
 	for (it = range.first; it != range.second; it++) {
 		if (((strcmp((*it).second->filename, image_basename.c_str())) == 0)
-				&& ((*it).second->start_addr == event->mmap.start)) {
+		    && ((*it).second->pid == 0 || (*it).second->pid == event->mmap.pid)
+		    && ((*it).second->start_addr <= event->mmap.start
+			&& ((*it).second->end_addr >= event->mmap.start + event->mmap.len)))
+		{
 			mapping = (*it).second;
 			break;
 		}
@@ -291,12 +294,15 @@ static void __handle_mmap_event(event_t * event)
 		 */
 		if (mapping->filename[0] == '[') {
 			mapping->is_anon_mapping = true;
+			mapping->pid = event->mmap.pid;
 		} else if ((strncmp(mapping->filename, "//anon",
 		                    strlen("//anon")) == 0)) {
 			mapping->is_anon_mapping = true;
+			mapping->pid = event->mmap.pid;
 			strcpy(mapping->filename, "anon");
 		} else if ((strncmp(mapping->filename, "/anon_hugepage",
 		                    strlen("/anon_hugepage")) == 0)) {
+			mapping->pid = event->mmap.pid;
 			mapping->is_anon_mapping = true;
 			strcpy(mapping->filename, "anon");
 		}

/*
 *  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();
  }
  exit(EXIT_SUCCESS);
}