Re: [PATCH] tracing - fix function graph trace to properly display failed entries

[Steven Rostedt <rostedt@goodmis.org>]

On Tue, 2009-11-24 at 23:53 +0100, Frederic Weisbecker wrote:
> On Tue, Nov 24, 2009 at 05:26:42PM -0500, Steven Rostedt wrote:
> > > But it happens with trace_pipe reading.
> > 
> > Yep, but I think we should be able to handle it without modifying
> > trace_seq.
> 
> 
> 
> Yeah. I guess now that the bug window is isolated to the
> trace_pipe case, the fix will probably (hopefully) be easier.
> 

Hmm, there is something funky going on. I did the following:

# echo 1 > /debug/tracing/tracing_on
# echo function_graph > /debug/tracing/current_tracer
# sleep 10
# echo 0 > /debug/tracing/tracing_on
# cat /debug/tracing/per_cpu/cpu0/trace > /tmp/t1
# cat /debug/tracing/per_cpu/cpu0/trace_pipe > /tmp/t2
(wait)
Ctrl^C (seems to block for more input)


# diff -u /tmp/t1 /tmp/t2

This is some interesting results:

--- /tmp/t1     2009-11-24 18:11:03.000000000 -0500
+++ /tmp/t2     2009-11-24 18:12:20.000000000 -0500
@@ -1,7 +1,3 @@
-# tracer: function_graph
-#
-# CPU  DURATION                  FUNCTION CALLS
-# |     |   |                     |   |   |   |
  0)   0.543 us    |                        }
  0)   0.670 us    |                        _spin_unlock_irqrestore();
  0)   8.741 us    |                      }

( Just to get the idea, "-" is trace and "+" is trace_pipe )

@@ -84,7 +80,7 @@
  0)   <========== |
  0) ! 99918.45 us |  }
  0)               |  tick_nohz_restart_sched_tick() {
- 0)   0.570 us    |    tick_nohz_stop_idle();
+ 0)   0.570 us    |    }
  0)   0.733 us    |    rcu_exit_nohz();
  0)   0.612 us    |    select_nohz_load_balancer();
  0)   0.573 us    |    ktime_get();

trace_pipe lost the tick_nohz_stop_idle with '}'

@@ -272,7 +264,7 @@
  0)   0.663 us    |                  account_system_time();
  0)   1.939 us    |                }
  0)               |                run_local_timers() {
- 0)               |                  hrtimer_run_queues() {
+ 0)   0.615 us    |                  hrtimer_run_queues();
  0)   0.660 us    |                  raise_softirq();
  0)               |                  softlockup_tick() {
  0)   0.873 us    |                    __touch_softlockup_watchdog();

Now trace adds a '{' where it looks like trace_pipe was correct.

@@ -351,12 +343,12 @@
  0)   0.760 us    |                        _spin_unlock_irqrestore();
  0)   0.905 us    |                        _spin_lock_irqsave();
  0)   0.523 us    |                        __set_se_shares();
- 0)               |                        _spin_unlock_irqrestore() {
+ 0)   0.705 us    |                        _spin_unlock_irqrestore();
  0)   9.272 us    |                      }
  0)   0.573 us    |                      tg_nop();
  0)               |                      tg_shares_up() {
  0)   0.891 us    |                        _spin_lock_irqsave();
- 0)   0.530 us    |                        __set_se_shares();
+ 0)   0.530 us    |                        }
  0)   0.693 us    |                        _spin_unlock_irqrestore();
  0)   0.891 us    |                        _spin_lock_irqsave();
  0)   0.527 us    |                        __set_se_shares();

Again, trace adds the '{' and later trace_pipe loses
__set_se_shares(); ??

And this goes on and on.


So both seem to be a bit buggy. The above really should be almost
identical, besides the header.

-- Steve