trace.c

Kernel code of linux kernel

{
	struct trace_array_cpu *data = iter->tr->data[iter->cpu];

	data->trace_tail_idx++;
	if (data->trace_tail_idx >= ENTRIES_PER_PAGE) {
		data->trace_tail = trace_next_page(data, data->trace_tail);
		data->trace_tail_idx = 0;
	}

	/* Check if we empty it, then reset the index */
	if (data->trace_head == data->trace_tail &&
	    data->trace_head_idx == data->trace_tail_idx)
		data->trace_idx = 0;
}

static void *find_next_entry_inc(struct trace_iterator *iter)
{
	struct trace_entry *next;
	int next_cpu = -1;

	next = find_next_entry(iter, &next_cpu);

	iter->prev_ent = iter->ent;
	iter->prev_cpu = iter->cpu;

	iter->ent = next;
	iter->cpu = next_cpu;

	if (next)
		trace_iterator_increment(iter);

	return next ? iter : NULL;
}

static void *s_next(struct seq_file *m, void *v, loff_t *pos)
{
	struct trace_iterator *iter = m->private;
	int i = (int)*pos;
	void *ent;

	(*pos)++;

	/* can't go backwards */
	if (iter->idx > i)
		return NULL;

	if (iter->idx < 0)
		ent = find_next_entry_inc(iter);
	else
		ent = iter;

	while (ent && iter->idx < i)
		ent = find_next_entry_inc(iter);

	iter->pos = *pos;

	return ent;
}

static void *s_start(struct seq_file *m, loff_t *pos)
{
	struct trace_iterator *iter = m->private;
	void *p = NULL;
	loff_t l = 0;
	int i;

	mutex_lock(&trace_types_lock);

	if (!current_trace || current_trace != iter->trace) {
		mutex_unlock(&trace_types_lock);
		return NULL;
	}

	atomic_inc(&trace_record_cmdline_disabled);

	/* let the tracer grab locks here if needed */
	if (current_trace->start)
		current_trace->start(iter);

	if (*pos != iter->pos) {
		iter->ent = NULL;
		iter->cpu = 0;
		iter->idx = -1;
		iter->prev_ent = NULL;
		iter->prev_cpu = -1;

		for_each_tracing_cpu(i) {
			iter->next_idx[i] = 0;
			iter->next_page[i] = NULL;
		}

		for (p = iter; p && l < *pos; p = s_next(m, p, &l))
			;

	} else {
		l = *pos - 1;
		p = s_next(m, p, &l);
	}

	return p;
}

static void s_stop(struct seq_file *m, void *p)
{
	struct trace_iterator *iter = m->private;

	atomic_dec(&trace_record_cmdline_disabled);

	/* let the tracer release locks here if needed */
	if (current_trace && current_trace == iter->trace && iter->trace->stop)
		iter->trace->stop(iter);

	mutex_unlock(&trace_types_lock);
}

#define KRETPROBE_MSG "[unknown/kretprobe'd]"

#ifdef CONFIG_KRETPROBES
static inline int kretprobed(unsigned long addr)
{
	return addr == (unsigned long)kretprobe_trampoline;
}
#else
static inline int kretprobed(unsigned long addr)
{
	return 0;
}
#endif /* CONFIG_KRETPROBES */

static int
seq_print_sym_short(struct trace_seq *s, const char *fmt, unsigned long address)
{
#ifdef CONFIG_KALLSYMS
	char str[KSYM_SYMBOL_LEN];

	kallsyms_lookup(address, NULL, NULL, NULL, str);

	return trace_seq_printf(s, fmt, str);
#endif
	return 1;
}

static int
seq_print_sym_offset(struct trace_seq *s, const char *fmt,
		     unsigned long address)
{
#ifdef CONFIG_KALLSYMS
	char str[KSYM_SYMBOL_LEN];

	sprint_symbol(str, address);
	return trace_seq_printf(s, fmt, str);
#endif
	return 1;
}

#ifndef CONFIG_64BIT
# define IP_FMT "%08lx"
#else
# define IP_FMT "%016lx"
#endif

static int
seq_print_ip_sym(struct trace_seq *s, unsigned long ip, unsigned long sym_flags)
{
	int ret;

	if (!ip)
		return trace_seq_printf(s, "0");

	if (sym_flags & TRACE_ITER_SYM_OFFSET)
		ret = seq_print_sym_offset(s, "%s", ip);
	else
		ret = seq_print_sym_short(s, "%s", ip);

	if (!ret)
		return 0;

	if (sym_flags & TRACE_ITER_SYM_ADDR)
		ret = trace_seq_printf(s, " <" IP_FMT ">", ip);
	return ret;
}

