Skip to content

Commit

Permalink
Merge branches 'tracing/blktrace', 'tracing/ftrace', 'tracing/functio…
Browse files Browse the repository at this point in the history
…n-graph-tracer' and 'tracing/power-tracer' into tracing/core
  • Loading branch information
Ingo Molnar committed Nov 27, 2008
4 parents 0bfc245 + d144d5e + 437f24f + f3f47a6 commit c7cc773
Show file tree
Hide file tree
Showing 24 changed files with 1,054 additions and 273 deletions.
79 changes: 79 additions & 0 deletions Documentation/ftrace.txt
Original file line number Diff line number Diff line change
Expand Up @@ -127,6 +127,8 @@ of ftrace. Here is a list of some of the key files:
be traced. If a function exists in both set_ftrace_filter
and set_ftrace_notrace, the function will _not_ be traced.

set_ftrace_pid: Have the function tracer only trace a single thread.

available_filter_functions: This lists the functions that ftrace
has processed and can trace. These are the function
names that you can pass to "set_ftrace_filter" or
Expand Down Expand Up @@ -1073,6 +1075,83 @@ For simple one time traces, the above is sufficent. For anything else,
a search through /proc/mounts may be needed to find where the debugfs
file-system is mounted.


Single thread tracing
---------------------

By writing into /debug/tracing/set_ftrace_pid you can trace a
single thread. For example:

# cat /debug/tracing/set_ftrace_pid
no pid
# echo 3111 > /debug/tracing/set_ftrace_pid
# cat /debug/tracing/set_ftrace_pid
3111
# echo function > /debug/tracing/current_tracer
# cat /debug/tracing/trace | head
# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
# echo -1 > /debug/tracing/set_ftrace_pid
# cat /debug/tracing/trace |head
# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
##### CPU 3 buffer started ####
yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit

If you want to trace a function when executing, you could use
something like this simple program:

#include <stdio.h>
#include <stdlib.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>

int main (int argc, char **argv)
{
if (argc < 1)
exit(-1);

if (fork() > 0) {
int fd, ffd;
char line[64];
int s;

ffd = open("/debug/tracing/current_tracer", O_WRONLY);
if (ffd < 0)
exit(-1);
write(ffd, "nop", 3);

fd = open("/debug/tracing/set_ftrace_pid", O_WRONLY);
s = sprintf(line, "%d\n", getpid());
write(fd, line, s);

write(ffd, "function", 8);

close(fd);
close(ffd);

execvp(argv[1], argv+1);
}

return 0;
}

dynamic ftrace
--------------

