[PATCH] timer_stats: add core information to event counters

[PATCH] timer_stats: add core information to event counters

[Daniel Sangorrin]

Hi,

This patch adds information specifying the CPU core where timer 
callbacks (events) were executed to the output of /proc/timer_stats.
I tested the patch on a dual-core x86_64 and another dual-core 
ARM board. This patch may be useful for debugging timer execution
in multi-core environments.

Daniel Sangorrin (1):
  timer_stats: add core information to event counters

 Documentation/timers/timer_stats.txt | 41 ++++++++++++++++++++----------------
 kernel/time/timer_stats.c            | 20 ++++++++++--------
 2 files changed, 34 insertions(+), 27 deletions(-)

-- 
1.8.1.1

[PATCH] timer_stats: add core information to event counters

[Daniel Sangorrin]

Add information specifying the CPU core where timer callbacks (events)
were executed to the output of /proc/timer_stats.

Signed-off-by: Daniel Sangorrin <daniel.sangorrin@toshiba.co.jp>
Signed-off-by: Yoshitake Kobayashi <yoshitake.kobayashi@toshiba.co.jp>
---
 Documentation/timers/timer_stats.txt | 41 ++++++++++++++++++++----------------
 kernel/time/timer_stats.c            | 20 ++++++++++--------
 2 files changed, 34 insertions(+), 27 deletions(-)

diff --git a/Documentation/timers/timer_stats.txt b/Documentation/timers/timer_stats.txt
index 8abd40b..e54077a 100644
--- a/Documentation/timers/timer_stats.txt
+++ b/Documentation/timers/timer_stats.txt
@@ -21,7 +21,7 @@ Linux system over a sample period:
 - the name of the process which initialized the timer
 - the function where the timer was initialized
 - the callback function which is associated to the timer
-- the number of events (callbacks)
+- the number of events (callbacks) executed per core
 
 timer_stats adds an entry to /proc: /proc/timer_stats
 
@@ -45,23 +45,28 @@ readouts.
 
 Sample output of /proc/timer_stats:
 
-Timerstats sample period: 3.888770 s
-  12,     0 swapper          hrtimer_stop_sched_tick (hrtimer_sched_tick)
-  15,     1 swapper          hcd_submit_urb (rh_timer_func)
-   4,   959 kedac            schedule_timeout (process_timeout)
-   1,     0 swapper          page_writeback_init (wb_timer_fn)
-  28,     0 swapper          hrtimer_stop_sched_tick (hrtimer_sched_tick)
-  22,  2948 IRQ 4            tty_flip_buffer_push (delayed_work_timer_fn)
-   3,  3100 bash             schedule_timeout (process_timeout)
-   1,     1 swapper          queue_delayed_work_on (delayed_work_timer_fn)
-   1,     1 swapper          queue_delayed_work_on (delayed_work_timer_fn)
-   1,     1 swapper          neigh_table_init_no_netlink (neigh_periodic_timer)
-   1,  2292 ip               __netdev_watchdog_up (dev_watchdog)
-   1,    23 events/1         do_cache_clean (delayed_work_timer_fn)
-90 total events, 30.0 events/sec
-
-The first column is the number of events, the second column the pid, the third
-column is the name of the process. The forth column shows the function which
+Timer Stats Version: v0.3
+Sample period: 4.365 s
+Collection: inactive
+     0,   4366,     0 swapper/1        tick_setup_sched_timer (tick_sched_timer)
+  4366,      0,     1 swapper/0        tick_setup_sched_timer (tick_sched_timer)
+     0,      5,  1132 sshd             sk_reset_timer (tcp_write_timer)
+     0,      4,   515 apache2          schedule_hrtimeout_range_clock (hrtimer_wakeup)
+    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
+    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
+    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
+    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
+    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
+     0,      7,     0 swapper/1        sk_reset_timer (tcp_delack_timer)
+     3,      4,     0 swapper/0        clocksource_watchdog (clocksource_watchdog)
+    0D,     3D,    13 kworker/1:0      queue_delayed_work_on (delayed_work_timer_fn)
+    3D,     0D,    22 kworker/0:1      queue_delayed_work_on (delayed_work_timer_fn)
+     1,      0,    22 kworker/0:1      e1000_watchdog_task (e1000_watchdog)
+8842 total events, 2025.658 events/sec
+
+The first comma-separated columns represent the number of events (one
+column per present core), the next column the pid, and the next one is the
+name of the process. The last column shows the function which
 initialized the timer and in parenthesis the callback function which was
 executed on expiry.
 