static void print_lat_help_header(struct seq_file *m)
{
	seq_puts(m, "#                _------=> CPU#            \n");
	seq_puts(m, "#               / _-----=> irqs-off        \n");
	seq_puts(m, "#              | / _----=> need-resched    \n");
	seq_puts(m, "#              || / _---=> hardirq/softirq \n");
	seq_puts(m, "#              ||| / _--=> preempt-depth   \n");
	seq_puts(m, "#              |||| /                      \n");
	seq_puts(m, "#              |||||     delay             \n");
	seq_puts(m, "#  cmd     pid ||||| time  |   caller      \n");
	seq_puts(m, "#     \\   /    |||||   \\   |   /           \n");
}

static void print_func_help_header(struct seq_file *m)
{
	seq_puts(m, "#           TASK-PID   CPU#    TIMESTAMP  FUNCTION\n");
	seq_puts(m, "#              | |      |          |         |\n");
}


static void
print_trace_header(struct seq_file *m, struct trace_iterator *iter)
{
	unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
	struct trace_array *tr = iter->tr;
	struct trace_array_cpu *data = tr->data[tr->cpu];
	struct tracer *type = current_trace;
	unsigned long total   = 0;
	unsigned long entries = 0;
	int cpu;
	const char *name = "preemption";

	if (type)
		name = type->name;

	for_each_tracing_cpu(cpu) {
		if (head_page(tr->data[cpu])) {
			total += tr->data[cpu]->trace_idx;
			if (tr->data[cpu]->trace_idx > tr->entries)
				entries += tr->entries;
			else
				entries += tr->data[cpu]->trace_idx;
		}
	}

	seq_printf(m, "%s latency trace v1.1.5 on %s\n",
		   name, UTS_RELEASE);
	seq_puts(m, "-----------------------------------"
		 "---------------------------------\n");
	seq_printf(m, " latency: %lu us, #%lu/%lu, CPU#%d |"
		   " (M:%s VP:%d, KP:%d, SP:%d HP:%d",
		   nsecs_to_usecs(data->saved_latency),
		   entries,
		   total,
		   tr->cpu,
#if defined(CONFIG_PREEMPT_NONE)
		   "server",
#elif defined(CONFIG_PREEMPT_VOLUNTARY)
		   "desktop",
#elif defined(CONFIG_PREEMPT)
		   "preempt",
#else
		   "unknown",
#endif
		   /* These are reserved for later use */
		   0, 0, 0, 0);
#ifdef CONFIG_SMP
	seq_printf(m, " #P:%d)\n", num_online_cpus());
#else
	seq_puts(m, ")\n");
#endif
	seq_puts(m, "    -----------------\n");
	seq_printf(m, "    | task: %.16s-%d "
		   "(uid:%d nice:%ld policy:%ld rt_prio:%ld)\n",
		   data->comm, data->pid, data->uid, data->nice,
		   data->policy, data->rt_priority);
	seq_puts(m, "    -----------------\n");

	if (data->critical_start) {
		seq_puts(m, " => started at: ");
		seq_print_ip_sym(&iter->seq, data->critical_start, sym_flags);
		trace_print_seq(m, &iter->seq);
		seq_puts(m, "\n => ended at:   ");
		seq_print_ip_sym(&iter->seq, data->critical_end, sym_flags);
		trace_print_seq(m, &iter->seq);
		seq_puts(m, "\n");
	}

	seq_puts(m, "\n");
}

static void
lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu)
{
	int hardirq, softirq;
	char *comm;

	comm = trace_find_cmdline(entry->pid);

	trace_seq_printf(s, "%8.8s-%-5d ", comm, entry->pid);
	trace_seq_printf(s, "%d", cpu);
	trace_seq_printf(s, "%c%c",
			(entry->flags & TRACE_FLAG_IRQS_OFF) ? 'd' : '.',
			((entry->flags & TRACE_FLAG_NEED_RESCHED) ? 'N' : '.'));

	hardirq = entry->flags & TRACE_FLAG_HARDIRQ;
	softirq = entry->flags & TRACE_FLAG_SOFTIRQ;
	if (hardirq && softirq) {
		trace_seq_putc(s, 'H');
	} else {
		if (hardirq) {
			trace_seq_putc(s, 'h');
		} else {
			if (softirq)
				trace_seq_putc(s, 's');
			else
				trace_seq_putc(s, '.');
		}
	}

	if (entry->preempt_count)
		trace_seq_printf(s, "%x", entry->preempt_count);
	else
		trace_seq_puts(s, ".");
}

