Bug 604732

Summary: "trace-cmd report" fails to generate useful output
Product: Red Hat Enterprise Linux 6 Reporter: William Cohen <wcohen>
Component: trace-cmdAssignee: John Kacur <jkacur>
Status: CLOSED CURRENTRELEASE QA Contact: Red Hat Kernel QE team <kernel-qe>
Severity: medium Docs Contact:
Priority: low    
Version: 6.0CC: srostedt
Target Milestone: rc   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: trace-cmd-1.0.2-6.el6 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-08-12 20:00:58 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
compressed trace.dat file that demonstrates problem
none
patch to not crash on FORMAT TOO BIG error from kernel none

Description William Cohen 2010-06-16 15:48:20 UTC
Description of problem:

Attempted to follow the steps listed http://lwn.net/Articles/383334/ to try out RHEL-6 trace-cmd. 

Version-Release number of selected component (if applicable):

trace-cmd-1.0.1-5.el6.x86_64

How reproducible:

All the time


Steps to Reproduce:
1. trace-cmd record -p function ls
2. trace-cmd report

  
Actual results:

# trace-cmd record -p function ls
  plugin function
disable all
anaconda-ks.cfg  install.log.syslog  trace.dat.cpu0  trace.dat.cpu2
install.log	 trace.dat	     trace.dat.cpu1  trace.dat.cpu3
offset=380000
offset=41c000
offset=46d000
offset=55e000
Kernel buffer statistics:
  Note: "entries" are the entries left in the kernel ring buffer and are not
        recorded in the trace data. They should all be zero.

CPU: 0
entries: 0
overrun: 0
commit overrun: 0

CPU: 1
entries: 0
overrun: 0
commit overrun: 0

CPU: 2
entries: 0
overrun: 0
commit overrun: 0

CPU: 3
entries: 0
overrun: 0
commit overrun: 0

