#291 Oprofile fails to run on ARM iMX.6 boards

[Ricky]

Hi,

I am just trying to use the profiling tools, used Yocto & buildroot buildsystem to crosscompile the oprofile by enabling the kernel profiling tokens. Previously 1.1.0 version was working good. But the new version 1.3.0 fails as below. Could you help me to debug this further?

root@beaglebone-yocto:~# operf -version
Unexpected error running operf: Operation not supported

[William Cohen]

It doesn't look like "Operation not support" is coming from operf. The message doesn't seem to be in the oprofile source code. could you do a "which operf" to check to see which operf is being run? Could you give more destails on how oprofile-1.3.0 was built and installed on the machine? Where is oprofile installed on the machine? You might try to use the full path to make sure that the desired one is being used. Is it possible run "strace operf --version" to get a better idea when and where things go wrong?

If you go back to installing oprofile-1.1.0 everything works fine?

[Ricky]

Hi William,

Yes I too grep from the same and found none, but I could see the profiling works good when the version was downgraded to 1.1.0.

Just added the profiling tools and oprofile from meta-Openembedded in yocto & selected oprofile from Buildroot. Found the same issue.

Here is the log;

root@beaglebone-yocto:~# strace operf --version
execve("/usr/bin/operf", ["operf", "--version"], 0xbec3ad94 /* 15 vars */) = 0
brk(NULL)                               = 0x50c000
uname({sysname="Linux", nodename="beaglebone-yocto", ...}) = 0
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f43000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=21819, ...}) = 0
mmap2(NULL, 21819, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb6f3d000
close(3)                                = 0
openat(AT_FDCWD, "/usr/lib/libstdc++.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0000\343\6\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=11548400, ...}) = 0
mmap2(NULL, 1331004, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6dd0000
mprotect(0xb6efd000, 65536, PROT_NONE)  = 0
mmap2(0xb6f0d000, 28672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x12d000) = 0xb6f0d000
mmap2(0xb6f14000, 3900, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb6f14000
close(3)                                = 0
openat(AT_FDCWD, "/lib/libgcc_s.so.1", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\10\321\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=8399028, ...}) = 0
mmap2(NULL, 180284, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6da3000
mprotect(0xb6dbf000, 61440, PROT_NONE)  = 0
mmap2(0xb6dce000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b000) = 0xb6dce000
close(3)                                = 0
openat(AT_FDCWD, "/lib/tls/v7l/neon/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/v7l/neon/vfp", 0xbef4a1b8) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/v7l/neon/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/v7l/neon", 0xbef4a1b8) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/v7l/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/v7l/vfp", 0xbef4a1b8)  = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/v7l/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/v7l", 0xbef4a1b8)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/neon/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/neon/vfp", 0xbef4a1b8) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/neon/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/neon", 0xbef4a1b8)     = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/vfp", 0xbef4a1b8)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls", 0xbef4a1b8)          = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/v7l/neon/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/v7l/neon/vfp", 0xbef4a1b8) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/v7l/neon/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/v7l/neon", 0xbef4a1b8)     = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/v7l/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/v7l/vfp", 0xbef4a1b8)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/v7l/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/v7l", 0xbef4a1b8)          = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/neon/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/neon/vfp", 0xbef4a1b8)     = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/neon/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/neon", 0xbef4a1b8)         = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/vfp", 0xbef4a1b8)          = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\34\256\1\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=16267100, ...}) = 0
mmap2(NULL, 1312744, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6c62000
mprotect(0xb6d8d000, 65536, PROT_NONE)  = 0
mmap2(0xb6d9d000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x12b000) = 0xb6d9d000
mmap2(0xb6da1000, 6120, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb6da1000
close(3)                                = 0
openat(AT_FDCWD, "/lib/libm.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0000\217\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=2454084, ...}) = 0
mmap2(NULL, 442384, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6bf5000
mprotect(0xb6c51000, 61440, PROT_NONE)  = 0
mmap2(0xb6c60000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5b000) = 0xb6c60000
close(3)                                = 0
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f3b000
set_tls(0xb6f3b4d0)                     = 0
mprotect(0xb6d9d000, 8192, PROT_READ)   = 0
mprotect(0xb6c60000, 4096, PROT_READ)   = 0
mprotect(0xb6dce000, 4096, PROT_READ)   = 0
mprotect(0xb6f0d000, 24576, PROT_READ)  = 0
mprotect(0x4e4000, 4096, PROT_READ)     = 0
mprotect(0xb6f45000, 4096, PROT_READ)   = 0
munmap(0xb6f3d000, 21819)               = 0
brk(NULL)                               = 0x50c000
brk(0x52d000)                           = 0x52d000
openat(AT_FDCWD, "/dev/null", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 3
openat(AT_FDCWD, "/proc/sys/kernel/perf_event_paranoid", O_RDONLY) = 4
fstat64(4, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
read(4, "2\n", 1024)                    = 2
close(4)                                = 0
geteuid32()                             = 0
gettimeofday({tv_sec=1568181826, tv_usec=582568}, NULL) = 0
openat(AT_FDCWD, "/sys/devices/system/cpu/online", O_RDONLY|O_CLOEXEC) = 4
read(4, "0\n", 8192)                    = 2
close(4)                                = 0
openat(AT_FDCWD, "/sys/devices/system/cpu/online", O_RDONLY) = 4
fstat64(4, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
read(4, "0\n", 4096)                    = 2
close(4)                                = 0
getpid()                                = 392
perf_event_open({type=PERF_TYPE_HARDWARE, size=PERF_ATTR_SIZE_VER5, config=PERF_COUNT_HW_CPU_CYCLES, ...}, 392, 0, -1, 0) = -1 EOPNOTSUPP (Operation not supported)
write(2, "Unexpected error running operf: ", 32Unexpected error running operf: ) = 32
write(2, "Operation not supported", 23Operation not supported) = 23
write(2, "\n", 1
)                       = 1
close(3)                                = 0
exit_group(1)                           = ?
+++ exited with 1 +++
root@beaglebone-yocto:~#

root@beaglebone-yocto:~# which operf 
/usr/bin/operf

[Ricky]

Hi,

I too grep for the same and didn't get any way to trace this.

I just build the package from Yocto (meta-openembedded) and buildroot both, which yields the same.

If you go back to installing oprofile-1.1.0 everything works fine?

Yes with the same build system for 1.1.0 was working good.

Find the attached strace log and which operf

[William Cohen]

What does the strace output look like for the oprofile-1.1.0 operf?
Does the oprofile-1.1.0 build have any patches in it? Or is it the completely stock oprofile-1.1.0?