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

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

2015-06-23 15:00 GMT-05:00 大平怜 <[email protected]>:

> Hi Will,
>
> > Are the small sized maps always zero-sized?
>
> No, it does not seem to have anything to do with zero-sized maps.
>
> > Could you run operf with the following option on the problem testcase to
> see if there are any lines with "end addr: 0"?
> >
> > operf -V convert <command_being_measured>
>
> I did not find any lines with "end addr: 0".
>
> >>> However, what happens when two different processes have anon regions
> that have the same starting address and are the same size?
> >>
> >> In that case, they share the same operf_mmap struct.  Is there any
> problem in it?
> >
> > For read only regions of regular executable code this is okay.  However,
> if the anon memory is for different processes, they are likely to have
> different contents and it isn't a good idea to assume they are the same.
> That what the patch I sent was trying to address, keep them separate so the
> contents don't get confused.
>
> OK.... To me, it looks like operf_mmap does not contain any information
> that can cause problems when shared across multiple processes as anon
> (pgoff might cause a problem, but it is not used anywhere), and it is used
> just to pass the information to operf_transient in __get_operf_trans().
> But to be honest, I don't understand every detail, so I don't insist too
> much on it.
>
> >> I have just git-cloned oprofile-test but could not figure out how to
> run it.  Could you help me create a test case?
> >
> > I can help you get a test written for oprofile-test.  For the time being
> it would be great if you just have some steps that you used to create the
> problem.
>
> I encountered this problem when running a really large Java application
> with 100 GB of data set.  I'll write some notes, but it would not be
> realistic for others to reproduce it, so I'll work on creating a new tiny
> test case.
>
>
> Thanks,
> Rei Odaira
>
> 2015-06-22 20:32 GMT-05:00 William Cohen <[email protected]>:
>
>> On 06/22/2015 07:19 PM, 大平怜 wrote:
>> > Thanks for the investigation, Will,
>> >
>> > Unfortunately, your patch does not solve my problem. In my previous
>> email, I mentioned only the situation where multiple processes have
>> different-sized anon regions that happen to have the same starting address.
>> However, there is another situation, in which a process expands its anon
>> region (by mremap(2)?) with the same starting address.  Since your patch
>> does not check the ending address, oprofile incorrectly reuses an existing
>> operf_mmap struct representing a smaller anon region.  I think in any way
>> the checking of the ending address is inevitable.
>> >
>>
>> Hi Rei,
>>
>> Thanks for the testing.  I originally thought that the problem was due to
>> different processes having overlapping maps.  However, from the testing it
>> sounds like there are multiple maps for the same process and the smaller
>> map is removing the correct mapping from the list.  Are the small sized
>> maps always zero-sized?  The existing code to compute mapping->end_addr is
>> a bit odd in that it special cases the end_addr as 0 for zero sized
>> mappings because region is start_addr<=addr<=end_addr and there isn't a
>> great way of indicating nothing is in the region. The patch is matching
>> that behavior.  Would it be better if the event->mmap.len is 0 just skip
>> making the entry? That would have the plus of reducing the number of
>> entries to scan through.
>>
>> Could you run operf with the following option on the problem testcase to
>> see if there are any lines with "end addr: 0"?
>>
>>  operf -V convert <command_being_measured>
>>
>> >> However, what happens when two different processes have anon regions
>> that have the same starting address and are the same size?
>> >
>> > In that case, they share the same operf_mmap struct.  Is there any
>> problem in it?
>>
>> For read only regions of regular executable code this is okay.  However,
>> if the anon memory is for different processes, they are likely to have
>> different contents and it isn't a good idea to assume they are the same.
>> That what the patch I sent was trying to address, keep them separate so the
>> contents don't get confused.
>>
>> >
>> > I have just git-cloned oprofile-test but could not figure out how to
>> run it.  Could you help me create a test case?
>>
>> I can help you get a test written for oprofile-test.  For the time being
>> it would be great if you just have some steps that you used to create the
>> problem.  It doesn't have the be an actual script.  Just a list of commands
>> and some text description what is expected when it doesn't work and when it
>> does work.  From earlier email this problem is only on some versions of the
>> jvm and architectures also make a note of that in the writeup.  I will be
>> at the Red hat summit in Boston, MA most of this week, so I may not be able
>> to do too much on this the next couple of days.
>>
>>
>> -Will
>>
>> >
>> >
>> > Thanks,
>> > Rei Odaira
>> >
>> >
>> > 2015-06-17 8:55 GMT-05:00 William Cohen <[email protected] <mailto:
>> [email protected]>>:
>> >
>> >     On 06/16/2015 04:24 PM, William Cohen wrote:
>> >     > On 06/12/2015 04:49 PM, 大平怜 wrote:
>> >     >> Hi,
>> >     >>
>> >     >> Anyone has any suggestions?  I hope my patch is included in
>> OProfile-1.1.
>> >     >>
>> >     >>
>> >     >> Thanks,
>> >     >> Rei Odaira
>> >     >>
>> >     >> 2015-05-31 22:00 GMT-05:00 大平怜 <[email protected] <mailto:
>> [email protected]> <mailto:[email protected] <mailto:
>> [email protected]>>>:
>> >     >>
>> >     >>     Hi,
>> >     >>
>> >     >>     I found when profiling multiple JVMs, many samples that
>> should have hit JITted methods were lost due to no permanent mapping. This
>> was because OProfile did not have correct operf_mmap for the JITted code
>> anon regions of some of the JVMs. This error can happen as follows:
>> >     >>
>> >     >>     (1) __handle_mmap_event() creates a new operf_mmap for a
>> small anon region of a JVM.
>> >     >>     (2) When another JVM happens to allocate its anon region at
>> the same starting virtual address but with a larger size,
>> __handle_mmap_event() first searches all_images_map.
>> >     >>     (3) __handle_mmap_event() finds the previously created
>> operf_mmap in all_images_map and reuses it, because it checks only filename
>> and start_addr.
>> >     >>     (4) As a result, when a sample hits a JITted method that was
>> generated between the incorrect end_addr and the actual end address,
>> __get_operf_trans() cannot find an appropriate mapping.
>> >     >>
>> >     >>     The root cause of this problem is that __handle_mmap_event()
>> does not check end_addr when searching all_images_map. This should work for
>> a normal file, which should have the same size when mapped to different
>> processes, but not for anon regions, which can have different sizes in
>> different processes. The attached patch will add this check.
>> >     >>
>> >     >
>> >     > Hi Rei,
>> >     >
>> >     > The patch sounds like a step in the right direction.  However,
>> what happens when two different processes have anon regions that have the
>> same starting address and are the same size?  It  would be preferable to
>> use the pid of struct mmap_event to determine whether the maps for the
>> anonymous regions are for the same process, but the struct operf_mmap
>> doesn't keep the pid information.  Maybe the struct operf_mmap should be
>> modified and the code include that for the anonymous memory maps.  Use pid
>> value of 0 for mappings for multiple pids.
>> >     >
>> >     >>     More fundamentally, I am wondering what the purpose of
>> all_images_region is. I guess it is to reuse operf_mmap structures for more
>> than one processes. The file names in all_images_map are stored in absolute
>> paths, but they are compared against a file base name in
>> __handle_mmap_event(). As a result, this comparison succeeds only for anon
>> and [vdso]. Is this intended behavior?
>> >     >>
>> >     >
>> >     > I haven't done that much looking in this area of the oprofile
>> code.  I did some code archaeology with gitk to see how to code evolved and
>> see if there was anything in the commits that described what was being
>> addressed.  It looks like the following patch put in that particular code
>> that your patch is modifying.  The goal is to avoid having multiple
>> mappings for different processes with the same binaries/mappings.  There
>> needs to be some checking earlier to see whether the mapping is something
>> that is unique to the process (an anonymous mapping) and avoid the
>> incorrect matching of pseudo file names ("//anon" , "/anon_hugepage").
>> >     >
>> >     >
>> >     >
>> >     > Author: Maynard Johnson <[email protected] <mailto:
>> [email protected]>>  2012-03-27 19:03:45
>> >     > Committer: Maynard Johnson <[email protected] <mailto:
>> [email protected]>>  2012-03-27 19:03:45
>> >     > Parent: ed9f73aab1adb7ee368027a2532649baf867a45d (Fix problem
>> when passed app name is of the form '<subdir>/<app_name>')
>> >     > Child:  f7f71a580b65f5fedcd1bbd94825838a94a0945a (Fix
>> timing-related problems with app name)
>> >     > Branches: master, remotes/origin/master
>> >     > Follows: RELEASE_0_9_7
>> >     > Precedes: RELEASE_0_9_8
>> >     >
>> >     >     Minor bug fixes and performance improvement for system-wide
>> mode.
>> >     >
>> >     >     The operf_sfile hashing algorithm was modified from legacy
>> hashing
>> >     >     to use either a build-id or a checksum.  I had not yet
>> implemented the
>> >     >     getting the build-id, so was falling back to the checksum.
>> Getting
>> >     >     the checksum (via gelf_checksum) was terribly expensive,
>> especially
>> >     >     noticeable when running with the system-wide option.  So I
>> spent
>> >     >     some time comparing using a build-id (obtained from the
>> binary file's
>> >     >     NT_GNU_BUILD_ID note) for the hashing algorithm versus simply
>> hashing
>> >     >     on a substring of the image name.  The simple string hash was
>> as
>> >     >     effective as the build-id method.  Both were way better than
>> the checksum
>> >     >     technique. In the end, I removed all of the checksum and
>> build-id stuff,
>> >     >     and settled on the image name string hash method for finding
>> operf_sfiles.
>> >     >
>> >     >     Aside from the above big performance improvement described
>> above, I also
>> >     >     created a global multimap for holding operf_mmap objects.
>> The operf_mmap
>> >     >     encapsulates an MMAP event.  In system-wide mode, we get lots
>> of MMAP events
>> >     >     for the same libraries being used by many different
>> processes, so it was
>> >     >     logical to create just one operf_mmap object per unique
>> binary.
>> >     >
>> >     >
>> >     > -Will
>> >
>> >
>> >     Hi Rei,
>> >
>> >     I was thinking something along the lines of the attached patch to
>> address this problem.  Could you try it out and see whether that resolves
>> the issue?  Also do you have a reproducer that could be added to the
>> testsuite to verify that this problem is fixed and doesn't get reintroduced
>> into oprofile?
>> >
>> >     -Will
>> >
>> >
>>
>>
>

------------------------------------------------------------------------------

_______________________________________________
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.
 *  This code assumes x86.
 */

#include <stdio.h>
#include <stdlib.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)

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

buffer                    func_start_addr
|                         |
v                         v
<-- initial_buffer_size -->
<-----            remapped_buffer_size                ----->
|.........................|add add add add add ... add retq|
 */
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 - 1;
  char *cursor;

  for (cursor = func_start_addr; cursor < func_end_addr - 2; cursor += 3) {
    /* add $0x1,%eax */
    cursor[0] = 0x83;
    cursor[1] = 0xc0;
    cursor[2] = 0x01;
  }
  /* retq */
  cursor[0] = 0xc3;

  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();
  }
}