# trace-cmd report
version = 6
trace-cmd: No such file or directory
  bad op token {
  failed to read event print fmt for kvm_mmu_get_page
  bad op token {
  failed to read event print fmt for kvm_mmu_sync_page
  bad op token {
  failed to read event print fmt for kvm_mmu_unsync_page
  bad op token {
  failed to read event print fmt for kvm_mmu_zap_page
  Error: expected type 4 but read 7
  Error: expected type 5 but read 0
  failed to read event print fmt for kvm_apic
  function ftrace_print_symbols_seq not defined
  failed to read event print fmt for kvm_exit
  function scsi_trace_parse_cdb not defined
  failed to read event print fmt for scsi_dispatch_cmd_start
  function scsi_trace_parse_cdb not defined
  failed to read event print fmt for scsi_dispatch_cmd_error
  Error: expected 'name' but read 'FORMAT'
  failed to read event name


Expected results:

No complaint "No such file or directory"
And output of data.


Additional info:

Note that the upstream trace-cmd from the git repository works generates some useful output with the same trace.dat:

# ~wcohen/research/profiling/trace-cmd/trace-cmd/trace-cmd report |more
trace-cmd: No such file or directory
  bad op token {
  failed to read event print fmt for kvm_mmu_get_page
  bad op token {
  failed to read event print fmt for kvm_mmu_sync_page
  bad op token {
  failed to read event print fmt for kvm_mmu_unsync_page
  bad op token {
  failed to read event print fmt for kvm_mmu_zap_page
  Error: expected type 4 but read 7
  Error: expected type 5 but read 0
  failed to read event print fmt for kvm_apic
  function ftrace_print_symbols_seq not defined
  failed to read event print fmt for kvm_exit
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_free_inode
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_request_inode
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_allocate_inode
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_write_begin
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_da_write_begin
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_ordered_write_end
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_writeback_write_end
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_journalled_write_end
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_da_write_end
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_writepage
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_da_writepages
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_da_write_pages
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_da_writepages_result
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_discard_blocks
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_mb_new_inode_pa
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_mb_new_group_pa
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_mb_release_inode_pa
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_mb_release_group_pa
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_discard_preallocations
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_mb_discard_preallocations
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_request_blocks
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_allocate_blocks
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_free_blocks
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_sync_file
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_sync_fs
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_alloc_da_blocks
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_mballoc_alloc
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_mballoc_prealloc
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_mballoc_discard
  function jbd2_dev_to_name not defined
  failed to read event print fmt for ext4_mballoc_free
  function jbd2_dev_to_name not defined
  failed to read event print fmt for jbd2_checkpoint
  function jbd2_dev_to_name not defined
  failed to read event print fmt for jbd2_start_commit
  function jbd2_dev_to_name not defined
  failed to read event print fmt for jbd2_commit_locking
  function jbd2_dev_to_name not defined
  failed to read event print fmt for jbd2_commit_flushing
  function jbd2_dev_to_name not defined
  failed to read event print fmt for jbd2_commit_logging
  function jbd2_dev_to_name not defined
  failed to read event print fmt for jbd2_end_commit
  function jbd2_dev_to_name not defined
  failed to read event print fmt for jbd2_submit_inode_data
  function jbd2_dev_to_name not defined
  failed to read event print fmt for jbd2_run_stats
  function jbd2_dev_to_name not defined
  failed to read event print fmt for jbd2_checkpoint_stats
  function scsi_trace_parse_cdb not defined
  failed to read event print fmt for scsi_dispatch_cmd_start
  function scsi_trace_parse_cdb not defined
  failed to read event print fmt for scsi_dispatch_cmd_error
  Error: expected 'name' but read 'FORMAT'
  Error: expected 'name' but read 'FORMAT'
  unknown op '{'
  failed to read event print fmt for hrtimer_start
  unknown op '{'
  failed to read event print fmt for hrtimer_expire_entry
version = 6
cpus=4
     ibus-daemon-3003  [000]  6786.516169: function:             sock_poll <-- d
o_sys_poll
              ls-16248 [003]  6786.516169: function:             inotify_inode_q
ueue_event <-- vfs_write

Comment 2 RHEL Program Management 2010-06-16 16:12:54 UTC
This request was evaluated by Red Hat Product Management for inclusion in a Red
Hat Enterprise Linux major release.  Product Management has requested further
review of this request by Red Hat Engineering, for potential inclusion in a Red
Hat Enterprise Linux Major release.  This request is not yet committed for
inclusion.

Comment 3 John Kacur 2010-06-16 21:28:46 UTC
The error messages are normal, the problem is if you don't have any useful information.

Can you repeat the test after doing
echo 1 > /debug/tracing/tracing_enabled

it is possible that certain programs like latencytop are resetting that to 0

if this solves the problem, we'll see if we can set this to 1 from trace_cmd

thanks

Comment 4 William Cohen 2010-06-16 21:42:06 UTC
There appears to be data in the trace.dat,

# ls -l trace.dat
-rw-r--r--. 1 root root 6311936 Jun 16 17:35 trace.dat

However "trace-cmd report trace.dat" doesn't give any output for the trace.dat file. Using the upstream git version provides all sorts of output.

repeated the experiment preceeded with:

 echo 1 > /sys/kernel/debug/tracing/tracing_enabled

Get the same results.

I don't think there are any other programs running on the system using the tracing subsystem.

Comment 5 Steven Rostedt 2010-06-16 22:15:01 UTC
William,

Can you attach a bzip version of the trace.dat file.

Basically, what you are saying is that the stable release of trace-cmd produces no output from the file, where as the mainline version does?

Comment 6 William Cohen 2010-06-17 14:11:12 UTC
Created attachment 424832 [details]
compressed trace.dat file that demonstrates problem

This is an example trace.dat file generated on rhel-6 machine. The kernel used to generate this was:

$ uname -a
Linux cannondale 2.6.32-33.el6.x86_64 #1 SMP Thu Jun 3 13:00:03 EDT 2010 x86_64 x86_64 x86_64 GNU/Linux

There is plenty of output with git version of trace-cmd, but no output with the rhel-6 trace-cmd-1.0.1-5.el6.x86_64.

Comment 7 Steven Rostedt 2010-06-17 17:22:17 UTC
Created attachment 424889 [details]
patch to not crash on FORMAT TOO BIG error from kernel

The trace.dat file seems to be a trace that is not from the RHEL6 kernel. It includes tracepoints that were added for 2.6.35.

These tracepoints are from the SCSI system that made the output format bigger than a page. The current code in the kernel failed to output anything when this happened and simply had the format file be "FORMAT TOO BIG".

Trace-cmd could not handle this input and would simply crash. The given patch fixes trace-cmd to prevent it from crashing. Also, these events are simply ignored now.

I already fixed the code in the kernel so these events will now be printed properly. But it was a rewrite of the output code and was too big to try to push it past Linus's strictness in this release. Thus, trace-cmd will not be able to read these events in the 2.6.35 kernel. Neither will perf.

These events are fine with the debugfs/tracing/trace output, because the format file is not needed for the in-kernel pretty printing.

The attached patch is already in stable release trace-cmd-v1.0.3.

Comment 8 William Cohen 2010-06-17 17:48:14 UTC
Tried trace-cmd-1.0.2-6.el6.x86_64.rpm. The problem appears to be resolved in this most recent build.

Comment 9 RHEL Program Management 2010-07-15 14:45:53 UTC
This issue has been proposed when we are only considering blocker
issues in the current Red Hat Enterprise Linux release. It has
been denied for the current Red Hat Enterprise Linux release.

** If you would still like this issue considered for the current
release, ask your support representative to file as a blocker on
your behalf. Otherwise ask that it be considered for the next
Red Hat Enterprise Linux release. **