All of lore.kernel.org
 help / color / mirror / Atom feed
* odd error from "perf record"
@ 2016-01-15 20:35 Gary Byers
  2016-01-15 21:17 ` Arnaldo Carvalho de Melo
  0 siblings, 1 reply; 5+ messages in thread
From: Gary Byers @ 2016-01-15 20:35 UTC (permalink / raw)
  To: linux-perf-users

Hi.

I happen to be using Ubuntu 15.10

[~] gb@abq> uname -a
Linux abq 4.2.0-23-generic #28-Ubuntu SMP Sun Dec 27 17:47:31 UTC 2015 
x86_64 x86_64 x86_64 GNU/Linux


I am trying to use perf to profile a 64-bit x86 Linux program. The 
program maps a large (512gb) chunk
of address space, but "only" about 20mb of that are mapped with 
permissions that allow any of read,
write, or execute access. (The atypical memory mapping is done for what 
I believe to be very good
reasons and I don't think that those reasons are directly relevant here.)

Some of the code that I an trying to profile is on pages that have read 
and execute permissions
and atypically "high" addresses, often of the form 0000300000xxxxxx,  If 
anyone reading this would
find it helpful, I can certainly provide a copy of /proc/<pid>/maps or 
similar for a typical instance
of the process.  As far as I know, few (if any) pages in the process are 
locked via mlock() or variants.

For the sake of argument, it may be helpful to think of that code as 
having been "JITted" there.  it is
not mapped from an ELF executable or library, and my later questions may 
have to do with the .map file
that I am trying to use to provide symbolic information

I have other issues that I would like to discuss in a followup message, 
but first:

When I call "perf record" on a running instance of the process, I often 
get an error
  gb@abq> [~] gb@abq> perf record -p 18310
Permission error mapping pages.
Consider increasing /proc/sys/kernel/perf_event_mlock_kb,
or try again with a smaller value of -m/--mmap_pages.
(current value: 4294967295,0)
[~] gb@abq> cat /proc/sys/kernel/perf_event_mlock_kb
516

If I try again with an explicit -m argument,I get a similar but slightly 
different error:
[~] gb@abq> perf record -m 8 -p 18310

Permission error mapping pages.
Consider increasing /proc/sys/kernel/perf_event_mlock_kb,
or try again with a smaller value of -m/--mmap_pages.
(current value: 8,0)

If I run 'perf record ..." as root, I get past this point but run into 
other issues that
I will try to discuss in a later message and running as root is not 
always possible for my
uaers

The code in question (and its source) are freely available and the 
source is licensed under an LGPL variant.

I'd be glad to provide that and any other help that anyone needs, and 
thanks for any help
that anyone can provide,

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: odd error from "perf record"
  2016-01-15 20:35 odd error from "perf record" Gary Byers
@ 2016-01-15 21:17 ` Arnaldo Carvalho de Melo
  2016-01-16 20:55   ` Gary Byers
  0 siblings, 1 reply; 5+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-01-15 21:17 UTC (permalink / raw)
  To: Gary Byers; +Cc: linux-perf-users

Em Fri, Jan 15, 2016 at 01:35:05PM -0700, Gary Byers escreveu:
> Hi.
> 
> I happen to be using Ubuntu 15.10
> 
> [~] gb@abq> uname -a
> Linux abq 4.2.0-23-generic #28-Ubuntu SMP Sun Dec 27 17:47:31 UTC 2015
> x86_64 x86_64 x86_64 GNU/Linux
> 
> 
> I am trying to use perf to profile a 64-bit x86 Linux program. The program
> maps a large (512gb) chunk
> of address space, but "only" about 20mb of that are mapped with permissions
> that allow any of read,
> write, or execute access. (The atypical memory mapping is done for what I
> believe to be very good
> reasons and I don't think that those reasons are directly relevant here.)
> 
> Some of the code that I an trying to profile is on pages that have read and
> execute permissions
> and atypically "high" addresses, often of the form 0000300000xxxxxx,  If
> anyone reading this would
> find it helpful, I can certainly provide a copy of /proc/<pid>/maps or
> similar for a typical instance
> of the process.  As far as I know, few (if any) pages in the process are
> locked via mlock() or variants.
> 
> For the sake of argument, it may be helpful to think of that code as having
> been "JITted" there.  it is
> not mapped from an ELF executable or library, and my later questions may
> have to do with the .map file
> that I am trying to use to provide symbolic information

Right, see tools/perf/Documentation/jit-interface.txt to see how to
provide that map.

> 
> I have other issues that I would like to discuss in a followup message, but
> first:
> 
> When I call "perf record" on a running instance of the process, I often get
> an error
>  gb@abq> [~] gb@abq> perf record -p 18310
> Permission error mapping pages.
> Consider increasing /proc/sys/kernel/perf_event_mlock_kb,
> or try again with a smaller value of -m/--mmap_pages.
> (current value: 4294967295,0)

This current warning is useless, that big number means: nothing was set,
use the default 

The kernel returns EPERM for perf_mmap in these line in
kernel/events/core.c:

        user_lock_limit = sysctl_perf_event_mlock >> (PAGE_SHIFT - 10);

        /*
         * Increase the limit linearly with more CPUs:
         */
        user_lock_limit *= num_online_cpus();

        user_locked = atomic_long_read(&user->locked_vm) + user_extra;

        if (user_locked > user_lock_limit)
                extra = user_locked - user_lock_limit;

        lock_limit = rlimit(RLIMIT_MEMLOCK);
        lock_limit >>= PAGE_SHIFT;
        locked = vma->vm_mm->pinned_vm + extra;

        if ((locked > lock_limit) && perf_paranoid_tracepoint_raw() &&
                !capable(CAP_IPC_LOCK)) {
                ret = -EPERM;
                goto unlock;
        }


So you probably have a lot of CPUs, right? You hat CAP_IPC_LOCK is what
makes it not consider these limits for the root user, bump
/proc/sys/kernel/perf_event_mlock_kb it to a high enough value and you
should use it as a normal user, I think.

> [~] gb@abq> cat /proc/sys/kernel/perf_event_mlock_kb
> 516
> 
> If I try again with an explicit -m argument,I get a similar but slightly
> different error:
> [~] gb@abq> perf record -m 8 -p 18310
> 
> Permission error mapping pages.
> Consider increasing /proc/sys/kernel/perf_event_mlock_kb,
> or try again with a smaller value of -m/--mmap_pages.
> (current value: 8,0)
> 
> If I run 'perf record ..." as root, I get past this point but run into other
> issues that
> I will try to discuss in a later message and running as root is not always
> possible for my
> uaers
> 
> The code in question (and its source) are freely available and the source is
> licensed under an LGPL variant.
> 
> I'd be glad to provide that and any other help that anyone needs, and thanks
> for any help
> that anyone can provide,

if you could provide the minimal reproducer for this, i.e. a simple
program that does the kind of mapping you described and when monitored
produces the error being reported.

But please try bumping /proc/sys/kernel/perf_event_mlock_kb first.
 
> 
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: odd error from "perf record"
  2016-01-15 21:17 ` Arnaldo Carvalho de Melo
