Bug 486569 - No samples collected by oprofile
Summary: No samples collected by oprofile
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: oprofile
Version: 10
Hardware: x86_64
OS: Linux
low
high
Target Milestone: ---
Assignee: William Cohen
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2009-02-20 11:55 UTC by Richard Morgan
Modified: 2009-04-21 13:50 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2009-04-21 13:50:30 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
oprofiled log (1.50 KB, application/octet-stream)
2009-02-20 12:01 UTC, Richard Morgan
no flags Details
oprofiled log (1.50 KB, text/plain)
2009-02-20 12:02 UTC, Richard Morgan
no flags Details
script to test oprofile data collection (257 bytes, text/plain)
2009-04-10 01:51 UTC, William Cohen
no flags Details
Output of the script showing data being collected on an F-10 machine (10.56 KB, application/octet-stream)
2009-04-10 01:53 UTC, William Cohen
no flags Details
Output of the script on the machine that is failing. (2.33 KB, text/plain)
2009-04-20 09:32 UTC, Richard Morgan
no flags Details
The daemonrc file when the collection was failing (360 bytes, text/plain)
2009-04-21 08:54 UTC, Richard Morgan
no flags Details

Description Richard Morgan 2009-02-20 11:55:10 UTC
Description of problem:
No samples are written following a profiling session, therefore no results are available. The oprofiled log file (attached) shows that samples were received, however the directory /var/lib/oprofile/samples/current is empty.

Version-Release number of selected component (if applicable):
opcontrol: oprofile 0.9.4 compiled on Sep 29 2008 14:41:59

Steps to Reproduce:
1.opcontrol --status
2.opcontrol --start
3.sleep 10; opcontrol --shutdown
4.opreport
  
Actual results:
[root@u-morganr ~]# opcontrol --status
Daemon not running
Event 0: CPU_CLK_UNHALTED:100000:0:1:1
Event 1: INST_RETIRED_ANY_P:1197026:0:1:1
Separate options: none
vmlinux file: /usr/lib/debug/lib/modules/2.6.27.15-170.2.24.fc10.x86_64/vmlinux
Image filter: all
Call-graph depth: 0
Buffer size: 65536
[root@u-morganr ~]# opcontrol --start
Using 2.6+ OProfile kernel interface.
Reading module info.
Using log file /var/lib/oprofile/samples/oprofiled.log
Daemon started.
Profiler running.
[root@u-morganr ~]# sleep 10; opcontrol --shutdown
Stopping profiling.
Killing daemon.
[root@u-morganr ~]# opreport
opreport error: No sample file found: try running opcontrol --dump
or specify a session containing sample files


Expected results:
As above, but with a list of images and the percentage of time spent in each instead of the error message from opreport

Additional info:
[root@u-morganr richard]# uname -r
2.6.27.15-170.2.24.fc10.x86_64

[root@u-morganr richard]# cat /proc/cpuinfo
processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 15
model name	: Intel(R) Core(TM)2 CPU          6600  @ 2.40GHz
stepping	: 6
cpu MHz		: 2394.050
cache size	: 4096 KB
physical id	: 0
siblings	: 2
core id		: 0
cpu cores	: 2
apicid		: 0
initial apicid	: 0
fpu		: yes
fpu_exception	: yes
cpuid level	: 10
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm constant_tsc arch_perfmon pebs bts rep_good nopl pni monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr lahf_lm
bogomips	: 4788.10
clflush size	: 64
cache_alignment	: 64
address sizes	: 36 bits physical, 48 bits virtual
power management:

processor	: 1
vendor_id	: GenuineIntel
cpu family	: 6
model		: 15
model name	: Intel(R) Core(TM)2 CPU          6600  @ 2.40GHz
stepping	: 6
cpu MHz		: 2394.050
cache size	: 4096 KB
physical id	: 0
siblings	: 2
core id		: 1
cpu cores	: 2
apicid		: 1
initial apicid	: 1
fpu		: yes
fpu_exception	: yes
cpuid level	: 10
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm constant_tsc arch_perfmon pebs bts rep_good nopl pni monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr lahf_lm
bogomips	: 4788.14
clflush size	: 64
cache_alignment	: 64
address sizes	: 36 bits physical, 48 bits virtual
power management:

[root@u-morganr richard]# lsmod
Module                  Size  Used by
oprofile               42080  1 
bridge                 56224  0 
stp                    10756  1 bridge
bnep                   22016  2 
sco                    19204  2 
l2cap                  28544  3 bnep
bluetooth              60068  5 bnep,sco,l2cap
sunrpc                191208  3 
nf_conntrack_netbios_ns    10880  0 
nf_conntrack_ftp       16696  0 
ip6t_REJECT            12160  2 
nf_conntrack_ipv6      22984  20 
ip6table_filter        11136  1 
ip6_tables             26128  1 ip6table_filter
ipv6                  287400  38 ip6t_REJECT,nf_conntrack_ipv6
fuse                   60992  4 
dm_multipath           23704  0 
uinput                 16128  0 
snd_hda_intel         480160  3 
mptsas                 39696  1 
snd_seq_dummy          11396  0 
snd_seq_oss            39104  0 
snd_seq_midi_event     14848  1 snd_seq_oss
mptscsih               38784  1 mptsas
snd_seq                61968  5 snd_seq_dummy,snd_seq_oss,snd_seq_midi_event
mptbase                79332  2 mptsas,mptscsih
snd_seq_device         15380  3 snd_seq_dummy,snd_seq_oss,snd_seq
scsi_transport_sas     36224  1 mptsas
snd_pcm_oss            52224  0 
i82975x_edac           13064  0 
pcspkr                 11008  0 
shpchp                 38300  0 
serio_raw              14084  0 
iTCO_wdt               20176  0 
snd_mixer_oss          23168  1 snd_pcm_oss
snd_pcm                85512  2 snd_hda_intel,snd_pcm_oss
edac_core              48576  1 i82975x_edac
iTCO_vendor_support    11652  1 iTCO_wdt
ppdev                  15752  0 
snd_timer              30352  2 snd_seq,snd_pcm
dcdbas                 15920  0 
nvidia               8117992  26 
snd_page_alloc         16656  2 snd_hda_intel,snd_pcm
snd_hwdep              16392  1 snd_hda_intel
i2c_i801               17820  0 
i2c_core               29216  2 nvidia,i2c_i801
skge                   47888  0 
parport_pc             34200  0 
snd                    68984  16 snd_hda_intel,snd_seq_dummy,snd_seq_oss,snd_seq,snd_seq_device,snd_pcm_oss,snd_mixer_oss,snd_pcm,snd_timer,snd_hwdep
soundcore              14992  1 snd
tg3                   122500  0 
libphy                 25600  1 tg3
parport                42784  2 ppdev,parport_pc
ata_generic            13956  0 
pata_acpi              13056  0

Comment 1 Richard Morgan 2009-02-20 12:01:25 UTC
Created attachment 332694 [details]
oprofiled log

Comment 2 Richard Morgan 2009-02-20 12:02:38 UTC
Created attachment 332695 [details]
oprofiled log

Comment 3 William Cohen 2009-04-10 01:51:38 UTC
Created attachment 339038 [details]
script to test oprofile data collection

I wrote a little script to exercise things and I tried running it on a similar F10 machine with core2 process with a newer kernel and oprofile (just in koji build system).

$ uname -a
Linux tandem 2.6.27.19-170.2.35.fc10.x86_64 #1 SMP Mon Feb 23 13:00:23 EST 2009 
x86_64 x86_64 x86_64 GNU/Linux
$ rpm -q oprofile
oprofile-0.9.4-6.fc10.x86_64

The oprofile is available from
http://koji.fedoraproject.org/koji/buildinfo?buildID=97193

The resulting output show that samples are being taken for both events. Could you check to see whether the newer kernel/oprofile combination resolve this problem? Did some earlier combination kernel/oprofile allow data collection on the particular machine that the problem was observed on? If oprofile never worked on the machine then there might be some problem with interrupt routing. Is there a smolt entry describing the machine?

Comment 4 William Cohen 2009-04-10 01:53:18 UTC
Created attachment 339039 [details]
Output of the script showing data being collected on an F-10 machine

This output shows that the script is collecting data on the machine. What does the output look like on the problem machine?

Comment 5 Richard Morgan 2009-04-20 09:32:10 UTC
Created attachment 340308 [details]
Output of the script on the machine that is failing.

I ran the script as suggested, with a newer version of the kernel/oprofile. I also made a smolt entry available;

http://www.smolts.org/show?uuid=pub_01888ff4-6fc8-45b6-9aa9-c3db518672da

I have had oprofile working on this machine (on either F8 or F9), I think I even got some results when I very first installed F10. I'll be moving to clean install of F11 at some point, so I should have some more info then.

Comment 6 William Cohen 2009-04-20 15:51:54 UTC
Try to narrow down the problem between the userspace package and the kernel. Could you attach:

/var/lib/oprofile/samples/oprofiled.log
/root/.oprofile/daemonrc

One possibility is there is a IMAGE_FILTER in the daemonrc and that would result in no samples. Try removing the /root/.oprofile/daemonrc and running the experiment.

OProfile uses the NMI interrupts you should be able to see non-zero numbers after running data collection with:

$ more /proc/interrupts |grep NMI
 NMI:      10480       6935   Non-maskable interrupts

This would indicate the kernel is taking samples.

Comment 7 Richard Morgan 2009-04-21 08:54:49 UTC
Created attachment 340487 [details]
The daemonrc file when the collection was failing

After removing this file daemonrc the experiment did produce results. Looks like the problem was a misconfiguration, sorry!

failing:
IMAGE_FILTER=all
BUF_SIZE=65536
BUF_WATERSHED=32768
CPU_BUF_SIZE=65536
CALLGRAPH=0
KERNEL_RANGE=ffffffff81000000,ffffffff8133a892

succeeding:
IMAGE_FILTER=
CPU_BUF_SIZE=0
CALLGRAPH=0

I'm not quite sure how I got the config file to that state - I was using oprofile_gui, I may have manually editted as well. I guess you can marked this notabug...

Comment 8 William Cohen 2009-04-21 13:50:30 UTC
The behavior is to read in the existing daemonrc changing what is specified by "opcontrol --setup". It would be more intuitive if the "opcontrol --setup" started with a clean slate.


Note You need to log in before you can comment on or make changes to this bug.