kernel/time/timer_stats.c

   1 /*
   2  * kernel/time/timer_stats.c
   3  *
   4  * Collect timer usage statistics.
   5  *
   6  * Copyright(C) 2006, Red Hat, Inc., Ingo Molnar
   7  * Copyright(C) 2006 Timesys Corp., Thomas Gleixner <tglx@timesys.com>
   8  *
   9  * timer_stats is based on timer_top, a similar functionality which was part of
  10  * Con Kolivas dyntick patch set. It was developed by Daniel Petrini at the
  11  * Instituto Nokia de Tecnologia - INdT - Manaus. timer_top's design was based
  12  * on dynamic allocation of the statistics entries and linear search based
  13  * lookup combined with a global lock, rather than the static array, hash
  14  * and per-CPU locking which is used by timer_stats. It was written for the
  15  * pre hrtimer kernel code and therefore did not take hrtimers into account.
  16  * Nevertheless it provided the base for the timer_stats implementation and
  17  * was a helpful source of inspiration. Kudos to Daniel and the Nokia folks
  18  * for this effort.
  19  *
  20  * timer_top.c is
  21  *      Copyright (C) 2005 Instituto Nokia de Tecnologia - INdT - Manaus
  22  *      Written by Daniel Petrini <d.pensator@gmail.com>
  23  *      timer_top.c was released under the GNU General Public License version 2
  24  *
  25  * We export the addresses and counting of timer functions being called,
  26  * the pid and cmdline from the owner process if applicable.
  27  *
  28  * Start/stop data collection:
  29  * # echo 1[0] >/proc/timer_stats
  30  *
  31  * Display the information collected so far:
  32  * # cat /proc/timer_stats
  33  *
  34  * This program is free software; you can redistribute it and/or modify
  35  * it under the terms of the GNU General Public License version 2 as
  36  * published by the Free Software Foundation.
  37  */
  38
  39 #include <linux/proc_fs.h>
  40 #include <linux/module.h>
  41 #include <linux/spinlock.h>
  42 #include <linux/sched.h>
  43 #include <linux/seq_file.h>
  44 #include <linux/kallsyms.h>
  45
  46 #include <asm/uaccess.h>
  47
  48 /*
  49  * This is our basic unit of interest: a timer expiry event identified
  50  * by the timer, its start/expire functions and the PID of the task that
  51  * started the timer. We count the number of times an event happens:
  52  */
  53 struct entry {
  54         /*
  55          * Hash list:
  56          */
  57         struct entry            *next;
  58
  59         /*
  60          * Hash keys:
  61          */
  62         void                    *timer;
  63         void                    *start_func;
  64         void                    *expire_func;
  65         pid_t                   pid;
  66
  67         /*
  68          * Number of timeout events:
  69          */
  70         unsigned long           count;
  71         unsigned int            timer_flag;
  72
  73         /*
  74          * We save the command-line string to preserve
  75          * this information past task exit:
  76          */
  77         char                    comm[TASK_COMM_LEN + 1];
  78
  79 } ____cacheline_aligned_in_smp;
  80
  81 /*
  82  * Spinlock protecting the tables - not taken during lookup:
  83  */
  84 static DEFINE_SPINLOCK(table_lock);
  85
  86 /*
  87  * Per-CPU lookup locks for fast hash lookup:
  88  */
  89 static DEFINE_PER_CPU(spinlock_t, lookup_lock);
  90
  91 /*
  92  * Mutex to serialize state changes with show-stats activities:
  93  */
  94 static DEFINE_MUTEX(show_mutex);
  95
  96 /*
  97  * Collection status, active/inactive:
  98  */
  99 static int __read_mostly active;
 100
 101 /*
 102  * Beginning/end timestamps of measurement:
 103  */
 104 static ktime_t time_start, time_stop;
 105
 106 /*
 107  * tstat entry structs only get allocated while collection is
 108  * active and never freed during that time - this simplifies
 109  * things quite a bit.
 110  *
 111  * They get freed when a new collection period is started.
 112  */
 113 #define MAX_ENTRIES_BITS        10
 114 #define MAX_ENTRIES             (1UL << MAX_ENTRIES_BITS)
 115
 116 static unsigned long nr_entries;
 117 static struct entry entries[MAX_ENTRIES];
 118
 119 static atomic_t overflow_count;
 120
 121 /*
 122  * The entries are in a hash-table, for fast lookup:
 123  */
 124 #define TSTAT_HASH_BITS         (MAX_ENTRIES_BITS - 1)
 125 #define TSTAT_HASH_SIZE         (1UL << TSTAT_HASH_BITS)
 126 #define TSTAT_HASH_MASK         (TSTAT_HASH_SIZE - 1)
 127
 128 #define __tstat_hashfn(entry)                                           \
 129         (((unsigned long)(entry)->timer       ^                         \
 130           (unsigned long)(entry)->start_func  ^                         \
 131           (unsigned long)(entry)->expire_func ^                         \
 132           (unsigned long)(entry)->pid           ) & TSTAT_HASH_MASK)
 133
 134 #define tstat_hashentry(entry)  (tstat_hash_table + __tstat_hashfn(entry))
 135
 136 static struct entry *tstat_hash_table[TSTAT_HASH_SIZE] __read_mostly;
 137
 138 static void reset_entries(void)
 139 {
 140         nr_entries = 0;
 141         memset(entries, 0, sizeof(entries));
 142         memset(tstat_hash_table, 0, sizeof(tstat_hash_table));
 143         atomic_set(&overflow_count, 0);
 144 }
 145
 146 static struct entry *alloc_entry(void)
 147 {
 148         if (nr_entries >= MAX_ENTRIES)
 149                 return NULL;
 150
 151         return entries + nr_entries++;
 152 }
 153
 154 static int match_entries(struct entry *entry1, struct entry *entry2)
 155 {
 156         return entry1->timer       == entry2->timer       &&
 157                entry1->start_func  == entry2->start_func  &&
 158                entry1->expire_func == entry2->expire_func &&
 159                entry1->pid         == entry2->pid;
 160 }
 161
 162 /*
 163  * Look up whether an entry matching this item is present
 164  * in the hash already. Must be called with irqs off and the
 165  * lookup lock held:
 166  */
 167 static struct entry *tstat_lookup(struct entry *entry, char *comm)
 168 {
 169         struct entry **head, *curr, *prev;
 170
 171         head = tstat_hashentry(entry);
 172         curr = *head;
 173
 174         /*
 175          * The fastpath is when the entry is already hashed,
 176          * we do this with the lookup lock held, but with the
 177          * table lock not held:
 178          */
 179         while (curr) {
 180                 if (match_entries(curr, entry))
 181                         return curr;
 182
 183                 curr = curr->next;
 184         }
 185         /*
 186          * Slowpath: allocate, set up and link a new hash entry:
 187          */
 188         prev = NULL;
 189         curr = *head;
 190
 191         spin_lock(&table_lock);
 192         /*
 193          * Make sure we have not raced with another CPU:
 194          */
 195         while (curr) {
 196                 if (match_entries(curr, entry))
 197                         goto out_unlock;
 198
 199                 prev = curr;
 200                 curr = curr->next;
 201         }
 202
 203         curr = alloc_entry();
 204         if (curr) {
 205                 *curr = *entry;
 206                 curr->count = 0;
 207                 curr->next = NULL;
 208                 memcpy(curr->comm, comm, TASK_COMM_LEN);
 209
 210                 smp_mb(); /* Ensure that curr is initialized before insert */
 211
 212                 if (prev)
 213                         prev->next = curr;
 214                 else
 215                         *head = curr;
 216         }
 217  out_unlock:
 218         spin_unlock(&table_lock);
 219
 220         return curr;
 221 }
 222
 223 /**
 224  * timer_stats_update_stats - Update the statistics for a timer.
 225  * @timer:      pointer to either a timer_list or a hrtimer
 226  * @pid:        the pid of the task which set up the timer
 227  * @startf:     pointer to the function which did the timer setup
 228  * @timerf:     pointer to the timer callback function of the timer
 229  * @comm:       name of the process which set up the timer
 230  *
 231  * When the timer is already registered, then the event counter is
 232  * incremented. Otherwise the timer is registered in a free slot.
 233  */
 234 void timer_stats_update_stats(void *timer, pid_t pid, void *startf,
 235                               void *timerf, char *comm,
 236                               unsigned int timer_flag)
 237 {
 238         /*
 239          * It doesnt matter which lock we take:
 240          */
 241         spinlock_t *lock;
 242         struct entry *entry, input;
 243         unsigned long flags;
 244
 245         if (likely(!active))
 246                 return;
 247
 248         lock = &per_cpu(lookup_lock, raw_smp_processor_id());
 249
 250         input.timer = timer;
 251         input.start_func = startf;
 252         input.expire_func = timerf;
 253         input.pid = pid;
 254         input.timer_flag = timer_flag;
 255
 256         spin_lock_irqsave(lock, flags);
 257         if (!active)
 258                 goto out_unlock;
 259
 260         entry = tstat_lookup(&input, comm);
 261         if (likely(entry))
 262                 entry->count++;
 263         else
 264                 atomic_inc(&overflow_count);
 265
 266  out_unlock:
 267         spin_unlock_irqrestore(lock, flags);
 268 }
 269
 270 static void print_name_offset(struct seq_file *m, unsigned long addr)
 271 {
 272         char symname[KSYM_NAME_LEN];
 273
 274         if (lookup_symbol_name(addr, symname) < 0)
 275                 seq_printf(m, "<%p>", (void *)addr);
 276         else
 277                 seq_printf(m, "%s", symname);
 278 }
 279
 280 static int tstats_show(struct seq_file *m, void *v)
 281 {
 282         struct timespec period;
 283         struct entry *entry;
 284         unsigned long ms;
 285         long events = 0;
 286         ktime_t time;
 287         int i;
 288
 289         mutex_lock(&show_mutex);
 290         /*
 291          * If still active then calculate up to now:
 292          */
 293         if (active)
 294                 time_stop = ktime_get();
 295
 296         time = ktime_sub(time_stop, time_start);
 297
 298         period = ktime_to_timespec(time);
 299         ms = period.tv_nsec / 1000000;
 300
 301         seq_puts(m, "Timer Stats Version: v0.2\n");
 302         seq_printf(m, "Sample period: %ld.%03ld s\n", period.tv_sec, ms);
 303         if (atomic_read(&overflow_count))
 304                 seq_printf(m, "Overflow: %d entries\n",
 305                         atomic_read(&overflow_count));
 306
 307         for (i = 0; i < nr_entries; i++) {
 308                 entry = entries + i;
 309                 if (entry->timer_flag & TIMER_STATS_FLAG_DEFERRABLE) {
 310                         seq_printf(m, "%4luD, %5d %-16s ",
 311                                 entry->count, entry->pid, entry->comm);
 312                 } else {
 313                         seq_printf(m, " %4lu, %5d %-16s ",
 314                                 entry->count, entry->pid, entry->comm);
 315                 }
 316
 317                 print_name_offset(m, (unsigned long)entry->start_func);
 318                 seq_puts(m, " (");
 319                 print_name_offset(m, (unsigned long)entry->expire_func);
 320                 seq_puts(m, ")\n");
 321
 322                 events += entry->count;
 323         }
 324
 325         ms += period.tv_sec * 1000;
 326         if (!ms)
 327                 ms = 1;
 328
 329         if (events && period.tv_sec)
 330                 seq_printf(m, "%ld total events, %ld.%ld events/sec\n", events,
 331                            events / period.tv_sec, events * 1000 / ms);
 332         else
 333                 seq_printf(m, "%ld total events\n", events);
 334
 335         mutex_unlock(&show_mutex);
 336
 337         return 0;
 338 }
 339
 340 /*
 341  * After a state change, make sure all concurrent lookup/update
 342  * activities have stopped:
 343  */
 344 static void sync_access(void)
 345 {
 346         unsigned long flags;
 347         int cpu;
 348
 349         for_each_online_cpu(cpu) {
 350                 spin_lock_irqsave(&per_cpu(lookup_lock, cpu), flags);
 351                 /* nothing */
 352                 spin_unlock_irqrestore(&per_cpu(lookup_lock, cpu), flags);
 353         }
 354 }
 355
 356 static ssize_t tstats_write(struct file *file, const char __user *buf,
 357                             size_t count, loff_t *offs)
 358 {
 359         char ctl[2];
 360
 361         if (count != 2 || *offs)
 362                 return -EINVAL;
 363
 364         if (copy_from_user(ctl, buf, count))
 365                 return -EFAULT;
 366
 367         mutex_lock(&show_mutex);
 368         switch (ctl[0]) {
 369         case '0':
 370                 if (active) {
 371                         active = 0;
 372                         time_stop = ktime_get();
 373                         sync_access();
 374                 }
 375                 break;
 376         case '1':
 377                 if (!active) {
 378                         reset_entries();
 379                         time_start = ktime_get();
 380                         smp_mb();
 381                         active = 1;
 382                 }
 383                 break;
 384         default:
 385                 count = -EINVAL;
 386         }
 387         mutex_unlock(&show_mutex);
 388
 389         return count;
 390 }
 391
 392 static int tstats_open(struct inode *inode, struct file *filp)
 393 {
 394         return single_open(filp, tstats_show, NULL);
 395 }
 396
 397 static struct file_operations tstats_fops = {
 398         .open           = tstats_open,
 399         .read           = seq_read,
 400         .write          = tstats_write,
 401         .llseek         = seq_lseek,
 402         .release        = single_release,
 403 };
 404
 405 void __init init_timer_stats(void)
 406 {
 407         int cpu;
 408
 409         for_each_possible_cpu(cpu)
 410                 spin_lock_init(&per_cpu(lookup_lock, cpu));
 411 }
 412
 413 static int __init init_tstats_procfs(void)
 414 {
 415         struct proc_dir_entry *pe;
 416
 417         pe = create_proc_entry("timer_stats", 0644, NULL);
 418         if (!pe)
 419                 return -ENOMEM;
 420
 421         pe->proc_fops = &tstats_fops;
 422
 423         return 0;
 424 }
 425 __initcall(init_tstats_procfs);