Expand Down
2 changes: 1 addition & 1 deletion arch/x86/Kconfig
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,7 @@ config X86
select HAVE_FTRACE_MCOUNT_RECORD
select HAVE_DYNAMIC_FTRACE
select HAVE_FUNCTION_TRACER
select HAVE_FUNCTION_RET_TRACER if X86_32
select HAVE_FUNCTION_GRAPH_TRACER if X86_32
select HAVE_FUNCTION_TRACE_MCOUNT_TEST
select HAVE_KVM if ((X86_32 && !X86_VOYAGER && !X86_VISWS && !X86_NUMAQ) || X86_64)
select HAVE_ARCH_KGDB if !X86_VOYAGER
Expand Down
4 changes: 2 additions & 2 deletions arch/x86/include/asm/ftrace.h
Original file line number Diff line number Diff line change
Expand Up @@ -28,7 +28,7 @@ struct dyn_arch_ftrace {
#endif /* __ASSEMBLY__ */
#endif /* CONFIG_FUNCTION_TRACER */

#ifdef CONFIG_FUNCTION_RET_TRACER
#ifdef CONFIG_FUNCTION_GRAPH_TRACER

#ifndef __ASSEMBLY__

Expand All @@ -51,6 +51,6 @@ struct ftrace_ret_stack {
extern void return_to_handler(void);

#endif /* __ASSEMBLY__ */
#endif /* CONFIG_FUNCTION_RET_TRACER */
#endif /* CONFIG_FUNCTION_GRAPH_TRACER */

#endif /* _ASM_X86_FTRACE_H */
4 changes: 2 additions & 2 deletions arch/x86/kernel/Makefile
Original file line number Diff line number Diff line change
Expand Up @@ -14,7 +14,7 @@ CFLAGS_REMOVE_paravirt-spinlocks.o = -pg
CFLAGS_REMOVE_ftrace.o = -pg
endif

ifdef CONFIG_FUNCTION_RET_TRACER
ifdef CONFIG_FUNCTION_GRAPH_TRACER
# Don't trace __switch_to() but let it for function tracer
CFLAGS_REMOVE_process_32.o = -pg
endif
Expand Down Expand Up @@ -70,7 +70,7 @@ obj-$(CONFIG_X86_LOCAL_APIC) += apic.o nmi.o
obj-$(CONFIG_X86_IO_APIC) += io_apic.o
obj-$(CONFIG_X86_REBOOTFIXUPS) += reboot_fixups_32.o
obj-$(CONFIG_DYNAMIC_FTRACE) += ftrace.o
obj-$(CONFIG_FUNCTION_RET_TRACER) += ftrace.o
obj-$(CONFIG_FUNCTION_GRAPH_TRACER) += ftrace.o
obj-$(CONFIG_KEXEC) += machine_kexec_$(BITS).o
obj-$(CONFIG_KEXEC) += relocate_kernel_$(BITS).o crash.o
obj-$(CONFIG_CRASH_DUMP) += crash_dump_$(BITS).o
Expand Down
4 changes: 4 additions & 0 deletions arch/x86/kernel/cpu/cpufreq/acpi-cpufreq.c
Original file line number Diff line number Diff line change
Expand Up @@ -33,6 +33,7 @@
#include <linux/cpufreq.h>
#include <linux/compiler.h>
#include <linux/dmi.h>
#include <linux/ftrace.h>

#include <linux/acpi.h>
#include <acpi/processor.h>
Expand Down Expand Up @@ -391,6 +392,7 @@ static int acpi_cpufreq_target(struct cpufreq_policy *policy,
unsigned int next_perf_state = 0; /* Index into perf table */
unsigned int i;
int result = 0;
struct power_trace it;

dprintk("acpi_cpufreq_target %d (%d)\n", target_freq, policy->cpu);

Expand Down Expand Up @@ -427,6 +429,8 @@ static int acpi_cpufreq_target(struct cpufreq_policy *policy,
}
}

trace_power_mark(&it, POWER_PSTATE, next_perf_state);

switch (data->cpu_feature) {
case SYSTEM_INTEL_MSR_CAPABLE:
cmd.type = SYSTEM_INTEL_MSR_CAPABLE;
Expand Down
17 changes: 11 additions & 6 deletions arch/x86/kernel/entry_32.S
Original file line number Diff line number Diff line change
Expand Up @@ -1174,6 +1174,11 @@ ftrace_call:
popl %edx
popl %ecx
popl %eax
#ifdef CONFIG_FUNCTION_GRAPH_TRACER
.globl ftrace_graph_call
ftrace_graph_call:
jmp ftrace_stub
#endif

.globl ftrace_stub
ftrace_stub:
Expand All @@ -1188,9 +1193,9 @@ ENTRY(mcount)

cmpl $ftrace_stub, ftrace_trace_function
jnz trace
#ifdef CONFIG_FUNCTION_RET_TRACER
cmpl $ftrace_stub, ftrace_function_return
jnz ftrace_return_caller
#ifdef CONFIG_FUNCTION_GRAPH_TRACER
cmpl $ftrace_stub, ftrace_graph_return
jnz ftrace_graph_caller
#endif
.globl ftrace_stub
ftrace_stub:
Expand All @@ -1215,8 +1220,8 @@ END(mcount)
#endif /* CONFIG_DYNAMIC_FTRACE */
#endif /* CONFIG_FUNCTION_TRACER */

#ifdef CONFIG_FUNCTION_RET_TRACER
ENTRY(ftrace_return_caller)
#ifdef CONFIG_FUNCTION_GRAPH_TRACER
ENTRY(ftrace_graph_caller)
cmpl $0, function_trace_stop
jne ftrace_stub

Expand All @@ -1230,7 +1235,7 @@ ENTRY(ftrace_return_caller)
popl %ecx
popl %eax
ret
END(ftrace_return_caller)
END(ftrace_graph_caller)

.globl return_to_handler
return_to_handler:
Expand Down
90 changes: 72 additions & 18 deletions arch/x86/kernel/ftrace.c
Original file line number Diff line number Diff line change
Expand Up @@ -111,7 +111,6 @@ static void ftrace_mod_code(void)
*/
mod_code_status = probe_kernel_write(mod_code_ip, mod_code_newcode,
MCOUNT_INSN_SIZE);

}

void ftrace_nmi_enter(void)
Expand Down Expand Up @@ -323,9 +322,53 @@ int __init ftrace_dyn_arch_init(void *data)
}
#endif

#ifdef CONFIG_FUNCTION_RET_TRACER
#ifdef CONFIG_FUNCTION_GRAPH_TRACER

#ifdef CONFIG_DYNAMIC_FTRACE
extern void ftrace_graph_call(void);

static int ftrace_mod_jmp(unsigned long ip,
int old_offset, int new_offset)
{
unsigned char code[MCOUNT_INSN_SIZE];

if (probe_kernel_read(code, (void *)ip, MCOUNT_INSN_SIZE))
return -EFAULT;

if (code[0] != 0xe9 || old_offset != *(int *)(&code[1]))
return -EINVAL;

*(int *)(&code[1]) = new_offset;

if (do_ftrace_mod_code(ip, &code))
return -EPERM;

return 0;
}

int ftrace_enable_ftrace_graph_caller(void)
{
unsigned long ip = (unsigned long)(&ftrace_graph_call);
int old_offset, new_offset;

old_offset = (unsigned long)(&ftrace_stub) - (ip + MCOUNT_INSN_SIZE);
new_offset = (unsigned long)(&ftrace_graph_caller) - (ip + MCOUNT_INSN_SIZE);

return ftrace_mod_jmp(ip, old_offset, new_offset);
}

int ftrace_disable_ftrace_graph_caller(void)
{
unsigned long ip = (unsigned long)(&ftrace_graph_call);
int old_offset, new_offset;

old_offset = (unsigned long)(&ftrace_graph_caller) - (ip + MCOUNT_INSN_SIZE);
new_offset = (unsigned long)(&ftrace_stub) - (ip + MCOUNT_INSN_SIZE);

return ftrace_mod_jmp(ip, old_offset, new_offset);
}

#ifndef CONFIG_DYNAMIC_FTRACE
#else /* CONFIG_DYNAMIC_FTRACE */

/*
* These functions are picked from those used on
Expand All @@ -343,11 +386,12 @@ void ftrace_nmi_exit(void)
{
atomic_dec(&in_nmi);
}

#endif /* !CONFIG_DYNAMIC_FTRACE */

/* Add a function return address to the trace stack on thread info.*/
static int push_return_trace(unsigned long ret, unsigned long long time,
unsigned long func)
unsigned long func, int *depth)
{
int index;

Expand All @@ -365,21 +409,22 @@ static int push_return_trace(unsigned long ret, unsigned long long time,
current->ret_stack[index].ret = ret;
current->ret_stack[index].func = func;
current->ret_stack[index].calltime = time;
*depth = index;

return 0;
}

/* Retrieve a function return address to the trace stack on thread info.*/
static void pop_return_trace(unsigned long *ret, unsigned long long *time,
unsigned long *func, unsigned long *overrun)
static void pop_return_trace(struct ftrace_graph_ret *trace, unsigned long *ret)
{
int index;

index = current->curr_ret_stack;
*ret = current->ret_stack[index].ret;
*func = current->ret_stack[index].func;
*time = current->ret_stack[index].calltime;
*overrun = atomic_read(&current->trace_overrun);
trace->func = current->ret_stack[index].func;
trace->calltime = current->ret_stack[index].calltime;
trace->overrun = atomic_read(&current->trace_overrun);
trace->depth = index;
current->curr_ret_stack--;
}

Expand All @@ -389,13 +434,14 @@ static void pop_return_trace(unsigned long *ret, unsigned long long *time,
*/
unsigned long ftrace_return_to_handler(void)
{
struct ftrace_retfunc trace;
pop_return_trace(&trace.ret, &trace.calltime, &trace.func,
&trace.overrun);
struct ftrace_graph_ret trace;
unsigned long ret;

pop_return_trace(&trace, &ret);
trace.rettime = cpu_clock(raw_smp_processor_id());
ftrace_function_return(&trace);
ftrace_graph_return(&trace);

return trace.ret;
return ret;
}

/*
Expand All @@ -407,6 +453,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
unsigned long old;
unsigned long long calltime;
int faulted;
struct ftrace_graph_ent trace;
unsigned long return_hooker = (unsigned long)
&return_to_handler;

Expand Down Expand Up @@ -440,20 +487,27 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr)
);

if (WARN_ON(faulted)) {
unregister_ftrace_return();
unregister_ftrace_graph();
return;
}

if (WARN_ON(!__kernel_text_address(old))) {
unregister_ftrace_return();
unregister_ftrace_graph();
*parent = old;
return;
}

calltime = cpu_clock(raw_smp_processor_id());

if (push_return_trace(old, calltime, self_addr) == -EBUSY)
if (push_return_trace(old, calltime,
self_addr, &trace.depth) == -EBUSY) {
*parent = old;
return;
}

trace.func = self_addr;
ftrace_graph_entry(&trace);

}

#endif /* CONFIG_FUNCTION_RET_TRACER */
#endif /* CONFIG_FUNCTION_GRAPH_TRACER */
Loading

0 comments on commit c7cc773

Please sign in to comment.