unsigned long preempt_mark_thresh = 100;

static void
lat_print_timestamp(struct trace_seq *s, unsigned long long abs_usecs,
		    unsigned long rel_usecs)
{
	trace_seq_printf(s, " %4lldus", abs_usecs);
	if (rel_usecs > preempt_mark_thresh)
		trace_seq_puts(s, "!: ");
	else if (rel_usecs > 1)
		trace_seq_puts(s, "+: ");
	else
		trace_seq_puts(s, " : ");
}

static const char state_to_char[] = TASK_STATE_TO_CHAR_STR;

static int
print_lat_fmt(struct trace_iterator *iter, unsigned int trace_idx, int cpu)
{
	struct trace_seq *s = &iter->seq;
	unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
	struct trace_entry *next_entry = find_next_entry(iter, NULL);
	unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE);
	struct trace_entry *entry = iter->ent;
	unsigned long abs_usecs;
	unsigned long rel_usecs;
	char *comm;
	int S, T;
	int i;
	unsigned state;

	if (!next_entry)
		next_entry = entry;
	rel_usecs = ns2usecs(next_entry->t - entry->t);
	abs_usecs = ns2usecs(entry->t - iter->tr->time_start);

	if (verbose) {
		comm = trace_find_cmdline(entry->pid);
		trace_seq_printf(s, "%16s %5d %d %d %08x %08x [%08lx]"
				 " %ld.%03ldms (+%ld.%03ldms): ",
				 comm,
				 entry->pid, cpu, entry->flags,
				 entry->preempt_count, trace_idx,
				 ns2usecs(entry->t),
				 abs_usecs/1000,
				 abs_usecs % 1000, rel_usecs/1000,
				 rel_usecs % 1000);
	} else {
		lat_print_generic(s, entry, cpu);
		lat_print_timestamp(s, abs_usecs, rel_usecs);
	}
	switch (entry->type) {
	case TRACE_FN:
		seq_print_ip_sym(s, entry->fn.ip, sym_flags);
		trace_seq_puts(s, " (");
		if (kretprobed(entry->fn.parent_ip))
			trace_seq_puts(s, KRETPROBE_MSG);
		else
			seq_print_ip_sym(s, entry->fn.parent_ip, sym_flags);
		trace_seq_puts(s, ")\n");
		break;
	case TRACE_CTX:
	case TRACE_WAKE:
		T = entry->ctx.next_state < sizeof(state_to_char) ?
			state_to_char[entry->ctx.next_state] : 'X';

		state = entry->ctx.prev_state ? __ffs(entry->ctx.prev_state) + 1 : 0;
		S = state < sizeof(state_to_char) - 1 ? state_to_char[state] : 'X';
		comm = trace_find_cmdline(entry->ctx.next_pid);
		trace_seq_printf(s, " %5d:%3d:%c %s %5d:%3d:%c %s\n",
				 entry->ctx.prev_pid,
				 entry->ctx.prev_prio,
				 S, entry->type == TRACE_CTX ? "==>" : "  +",
				 entry->ctx.next_pid,
				 entry->ctx.next_prio,
				 T, comm);
		break;
	case TRACE_SPECIAL:
		trace_seq_printf(s, "# %ld %ld %ld\n",
				 entry->special.arg1,
				 entry->special.arg2,
				 entry->special.arg3);
		break;
	case TRACE_STACK:
		for (i = 0; i < FTRACE_STACK_ENTRIES; i++) {
			if (i)
				trace_seq_puts(s, " <= ");
			seq_print_ip_sym(s, entry->stack.caller[i], sym_flags);
		}
		trace_seq_puts(s, "\n");
		break;
	default:
		trace_seq_printf(s, "Unknown type %d\n", entry->type);
	}
	return 1;
}

