)]}' { "log": [ { "commit": "352ad25aa4a189c667cb2af333948d34692a2d27", "tree": "83a11c626b3818711d3b88061964c9ea603f7b68", "parents": [ "35e8e302e5d6e32675df2fc1dd3a53dfa6630dc1" ], "author": { "name": "Steven Rostedt", "email": "srostedt@redhat.com", "time": "Mon May 12 21:20:42 2008 +0200" }, "committer": { "name": "Thomas Gleixner", "email": "tglx@linutronix.de", "time": "Fri May 23 20:32:36 2008 +0200" }, "message": "ftrace: tracer for scheduler wakeup latency\n\nThis patch adds the tracer that tracks the wakeup latency of the\nhighest priority waking task.\n\n \"wakeup\" is added to /debugfs/tracing/available_tracers\n\nAlso added to /debugfs/tracing\n\n tracing_max_latency\n holds the current max latency for the wakeup\n\n wakeup_thresh\n if set to other than zero, a log will be recorded\n for every wakeup that takes longer than the number\n entered in here (usecs for all counters)\n (deletes previous trace)\n\nExamples:\n\n (with ftrace_enabled \u003d 0)\n\n\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\npreemption latency trace v1.1.5 on 2.6.24-rc8\nSigned-off-by: Ingo Molnar \u003cmingo@elte.hu\u003e\n--------------------------------------------------------------------\n latency: 26 us, #2/2, CPU#1 | (M:rt VP:0, KP:0, SP:0 HP:0 #P:2)\n -----------------\n | task: migration/0-3 (uid:0 nice:-5 policy:1 rt_prio:99)\n -----------------\n\n _------\u003d\u003e CPU#\n / _-----\u003d\u003e irqs-off\n | / _----\u003d\u003e need-resched\n || / _---\u003d\u003e hardirq/softirq\n ||| / _--\u003d\u003e preempt-depth\n |||| /\n ||||| delay\n cmd pid ||||| time | caller\n \\ / ||||| \\ | /\n quilt-8551 0d..3 0us+: wake_up_process+0x15/0x17 \u003cffffffff80233e80\u003e (sched_exec+0xc9/0x100 \u003cffffffff80235343\u003e)\n quilt-8551 0d..4 26us : sched_switch_callback+0x73/0x81 \u003cffffffff80338d2f\u003e (schedule+0x483/0x6d5 \u003cffffffff8048b3ee\u003e)\n\nvim:ft\u003dhelp\n\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\n\n (with ftrace_enabled \u003d 1)\n\n\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\npreemption latency trace v1.1.5 on 2.6.24-rc8\n--------------------------------------------------------------------\n latency: 36 us, #45/45, CPU#0 | (M:rt VP:0, KP:0, SP:0 HP:0 #P:2)\n -----------------\n | task: migration/1-5 (uid:0 nice:-5 policy:1 rt_prio:99)\n -----------------\n\n _------\u003d\u003e CPU#\n / _-----\u003d\u003e irqs-off\n | / _----\u003d\u003e need-resched\n || / _---\u003d\u003e hardirq/softirq\n ||| / _--\u003d\u003e preempt-depth\n |||| /\n ||||| delay\n cmd pid ||||| time | caller\n \\ / ||||| \\ | /\n bash-10653 1d..3 0us : wake_up_process+0x15/0x17 \u003cffffffff80233e80\u003e (sched_exec+0xc9/0x100 \u003cffffffff80235343\u003e)\n bash-10653 1d..3 1us : try_to_wake_up+0x271/0x2e7 \u003cffffffff80233dcf\u003e (sub_preempt_count+0xc/0x7a \u003cffffffff8023309e\u003e)\n bash-10653 1d..2 2us : try_to_wake_up+0x296/0x2e7 \u003cffffffff80233df4\u003e (update_rq_clock+0x9/0x20 \u003cffffffff802303f3\u003e)\n bash-10653 1d..2 2us : update_rq_clock+0x1e/0x20 \u003cffffffff80230408\u003e (__update_rq_clock+0xc/0x90 \u003cffffffff80230366\u003e)\n bash-10653 1d..2 3us : __update_rq_clock+0x1b/0x90 \u003cffffffff80230375\u003e (sched_clock+0x9/0x29 \u003cffffffff80214529\u003e)\n bash-10653 1d..2 4us : try_to_wake_up+0x2a6/0x2e7 \u003cffffffff80233e04\u003e (activate_task+0xc/0x3f \u003cffffffff8022ffca\u003e)\n bash-10653 1d..2 4us : activate_task+0x2d/0x3f \u003cffffffff8022ffeb\u003e (enqueue_task+0xe/0x66 \u003cffffffff8022ff66\u003e)\n bash-10653 1d..2 5us : enqueue_task+0x5b/0x66 \u003cffffffff8022ffb3\u003e (enqueue_task_rt+0x9/0x3c \u003cffffffff80233351\u003e)\n bash-10653 1d..2 6us : try_to_wake_up+0x2ba/0x2e7 \u003cffffffff80233e18\u003e (check_preempt_wakeup+0x12/0x99 \u003cffffffff80234f84\u003e)\n[...]\n bash-10653 1d..5 33us : tracing_record_cmdline+0xcf/0xd4 \u003cffffffff80338aad\u003e (_spin_unlock+0x9/0x33 \u003cffffffff8048d3ec\u003e)\n bash-10653 1d..5 34us : _spin_unlock+0x19/0x33 \u003cffffffff8048d3fc\u003e (sub_preempt_count+0xc/0x7a \u003cffffffff8023309e\u003e)\n bash-10653 1d..4 35us : wakeup_sched_switch+0x65/0x2ff \u003cffffffff80339f66\u003e (_spin_lock_irqsave+0xc/0xa9 \u003cffffffff8048d08b\u003e)\n bash-10653 1d..4 35us : _spin_lock_irqsave+0x19/0xa9 \u003cffffffff8048d098\u003e (add_preempt_count+0xe/0x77 \u003cffffffff8023311a\u003e)\n bash-10653 1d..4 36us : sched_switch_callback+0x73/0x81 \u003cffffffff80338d2f\u003e (schedule+0x483/0x6d5 \u003cffffffff8048b3ee\u003e)\n\nvim:ft\u003dhelp\n\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\n\nThe [...] was added here to not waste your email box space.\n\nSigned-off-by: Steven Rostedt \u003csrostedt@redhat.com\u003e\nSigned-off-by: Ingo Molnar \u003cmingo@elte.hu\u003e\nSigned-off-by: Thomas Gleixner \u003ctglx@linutronix.de\u003e\n" }, { "commit": "35e8e302e5d6e32675df2fc1dd3a53dfa6630dc1", "tree": "5b5b503666d882bbb4d805b7b20b4f3b11d2c40e", "parents": [ "1b29b01887e6032dcaf818c14999c7a39593b4e7" ], "author": { "name": "Steven Rostedt", "email": "srostedt@redhat.com", "time": "Mon May 12 21:20:42 2008 +0200" }, "committer": { "name": "Thomas Gleixner", "email": "tglx@linutronix.de", "time": "Fri May 23 20:32:27 2008 +0200" }, "message": "ftrace: add tracing of context switches\n\nThis patch adds context switch tracing, of the format of:\n\n _------\u003d\u003e CPU#\n / _-----\u003d\u003e irqs-off\n | / _----\u003d\u003e need-resched\n || / _---\u003d\u003e hardirq/softirq\n ||| / _--\u003d\u003e preempt-depth\n |||| /\n ||||| delay\n cmd pid ||||| time | pid:prio:state\n \\ / ||||| \\ | /\n swapper-0 1d..3 137us+: 0:140:R --\u003e 2912:120\n sshd-2912 1d..3 216us+: 2912:120:S --\u003e 0:140\n swapper-0 1d..3 261us+: 0:140:R --\u003e 2912:120\n bash-2920 0d..3 267us+: 2920:120:S --\u003e 0:140\n sshd-2912 1d..3 330us!: 2912:120:S --\u003e 0:140\n swapper-0 1d..3 2389us+: 0:140:R --\u003e 2847:120\n yum-upda-2847 1d..3 2411us!: 2847:120:S --\u003e 0:140\n swapper-0 0d..3 11089us+: 0:140:R --\u003e 3139:120\n gdm-bina-3139 0d..3 11113us!: 3139:120:S --\u003e 0:140\n swapper-0 1d..3 102328us+: 0:140:R --\u003e 2847:120\n yum-upda-2847 1d..3 102348us!: 2847:120:S --\u003e 0:140\n\n \"sched_switch\" is added to /debugfs/tracing/available_tracers\n\n[ Eugene Teo \u003ceugeneteo@kernel.sg: remove unused tracing_sched_switch_enabled ]\n\nSigned-off-by: Steven Rostedt \u003csrostedt@redhat.com\u003e\nCc: Mathieu Desnoyers \u003cmathieu.desnoyers@polymtl.ca\u003e\nSigned-off-by: Ingo Molnar \u003cmingo@elte.hu\u003e\nSigned-off-by: Thomas Gleixner \u003ctglx@linutronix.de\u003e\n" }, { "commit": "1b29b01887e6032dcaf818c14999c7a39593b4e7", "tree": "6bcef64d5a7822b0f259a52b852af8cade6b3468", "parents": [ "bc0c38d139ec7fcd5c030aea16b008f3732e42ac" ], "author": { "name": "Steven Rostedt", "email": "srostedt@redhat.com", "time": "Mon May 12 21:20:42 2008 +0200" }, "committer": { "name": "Thomas Gleixner", "email": "tglx@linutronix.de", "time": "Fri May 23 20:32:13 2008 +0200" }, "message": "ftrace: function tracer\n\nThis is a simple trace that uses the ftrace infrastructure. It is\ndesigned to be fast and small, and easy to use. It is useful to\nrecord things that happen over a very short period of time, and\nnot to analyze the system in general.\n\n Updates:\n\n available_tracers\n \"function\" is added to this file.\n\n current_tracer\n To enable the function tracer:\n\n echo function \u003e /debugfs/tracing/current_tracer\n\n To disable the tracer:\n\n echo disable \u003e /debugfs/tracing/current_tracer\n\nThe output of the function_trace file is as follows\n\n \"echo noverbose \u003e /debugfs/tracing/iter_ctrl\"\n\npreemption latency trace v1.1.5 on 2.6.24-rc7-tst\nSigned-off-by: Ingo Molnar \u003cmingo@elte.hu\u003e\n--------------------------------------------------------------------\n latency: 0 us, #419428/4361791, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)\n -----------------\n | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)\n -----------------\n\n _------\u003d\u003e CPU#\n / _-----\u003d\u003e irqs-off\n | / _----\u003d\u003e need-resched\n || / _---\u003d\u003e hardirq/softirq\n ||| / _--\u003d\u003e preempt-depth\n |||| /\n ||||| delay\n cmd pid ||||| time | caller\n \\ / ||||| \\ | /\n swapper-0 0d.h. 1595128us+: set_normalized_timespec+0x8/0x2d \u003cc043841d\u003e (ktime_get_ts+0x4a/0x4e \u003cc04499d4\u003e)\n swapper-0 0d.h. 1595131us+: _spin_lock+0x8/0x18 \u003cc0630690\u003e (hrtimer_interrupt+0x6e/0x1b0 \u003cc0449c56\u003e)\n\nOr with verbose turned on:\n\n \"echo verbose \u003e /debugfs/tracing/iter_ctrl\"\n\npreemption latency trace v1.1.5 on 2.6.24-rc7-tst\n--------------------------------------------------------------------\n latency: 0 us, #419428/4361791, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)\n -----------------\n | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)\n -----------------\n\n swapper 0 0 9 00000000 00000000 [f3675f41] 1595.128ms (+0.003ms): set_normalized_timespec+0x8/0x2d \u003cc043841d\u003e (ktime_get_ts+0x4a/0x4e \u003cc04499d4\u003e)\n swapper 0 0 9 00000000 00000001 [f3675f45] 1595.131ms (+0.003ms): _spin_lock+0x8/0x18 \u003cc0630690\u003e (hrtimer_interrupt+0x6e/0x1b0 \u003cc0449c56\u003e)\n swapper 0 0 9 00000000 00000002 [f3675f48] 1595.135ms (+0.003ms): _spin_lock+0x8/0x18 \u003cc0630690\u003e (hrtimer_interrupt+0x6e/0x1b0 \u003cc0449c56\u003e)\n\nThe \"trace\" file is not affected by the verbose mode, but is by the symonly.\n\n echo \"nosymonly\" \u003e /debugfs/tracing/iter_ctrl\n\ntracer:\n[ 81.479967] CPU 0: bash:3154 register_ftrace_function+0x5f/0x66 \u003cffffffff80337a4d\u003e \u003c-- _spin_unlock_irqrestore+0xe/0x5a \u003cffffffff8048cc8f\u003e\n[ 81.479967] CPU 0: bash:3154 _spin_unlock_irqrestore+0x3e/0x5a \u003cffffffff8048ccbf\u003e \u003c-- sub_preempt_count+0xc/0x7a \u003cffffffff80233d7b\u003e\n[ 81.479968] CPU 0: bash:3154 sub_preempt_count+0x30/0x7a \u003cffffffff80233d9f\u003e \u003c-- in_lock_functions+0x9/0x24 \u003cffffffff8025a75d\u003e\n[ 81.479968] CPU 0: bash:3154 vfs_write+0x11d/0x155 \u003cffffffff8029a043\u003e \u003c-- dnotify_parent+0x12/0x78 \u003cffffffff802d54fb\u003e\n[ 81.479968] CPU 0: bash:3154 dnotify_parent+0x2d/0x78 \u003cffffffff802d5516\u003e \u003c-- _spin_lock+0xe/0x70 \u003cffffffff8048c910\u003e\n[ 81.479969] CPU 0: bash:3154 _spin_lock+0x1b/0x70 \u003cffffffff8048c91d\u003e \u003c-- add_preempt_count+0xe/0x77 \u003cffffffff80233df7\u003e\n[ 81.479969] CPU 0: bash:3154 add_preempt_count+0x3e/0x77 \u003cffffffff80233e27\u003e \u003c-- in_lock_functions+0x9/0x24 \u003cffffffff8025a75d\u003e\n\n echo \"symonly\" \u003e /debugfs/tracing/iter_ctrl\n\ntracer:\n[ 81.479913] CPU 0: bash:3154 register_ftrace_function+0x5f/0x66 \u003c-- _spin_unlock_irqrestore+0xe/0x5a\n[ 81.479913] CPU 0: bash:3154 _spin_unlock_irqrestore+0x3e/0x5a \u003c-- sub_preempt_count+0xc/0x7a\n[ 81.479913] CPU 0: bash:3154 sub_preempt_count+0x30/0x7a \u003c-- in_lock_functions+0x9/0x24\n[ 81.479914] CPU 0: bash:3154 vfs_write+0x11d/0x155 \u003c-- dnotify_parent+0x12/0x78\n[ 81.479914] CPU 0: bash:3154 dnotify_parent+0x2d/0x78 \u003c-- _spin_lock+0xe/0x70\n[ 81.479914] CPU 0: bash:3154 _spin_lock+0x1b/0x70 \u003c-- add_preempt_count+0xe/0x77\n[ 81.479914] CPU 0: bash:3154 add_preempt_count+0x3e/0x77 \u003c-- in_lock_functions+0x9/0x24\n\nSigned-off-by: Steven Rostedt \u003csrostedt@redhat.com\u003e\nSigned-off-by: Arnaldo Carvalho de Melo \u003cacme@ghostprotocols.net\u003e\nSigned-off-by: Ingo Molnar \u003cmingo@elte.hu\u003e\nSigned-off-by: Thomas Gleixner \u003ctglx@linutronix.de\u003e\n" }, { "commit": "bc0c38d139ec7fcd5c030aea16b008f3732e42ac", "tree": "adaaf5e2ca49bbd7025bc357f87df9cb47641022", "parents": [ "16444a8a40d4c7b4f6de34af0cae1f76a4f6c901" ], "author": { "name": "Steven Rostedt", "email": "srostedt@redhat.com", "time": "Mon May 12 21:20:42 2008 +0200" }, "committer": { "name": "Thomas Gleixner", "email": "tglx@linutronix.de", "time": "Fri May 23 20:32:06 2008 +0200" }, "message": "ftrace: latency tracer infrastructure\n\nThis patch adds the latency tracer infrastructure. This patch\ndoes not add anything that will select and turn it on, but will\nbe used by later patches.\n\nIf it were to be compiled, it would add the following files\nto the debugfs:\n\n The root tracing directory:\n\n /debugfs/tracing/\n\nThis patch also adds the following files:\n\n available_tracers\n list of available tracers. Currently no tracers are\n available. Looking into this file only shows\n \"none\" which is used to unregister all tracers.\n\n current_tracer\n The trace that is currently active. Empty on start up.\n To switch to a tracer simply echo one of the tracers that\n are listed in available_tracers:\n\n example: (used with later patches)\n\n echo function \u003e /debugfs/tracing/current_tracer\n\n To disable the tracer:\n\n echo disable \u003e /debugfs/tracing/current_tracer\n\n tracing_enabled\n echoing \"1\" into this file starts the ftrace function tracing\n (if sysctl kernel.ftrace_enabled\u003d1)\n echoing \"0\" turns it off.\n\n latency_trace\n This file is readonly and holds the result of the trace.\n\n trace\n This file outputs a easier to read version of the trace.\n\n iter_ctrl\n Controls the way the output of traces look.\n So far there\u0027s two controls:\n echoing in \"symonly\" will only show the kallsyms variables\n without the addresses (if kallsyms was configured)\n echoing in \"verbose\" will change the output to show\n a lot more data, but not very easy to understand by\n humans.\n echoing in \"nosymonly\" turns off symonly.\n echoing in \"noverbose\" turns off verbose.\n\nSigned-off-by: Steven Rostedt \u003csrostedt@redhat.com\u003e\nSigned-off-by: Arnaldo Carvalho de Melo \u003cacme@ghostprotocols.net\u003e\nSigned-off-by: Ingo Molnar \u003cmingo@elte.hu\u003e\nSigned-off-by: Thomas Gleixner \u003ctglx@linutronix.de\u003e\n" }, { "commit": "16444a8a40d4c7b4f6de34af0cae1f76a4f6c901", "tree": "9c290bcdbdc1ecf8f578c30b3b36914e14fdaacc", "parents": [ "6e766410c4babd37bc7cd5e25009c179781742c8" ], "author": { "name": "Arnaldo Carvalho de Melo", "email": "acme@ghostprotocols.net", "time": "Mon May 12 21:20:42 2008 +0200" }, "committer": { "name": "Thomas Gleixner", "email": "tglx@linutronix.de", "time": "Fri May 23 20:31:58 2008 +0200" }, "message": "ftrace: add basic support for gcc profiler instrumentation\n\nIf CONFIG_FTRACE is selected and /proc/sys/kernel/ftrace_enabled is\nset to a non-zero value the ftrace routine will be called everytime\nwe enter a kernel function that is not marked with the \"notrace\"\nattribute.\n\nThe ftrace routine will then call a registered function if a function\nhappens to be registered.\n\n[ This code has been highly hacked by Steven Rostedt and Ingo Molnar,\n so don\u0027t blame Arnaldo for all of this ;-) ]\n\nUpdate:\n It is now possible to register more than one ftrace function.\n If only one ftrace function is registered, that will be the\n function that ftrace calls directly. If more than one function\n is registered, then ftrace will call a function that will loop\n through the functions to call.\n\nSigned-off-by: Arnaldo Carvalho de Melo \u003cacme@ghostprotocols.net\u003e\nSigned-off-by: Steven Rostedt \u003csrostedt@redhat.com\u003e\nSigned-off-by: Ingo Molnar \u003cmingo@elte.hu\u003e\nSigned-off-by: Thomas Gleixner \u003ctglx@linutronix.de\u003e\n" } ] }