• Tom Zanussi's avatar
    tracing: Add a check_val() check before updating cond_snapshot() track_val · 9b2ca371
    Tom Zanussi authored
    Without this check a snapshot is taken whenever a bucket's max is hit,
    rather than only when the global max is hit, as it should be.
    
    Before:
    
      In this example, we do a first run of the workload (cyclictest),
      examine the output, note the max ('triggering value') (347), then do
      a second run and note the max again.
    
      In this case, the max in the second run (39) is below the max in the
      first run, but since we haven't cleared the histogram, the first max
      is still in the histogram and is higher than any other max, so it
      should still be the max for the snapshot.  It isn't however - the
      value should still be 347 after the second run.
    
      # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
      # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio,prev_comm):onmax($wakeup_lat).snapshot() if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
    
      # cyclictest -p 80 -n -s -t 2 -D 2
    
      # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
    
      { next_pid:       2143 } hitcount:        199
        max:         44  next_prio:        120  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/4
    
      { next_pid:       2145 } hitcount:       1325
        max:         38  next_prio:         19  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/2
    
      { next_pid:       2144 } hitcount:       1982
        max:        347  next_prio:         19  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/6
    
      Snapshot taken (see tracing/snapshot).  Details:
          triggering value { onmax($wakeup_lat) }:        347
          triggered by event with key: { next_pid:       2144 }
    
      # cyclictest -p 80 -n -s -t 2 -D 2
    
      # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
    
      { next_pid:       2143 } hitcount:        199
        max:         44  next_prio:        120  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/4
    
      { next_pid:       2148 } hitcount:        199
        max:         16  next_prio:        120  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/1
    
      { next_pid:       2145 } hitcount:       1325
        max:         38  next_prio:         19  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/2
    
      { next_pid:       2150 } hitcount:       1326
        max:         39  next_prio:         19  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/4
    
      { next_pid:       2144 } hitcount:       1982
        max:        347  next_prio:         19  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/6
    
      { next_pid:       2149 } hitcount:       1983
        max:        130  next_prio:         19  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/0
    
      Snapshot taken (see tracing/snapshot).  Details:
        triggering value { onmax($wakeup_lat) }:    39
        triggered by event with key: { next_pid:       2150 }
    
    After:
    
      In this example, we do a first run of the workload (cyclictest),
      examine the output, note the max ('triggering value') (375), then do
      a second run and note the max again.
    
      In this case, the max in the second run is still 375, the highest in
      any bucket, as it should be.
    
      # cyclictest -p 80 -n -s -t 2 -D 2
    
      # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
    
      { next_pid:       2072 } hitcount:        200
        max:         28  next_prio:        120  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/5
    
      { next_pid:       2074 } hitcount:       1323
        max:        375  next_prio:         19  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/2
    
      { next_pid:       2073 } hitcount:       1980
        max:        153  next_prio:         19  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/6
    
      Snapshot taken (see tracing/snapshot).  Details:
        triggering value { onmax($wakeup_lat) }:        375
        triggered by event with key: { next_pid:       2074 }
    
      # cyclictest -p 80 -n -s -t 2 -D 2
    
      # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
    
      { next_pid:       2101 } hitcount:        199
        max:         49  next_prio:        120  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/6
    
      { next_pid:       2072 } hitcount:        200
        max:         28  next_prio:        120  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/5
    
      { next_pid:       2074 } hitcount:       1323
        max:        375  next_prio:         19  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/2
    
      { next_pid:       2103 } hitcount:       1325
        max:         74  next_prio:         19  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/4
    
      { next_pid:       2073 } hitcount:       1980
        max:        153  next_prio:         19  next_comm: cyclictest
        prev_pid:          0  prev_prio:        120  prev_comm: swapper/6
    
      { next_pid:       2102 } hitcount:       1981
        max:         84  next_prio:         19  next_comm: cyclictest
        prev_pid:         12  prev_prio:        120  prev_comm: kworker/0:1
    
      Snapshot taken (see tracing/snapshot).  Details:
        triggering value { onmax($wakeup_lat) }:        375
        triggered by event with key: { next_pid:       2074 }
    
    Link: http://lkml.kernel.org/r/95958351329f129c07504b4d1769c47a97b70d65.1555597045.git.tom.zanussi@linux.intel.com
    
    Cc: stable@vger.kernel.org
    Fixes: a3785b7e ("tracing: Add hist trigger snapshot() action")
    Signed-off-by: default avatarTom Zanussi <tom.zanussi@linux.intel.com>
    Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
    9b2ca371
trace_events_hist.c 150 KB