Skip to content

Commit

Permalink
Merge branch 'perf/test' of git://git.kernel.org/pub/scm/linux/kernel…
Browse files Browse the repository at this point in the history 
…/git/frederic/random-tracing into perf/core
  • Loading branch information
Ingo Molnar committed May 10, 2010
2 parents 232a5c9 + 76ba7e8 commit 1f0ac71
Show file tree
Hide file tree
Showing 7 changed files with 257 additions and 145 deletions.
55 changes: 17 additions & 38 deletions include/trace/events/lock.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -35,67 +35,46 @@ TRACE_EVENT(lock_acquire,
__get_str(name))
);

TRACE_EVENT(lock_release,
DECLARE_EVENT_CLASS(lock,

TP_PROTO(struct lockdep_map *lock, int nested, unsigned long ip),
TP_PROTO(struct lockdep_map *lock, unsigned long ip),

TP_ARGS(lock, nested, ip),
TP_ARGS(lock, ip),

TP_STRUCT__entry(
__string(name, lock->name)
__field(void *, lockdep_addr)
__string( name, lock->name )
__field( void *, lockdep_addr )
),

TP_fast_assign(
__assign_str(name, lock->name);
__entry->lockdep_addr = lock;
),

TP_printk("%p %s",
__entry->lockdep_addr, __get_str(name))
TP_printk("%p %s", __entry->lockdep_addr, __get_str(name))
);

#ifdef CONFIG_LOCK_STAT

TRACE_EVENT(lock_contended,
DEFINE_EVENT(lock, lock_release,

TP_PROTO(struct lockdep_map *lock, unsigned long ip),

TP_ARGS(lock, ip),
TP_ARGS(lock, ip)
);

TP_STRUCT__entry(
__string(name, lock->name)
__field(void *, lockdep_addr)
),
#ifdef CONFIG_LOCK_STAT

TP_fast_assign(
__assign_str(name, lock->name);
__entry->lockdep_addr = lock;
),
DEFINE_EVENT(lock, lock_contended,

TP_printk("%p %s",
__entry->lockdep_addr, __get_str(name))
);
TP_PROTO(struct lockdep_map *lock, unsigned long ip),

TRACE_EVENT(lock_acquired,
TP_PROTO(struct lockdep_map *lock, unsigned long ip, s64 waittime),
TP_ARGS(lock, ip)
);

TP_ARGS(lock, ip, waittime),
DEFINE_EVENT(lock, lock_acquired,

TP_STRUCT__entry(
__string(name, lock->name)
__field(s64, wait_nsec)
__field(void *, lockdep_addr)
),
TP_PROTO(struct lockdep_map *lock, unsigned long ip),

TP_fast_assign(
__assign_str(name, lock->name);
__entry->wait_nsec = waittime;
__entry->lockdep_addr = lock;
),
TP_printk("%p %s (%llu ns)", __entry->lockdep_addr,
__get_str(name),
__entry->wait_nsec)
TP_ARGS(lock, ip)
);

#endif
Expand Down
4 changes: 2 additions & 2 deletions kernel/lockdep.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3227,7 +3227,7 @@ void lock_release(struct lockdep_map *lock, int nested,
raw_local_irq_save(flags);
check_flags(flags);
current->lockdep_recursion = 1;
trace_lock_release(lock, nested, ip);
trace_lock_release(lock, ip);
__lock_release(lock, nested, ip);
current->lockdep_recursion = 0;
raw_local_irq_restore(flags);
Expand Down Expand Up @@ -3380,7 +3380,7 @@ __lock_acquired(struct lockdep_map *lock, unsigned long ip)
hlock->holdtime_stamp = now;
}

trace_lock_acquired(lock, ip, waittime);
trace_lock_acquired(lock, ip);

stats = get_lock_stats(hlock_class(hlock));
if (waittime) {
Expand Down
145 changes: 104 additions & 41 deletions tools/perf/builtin-lock.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -387,7 +387,20 @@ static struct lock_seq_stat *get_seq(struct thread_stat *ts, void *addr)
return seq;
}

static int bad_hist[4];
enum broken_state {
BROKEN_ACQUIRE,
BROKEN_ACQUIRED,
BROKEN_CONTENDED,
BROKEN_RELEASE,
BROKEN_MAX,
};

static int bad_hist[BROKEN_MAX];

enum acquire_flags {
TRY_LOCK = 1,
READ_LOCK = 2,
};

static void
report_lock_acquire_event(struct trace_acquire_event *acquire_event,
Expand All @@ -413,17 +426,17 @@ report_lock_acquire_event(struct trace_acquire_event *acquire_event,
if (!acquire_event->flag) {
seq->state = SEQ_STATE_ACQUIRING;
} else {
if (acquire_event->flag & 1)
if (acquire_event->flag & TRY_LOCK)
ls->nr_trylock++;
if (acquire_event->flag & 2)
if (acquire_event->flag & READ_LOCK)
ls->nr_readlock++;
seq->state = SEQ_STATE_READ_ACQUIRED;
seq->read_count = 1;
ls->nr_acquired++;
}
break;
case SEQ_STATE_READ_ACQUIRED:
if (acquire_event->flag & 2) {
if (acquire_event->flag & READ_LOCK) {
seq->read_count++;
ls->nr_acquired++;
goto end;
Expand All @@ -437,7 +450,7 @@ report_lock_acquire_event(struct trace_acquire_event *acquire_event,
broken:
/* broken lock sequence, discard it */
ls->discard = 1;
bad_hist[0]++;
bad_hist[BROKEN_ACQUIRE]++;
list_del(&seq->list);
free(seq);
goto end;
Expand Down Expand Up @@ -481,18 +494,17 @@ report_lock_acquired_event(struct trace_acquired_event *acquired_event,
case SEQ_STATE_CONTENDED:
contended_term = timestamp - seq->prev_event_time;
ls->wait_time_total += contended_term;

if (contended_term < ls->wait_time_min)
ls->wait_time_min = contended_term;
else if (ls->wait_time_max < contended_term)
if (ls->wait_time_max < contended_term)
ls->wait_time_max = contended_term;
break;
case SEQ_STATE_RELEASED:
case SEQ_STATE_ACQUIRED:
case SEQ_STATE_READ_ACQUIRED:
/* broken lock sequence, discard it */
ls->discard = 1;
bad_hist[1]++;
bad_hist[BROKEN_ACQUIRED]++;
list_del(&seq->list);
free(seq);
goto end;
Expand Down Expand Up @@ -540,7 +552,7 @@ report_lock_contended_event(struct trace_contended_event *contended_event,
case SEQ_STATE_CONTENDED:
/* broken lock sequence, discard it */
ls->discard = 1;
bad_hist[2]++;
bad_hist[BROKEN_CONTENDED]++;
list_del(&seq->list);
free(seq);
goto end;
Expand Down Expand Up @@ -594,7 +606,7 @@ report_lock_release_event(struct trace_release_event *release_event,
case SEQ_STATE_RELEASED:
/* broken lock sequence, discard it */
ls->discard = 1;
bad_hist[3]++;
bad_hist[BROKEN_RELEASE]++;
goto free_seq;
break;
default:
Expand Down Expand Up @@ -713,22 +725,37 @@ process_raw_event(void *data, int cpu, u64 timestamp, struct thread *thread)
process_lock_release_event(data, event, cpu, timestamp, thread);
}

static void print_bad_events(int bad, int total)
{
/* Output for debug, this have to be removed */
int i;
const char *name[4] =
{ "acquire", "acquired", "contended", "release" };

pr_info("\n=== output for debug===\n\n");
pr_info("bad: %d, total: %d\n", bad, total);
pr_info("bad rate: %f %%\n", (double)bad / (double)total * 100);
pr_info("histogram of events caused bad sequence\n");
for (i = 0; i < BROKEN_MAX; i++)
pr_info(" %10s: %d\n", name[i], bad_hist[i]);
}

/* TODO: various way to print, coloring, nano or milli sec */
static void print_result(void)
{
struct lock_stat *st;
char cut_name[20];
int bad, total;

printf("%20s ", "Name");
printf("%10s ", "acquired");
printf("%10s ", "contended");
pr_info("%20s ", "Name");
pr_info("%10s ", "acquired");
pr_info("%10s ", "contended");

printf("%15s ", "total wait (ns)");
printf("%15s ", "max wait (ns)");
printf("%15s ", "min wait (ns)");
pr_info("%15s ", "total wait (ns)");
pr_info("%15s ", "max wait (ns)");
pr_info("%15s ", "min wait (ns)");

printf("\n\n");
pr_info("\n\n");

bad = total = 0;
while ((st = pop_from_result())) {
Expand All @@ -741,55 +768,73 @@ static void print_result(void)

if (strlen(st->name) < 16) {
/* output raw name */
printf("%20s ", st->name);
pr_info("%20s ", st->name);
} else {
strncpy(cut_name, st->name, 16);
cut_name[16] = '.';
cut_name[17] = '.';
cut_name[18] = '.';
cut_name[19] = '\0';
/* cut off name for saving output style */
printf("%20s ", cut_name);
pr_info("%20s ", cut_name);
}

printf("%10u ", st->nr_acquired);
printf("%10u ", st->nr_contended);
pr_info("%10u ", st->nr_acquired);
pr_info("%10u ", st->nr_contended);

printf("%15llu ", st->wait_time_total);
printf("%15llu ", st->wait_time_max);
printf("%15llu ", st->wait_time_min == ULLONG_MAX ?
pr_info("%15llu ", st->wait_time_total);
pr_info("%15llu ", st->wait_time_max);
pr_info("%15llu ", st->wait_time_min == ULLONG_MAX ?
0 : st->wait_time_min);
printf("\n");
pr_info("\n");
}

{
/* Output for debug, this have to be removed */
int i;
const char *name[4] =
{ "acquire", "acquired", "contended", "release" };
print_bad_events(bad, total);
}

printf("\n=== output for debug===\n\n");
printf("bad:%d, total:%d\n", bad, total);
printf("bad rate:%f\n", (double)(bad / total));
static int info_threads;
static int info_map;

printf("histogram of events caused bad sequence\n");
for (i = 0; i < 4; i++)
printf(" %10s: %d\n", name[i], bad_hist[i]);
}
static void dump_threads(void)
{
struct thread_stat *st;
struct rb_node *node;
struct thread *t;

pr_info("%10s: comm\n", "Thread ID");

node = rb_first(&thread_stats);
while (node) {
st = container_of(node, struct thread_stat, rb);
t = perf_session__findnew(session, st->tid);
pr_info("%10d: %s\n", st->tid, t->comm);
node = rb_next(node);
};
}

static void dump_map(void)
{
unsigned int i;
struct lock_stat *st;

pr_info("Address of instance: name of class\n");
for (i = 0; i < LOCKHASH_SIZE; i++) {
list_for_each_entry(st, &lockhash_table[i], hash_entry) {
printf("%p: %s\n", st->addr, st->name);
pr_info(" %p: %s\n", st->addr, st->name);
}
}
}

static void dump_info(void)
{
if (info_threads)
dump_threads();
else if (info_map)
dump_map();
else
die("Unknown type of information\n");
}

static int process_sample_event(event_t *self, struct perf_session *s)
{
struct sample_data data;
Expand Down Expand Up @@ -858,6 +903,19 @@ static const struct option report_options[] = {
OPT_END()
};

static const char * const info_usage[] = {
"perf lock info [<options>]",
NULL
};

static const struct option info_options[] = {
OPT_BOOLEAN('t', "threads", &info_threads,
"dump thread list in perf.data"),
OPT_BOOLEAN('m', "map", &info_map,
"map of lock instances (name:address table)"),
OPT_END()
};

static const char * const lock_usage[] = {
"perf lock [<options>] {record|trace|report}",
NULL
Expand All @@ -872,7 +930,6 @@ static const struct option lock_options[] = {

static const char *record_args[] = {
"record",
"-a",
"-R",
"-f",
"-m", "1024",
Expand Down Expand Up @@ -929,12 +986,18 @@ int cmd_lock(int argc, const char **argv, const char *prefix __used)
} else if (!strcmp(argv[0], "trace")) {
/* Aliased to 'perf trace' */
return cmd_trace(argc, argv, prefix);
} else if (!strcmp(argv[0], "map")) {
} else if (!strcmp(argv[0], "info")) {
if (argc) {
argc = parse_options(argc, argv,
info_options, info_usage, 0);
if (argc)
usage_with_options(info_usage, info_options);
}
/* recycling report_lock_ops */
trace_handler = &report_lock_ops;
setup_pager();
read_events();
dump_map();
dump_info();
} else {
usage_with_options(lock_usage, lock_options);
}
Expand Down
Loading

0 comments on commit 1f0ac71

Please sign in to comment.