odd error from "perf record"

DISCUSSION Gary Byers 2 participants 5 messages Jan 15, 2016 – Jan 20, 2016 perf events

lore

Share & tools

lore

Gary Byers

author

2016-01-15 20:42 UTC #0 lore raw

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,

Arnaldo Carvalho de Melo

maintainer

2016-01-15 21:18 UTC #1 lore raw

Em Fri, Jan 15, 2016 at 01:35:05PM -0700, Gary Byers escreveu:

Quoted 26 lines

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.

Quoted 5 lines

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.

Quoted 11 lines

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.

Quoted 18 lines

[~] 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

Quoted 6 lines

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.

Quoted 6 lines

--
To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Gary Byers

author

2016-01-16 20:55 UTC #2 lore raw

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.

Quoted 33 lines · Arnaldo Carvalho de Melo

Em Fri, Jan 15, 2016 at 01:35:05PM -0700, Gary Byers escreveu:
Quoted 26 lines
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.
Quoted 5 lines
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

Quoted 9 lines

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.
Quoted 5 lines
--
To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in the body of a message to [email protected]
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]

Arnaldo Carvalho de Melo

maintainer

2016-01-19 22:14 UTC #3 lore raw

Em Sat, Jan 16, 2016 at 01:55:49PM -0700, Gary Byers escreveu:

Quoted 24 lines

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.

Quoted 3 lines

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.

Quoted 4 lines

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?

Quoted 10 lines

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

Quoted 3 lines

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

Quoted 9 lines

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

Quoted 8 lines

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.

Quoted 10 lines

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:

Quoted 5 lines

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.

tools/perf/util/map.c +1 -1

index 171b6d1..d4d706f 100644
@@ -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.

Quoted 240 lines

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.
Quoted 33 lines · Arnaldo Carvalho de Melo
Em Fri, Jan 15, 2016 at 01:35:05PM -0700, Gary Byers escreveu:
Quoted 26 lines
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.
Quoted 5 lines
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
Quoted 12 lines
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.
Quoted 5 lines
--
To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in the body of a message to [email protected]
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]

Gary Byers

author

2016-01-20 01:31 UTC #4 lore raw

Quoted 53 lines · Arnaldo Carvalho de Melo

Em Sat, Jan 16, 2016 at 01:55:49PM -0700, Gary Byers escreveu:
Quoted 24 lines
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.
Quoted 3 lines
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.

Quoted 8 lines

bisecting the kernel is possible but takes longer as reboots will have to be performed.
Quoted 4 lines
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.

Quoted 32 lines

Quoted 11 lines
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
Quoted 3 lines
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
Quoted 8 lines
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
Quoted 8 lines
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.

Quoted 4 lines

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

Quoted 66 lines

Quoted 11 lines
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:
Quoted 5 lines
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.
tools/perf/util/map.c +1 -1
index 171b6d1..d4d706f 100644
@@ -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:

Quoted 6 lines

   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.