@ 2016-01-16 20:55   ` Gary Byers
  2016-01-19 22:14     ` Arnaldo Carvalho de Melo
  0 siblings, 1 reply; 5+ messages in thread
From: Gary Byers @ 2016-01-16 20:55 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo; +Cc: linux-perf-users

[-- Attachment #1: Type: text/plain, Size: 9558 bytes --]

thanks.  I can work around the problem described in my previous message, 
but the problem
that I describe below is harder for me to describe and I  don't know 
exactly where the
problem might be and of course don't know how to work around it

The code that I am trying to profile is written in Clozure Common Lisp 
(CCL( <http://ccl.clozure.com>.
the memory regions that I am most interested in profiling contain lisp 
code; other regions mapped by
the process are mapped to ELF files which do not seem to exhibit problems.

the problems that I am most concerned about involve profiling compiled 
Lisp code, and a (somewhat
rambling) description of that problem and steps to reproduce it follows.

A copy of /proc/<pid>/maps for a running CCL process is enclosed as 
"mail.txt", the memory map
shown in that file is "typical" of a CCL process but may not be as 
typical of programs written
in other development systems.



I would like to be able to use "perf record ..." and "perf report" to 
profile that
code, and was able to do so for many years.  the details of how I was 
able to do so
are (probably) not relevant, but did not involve a /tmp/<pid>/map file 
when I used
earlier Linux kernels


The perf map file that I have been creating recently contains entries of 
the form

000030000010D000 2411 CCL::+-2
000030000010F490 25F9 CCL::--2
0000300000111B10 1531 CCL::*-2
00003000001130F0 2C29 CCL::/-2
0000300000115DB0 1EB1 CCL::=-2
0000300000117CD0 59 CCL::/=-2

those entries were in a text file named /tmp/perf-22415.map.
for a process whose pid was 22415 when I ran "perf record ..."
the .map file contains a few thousand such entries.

the output that I get from 'perf report .. "   -with or without
a ,map file -  looks like

     14.97%  lx86cl64  lx86cl64           [.] zero_dnodes
     14.55%  lx86cl64  lx86cl64.image     [.] 0x000000000011da1d
     11.55%  lx86cl64  lx86cl64.image     [.] 0x000000000011da11
      9.34%  lx86cl64  lx86cl64.image     [.] 0x000000000011da24

where "lx86cl64" is an ELF executable and "lx86cl64.image" is a file 
from which
the memory regions described by the perf  .map file are mmapped. Note 
that the addresses
in the "perf report" output do not seem to have much to do with the 
address ranges
described in the perf .map file, though they might be correct in some of 
their low bits.

If this is indeed a problem in 'perf' or related kernel components, as 
it appears to be, I believe that it may have been
introduced sometime after Linux 3.13 and sometime before 3.19.

In the code that I was running, the entries for the code from the ELF 
file (lx86cl64) look
plausible and may be correct,  The number of addresses reported for the 
code mapped from
the lx86cl64.image file seems plausible. but the addresses themselves do 
not.

The simplest way that I know of to reproduce this is to
1 ) download 
<http://ccl.clozure.com/ftp/pub/release/1.11/ccl-1.11-linuxx86.tar.gz> 
and extract its
contents.  This should create and populate a directory named ccl, which 
includes ccl/lx86cl64
and ccl/lx86cl64.image
2) execute ccl/lx86cl64 (with no arguments) from the shell.  note the 
pid of of the process.  You should see some startup
messages, followed by a "? " prompt. If you cannot run ccl/lx86cl64 
because of ELF symbol version issues, you
can build lx86cl64 on your system and avoid those issues by doing
$ pushd ccl/lisp-kernel/linuxx8664
$ make
$ popd

the Makefile depends on GNU m4 being installed as "m4" and an otherwise 
fairly vanilla gnu toolchain
and a fairly small set of libraries being installed.   If you need any 
additional shared object files, you would
probably have difficulty building most C programs,  'ldd lx86cl64" can 
tell you more precisely than I usually
can, and of course can help to identify problems related to symbol 
versioning issues.,

The lisp (lx86cl64) is in a traditional  read-eval-print loop (REPL), 
continually reading Lisp expressions,
printing the values of those expressions, and prompting (with "? ") for 
another expression.

3) in another shell, note the pid of the running lx86cl64 process (using 
'ps' or 'top' or other means)
$ perf record -p <pid of lx86cl64>

3) back in the lisp and at the "? " prompt, define a lisp function. 
Either type its definition  very carefully, or use
copy-and-paste and hope that I have typed carefully here:
(defun fact (n) (if (zerop n) 1 (* n (fact (1- n)))))
add a newline at the end of that line.

you should see
FACT
?
e.g. FACT and another prompt as output
FACT is simply the "value" of the function definition.



4) call that function.  Doing it this way (testing whether or not 
calling the function returns a null value) avoids
printing a very large integer.

? (null (fact 10000))
Of course that input should also be terminated by a newline,  the very 
large integer is not null, but we did
do about 10000 multiplications, many of which also involved very large 
integers.  We've also compiled a small
function and done a few other things, but a significant part of what we 
have done while "perf record" has been
running involves functions that are defined in lx86cl64.image.

5) The previous step should have returned and printed
NIL
?

(the large integer is not itself NIL)

and another prompt ,and at that prompt, typing
(quit)

should exit the process and also cause the process that has been running 
"perf record" to exit.


A subsequent call to "perf report" will show output like
# Overhead  Command   Shared Object Symbol
# ........  ........  ................. ...............................
#
     15.41%  lx86cl64  lx86cl64           [.] zero_dnodes
     12.64%  lx86cl64  lx86cl64.image     [.] 0x000000000007cb8d
      6.29%  lx86cl64  lx86cl64.image     [.] 0x0000000000088251
      6.01%  lx86cl64  lx86cl64.image     [.] 0x000000000007cb88
      5.87%  lx86cl64  lx86cl64.image     [.] 0x000000000007cb97

Note that we did not create a ,map file in the steps above.  When  I
do that , the output is essentially the same. the "symbols" in the
output immediately above do not have any obvious correlation to
the addresses that are mapped by the lx86cl64 process , and it is plausible
that we have spent as much time as we have in a small number
of lisp functions when we call (fact 10000)  but the addresses of
the samples seem to be unrelated to any mapped memory region in the process

In previous versions of perf and Linux, I was able to associate ELF
symbols with lisp function addresses using a fairly brutal hack,
if using the ,map file fails because of a problem with the ,map
file, it is in some ways preferable to using  that hack.  Using
the hack instead of the perf map file does not seem to affect
the "perf report" output for functions defined in lx86cl64.image

I believe that I have also seen perf report identify the "shared object"
as the name of  the perf.<pid>.map file in (iirc) linux 3.19, and
I believe that I've seen this regardless of whether a .map file
existed or not.

