1. 11 Sep, 2009 3 commits
    • Steven Rostedt's avatar
      tracing: consolidate code between trace_output.c and trace_function_graph.c · f81c972d
      Steven Rostedt authored
      
      
      Both trace_output.c and trace_function_graph.c do basically the same
      thing to handle the printing of the latency-format. This patch moves
      the code into one function that both can use.
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      f81c972d
    • Steven Rostedt's avatar
      tracing: add lock depth to entries · 637e7e86
      Steven Rostedt authored
      
      
      This patch adds the lock depth of the big kernel lock to the generic
      entry header. This way we can see the depth of the lock and help
      in removing the BKL.
      
      Example:
      
       #                  _------=> CPU#
       #                 / _-----=> irqs-off
       #                | / _----=> need-resched
       #                || / _---=> hardirq/softirq
       #                ||| / _--=> preempt-depth
       #                |||| /_--=> lock-depth
       #                |||||/     delay
       #  cmd     pid   |||||| time  |   caller
       #     \   /      ||||||   \   |   /
         <idle>-0       2.N..3 5902255250us+: lock_acquire: read rcu_read_lock
         <idle>-0       2.N..3 5902255253us+: lock_release: rcu_read_lock
         <idle>-0       2dN..3 5902255257us+: lock_acquire: xtime_lock
         <idle>-0       2dN..4 5902255259us : lock_acquire: clocksource_lock
         <idle>-0       2dN..4 5902255261us+: lock_release: clocksource_lock
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      637e7e86
    • Steven Rostedt's avatar
      tracing: add latency format to function_graph tracer · 49ff5903
      Steven Rostedt authored
      
      
      While debugging something with the function_graph tracer, I found the
      need to see the preempt count of the traces. Unfortunately, since
      the function graph tracer has its own output formatting, it does not
      honor the latency-format option.
      
      This patch makes the function_graph tracer honor the latency-format
      option, but still keeps control of the output. But now we have the
      same details that the latency-format supplies.
      
       # tracer: function_graph
       #
       #      _-----=> irqs-off
       #     / _----=> need-resched
       #    | / _---=> hardirq/softirq
       #    || / _--=> preempt-depth
       #    ||| /
       #    ||||
       # CPU||||  DURATION                  FUNCTION CALLS
       # |  ||||   |   |                     |   |   |   |
        3)  d..1  1.333 us    |        idle_cpu();
        3)  d.h1              |        tick_check_idle() {
        3)  d.h1  0.550 us    |          tick_check_oneshot_broadcast();
        3)  d.h1              |          tick_nohz_stop_idle() {
        3)  d.h1              |            ktime_get() {
        3)  d.h1              |              ktime_get_ts() {
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      49ff5903
  2. 04 Sep, 2009 1 commit
    • Steven Rostedt's avatar
      tracing: pass around ring buffer instead of tracer · e77405ad
      Steven Rostedt authored
      
      
      The latency tracers (irqsoff and wakeup) can swap trace buffers
      on the fly. If an event is happening and has reserved data on one of
      the buffers, and the latency tracer swaps the global buffer with the
      max buffer, the result is that the event may commit the data to the
      wrong buffer.
      
      This patch changes the API to the trace recording to be recieve the
      buffer that was used to reserve a commit. Then this buffer can be passed
      in to the commit.
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      e77405ad
  3. 06 Aug, 2009 2 commits
  4. 28 Jul, 2009 1 commit
    • Lai Jiangshan's avatar
      tracing: Fix invalid function_graph entry · 38ceb592
      Lai Jiangshan authored
      
      
      When print_graph_entry() computes a function call entry event, it needs
      to also check the next entry to guess if it matches the return event of
      the current function entry.
      In order to look at this next event, it needs to consume the current
      entry before going ahead in the ring buffer.
      
      However, if the current event that gets consumed is the last one in the
      ring buffer head page, the ring_buffer may reuse the page for writers.
      The consumed entry will then become invalid because of possible
      racy overwriting.
      
      Me must then handle this entry by making a copy of it.
      
      The fix also applies on 2.6.30
      Signed-off-by: default avatarLai Jiangshan <laijs@cn.fujitsu.com>
      Cc: Steven Rostedt <rostedt@goodmis.org>
      Cc: stable@kernel.org
      LKML-Reference: <4A6EEAEC.3050508@cn.fujitsu.com>
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      38ceb592
  5. 10 Jul, 2009 1 commit
  6. 18 Jun, 2009 1 commit
    • Steven Rostedt's avatar
      function-graph: add stack frame test · 71e308a2
      Steven Rostedt authored
      
      
      In case gcc does something funny with the stack frames, or the return
      from function code, we would like to detect that.
      
      An arch may implement passing of a variable that is unique to the
      function and can be saved on entering a function and can be tested
      when exiting the function. Usually the frame pointer can be used for
      this purpose.
      
      This patch also implements this for x86. Where it passes in the stack
      frame of the parent function, and will test that frame on exit.
      
      There was a case in x86_32 with optimize for size (-Os) where, for a
      few functions, gcc would align the stack frame and place a copy of the
      return address into it. The function graph tracer modified the copy and
      not the actual return address. On return from the funtion, it did not go
      to the tracer hook, but returned to the parent. This broke the function
      graph tracer, because the return of the parent (where gcc did not do
      this funky manipulation) returned to the location that the child function
      was suppose to. This caused strange kernel crashes.
      
      This test detected the problem and pointed out where the issue was.
      
      This modifies the parameters of one of the functions that the arch
      specific code calls, so it includes changes to arch code to accommodate
      the new prototype.
      
      Note, I notice that the parsic arch implements its own push_return_trace.
      This is now a generic function and the ftrace_push_return_trace should be
      used instead. This patch does not touch that code.
      
      Cc: Benjamin Herrenschmidt <benh@kernel.crashing.org>
      Cc: Paul Mackerras <paulus@samba.org>
      Cc: Heiko Carstens <heiko.carstens@de.ibm.com>
      Cc: Martin Schwidefsky <schwidefsky@de.ibm.com>
      Cc: Frederic Weisbecker <fweisbec@gmail.com>
      Cc: Helge Deller <deller@gmx.de>
      Cc: Kyle McMartin <kyle@mcmartin.ca>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      71e308a2
  7. 02 Jun, 2009 1 commit
    • Steven Rostedt's avatar
      function-graph: enable the stack after initialization of other variables · 82310a32
      Steven Rostedt authored
      
      
      The function graph tracer checks if the task_struct has ret_stack defined
      to know if it is OK or not to use it. The initialization is done for
      all tasks by one process, but the idle tasks use the same initialization
      used by new tasks.
      
      If an interrupt happens on an idle task that just had the ret_stack
      created, but before the rest of the initialization took place, then
      we can corrupt the return address of the functions.
      
      This patch moves the setting of the task_struct's ret_stack to after
      the other variables have been initialized.
      
      [ Impact: prevent kernel panic on idle task when starting function graph ]
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      82310a32
  8. 25 Mar, 2009 2 commits
    • Steven Rostedt's avatar
      function-graph: add option to calculate graph time or not · a2a16d6a
      Steven Rostedt authored
      
      
      graph time is the time that a function is executing another function.
      Thus if function A calls B, if graph-time is set, then the time for
      A includes B. This is the default behavior. But if graph-time is off,
      then the time spent executing B is subtracted from A.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      a2a16d6a
    • Steven Rostedt's avatar
      tracing: adding function timings to function profiler · 0706f1c4
      Steven Rostedt authored
      
      
      If the function graph trace is enabled, the function profiler will
      use it to take the timing of the functions.
      
       cat /debug/tracing/trace_stat/functions
      
        Function                               Hit    Time
        --------                               ---    ----
        mwait_idle                             127    183028.4 us
        schedule                                26    151997.7 us
        __schedule                              31    151975.1 us
        sys_wait4                                2    74080.53 us
        do_wait                                  2    74077.80 us
        sys_newlstat                           138    39929.16 us
        do_path_lookup                         179    39845.79 us
        vfs_lstat_fd                           138    39761.97 us
        user_path_at                           153    39469.58 us
        path_walk                              179    39435.76 us
        __link_path_walk                       189    39143.73 us
      [...]
      
      Note the times are skewed due to the function graph tracer not taking
      into account schedules.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      0706f1c4
  9. 24 Mar, 2009 1 commit
  10. 19 Mar, 2009 3 commits
    • Steven Rostedt's avatar
      function-graph: show binary events as comments · 5087f8d2
      Steven Rostedt authored
      
      
      With the added TRACE_EVENT macro, the events no longer appear in
      the function graph tracer. This was because the function graph
      did not know how to display the entries. The graph tracer was
      only aware of its own entries and the printk entries.
      
      By using the event call back feature, the graph tracer can now display
      the events.
      
       # echo irq > /debug/tracing/set_event
      
      Which can show:
      
       0)               |          handle_IRQ_event() {
       0)               |            /* irq_handler_entry: irq=48 handler=eth0 */
       0)               |            e1000_intr() {
       0)   0.926 us    |              __napi_schedule();
       0)   3.888 us    |            }
       0)               |            /* irq_handler_exit: irq=48 return=handled */
       0)   0.655 us    |            runqueue_is_locked();
       0)               |            __wake_up() {
       0)   0.831 us    |              _spin_lock_irqsave();
      
      The irq entry and exit events show up as comments.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      5087f8d2
    • Steven Rostedt's avatar
      function-graph: calculate function depth within function graph tracer · 2fbcdb35
      Steven Rostedt authored
      
      
      Currently, the function graph tracer depends on the trace_printk
      to record the depth. All the information is already there in the trace
      to calculate function depth, with the exception of having the printk
      be the first item. But as soon as a entry or exit is reached, then
      we know the depth.
      
      This patch changes the iter->private data from recording a per cpu
      last_pid, to a structure that holds both the last_pid and the current
      depth. This data is used to determine the function depth for the
      printks.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      2fbcdb35
    • Steven Rostedt's avatar
      function-graph: consolidate prologues for output · ac5f6c96
      Steven Rostedt authored
      
      
      Impact: clean up
      
      The prologue of the function graph entry, return and comments all
      start out pretty much the same. Each of these duplicate code and
      do so slightly differently.
      
      This patch consolidates the printing of the pid, absolute time,
      cpu and proc (and for entry, the interrupt).
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      ac5f6c96
  11. 17 Mar, 2009 1 commit
    • Steven Rostedt's avatar
      tracing: protect reader of cmdline output · 4ca53085
      Steven Rostedt authored
      
      
      Impact: fix to one cause of incorrect comm outputs in trace
      
      The spinlock only protected the creation of a comm <=> pid pair.
      But it was possible that a reader could look up a pid, and get the
      wrong comm because it had no locking.
      
      This also required changing trace_find_cmdline to copy the comm cache
      and not just send back a pointer to it.
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      4ca53085
  12. 13 Mar, 2009 1 commit
    • Frederic Weisbecker's avatar
      tracing/core: bring back raw trace_printk for dynamic formats strings · 48ead020
      Frederic Weisbecker authored
      
      
      Impact: fix callsites with dynamic format strings
      
      Since its new binary implementation, trace_printk() internally uses static
      containers for the format strings on each callsites. But the value is
      assigned once at build time, which means that it can't take dynamic
      formats.
      
      So this patch unearthes the raw trace_printk implementation for the callers
      that will need trace_printk to be able to carry these dynamic format
      strings. The trace_printk() macro will use the appropriate implementation
      for each callsite. Most of the time however, the binary implementation will
      still be used.
      
      The other impact of this patch is that mmiotrace_printk() will use the old
      implementation because it calls the low level trace_vprintk and we can't
      guess here whether the format passed in it is dynamic or not.
      
      Some parts of this patch have been written by Steven Rostedt (most notably
      the part that chooses the appropriate implementation for each callsites).
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
      48ead020
  13. 10 Mar, 2009 1 commit
  14. 06 Mar, 2009 1 commit
    • Frederic Weisbecker's avatar
      tracing/core: drop the old trace_printk() implementation in favour of trace_bprintk() · 769b0441
      Frederic Weisbecker authored
      
      
      Impact: faster and lighter tracing
      
      Now that we have trace_bprintk() which is faster and consume lesser
      memory than trace_printk() and has the same purpose, we can now drop
      the old implementation in favour of the binary one from trace_bprintk(),
      which means we move all the implementation of trace_bprintk() to
      trace_printk(), so the Api doesn't change except that we must now use
      trace_seq_bprintk() to print the TRACE_PRINT entries.
      
      Some changes result of this:
      
      - Previously, trace_bprintk depended of a single tracer and couldn't
        work without. This tracer has been dropped and the whole implementation
        of trace_printk() (like the module formats management) is now integrated
        in the tracing core (comes with CONFIG_TRACING), though we keep the file
        trace_printk (previously trace_bprintk.c) where we can find the module
        management. Thus we don't overflow trace.c
      
      - changes some parts to use trace_seq_bprintk() to print TRACE_PRINT entries.
      
      - change a bit trace_printk/trace_vprintk macros to support non-builtin formats
        constants, and fix 'const' qualifiers warnings. But this is all transparent for
        developers.
      
      - etc...
      
      V2:
      
      - Rebase against last changes
      - Fix mispell on the changelog
      
      V3:
      
      - Rebase against last changes (moving trace_printk() to kernel.h)
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Acked-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      LKML-Reference: <1236356510-8381-5-git-send-email-fweisbec@gmail.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      769b0441
  15. 05 Mar, 2009 1 commit
  16. 19 Feb, 2009 2 commits
    • Ingo Molnar's avatar
      tracing/function-graph-tracer: fix merge · 00a8bf85
      Ingo Molnar authored
      
      
      Merge artifact: pid got changed to ent->pid meanwhile.
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      00a8bf85
    • Frederic Weisbecker's avatar
      tracing/function-graph-tracer: fix traces weirdness while absolute time printing · d1f9cbd7
      Frederic Weisbecker authored
      
      
      Impact: trace output cleanup/reordering
      
      When an interrupt occurs and and the abstime option is selected:
      
        echo funcgraph-abstime > /debug/tracing/trace_options
      
      then we observe broken traces:
      
      30581.025422 |   0)   Xorg-4291    |   0.503 us    |      idle_cpu();
      30581.025424 |   0)   Xorg-4291    |   2.576 us    |    }
      30581.025424 |   0)   Xorg-4291    | + 75.771 us   |  }
       0)   Xorg-4291    |   <========== |
      30581.025425 |   0)   Xorg-4291    |               |  schedule() {
      30581.025426 |   0)   Xorg-4291    |               |    __schedule() {
      30581.025426 |   0)   Xorg-4291    |   0.705 us    |      _spin_lock_irq();
      
      With this patch, the interrupts output better adapts
      to absolute time printing:
      
        414.856543 |   1)   Xorg-4279    |   8.816 us    |                        }
        414.856544 |   1)   Xorg-4279    |   0.525 us    |                        rcu_irq_exit();
        414.856545 |   1)   Xorg-4279    |   0.526 us    |                        idle_cpu();
        414.856546 |   1)   Xorg-4279    | + 12.157 us   |                      }
        414.856549 |   1)   Xorg-4279    | ! 104.114 us  |                    }
        414.856549 |   1)   Xorg-4279    |   <========== |
        414.856549 |   1)   Xorg-4279    | ! 107.944 us  |                  }
        414.856550 |   1)   Xorg-4279    | ! 137.010 us  |                }
        414.856551 |   1)   Xorg-4279    |   0.624 us    |                _read_unlock();
        414.856552 |   1)   Xorg-4279    | ! 140.930 us  |              }
        414.856552 |   1)   Xorg-4279    | ! 166.159 us  |            }
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      d1f9cbd7
  17. 18 Feb, 2009 2 commits
  18. 10 Feb, 2009 1 commit
  19. 09 Feb, 2009 2 commits
  20. 06 Feb, 2009 1 commit
  21. 29 Jan, 2009 1 commit
  22. 23 Jan, 2009 1 commit
    • Frederic Weisbecker's avatar
      tracing/function-graph-tracer: various fixes and features · 9005f3eb
      Frederic Weisbecker authored
      
      
      This patch brings various bugfixes:
      
      - Drop the first irrelevant task switch on the very beginning of a trace.
      
      - Drop the OVERHEAD word from the headers, the DURATION word is sufficient
        and will not overlap other columns.
      
      - Make the headers fit well their respective columns whatever the
        selected options.
      
      Ie, default options:
      
       # tracer: function_graph
       #
       # CPU  DURATION                  FUNCTION CALLS
       # |     |   |                     |   |   |   |
      
        1)   0.646 us    |                    }
        1)               |                    mem_cgroup_del_lru_list() {
        1)   0.624 us    |                      lookup_page_cgroup();
        1)   1.970 us    |                    }
      
       echo funcgraph-proc > trace_options
      
       # tracer: function_graph
       #
       # CPU  TASK/PID        DURATION                  FUNCTION CALLS
       # |    |    |           |   |                     |   |   |   |
      
        0)   bash-2937    |   0.895 us    |                }
        0)   bash-2937    |   0.888 us    |                __rcu_read_unlock();
        0)   bash-2937    |   0.864 us    |                conv_uni_to_pc();
        0)   bash-2937    |   1.015 us    |                __rcu_read_lock();
      
       echo nofuncgraph-cpu > trace_options
       echo nofuncgraph-proc > trace_options
      
       # tracer: function_graph
       #
       #   DURATION                  FUNCTION CALLS
       #    |   |                     |   |   |   |
      
         3.752 us    |                  native_pud_val();
         0.616 us    |                  native_pud_val();
         0.624 us    |                  native_pmd_val();
      
      About features, one can now disable the duration (this will hide the
      overhead too for convenient reasons and because on  doesn't need
      overhead if it hasn't the duration):
      
       echo nofuncgraph-duration > trace_options
      
       # tracer: function_graph
       #
       #                FUNCTION CALLS
       #                |   |   |   |
      
                 cap_vm_enough_memory() {
                   __vm_enough_memory() {
                     vm_acct_memory();
                   }
                 }
               }
      
      And at last, an option to print the absolute time:
      
       //Restart from default options
       echo funcgraph-abstime > trace_options
      
       # tracer: function_graph
       #
       #      TIME       CPU  DURATION                  FUNCTION CALLS
       #       |         |     |   |                     |   |   |   |
      
         261.339774 |   1) + 42.823 us   |    }
         261.339775 |   1)   1.045 us    |    _spin_lock_irq();
         261.339777 |   1)   0.940 us    |    _spin_lock_irqsave();
         261.339778 |   1)   0.752 us    |    _spin_unlock_irqrestore();
         261.339780 |   1)   0.857 us    |    _spin_unlock_irq();
         261.339782 |   1)               |    flush_to_ldisc() {
         261.339783 |   1)               |      tty_ldisc_ref() {
         261.339783 |   1)               |        tty_ldisc_try() {
         261.339784 |   1)   1.075 us    |          _spin_lock_irqsave();
         261.339786 |   1)   0.842 us    |          _spin_unlock_irqrestore();
         261.339788 |   1)   4.211 us    |        }
         261.339788 |   1)   5.662 us    |      }
      
      The format is seconds.usecs.
      
      I guess no one needs the nanosec precision here, the main goal is to have
      an overview about the general timings of events, and to see the place when
      the trace switches from one cpu to another.
      
      ie:
      
         274.874760 |   1)   0.676 us    |      _spin_unlock();
         274.874762 |   1)   0.609 us    |      native_load_sp0();
         274.874763 |   1)   0.602 us    |      native_load_tls();
         274.878739 |   0)   0.722 us    |                  }
         274.878740 |   0)   0.714 us    |                  native_pmd_val();
         274.878741 |   0)   0.730 us    |                  native_pmd_val();
      
      Here there is a 4000 usecs difference when we switch the cpu.
      
      Changes in V2:
      
      - Completely fix the first pointless task switch.
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      9005f3eb
  23. 31 Dec, 2008 1 commit
  24. 29 Dec, 2008 2 commits
  25. 26 Dec, 2008 1 commit
  26. 12 Dec, 2008 1 commit
    • Frederic Weisbecker's avatar
      tracing/function-graph-tracer: Output arrows signal on hardirq call/return · f8b755ac
      Frederic Weisbecker authored
      
      
      Impact: make more obvious the hardirq calls in the output
      
      When a hardirq is triggered inside the codeflow on output, we have
      now two arrows that indicate the entry and return of the hardirq.
      
       0)               |          bit_waitqueue() {
       0)   0.880 us    |            __phys_addr();
       0)   2.699 us    |          }
       0)               |          __wake_up_bit() {
       0)   ==========> |          smp_apic_timer_interrupt() {
       0)   0.797 us    |            native_apic_mem_write();
       0)   0.715 us    |            exit_idle();
       0)               |            irq_enter() {
       0)   0.722 us    |              idle_cpu();
       0)   5.519 us    |            }
       0)               |            hrtimer_interrupt() {
       0)               |              ktime_get() {
       0)               |                ktime_get_ts() {
       0)   0.805 us    |                  getnstimeofday();
      
       [...]
      
       0) ! 108.528 us  |            }
       0)               |            irq_exit() {
       0)               |              do_softirq() {
       0)               |                __do_softirq() {
       0)   0.895 us    |                  __local_bh_disable();
       0)               |                  run_timer_softirq() {
       0)   0.827 us    |                    hrtimer_run_pending();
       0)   1.226 us    |                    _spin_lock_irq();
       0)               |                    _spin_unlock_irq() {
       0)   6.550 us    |                  }
       0)   0.924 us    |                  _local_bh_enable();
       0) + 12.129 us   |                }
       0) + 13.911 us   |              }
       0)   0.707 us    |              idle_cpu();
       0) + 17.009 us   |            }
       0) ! 137.419 us  |          }
       0)   <========== |
       0)   1.045 us    |          }
       0) ! 148.908 us  |        }
       0) ! 151.022 us  |      }
       0) ! 153.022 us  |    }
       0)   0.963 us    |    journal_mark_dirty();
       0)   0.925 us    |    __brelse();
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      f8b755ac
  27. 08 Dec, 2008 1 commit
  28. 04 Dec, 2008 1 commit
    • Frederic Weisbecker's avatar
      tracing/function-graph-tracer: handle ftrace_printk entries · 1fd8f2a3
      Frederic Weisbecker authored
      
      
      Handle the TRACE_PRINT entries from the function grapg tracer
      and output them as a C comment just below the function that called
      it, as if it was a comment inside this function.
      
      Example with an ftrace_printk inside might_sleep() function:
      
      void __might_sleep(char *file, int line)
      {
      	static unsigned long prev_jiffy;	/* ratelimiting */
      
      	ftrace_printk("Hi I'm a comment in might_sleep() :-)");
      
      A chunk of a resulting trace:
      
       0)               |        _reiserfs_free_block() {
       0)               |          reiserfs_read_bitmap_block() {
       0)               |            __bread() {
       0)               |              __getblk() {
       0)               |                __find_get_block() {
       0)   0.698 us    |                  mark_page_accessed();
       0)   2.267 us    |                }
       0)               |                __might_sleep() {
       0)               |                  /* Hi I'm a comment in might_sleep() :-) */
       0)   1.321 us    |                }
       0)   5.872 us    |              }
       0)   7.313 us    |            }
       0)   8.718 us    |          }
      
      And this patch brings two minor fixes:
      
      - The newline after a switch-out task has disappeared
      - The "|" sign just before the cpu number on task-switch has been deleted.
      
       0)   0.616 us    |                pick_next_task_rt();
       0)   1.457 us    |                _spin_trylock();
       0)   0.653 us    |                _spin_unlock();
       0)   0.728 us    |                _spin_trylock();
       0)   0.631 us    |                _spin_unlock();
       0)   0.729 us    |                native_load_sp0();
       0)   0.593 us    |                native_load_tls();
       ------------------------------------------
       0)    cat-2834    =>   migrati-3
       ------------------------------------------
      
       0)               |    finish_task_switch() {
       0)   0.841 us    |      _spin_unlock_irq();
       0)   0.616 us    |      post_schedule_rt();
       0)   3.882 us    |    }
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Acked-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      1fd8f2a3
  29. 03 Dec, 2008 2 commits
    • Frederic Weisbecker's avatar
      tracing/function-graph-tracer: improve duration output · 166d3c79
      Frederic Weisbecker authored
      
      
      Impact: better trace output of duration for long calls
      
      The old duration output didn't exceeded 9999.999 us to fit the column
      and the nanosecs were always 3 numbers. As Ingo suggested, it's better
      to have the whole microseconds elapsed time and shift the nanosecs precision
      if needed to fit the maximum 7 numbers. And usec need more number, the case
      should be rare and important enough to break a bit the column alignment to
      show it.
      
      So, depending of the duration value, we now have these patterns:
      
          u.nnn us
         uu.nnn us
        uuu.nnn us
       uuuu.nnn us
       uuuuu.nn us
       uuuuuu.n us
       uuuuuuuu..... us
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      166d3c79
    • Frederic Weisbecker's avatar
      tracing/function-graph-tracer: display unified style cmdline and pid · 11e84acc
      Frederic Weisbecker authored
      
      
      Impact: extend function-graph output: let one know which thread called a function
      
      This patch implements a helper function to print the couple cmdline/pid.
      Its output is provided during task switching and on each row if the new
      "funcgraph-proc" defualt-off option is set through trace_options file.
      
      The output is center aligned and never exceeds 14 characters. The cmdline
      is truncated over 7 chars.
      But note that if the pid exceeds 6 characters, the column will overflow (but
      the situation is abnormal).
      Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
      Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
      11e84acc