diff --git a/kernel/time/timer_stats.c b/kernel/time/timer_stats.c
index 1fb08f2..53d1544 100644
--- a/kernel/time/timer_stats.c
+++ b/kernel/time/timer_stats.c
@@ -67,7 +67,7 @@ struct entry {
 	/*
 	 * Number of timeout events:
 	 */
-	unsigned long		count;
+	unsigned long		count[NR_CPUS];
 	unsigned int		timer_flag;
 
 	/*
@@ -203,7 +203,7 @@ static struct entry *tstat_lookup(struct entry *entry, char *comm)
 	curr = alloc_entry();
 	if (curr) {
 		*curr = *entry;
-		curr->count = 0;
+		memset(curr->count, 0, sizeof(curr->count));
 		curr->next = NULL;
 		memcpy(curr->comm, comm, TASK_COMM_LEN);
 
@@ -259,7 +259,7 @@ void timer_stats_update_stats(void *timer, pid_t pid, void *startf,
 
 	entry = tstat_lookup(&input, comm);
 	if (likely(entry))
-		entry->count++;
+		entry->count[raw_smp_processor_id()]++;
 	else
 		atomic_inc(&overflow_count);
 
@@ -284,7 +284,7 @@ static int tstats_show(struct seq_file *m, void *v)
 	unsigned long ms;
 	long events = 0;
 	ktime_t time;
-	int i;
+	int i, cpu;
 
 	mutex_lock(&show_mutex);
 	/*
@@ -307,19 +307,21 @@ static int tstats_show(struct seq_file *m, void *v)
 	for (i = 0; i < nr_entries; i++) {
 		entry = entries + i;
 		if (entry->timer_flag & TIMER_STATS_FLAG_DEFERRABLE) {
-			seq_printf(m, "%4luD, %5d %-16s ",
-				entry->count, entry->pid, entry->comm);
+			for_each_present_cpu(cpu)
+				seq_printf(m, "%5luD, ", entry->count[cpu]);
 		} else {
-			seq_printf(m, " %4lu, %5d %-16s ",
-				entry->count, entry->pid, entry->comm);
+			for_each_present_cpu(cpu)
+				seq_printf(m, " %5lu, ", entry->count[cpu]);
 		}
+		seq_printf(m, "%5d %-16s ", entry->pid, entry->comm);
 
 		print_name_offset(m, (unsigned long)entry->start_func);
 		seq_puts(m, " (");
 		print_name_offset(m, (unsigned long)entry->expire_func);
 		seq_puts(m, ")\n");
 
-		events += entry->count;
+		for_each_present_cpu(cpu)
+			events += entry->count[cpu];
 	}
 
 	ms += period.tv_sec * 1000;
-- 
1.8.1.1

Re: [PATCH] timer_stats: add core information to event counters

[Viresh Kumar]

On 24 April 2014 13:17, Daniel Sangorrin <daniel.sangorrin@toshiba.co.jp> wrote:
> Add information specifying the CPU core where timer callbacks (events)
> were executed to the output of /proc/timer_stats.
>
> Signed-off-by: Daniel Sangorrin <daniel.sangorrin@toshiba.co.jp>
> Signed-off-by: Yoshitake Kobayashi <yoshitake.kobayashi@toshiba.co.jp>
> ---
>  Documentation/timers/timer_stats.txt | 41 ++++++++++++++++++++----------------
>  kernel/time/timer_stats.c            | 20 ++++++++++--------
>  2 files changed, 34 insertions(+), 27 deletions(-)

Nice and useful work.

Reviewed-by: Viresh Kumar <viresh.kumar@linaro.org>

Re: [PATCH] timer_stats: add core information to event counters

[Randy Dunlap]

On 04/24/14 00:47, Daniel Sangorrin wrote:
> Add information specifying the CPU core where timer callbacks (events)
> were executed to the output of /proc/timer_stats.
> 
> Signed-off-by: Daniel Sangorrin <daniel.sangorrin@toshiba.co.jp>
> Signed-off-by: Yoshitake Kobayashi <yoshitake.kobayashi@toshiba.co.jp>
> ---
>  Documentation/timers/timer_stats.txt | 41 ++++++++++++++++++++----------------
>  kernel/time/timer_stats.c            | 20 ++++++++++--------
>  2 files changed, 34 insertions(+), 27 deletions(-)
> 
> diff --git a/Documentation/timers/timer_stats.txt b/Documentation/timers/timer_stats.txt
> index 8abd40b..e54077a 100644
> --- a/Documentation/timers/timer_stats.txt
> +++ b/Documentation/timers/timer_stats.txt
> @@ -21,7 +21,7 @@ Linux system over a sample period:
>  - the name of the process which initialized the timer
>  - the function where the timer was initialized
>  - the callback function which is associated to the timer
> -- the number of events (callbacks)
> +- the number of events (callbacks) executed per core
>  
>  timer_stats adds an entry to /proc: /proc/timer_stats
>  
> @@ -45,23 +45,28 @@ readouts.
>  
>  Sample output of /proc/timer_stats:
>  
> -Timerstats sample period: 3.888770 s
> -  12,     0 swapper          hrtimer_stop_sched_tick (hrtimer_sched_tick)
> -  15,     1 swapper          hcd_submit_urb (rh_timer_func)
> -   4,   959 kedac            schedule_timeout (process_timeout)
> -   1,     0 swapper          page_writeback_init (wb_timer_fn)
> -  28,     0 swapper          hrtimer_stop_sched_tick (hrtimer_sched_tick)
> -  22,  2948 IRQ 4            tty_flip_buffer_push (delayed_work_timer_fn)
> -   3,  3100 bash             schedule_timeout (process_timeout)
> -   1,     1 swapper          queue_delayed_work_on (delayed_work_timer_fn)
> -   1,     1 swapper          queue_delayed_work_on (delayed_work_timer_fn)
> -   1,     1 swapper          neigh_table_init_no_netlink (neigh_periodic_timer)
> -   1,  2292 ip               __netdev_watchdog_up (dev_watchdog)
> -   1,    23 events/1         do_cache_clean (delayed_work_timer_fn)
> -90 total events, 30.0 events/sec
> -
> -The first column is the number of events, the second column the pid, the third
> -column is the name of the process. The forth column shows the function which
> +Timer Stats Version: v0.3
> +Sample period: 4.365 s
> +Collection: inactive
> +     0,   4366,     0 swapper/1        tick_setup_sched_timer (tick_sched_timer)
> +  4366,      0,     1 swapper/0        tick_setup_sched_timer (tick_sched_timer)
> +     0,      5,  1132 sshd             sk_reset_timer (tcp_write_timer)
> +     0,      4,   515 apache2          schedule_hrtimeout_range_clock (hrtimer_wakeup)
> +    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
> +    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
> +    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
> +    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
> +    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
> +     0,      7,     0 swapper/1        sk_reset_timer (tcp_delack_timer)
> +     3,      4,     0 swapper/0        clocksource_watchdog (clocksource_watchdog)
> +    0D,     3D,    13 kworker/1:0      queue_delayed_work_on (delayed_work_timer_fn)
> +    3D,     0D,    22 kworker/0:1      queue_delayed_work_on (delayed_work_timer_fn)
> +     1,      0,    22 kworker/0:1      e1000_watchdog_task (e1000_watchdog)
> +8842 total events, 2025.658 events/sec
> +

Is the number of events in decimal or hex?  If in decimal, what do
0D and 3D mean?

> +The first comma-separated columns represent the number of events (one
> +column per present core), the next column the pid, and the next one is the
> +name of the process. The last column shows the function which
>  initialized the timer and in parenthesis the callback function which was

                                parentheses

>  executed on expiry.
>  


-- 
~Randy

Re: [PATCH] timer_stats: add core information to event counters

[Daniel Sangorrin]

On 2014/04/25 2:54, Randy Dunlap wrote:
> On 04/24/14 00:47, Daniel Sangorrin wrote:
>> Add information specifying the CPU core where timer callbacks (events)
>> were executed to the output of /proc/timer_stats.
>>
>> Signed-off-by: Daniel Sangorrin <daniel.sangorrin@toshiba.co.jp>
>> Signed-off-by: Yoshitake Kobayashi <yoshitake.kobayashi@toshiba.co.jp>
>> ---
>>  Documentation/timers/timer_stats.txt | 41 ++++++++++++++++++++----------------
>>  kernel/time/timer_stats.c            | 20 ++++++++++--------
>>  2 files changed, 34 insertions(+), 27 deletions(-)
>>
>> diff --git a/Documentation/timers/timer_stats.txt b/Documentation/timers/timer_stats.txt
>> index 8abd40b..e54077a 100644
>> --- a/Documentation/timers/timer_stats.txt
>> +++ b/Documentation/timers/timer_stats.txt
>> @@ -21,7 +21,7 @@ Linux system over a sample period:
>>  - the name of the process which initialized the timer
>>  - the function where the timer was initialized
>>  - the callback function which is associated to the timer
>> -- the number of events (callbacks)
>> +- the number of events (callbacks) executed per core
>>  
>>  timer_stats adds an entry to /proc: /proc/timer_stats
>>  
>> @@ -45,23 +45,28 @@ readouts.
>>  
>>  Sample output of /proc/timer_stats:
>>  
>> -Timerstats sample period: 3.888770 s
>> -  12,     0 swapper          hrtimer_stop_sched_tick (hrtimer_sched_tick)
>> -  15,     1 swapper          hcd_submit_urb (rh_timer_func)
>> -   4,   959 kedac            schedule_timeout (process_timeout)
>> -   1,     0 swapper          page_writeback_init (wb_timer_fn)
>> -  28,     0 swapper          hrtimer_stop_sched_tick (hrtimer_sched_tick)
>> -  22,  2948 IRQ 4            tty_flip_buffer_push (delayed_work_timer_fn)
>> -   3,  3100 bash             schedule_timeout (process_timeout)
>> -   1,     1 swapper          queue_delayed_work_on (delayed_work_timer_fn)
>> -   1,     1 swapper          queue_delayed_work_on (delayed_work_timer_fn)
>> -   1,     1 swapper          neigh_table_init_no_netlink (neigh_periodic_timer)
>> -   1,  2292 ip               __netdev_watchdog_up (dev_watchdog)
>> -   1,    23 events/1         do_cache_clean (delayed_work_timer_fn)
>> -90 total events, 30.0 events/sec
>> -
>> -The first column is the number of events, the second column the pid, the third
>> -column is the name of the process. The forth column shows the function which
>> +Timer Stats Version: v0.3
>> +Sample period: 4.365 s
>> +Collection: inactive
>> +     0,   4366,     0 swapper/1        tick_setup_sched_timer (tick_sched_timer)
>> +  4366,      0,     1 swapper/0        tick_setup_sched_timer (tick_sched_timer)
>> +     0,      5,  1132 sshd             sk_reset_timer (tcp_write_timer)
>> +     0,      4,   515 apache2          schedule_hrtimeout_range_clock (hrtimer_wakeup)
>> +    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
>> +    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
>> +    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
>> +    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
>> +    16,      0,     0 swapper/0        usb_hcd_poll_rh_status (rh_timer_func)
>> +     0,      7,     0 swapper/1        sk_reset_timer (tcp_delack_timer)
>> +     3,      4,     0 swapper/0        clocksource_watchdog (clocksource_watchdog)
>> +    0D,     3D,    13 kworker/1:0      queue_delayed_work_on (delayed_work_timer_fn)
>> +    3D,     0D,    22 kworker/0:1      queue_delayed_work_on (delayed_work_timer_fn)
>> +     1,      0,    22 kworker/0:1      e1000_watchdog_task (e1000_watchdog)
>> +8842 total events, 2025.658 events/sec
>> +
> 
> Is the number of events in decimal or hex?  If in decimal, what do
> 0D and 3D mean?

It is in decimal notation. The 'D' means 'deferrable timer' and it is
already described in timer_stats.txt.

>> +The first comma-separated columns represent the number of events (one
>> +column per present core), the next column the pid, and the next one is the
>> +name of the process. The last column shows the function which
>>  initialized the timer and in parenthesis the callback function which was
> 
>                                 parentheses

Well spotted. I'll fix it and send it again.

Thanks,
Daniel

-- 
Toshiba Corporate Software Engineering Center
Daniel SANGORRIN
E-mail:  daniel.sangorrin@toshiba.co.jp