If the "symbols" reported by "perf report" are (virtual, logical) 
addresses associated
with samples in the perf.out file, they don't seem to have much to do
with the address of any code in the process. If the reported "symbols" 
are something
other than addresses, I have no idea what they are.

at some point, I may have thought that the reported "symbols" were 
simply being truncated
to 32 bits, but I am not certain of that.

I hope that anyone who wants to reproduce this will find it relatively 
easy to do so.

the attached "mail.txt" file shows a typical /proc/pid/maps
file which may be helpful.

Thanks.

On 01/15/2016 02:17 PM, Arnaldo Carvalho de Melo wrote:
> Em Fri, Jan 15, 2016 at 01:35:05PM -0700, Gary Byers escreveu:
>
>> Hi.
>>
>> I happen to be using Ubuntu 15.10
>>
>> [~] gb@abq> uname -a
>> Linux abq 4.2.0-23-generic #28-Ubuntu SMP Sun Dec 27 17:47:31 UTC 2015
>> x86_64 x86_64 x86_64 GNU/Linux
>>
>>
>> I am trying to use perf to profile a 64-bit x86 Linux program. The program
>> maps a large (512gb) chunk
>> of address space, but "only" about 20mb of that are mapped with permissions
>> that allow any of read,
>> write, or execute access. (The atypical memory mapping is done for what I
>> believe to be very good
>> reasons and I don't think that those reasons are directly relevant here.)
>>
>> Some of the code that I an trying to profile is on pages that have read and
>> execute permissions
>> and atypically "high" addresses, often of the form 0000300000xxxxxx,  If
>> anyone reading this would
>> find it helpful, I can certainly provide a copy of /proc/<pid>/maps or
>> similar for a typical instance
>> of the process.  As far as I know, few (if any) pages in the process are
>> locked via mlock() or variants.
>>
>> For the sake of argument, it may be helpful to think of that code as having
>> been "JITted" there.  it is
>> not mapped from an ELF executable or library, and my later questions may
>> have to do with the .map file
>> that I am trying to use to provide symbolic information
> Right, see tools/perf/Documentation/jit-interface.txt to see how to
> provide that map.
>
> if you could provide the minimal reproducer for this, i.e. a simple 
> program that does the kind of mapping you described and when monitored 
> produces the error being reported. But please try bumping 
> /proc/sys/kernel/perf_event_mlock_kb first.
>>
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html


[-- Attachment #2: mail.txt --]
[-- Type: text/plain, Size: 5508 bytes --]

00012000-00014000 rwxp 00000000 08:07 18350962                           /usr/local/src/ccl/lx86cl64.image
00015000-00016000 rwxp 00000000 00:00 0 
00400000-00430000 r-xp 00000000 08:07 18375976                           /usr/local/src/ccl/lx86cl64
00630000-00631000 r-xp 00030000 08:07 18375976                           /usr/local/src/ccl/lx86cl64
00631000-00632000 rwxp 00031000 08:07 18375976                           /usr/local/src/ccl/lx86cl64
00632000-00633000 rwxp 00000000 00:00 0 
00edd000-00f22000 rwxp 00000000 00:00 0                                  [heap]
300000000000-300000fc6000 r-xp 00002000 08:07 18350962                   /usr/local/src/ccl/lx86cl64.image
300000fc6000-300000fc8000 rwxp 00fc8000 08:07 18350962                   /usr/local/src/ccl/lx86cl64.image
300000fc8000-300001559000 r-xp 00fca000 08:07 18350962                   /usr/local/src/ccl/lx86cl64.image
300001559000-300040000000 ---p 00000000 00:00 0 
300040000000-300040568000 rwxp 019d9000 08:07 18350962                   /usr/local/src/ccl/lx86cl64.image
300040568000-302000000000 ---p 00000000 00:00 0 
302000000000-30200047e000 rwxp 0155b000 08:07 18350962                   /usr/local/src/ccl/lx86cl64.image
30200047e000-302002480000 rwxp 00000000 00:00 0 
302002480000-307bfe000000 ---p 00000000 00:00 0 
307bfe000000-307bfe04a000 rwxp 00000000 00:00 0 
307bfe04a000-307dfe000000 ---p 00000000 00:00 0 
307dfe000000-307e0000b000 rwxp 00000000 00:00 0 
307e0000b000-307e3f800000 ---p 00000000 00:00 0 
307e3f800000-307e3f84a000 rwxp 00000000 00:00 0 
307e3f84a000-308000020000 ---p 00000000 00:00 0 
7ffb54000000-7ffb54021000 rwxp 00000000 00:00 0 
7ffb54021000-7ffb58000000 ---p 00000000 00:00 0 
7ffb5aeee000-7ffb5af08000 r-xp 00000000 00:00 0 
7ffb5af08000-7ffb5b109000 rwxp 00000000 00:00 0 
7ffb5b109000-7ffb5b10a000 ---p 00000000 00:00 0 
7ffb5b10a000-7ffb5b36d000 rwxp 00000000 00:00 0                          [stack:28309]
7ffb5b36d000-7ffb5b387000 r-xp 00000000 00:00 0 
7ffb5b387000-7ffb5b5bb000 rwxp 00000000 00:00 0 
7ffb5b5bb000-7ffb5b7b6000 ---p 00000000 00:00 0 
7ffb5b7b6000-7ffb5b7c1000 rwxp 01f41000 08:07 18350962                   /usr/local/src/ccl/lx86cl64.image
7ffb5b7c1000-7ffb7b3b6000 ---p 00000000 00:00 0 
7ffb7b3b6000-7ffb7b576000 r-xp 00000000 08:07 266583                     /lib/x86_64-linux-gnu/libc-2.21.so
7ffb7b576000-7ffb7b776000 ---p 001c0000 08:07 266583                     /lib/x86_64-linux-gnu/libc-2.21.so
7ffb7b776000-7ffb7b77a000 r-xp 001c0000 08:07 266583                     /lib/x86_64-linux-gnu/libc-2.21.so
7ffb7b77a000-7ffb7b77c000 rwxp 001c4000 08:07 266583                     /lib/x86_64-linux-gnu/libc-2.21.so
7ffb7b77c000-7ffb7b780000 rwxp 00000000 00:00 0 
7ffb7b780000-7ffb7b787000 r-xp 00000000 08:07 266727                     /lib/x86_64-linux-gnu/librt-2.21.so
7ffb7b787000-7ffb7b986000 ---p 00007000 08:07 266727                     /lib/x86_64-linux-gnu/librt-2.21.so
7ffb7b986000-7ffb7b987000 r-xp 00006000 08:07 266727                     /lib/x86_64-linux-gnu/librt-2.21.so
7ffb7b987000-7ffb7b988000 rwxp 00007000 08:07 266727                     /lib/x86_64-linux-gnu/librt-2.21.so
7ffb7b988000-7ffb7b9a0000 r-xp 00000000 08:07 266719                     /lib/x86_64-linux-gnu/libpthread-2.21.so
7ffb7b9a0000-7ffb7bba0000 ---p 00018000 08:07 266719                     /lib/x86_64-linux-gnu/libpthread-2.21.so
7ffb7bba0000-7ffb7bba1000 r-xp 00018000 08:07 266719                     /lib/x86_64-linux-gnu/libpthread-2.21.so
7ffb7bba1000-7ffb7bba2000 rwxp 00019000 08:07 266719                     /lib/x86_64-linux-gnu/libpthread-2.21.so
7ffb7bba2000-7ffb7bba6000 rwxp 00000000 00:00 0 
7ffb7bba6000-7ffb7bcad000 r-xp 00000000 08:07 266645                     /lib/x86_64-linux-gnu/libm-2.21.so
7ffb7bcad000-7ffb7beac000 ---p 00107000 08:07 266645                     /lib/x86_64-linux-gnu/libm-2.21.so
7ffb7beac000-7ffb7bead000 r-xp 00106000 08:07 266645                     /lib/x86_64-linux-gnu/libm-2.21.so
7ffb7bead000-7ffb7beae000 rwxp 00107000 08:07 266645                     /lib/x86_64-linux-gnu/libm-2.21.so
7ffb7beae000-7ffb7beb1000 r-xp 00000000 08:07 266602                     /lib/x86_64-linux-gnu/libdl-2.21.so
7ffb7beb1000-7ffb7c0b0000 ---p 00003000 08:07 266602                     /lib/x86_64-linux-gnu/libdl-2.21.so
7ffb7c0b0000-7ffb7c0b1000 r-xp 00002000 08:07 266602                     /lib/x86_64-linux-gnu/libdl-2.21.so
7ffb7c0b1000-7ffb7c0b2000 rwxp 00003000 08:07 266602                     /lib/x86_64-linux-gnu/libdl-2.21.so
7ffb7c0b2000-7ffb7c0d6000 r-xp 00000000 08:07 266555                     /lib/x86_64-linux-gnu/ld-2.21.so
7ffb7c11d000-7ffb7c12d000 rwxp 00000000 00:00 0 
7ffb7c12d000-7ffb7c14f000 r-xp 00000000 00:00 0 
7ffb7c14f000-7ffb7c250000 rwxp 00000000 00:00 0 
7ffb7c250000-7ffb7c272000 r-xp 00000000 00:00 0 
7ffb7c272000-7ffb7c2b7000 rwxp 00000000 00:00 0 
7ffb7c2c2000-7ffb7c2d5000 rwxp 00000000 00:00 0 
7ffb7c2d5000-7ffb7c2d6000 r-xp 00023000 08:07 266555                     /lib/x86_64-linux-gnu/ld-2.21.so
7ffb7c2d6000-7ffb7c2d7000 rwxp 00024000 08:07 266555                     /lib/x86_64-linux-gnu/ld-2.21.so
7ffb7c2d7000-7ffb7c2d8000 rwxp 00000000 00:00 0 
7fff7a102000-7fff7a123000 rwxp 00000000 00:00 0                          [stack]
7fff7a1b4000-7fff7a1b6000 r--p 00000000 00:00 0                          [vvar]
7fff7a1b6000-7fff7a1b8000 r-xp 00000000 00:00 0                          [vdso]
ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0                  [vsyscall]

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: odd error from "perf record"
  2016-01-16 20:55   ` Gary Byers
@ 2016-01-19 22:14     ` Arnaldo Carvalho de Melo
  2016-01-20  1:31       ` Gary Byers
  0 siblings, 1 reply; 5+ messages in thread
From: Arnaldo Carvalho de Melo @ 2016-01-19 22:14 UTC (permalink / raw)
  To: Gary Byers; +Cc: linux-perf-users

Em Sat, Jan 16, 2016 at 01:55:49PM -0700, Gary Byers escreveu:
> thanks.  I can work around the problem described in my previous message, but
> the problem
> that I describe below is harder for me to describe and I  don't know exactly
> where the
> problem might be and of course don't know how to work around it
 
> The code that I am trying to profile is written in Clozure Common Lisp (CCL(
> <http://ccl.clozure.com>.
> the memory regions that I am most interested in profiling contain lisp code;
> other regions mapped by
> the process are mapped to ELF files which do not seem to exhibit problems.
> 
> the problems that I am most concerned about involve profiling compiled Lisp
> code, and a (somewhat
> rambling) description of that problem and steps to reproduce it follows.
> 
> A copy of /proc/<pid>/maps for a running CCL process is enclosed as
> "mail.txt", the memory map
> shown in that file is "typical" of a CCL process but may not be as typical
> of programs written
> in other development systems.
> 
> 
> 
> I would like to be able to use "perf record ..." and "perf report" to
> profile that
> code, and was able to do so for many years.  the details of how I was able

If so, would it be possible for you to use 'git bisect' on a kernel that
works with a recent kernel sources so that you can go on building just
the tooling side and testing it to check if the problem is tooling
related?

Or have you checked that already, i.e. is it a single perf tool version
with different kernel that causes the problem?

I use these scripts to do a git bisect run, i.e. automated bisection:

[acme@zoo ~]$ cat ~/bin/mbisect 
#!/bin/bash

rm -rf /tmp/build/perf ; mkdir -p /tmp/build/perf ; make O=/tmp/build/perf -C tools/perf install-bin > /tmp/log.m 2>&1 || exit 125
ptest $1
[acme@zoo ~]$ cat ~/bin/ptest
#!/bin/sh

perf test $1 2>&1 | grep -q Ok$

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

Just replace that ptest one with whatever you have that returns 0 for ok, 1 for
problems.

bisecting the kernel is possible but takes longer as reboots will have to be
performed.

> to do so
> are (probably) not relevant, but did not involve a /tmp/<pid>/map file when
> I used
> earlier Linux kernels

Define "earlier", what version?

> The perf map file that I have been creating recently contains entries of the
> form
> 
> 000030000010D000 2411 CCL::+-2
> 000030000010F490 25F9 CCL::--2
> 0000300000111B10 1531 CCL::*-2
> 00003000001130F0 2C29 CCL::/-2
> 0000300000115DB0 1EB1 CCL::=-2
> 0000300000117CD0 59 CCL::/=-2
> 
> those entries were in a text file named /tmp/perf-22415.map.
> for a process whose pid was 22415 when I ran "perf record ..."
> the .map file contains a few thousand such entries.

So, these will be used, IIRC, if this is an anonymous map

> 
> the output that I get from 'perf report .. "   -with or without
> a ,map file -  looks like
> 
>     14.97%  lx86cl64  lx86cl64           [.] zero_dnodes
>     14.55%  lx86cl64  lx86cl64.image     [.] 0x000000000011da1d
>     11.55%  lx86cl64  lx86cl64.image     [.] 0x000000000011da11
>      9.34%  lx86cl64  lx86cl64.image     [.] 0x000000000011da24
> 
> where "lx86cl64" is an ELF executable and "lx86cl64.image" is a file from
> which
> the memory regions described by the perf  .map file are mmapped. Note that
> the addresses
> in the "perf report" output do not seem to have much to do with the address
> ranges
> described in the perf .map file, though they might be correct in some of
> their low bits.

They are offsets to the map where they were found, so if you look at the
/proc/PID/maps and add the mmap where the lx86cl64.image is + the values you
see above, you'll get the virtual address, like you used in that
/tmp/perf-PID.map.
 
> If this is indeed a problem in 'perf' or related kernel components, as it
> appears to be, I believe that it may have been
> introduced sometime after Linux 3.13 and sometime before 3.19.
> 
> In the code that I was running, the entries for the code from the ELF file
> (lx86cl64) look
> plausible and may be correct,  The number of addresses reported for the code
> mapped from
> the lx86cl64.image file seems plausible. but the addresses themselves do
> not.

See the comment above.

so, from your /proc/pid/map file, we see:

> 300000000000-300000fc6000 r-xp 00002000 08:07 18350962     /usr/local/src/ccl/lx86cl64.image
> 300000fc6000-300000fc8000 rwxp 00fc8000 08:07 18350962     /usr/local/src/ccl/lx86cl64.image
> 300000fc8000-300001559000 r-xp 00fca000 08:07 18350962     /usr/local/src/ccl/lx86cl64.image
> 300040000000-300040568000 rwxp 019d9000 08:07 18350962     /usr/local/src/ccl/lx86cl64.image
> 302000000000-30200047e000 rwxp 0155b000 08:07 18350962     /usr/local/src/ccl/lx86cl64.image

Which will make it try to find symbols in /usr/local/src/ccl/lx86cl64.image, which,
looking at your tarball, I see as:

[acme@zoo ccl]$ file lx86cl64.image 
lx86cl64.image: data

So, it would have to fallback to using the method it uses for anonymous maps to
be able to use that /tmp/perf-PID.map file, that would be the explanation for
it to work in that distant past, that I would have to check if it would be the case...

Yeah, for such a case, where you have a pathname but that pathname is not to a
file with a symtab, we would have to save the pid in the struct map, then at
map__load() time notice that we didn't managed to load any symtab, then try to
do what map__new does at this point:

                if ((anon || no_dso) && type == MAP__FUNCTION) {
                        snprintf(newfilename, sizeof(newfilename), "/tmp/perf-%d.map", pid);
                        filename = newfilename;
                }

Then replace map->dso with:

      dso = machine__findnew_dso(machine, filename);

A hack just for your usecase would be to make it think it is anonymous memory if the filename
ends in ".image", then it would use the /tmp/perf-%d.map method.

Quick hack, maybe will help you.

diff --git a/tools/perf/util/map.c b/tools/perf/util/map.c
index 171b6d1..d4d706f 100644
--- a/tools/perf/util/map.c
+++ b/tools/perf/util/map.c
@@ -154,7 +154,7 @@ struct map *map__new(struct machine *machine, u64 start, u64 len,
 		int anon, no_dso, vdso, android;
 
 		android = is_android_lib(filename);
-		anon = is_anon_memory(filename);
+		anon = is_anon_memory(filename) || strstr(filename, ".image");
 		vdso = is_vdso_map(filename);
 		no_dso = is_no_dso_memory(filename);
 

Having it as anonymous, as you can see a little later in map__new() will
make it a identity map:

  if (anon || no_dso) {
      map->map_ip = map->unmap_ip = identity__map_ip;


I.e. your symtab, that /tmp/perf-PID.map can have virtual address, and unresolved
symbols will appear not as offsets, as they are appearing now.

 
> The simplest way that I know of to reproduce this is to
> 1 ) download
> <http://ccl.clozure.com/ftp/pub/release/1.11/ccl-1.11-linuxx86.tar.gz> and
> extract its
> contents.  This should create and populate a directory named ccl, which
> includes ccl/lx86cl64
> and ccl/lx86cl64.image
> 2) execute ccl/lx86cl64 (with no arguments) from the shell.  note the pid of
> of the process.  You should see some startup
> messages, followed by a "? " prompt. If you cannot run ccl/lx86cl64 because
> of ELF symbol version issues, you
> can build lx86cl64 on your system and avoid those issues by doing
> $ pushd ccl/lisp-kernel/linuxx8664
> $ make
> $ popd
> 
> the Makefile depends on GNU m4 being installed as "m4" and an otherwise
> fairly vanilla gnu toolchain
> and a fairly small set of libraries being installed.   If you need any
> additional shared object files, you would
> probably have difficulty building most C programs,  'ldd lx86cl64" can tell
> you more precisely than I usually
> can, and of course can help to identify problems related to symbol
> versioning issues.,
> 
> The lisp (lx86cl64) is in a traditional  read-eval-print loop (REPL),
> continually reading Lisp expressions,
> printing the values of those expressions, and prompting (with "? ") for
> another expression.
> 
> 3) in another shell, note the pid of the running lx86cl64 process (using
> 'ps' or 'top' or other means)
> $ perf record -p <pid of lx86cl64>
> 
> 3) back in the lisp and at the "? " prompt, define a lisp function. Either
> type its definition  very carefully, or use
> copy-and-paste and hope that I have typed carefully here:
> (defun fact (n) (if (zerop n) 1 (* n (fact (1- n)))))
> add a newline at the end of that line.
> 
> you should see
> FACT
> ?
> e.g. FACT and another prompt as output
> FACT is simply the "value" of the function definition.
> 
> 
> 
> 4) call that function.  Doing it this way (testing whether or not calling
> the function returns a null value) avoids
> printing a very large integer.
> 
> ? (null (fact 10000))
> Of course that input should also be terminated by a newline,  the very large
> integer is not null, but we did
> do about 10000 multiplications, many of which also involved very large
> integers.  We've also compiled a small
> function and done a few other things, but a significant part of what we have
> done while "perf record" has been
> running involves functions that are defined in lx86cl64.image.
> 
> 5) The previous step should have returned and printed
> NIL
> ?
> 
> (the large integer is not itself NIL)
> 
> and another prompt ,and at that prompt, typing
> (quit)
> 
> should exit the process and also cause the process that has been running
> "perf record" to exit.
> 
> 
> A subsequent call to "perf report" will show output like
> # Overhead  Command   Shared Object Symbol
> # ........  ........  ................. ...............................
> #
>     15.41%  lx86cl64  lx86cl64           [.] zero_dnodes
>     12.64%  lx86cl64  lx86cl64.image     [.] 0x000000000007cb8d
>      6.29%  lx86cl64  lx86cl64.image     [.] 0x0000000000088251
>      6.01%  lx86cl64  lx86cl64.image     [.] 0x000000000007cb88
>      5.87%  lx86cl64  lx86cl64.image     [.] 0x000000000007cb97
> 
> Note that we did not create a ,map file in the steps above.  When  I
> do that , the output is essentially the same. the "symbols" in the
> output immediately above do not have any obvious correlation to
> the addresses that are mapped by the lx86cl64 process , and it is plausible
> that we have spent as much time as we have in a small number
> of lisp functions when we call (fact 10000)  but the addresses of
> the samples seem to be unrelated to any mapped memory region in the process
> 
> In previous versions of perf and Linux, I was able to associate ELF
> symbols with lisp function addresses using a fairly brutal hack,
> if using the ,map file fails because of a problem with the ,map
> file, it is in some ways preferable to using  that hack.  Using
> the hack instead of the perf map file does not seem to affect
> the "perf report" output for functions defined in lx86cl64.image
> 
> I believe that I have also seen perf report identify the "shared object"
> as the name of  the perf.<pid>.map file in (iirc) linux 3.19, and
> I believe that I've seen this regardless of whether a .map file
> existed or not.
> 
> If the "symbols" reported by "perf report" are (virtual, logical) addresses
> associated
> with samples in the perf.out file, they don't seem to have much to do
> with the address of any code in the process. If the reported "symbols" are
> something
> other than addresses, I have no idea what they are.
> 
> at some point, I may have thought that the reported "symbols" were simply
> being truncated
> to 32 bits, but I am not certain of that.
> 
> I hope that anyone who wants to reproduce this will find it relatively easy
> to do so.
> 
> the attached "mail.txt" file shows a typical /proc/pid/maps
> file which may be helpful.
> 
> Thanks.
> 
> On 01/15/2016 02:17 PM, Arnaldo Carvalho de Melo wrote:
> >Em Fri, Jan 15, 2016 at 01:35:05PM -0700, Gary Byers escreveu:
> >
> >>Hi.
> >>
> >>I happen to be using Ubuntu 15.10
> >>
> >>[~] gb@abq> uname -a
> >>Linux abq 4.2.0-23-generic #28-Ubuntu SMP Sun Dec 27 17:47:31 UTC 2015
> >>x86_64 x86_64 x86_64 GNU/Linux
> >>
> >>
> >>I am trying to use perf to profile a 64-bit x86 Linux program. The program
> >>maps a large (512gb) chunk
> >>of address space, but "only" about 20mb of that are mapped with permissions
> >>that allow any of read,
> >>write, or execute access. (The atypical memory mapping is done for what I
> >>believe to be very good
> >>reasons and I don't think that those reasons are directly relevant here.)
> >>
> >>Some of the code that I an trying to profile is on pages that have read and
> >>execute permissions
> >>and atypically "high" addresses, often of the form 0000300000xxxxxx,  If
> >>anyone reading this would
> >>find it helpful, I can certainly provide a copy of /proc/<pid>/maps or
> >>similar for a typical instance
> >>of the process.  As far as I know, few (if any) pages in the process are
> >>locked via mlock() or variants.
> >>
> >>For the sake of argument, it may be helpful to think of that code as having
> >>been "JITted" there.  it is
> >>not mapped from an ELF executable or library, and my later questions may
> >>have to do with the .map file
> >>that I am trying to use to provide symbolic information
> >Right, see tools/perf/Documentation/jit-interface.txt to see how to
> >provide that map.
> >
> >if you could provide the minimal reproducer for this, i.e. a simple
> >program that does the kind of mapping you described and when monitored
> >produces the error being reported. But please try bumping
> >/proc/sys/kernel/perf_event_mlock_kb first.
> >>
> >>--
> >>To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> >>the body of a message to majordomo@vger.kernel.org
> >>More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 

> 00012000-00014000 rwxp 00000000 08:07 18350962                           /usr/local/src/ccl/lx86cl64.image
> 00015000-00016000 rwxp 00000000 00:00 0 
> 00400000-00430000 r-xp 00000000 08:07 18375976                           /usr/local/src/ccl/lx86cl64
> 00630000-00631000 r-xp 00030000 08:07 18375976                           /usr/local/src/ccl/lx86cl64
> 00631000-00632000 rwxp 00031000 08:07 18375976                           /usr/local/src/ccl/lx86cl64
> 00632000-00633000 rwxp 00000000 00:00 0 
> 00edd000-00f22000 rwxp 00000000 00:00 0                                  [heap]
> 300000000000-300000fc6000 r-xp 00002000 08:07 18350962                   /usr/local/src/ccl/lx86cl64.image
> 300000fc6000-300000fc8000 rwxp 00fc8000 08:07 18350962                   /usr/local/src/ccl/lx86cl64.image
> 300000fc8000-300001559000 r-xp 00fca000 08:07 18350962                   /usr/local/src/ccl/lx86cl64.image
> 300001559000-300040000000 ---p 00000000 00:00 0 
> 300040000000-300040568000 rwxp 019d9000 08:07 18350962                   /usr/local/src/ccl/lx86cl64.image
> 300040568000-302000000000 ---p 00000000 00:00 0 
> 302000000000-30200047e000 rwxp 0155b000 08:07 18350962                   /usr/local/src/ccl/lx86cl64.image
> 30200047e000-302002480000 rwxp 00000000 00:00 0 
> 302002480000-307bfe000000 ---p 00000000 00:00 0 
> 307bfe000000-307bfe04a000 rwxp 00000000 00:00 0 
> 307bfe04a000-307dfe000000 ---p 00000000 00:00 0 
> 307dfe000000-307e0000b000 rwxp 00000000 00:00 0 
> 307e0000b000-307e3f800000 ---p 00000000 00:00 0 
> 307e3f800000-307e3f84a000 rwxp 00000000 00:00 0 
> 307e3f84a000-308000020000 ---p 00000000 00:00 0 
> 7ffb54000000-7ffb54021000 rwxp 00000000 00:00 0 
> 7ffb54021000-7ffb58000000 ---p 00000000 00:00 0 
> 7ffb5aeee000-7ffb5af08000 r-xp 00000000 00:00 0 
> 7ffb5af08000-7ffb5b109000 rwxp 00000000 00:00 0 
> 7ffb5b109000-7ffb5b10a000 ---p 00000000 00:00 0 
> 7ffb5b10a000-7ffb5b36d000 rwxp 00000000 00:00 0                          [stack:28309]
> 7ffb5b36d000-7ffb5b387000 r-xp 00000000 00:00 0 
> 7ffb5b387000-7ffb5b5bb000 rwxp 00000000 00:00 0 
> 7ffb5b5bb000-7ffb5b7b6000 ---p 00000000 00:00 0 
> 7ffb5b7b6000-7ffb5b7c1000 rwxp 01f41000 08:07 18350962                   /usr/local/src/ccl/lx86cl64.image
> 7ffb5b7c1000-7ffb7b3b6000 ---p 00000000 00:00 0 
> 7ffb7b3b6000-7ffb7b576000 r-xp 00000000 08:07 266583                     /lib/x86_64-linux-gnu/libc-2.21.so
> 7ffb7b576000-7ffb7b776000 ---p 001c0000 08:07 266583                     /lib/x86_64-linux-gnu/libc-2.21.so
> 7ffb7b776000-7ffb7b77a000 r-xp 001c0000 08:07 266583                     /lib/x86_64-linux-gnu/libc-2.21.so
> 7ffb7b77a000-7ffb7b77c000 rwxp 001c4000 08:07 266583                     /lib/x86_64-linux-gnu/libc-2.21.so
> 7ffb7b77c000-7ffb7b780000 rwxp 00000000 00:00 0 
> 7ffb7b780000-7ffb7b787000 r-xp 00000000 08:07 266727                     /lib/x86_64-linux-gnu/librt-2.21.so
> 7ffb7b787000-7ffb7b986000 ---p 00007000 08:07 266727                     /lib/x86_64-linux-gnu/librt-2.21.so
> 7ffb7b986000-7ffb7b987000 r-xp 00006000 08:07 266727                     /lib/x86_64-linux-gnu/librt-2.21.so
> 7ffb7b987000-7ffb7b988000 rwxp 00007000 08:07 266727                     /lib/x86_64-linux-gnu/librt-2.21.so
> 7ffb7b988000-7ffb7b9a0000 r-xp 00000000 08:07 266719                     /lib/x86_64-linux-gnu/libpthread-2.21.so
> 7ffb7b9a0000-7ffb7bba0000 ---p 00018000 08:07 266719                     /lib/x86_64-linux-gnu/libpthread-2.21.so
> 7ffb7bba0000-7ffb7bba1000 r-xp 00018000 08:07 266719                     /lib/x86_64-linux-gnu/libpthread-2.21.so
> 7ffb7bba1000-7ffb7bba2000 rwxp 00019000 08:07 266719                     /lib/x86_64-linux-gnu/libpthread-2.21.so
> 7ffb7bba2000-7ffb7bba6000 rwxp 00000000 00:00 0 
> 7ffb7bba6000-7ffb7bcad000 r-xp 00000000 08:07 266645                     /lib/x86_64-linux-gnu/libm-2.21.so
> 7ffb7bcad000-7ffb7beac000 ---p 00107000 08:07 266645                     /lib/x86_64-linux-gnu/libm-2.21.so
> 7ffb7beac000-7ffb7bead000 r-xp 00106000 08:07 266645                     /lib/x86_64-linux-gnu/libm-2.21.so
> 7ffb7bead000-7ffb7beae000 rwxp 00107000 08:07 266645                     /lib/x86_64-linux-gnu/libm-2.21.so
> 7ffb7beae000-7ffb7beb1000 r-xp 00000000 08:07 266602                     /lib/x86_64-linux-gnu/libdl-2.21.so
> 7ffb7beb1000-7ffb7c0b0000 ---p 00003000 08:07 266602                     /lib/x86_64-linux-gnu/libdl-2.21.so
> 7ffb7c0b0000-7ffb7c0b1000 r-xp 00002000 08:07 266602                     /lib/x86_64-linux-gnu/libdl-2.21.so
> 7ffb7c0b1000-7ffb7c0b2000 rwxp 00003000 08:07 266602                     /lib/x86_64-linux-gnu/libdl-2.21.so
> 7ffb7c0b2000-7ffb7c0d6000 r-xp 00000000 08:07 266555                     /lib/x86_64-linux-gnu/ld-2.21.so
> 7ffb7c11d000-7ffb7c12d000 rwxp 00000000 00:00 0 
> 7ffb7c12d000-7ffb7c14f000 r-xp 00000000 00:00 0 
> 7ffb7c14f000-7ffb7c250000 rwxp 00000000 00:00 0 
> 7ffb7c250000-7ffb7c272000 r-xp 00000000 00:00 0 
> 7ffb7c272000-7ffb7c2b7000 rwxp 00000000 00:00 0 
> 7ffb7c2c2000-7ffb7c2d5000 rwxp 00000000 00:00 0 
> 7ffb7c2d5000-7ffb7c2d6000 r-xp 00023000 08:07 266555                     /lib/x86_64-linux-gnu/ld-2.21.so
> 7ffb7c2d6000-7ffb7c2d7000 rwxp 00024000 08:07 266555                     /lib/x86_64-linux-gnu/ld-2.21.so
> 7ffb7c2d7000-7ffb7c2d8000 rwxp 00000000 00:00 0 
> 7fff7a102000-7fff7a123000 rwxp 00000000 00:00 0                          [stack]
> 7fff7a1b4000-7fff7a1b6000 r--p 00000000 00:00 0                          [vvar]
> 7fff7a1b6000-7fff7a1b8000 r-xp 00000000 00:00 0                          [vdso]
> ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0                  [vsyscall]

^ permalink raw reply related	[flat|nested] 5+ messages in thread

* Re: odd error from "perf record"
  2016-01-19 22:14     ` Arnaldo Carvalho de Melo
@ 2016-01-20  1:31       ` Gary Byers
  0 siblings, 0 replies; 5+ messages in thread
From: Gary Byers @ 2016-01-20  1:31 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo; +Cc: linux-perf-users



On 01/19/2016 03:14 PM, Arnaldo Carvalho de Melo wrote:
> Em Sat, Jan 16, 2016 at 01:55:49PM -0700, Gary Byers escreveu:
>> thanks.  I can work around the problem described in my previous message, but
>> the problem
>> that I describe below is harder for me to describe and I  don't know exactly
>> where the
>> problem might be and of course don't know how to work around it
>   
>> The code that I am trying to profile is written in Clozure Common Lisp (CCL(
>> <http://ccl.clozure.com>.
>> the memory regions that I am most interested in profiling contain lisp code;
>> other regions mapped by
>> the process are mapped to ELF files which do not seem to exhibit problems.
>>
>> the problems that I am most concerned about involve profiling compiled Lisp
>> code, and a (somewhat
>> rambling) description of that problem and steps to reproduce it follows.
>>
>> A copy of /proc/<pid>/maps for a running CCL process is enclosed as
>> "mail.txt", the memory map
>> shown in that file is "typical" of a CCL process but may not be as typical
>> of programs written
>> in other development systems.
>>
>>
>>
>> I would like to be able to use "perf record ..." and "perf report" to
>> profile that
>> code, and was able to do so for many years.  the details of how I was able
> If so, would it be possible for you to use 'git bisect' on a kernel that
> works with a recent kernel sources so that you can go on building just
> the tooling side and testing it to check if the problem is tooling
> related?
>
> Or have you checked that already, i.e. is it a single perf tool version
> with different kernel that causes the problem?
>
> I use these scripts to do a git bisect run, i.e. automated bisection:
>
> [acme@zoo ~]$ cat ~/bin/mbisect
> #!/bin/bash
>
> rm -rf /tmp/build/perf ; mkdir -p /tmp/build/perf ; make O=/tmp/build/perf -C tools/perf install-bin > /tmp/log.m 2>&1 || exit 125
> ptest $1
> [acme@zoo ~]$ cat ~/bin/ptest
> #!/bin/sh
>
> perf test $1 2>&1 | grep -q Ok$
>
> ------------------------
>
> Just replace that ptest one with whatever you have that returns 0 for ok, 1 for
> problems.
>
> bisecting the kernel is possible but takes longer as reboots will have to be
> performed.
>
>> to do so
>> are (probably) not relevant, but did not involve a /tmp/<pid>/map file when
>> I used
>> earlier Linux kernels
> Define "earlier", what version?


I started noticing the problem after upgrading from Ubuntu 14.10 and 
Linux 3.13.x
to Ubuntu 15.04 and Linux 3.19.

I have a version of the .image file that I created "the old way", using 
some utilities
defined in libelf.so to try to fool perf into believing that the memory 
regions were
mapped by the dynamic linker.  The "file" command is at least partly fooled

~] gb@abq> file perfccl.image
perfccl.image: ELF 64-bit LSB shared object, x86-64, version 1 (SYSV), 
statically linked, not stripped

and I suspect that the point where things seem to have stopped working 
may be around the time
that perf stopped  being fooled by this.


>
>> The perf map file that I have been creating recently contains entries of the
>> form
>>
>> 000030000010D000 2411 CCL::+-2
>> 000030000010F490 25F9 CCL::--2
>> 0000300000111B10 1531 CCL::*-2
>> 00003000001130F0 2C29 CCL::/-2
>> 0000300000115DB0 1EB1 CCL::=-2
>> 0000300000117CD0 59 CCL::/=-2
>>
>> those entries were in a text file named /tmp/perf-22415.map.
>> for a process whose pid was 22415 when I ran "perf record ..."
>> the .map file contains a few thousand such entries.
> So, these will be used, IIRC, if this is an anonymous map
>
>> the output that I get from 'perf report .. "   -with or without
>> a ,map file -  looks like
>>
>>      14.97%  lx86cl64  lx86cl64           [.] zero_dnodes
>>      14.55%  lx86cl64  lx86cl64.image     [.] 0x000000000011da1d
>>      11.55%  lx86cl64  lx86cl64.image     [.] 0x000000000011da11
>>       9.34%  lx86cl64  lx86cl64.image     [.] 0x000000000011da24
>>
>> where "lx86cl64" is an ELF executable and "lx86cl64.image" is a file from
>> which
>> the memory regions described by the perf  .map file are mmapped. Note that
>> the addresses
>> in the "perf report" output do not seem to have much to do with the address
>> ranges
>> described in the perf .map file, though they might be correct in some of
>> their low bits.
> They are offsets to the map where they were found, so if you look at the
> /proc/PID/maps and add the mmap where the lx86cl64.image is + the values you
> see above, you'll get the virtual address, like you used in that
> /tmp/perf-PID.map.

thanks
>   
>> If this is indeed a problem in 'perf' or related kernel components, as it
>> appears to be, I believe that it may have been
>> introduced sometime after Linux 3.13 and sometime before 3.19.
>>
>> In the code that I was running, the entries for the code from the ELF file
>> (lx86cl64) look
>> plausible and may be correct,  The number of addresses reported for the code
>> mapped from
>> the lx86cl64.image file seems plausible. but the addresses themselves do
>> not.
> See the comment above.
>
> so, from your /proc/pid/map file, we see:
>
>> 300000000000-300000fc6000 r-xp 00002000 08:07 18350962     /usr/local/src/ccl/lx86cl64.image
>> 300000fc6000-300000fc8000 rwxp 00fc8000 08:07 18350962     /usr/local/src/ccl/lx86cl64.image
>> 300000fc8000-300001559000 r-xp 00fca000 08:07 18350962     /usr/local/src/ccl/lx86cl64.image
>> 300040000000-300040568000 rwxp 019d9000 08:07 18350962     /usr/local/src/ccl/lx86cl64.image
>> 302000000000-30200047e000 rwxp 0155b000 08:07 18350962     /usr/local/src/ccl/lx86cl64.image
> Which will make it try to find symbols in /usr/local/src/ccl/lx86cl64.image, which,
> looking at your tarball, I see as:
>
> [acme@zoo ccl]$ file lx86cl64.image
> lx86cl64.image: data
>
> So, it would have to fallback to using the method it uses for anonymous maps to
> be able to use that /tmp/perf-PID.map file, that would be the explanation for
> it to work in that distant past, that I would have to check if it would be the case...
>
> Yeah, for such a case, where you have a pathname but that pathname is not to a
> file with a symtab, we would have to save the pid in the struct map, then at
> map__load() time notice that we didn't managed to load any symtab, then try to
> do what map__new does at this point:
>
>                  if ((anon || no_dso) && type == MAP__FUNCTION) {
>                          snprintf(newfilename, sizeof(newfilename), "/tmp/perf-%d.map", pid);
>                          filename = newfilename;
>                  }
>
> Then replace map->dso with:
>
>        dso = machine__findnew_dso(machine, filename);
>
> A hack just for your usecase would be to make it think it is anonymous memory if the filename
> ends in ".image", then it would use the /tmp/perf-%d.map method.
>
> Quick hack, maybe will help you.
>
> diff --git a/tools/perf/util/map.c b/tools/perf/util/map.c
> index 171b6d1..d4d706f 100644
> --- a/tools/perf/util/map.c
> +++ b/tools/perf/util/map.c
> @@ -154,7 +154,7 @@ struct map *map__new(struct machine *machine, u64 start, u64 len,
>   		int anon, no_dso, vdso, android;
>   
>   		android = is_android_lib(filename);
> -		anon = is_anon_memory(filename);
> +		anon = is_anon_memory(filename) || strstr(filename, ".image");
>   		vdso = is_vdso_map(filename);
>   		no_dso = is_no_dso_memory(filename);
>   
>
> Having it as anonymous, as you can see a little later in map__new() will
> make it a identity map:
>
>    if (anon || no_dso) {
>        map->map_ip = map->unmap_ip = identity__map_ip;
>
>
> I.e. your symtab, that /tmp/perf-PID.map can have virtual address, and unresolved
> symbols will appear not as offsets, as they are appearing now.
Thanks

Do I understand correctly that is_anon_memory()  currently returns false 
(and causes the variable anon
to be set to false), and if the memory regions were mapped differently 
when the .image file was mmapped
so that (is_anon_memory() returned true) that might have the the same 
effect on map->map_ip  and friends?

I'll look as is_anon_memory and see if it means what I think it does, 
and have a few more ideas about how
to proceed now, which is a few more ideas than I've had to this point.

Thanks again.

^ permalink raw reply	[flat|nested] 5+ messages in thread

end of thread, other threads:[~2016-01-20  1:31 UTC | newest]

Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-01-15 20:35 odd error from "perf record" Gary Byers
2016-01-15 21:17 ` Arnaldo Carvalho de Melo
2016-01-16 20:55   ` Gary Byers
2016-01-19 22:14     ` Arnaldo Carvalho de Melo
2016-01-20  1:31       ` Gary Byers

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.