static int print_trace_fmt(struct trace_iterator *iter)
{
	struct trace_seq *s = &iter->seq;
	unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
	struct trace_entry *entry;
	unsigned long usec_rem;
	unsigned long long t;
	unsigned long secs;
	char *comm;
	int ret;
	int S, T;
	int i;

	entry = iter->ent;

	comm = trace_find_cmdline(iter->ent->pid);

	t = ns2usecs(entry->t);
	usec_rem = do_div(t, 1000000ULL);
	secs = (unsigned long)t;

	ret = trace_seq_printf(s, "%16s-%-5d ", comm, entry->pid);
	if (!ret)
		return 0;
	ret = trace_seq_printf(s, "[%02d] ", iter->cpu);
	if (!ret)
		return 0;
	ret = trace_seq_printf(s, "%5lu.%06lu: ", secs, usec_rem);
	if (!ret)
		return 0;

	switch (entry->type) {
	case TRACE_FN:
		ret = seq_print_ip_sym(s, entry->fn.ip, sym_flags);
		if (!ret)
			return 0;
		if ((sym_flags & TRACE_ITER_PRINT_PARENT) &&
						entry->fn.parent_ip) {
			ret = trace_seq_printf(s, " <-");
			if (!ret)
				return 0;
			if (kretprobed(entry->fn.parent_ip))
				ret = trace_seq_puts(s, KRETPROBE_MSG);
			else
				ret = seq_print_ip_sym(s, entry->fn.parent_ip,
						       sym_flags);
			if (!ret)
				return 0;
		}
		ret = trace_seq_printf(s, "\n");
		if (!ret)
			return 0;
		break;
	case TRACE_CTX:
	case TRACE_WAKE:
		S = entry->ctx.prev_state < sizeof(state_to_char) ?
			state_to_char[entry->ctx.prev_state] : 'X';
		T = entry->ctx.next_state < sizeof(state_to_char) ?
			state_to_char[entry->ctx.next_state] : 'X';
		ret = trace_seq_printf(s, " %5d:%3d:%c %s %5d:%3d:%c\n",
				       entry->ctx.prev_pid,
				       entry->ctx.prev_prio,
				       S,
				       entry->type == TRACE_CTX ? "==>" : "  +",
				       entry->ctx.next_pid,
				       entry->ctx.next_prio,
				       T);
		if (!ret)
			return 0;
		break;
	case TRACE_SPECIAL:
		ret = trace_seq_printf(s, "# %ld %ld %ld\n",
				 entry->special.arg1,
				 entry->special.arg2,
				 entry->special.arg3);
		if (!ret)
			return 0;
		break;
	case TRACE_STACK:
		for (i = 0; i < FTRACE_STACK_ENTRIES; i++) {
			if (i) {
				ret = trace_seq_puts(s, " <= ");
				if (!ret)
					return 0;
			}
			ret = seq_print_ip_sym(s, entry->stack.caller[i],
					       sym_flags);
			if (!ret)
				return 0;
		}
		ret = trace_seq_puts(s, "\n");
		if (!ret)
			return 0;
		break;
	}
	return 1;
}

static int print_raw_fmt(struct trace_iterator *iter)
{
	struct trace_seq *s = &iter->seq;
	struct trace_entry *entry;
	int ret;
	int S, T;

	entry = iter->ent;

	ret = trace_seq_printf(s, "%d %d %llu ",
		entry->pid, iter->cpu, entry->t);
	if (!ret)
		return 0;

	switch (entry->type) {
	case TRACE_FN:
		ret = trace_seq_printf(s, "%x %x\n",
					entry->fn.ip, entry->fn.parent_ip);
		if (!ret)
			return 0;
		break;
	case TRACE_CTX:
	case TRACE_WAKE:
		S = entry->ctx.prev_state < sizeof(state_to_char) ?
			state_to_char[entry->ctx.prev_state] : 'X';
		T = entry->ctx.next_state < sizeof(state_to_char) ?
			state_to_char[entry->ctx.next_state] : 'X';
		if (entry->type == TRACE_WAKE)
			S = '+';
		ret = trace_seq_printf(s, "%d %d %c %d %d %c\n",
				       entry->ctx.prev_pid,
				       entry->ctx.prev_prio,
				       S,
				       entry->ctx.next_pid,
				       entry->ctx.next_prio,
				       T);
		if (!ret)
			return 0;
		break;
	case TRACE_SPECIAL:
	case TRACE_STACK:
		ret = trace_seq_printf(s, "# %ld %ld %ld\n",
				 entry->special.arg1,
				 entry->special.arg2,
				 entry->special.arg3);
		if (!ret)
			return 0;
		break;
	}
	return 1;
}

#define SEQ_PUT_FIELD_RET(s, x)				\
do {							\
	if (!trace_seq_putmem(s, &(x), sizeof(x)))	\
		return 0;				\
} while (0)

#define SEQ_PUT_HEX_FIELD_RET(s, x)			\
do {							\
	if (!trace_seq_putmem_hex(s, &(x), sizeof(x)))	\
		return 0;				\
} while (0)

static int print_hex_fmt(struct trace_iterator *iter)
{
	struct trace_seq *s = &iter->seq;
	unsigned char newline = '\n';
	struct trace_entry *entry;
	int S, T;