Re: [PATCH V2] hrtimer: Printing timer info when hitting BUG_ON()

[Yanmin Zhang]

On Tue, 2012-10-30 at 18:27 +0800, Chuansheng Liu wrote:
> We encounted one BUG_ON() issue at function __run_hrtimer(),
> but the panic info is not enough to find out which hrtimer
> users use the hrtimer wrongly.
> (in this BUG_ON case, it is callback running at the same time
> hrtimer_start() is executed on different context.)
> 
> We can print basic timer info before BUG(), it is easy to find
> out which hrtimer user has fault, the output info is like below:
> 
> <3>[   41.118552] timer info: state/3, func/test_timer_cb
> <3>[   41.118618] timer stats: pid/786(sh), site/hrtimer_start
> <0>[   41.118670] [ cut here ]
> <2>[   41.118691] kernel BUG at 
> /root/r4_code/hardware/intel/linux-2.6/kernel/hrtimer.c:1260!
> <0>[   41.118715] invalid opcode:  [#1] PREEMPT SMP
> 
> The infos of callback/state are very helpful for debugging this BUG_ON().
It's a useful patch.

Thomas,

Could you merge it into your testing tree, so other developers could also
benefit from it?

Thanks all.
Yanmin

> 
> Signed-off-by: Li Fei 
> Signed-off-by: liu chuansheng 
> ---
>  kernel/hrtimer.c |   21 -
>  1 files changed, 20 insertions(+), 1 deletions(-)
> 
> diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
> index 6db7a5e..0618eaf 100644
> --- a/kernel/hrtimer.c
> +++ b/kernel/hrtimer.c
> @@ -1204,6 +1204,22 @@ int hrtimer_get_res(const clockid_t which_clock, 
> struct timespec *tp)
>  }
>  EXPORT_SYMBOL_GPL(hrtimer_get_res);
>  
> +/*
> + * dump_hrtimer_callinfo - print hrtimer information including:
> + * state, callback function, pid and start_site.
> +*/
> +static void dump_hrtimer_callinfo(struct hrtimer *timer)
> +{
> +
> + pr_err("timer info: state/%lx, func/%pf\n",
> + timer->state, timer->function);
> +
> +#ifdef CONFIG_TIMER_STATS
> + pr_err("timer stats: pid/%d(%s), site/%pf\n",
> + timer->start_pid, timer->start_comm, timer->start_site);
> +#endif
> +}
> +
>  static void __run_hrtimer(struct hrtimer *timer, ktime_t *now)
>  {
>   struct hrtimer_clock_base *base = timer->base;
> @@ -1235,7 +1251,10 @@ static void __run_hrtimer(struct hrtimer *timer, 
> ktime_t *now)
>* hrtimer_start_range_ns() or in hrtimer_interrupt()
>*/
>   if (restart != HRTIMER_NORESTART) {
> - BUG_ON(timer->state != HRTIMER_STATE_CALLBACK);
> + if (timer->state != HRTIMER_STATE_CALLBACK) {
> + dump_hrtimer_callinfo(timer);
> + BUG();
> + }
>   enqueue_hrtimer(timer, base);
>   }
>  


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Re: [PATCH V2] hrtimer: Printing timer info when hitting BUG_ON()

[Yanmin Zhang]

On Tue, 2012-10-30 at 18:27 +0800, Chuansheng Liu wrote:
 We encounted one BUG_ON() issue at function __run_hrtimer(),
 but the panic info is not enough to find out which hrtimer
 users use the hrtimer wrongly.
 (in this BUG_ON case, it is callback running at the same time
 hrtimer_start() is executed on different context.)
 
 We can print basic timer info before BUG(), it is easy to find
 out which hrtimer user has fault, the output info is like below:
 
 3[   41.118552] timer info: state/3, func/test_timer_cb
 3[   41.118618] timer stats: pid/786(sh), site/hrtimer_start
 0[   41.118670] [ cut here ]
 2[   41.118691] kernel BUG at 
 /root/r4_code/hardware/intel/linux-2.6/kernel/hrtimer.c:1260!
 0[   41.118715] invalid opcode:  [#1] PREEMPT SMP
 
 The infos of callback/state are very helpful for debugging this BUG_ON().
It's a useful patch.

Thomas,

Could you merge it into your testing tree, so other developers could also
benefit from it?

Thanks all.
Yanmin

 
 Signed-off-by: Li Fei fei...@intel.com
 Signed-off-by: liu chuansheng chuansheng@intel.com
 ---
  kernel/hrtimer.c |   21 -
  1 files changed, 20 insertions(+), 1 deletions(-)
 
 diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
 index 6db7a5e..0618eaf 100644
 --- a/kernel/hrtimer.c
 +++ b/kernel/hrtimer.c
 @@ -1204,6 +1204,22 @@ int hrtimer_get_res(const clockid_t which_clock, 
 struct timespec *tp)
  }
  EXPORT_SYMBOL_GPL(hrtimer_get_res);
  
 +/*
 + * dump_hrtimer_callinfo - print hrtimer information including:
 + * state, callback function, pid and start_site.
 +*/
 +static void dump_hrtimer_callinfo(struct hrtimer *timer)
 +{
 +
 + pr_err(timer info: state/%lx, func/%pf\n,
 + timer-state, timer-function);
 +
 +#ifdef CONFIG_TIMER_STATS
 + pr_err(timer stats: pid/%d(%s), site/%pf\n,
 + timer-start_pid, timer-start_comm, timer-start_site);
 +#endif
 +}
 +
  static void __run_hrtimer(struct hrtimer *timer, ktime_t *now)
  {
   struct hrtimer_clock_base *base = timer-base;
 @@ -1235,7 +1251,10 @@ static void __run_hrtimer(struct hrtimer *timer, 
 ktime_t *now)
* hrtimer_start_range_ns() or in hrtimer_interrupt()
*/
   if (restart != HRTIMER_NORESTART) {
 - BUG_ON(timer-state != HRTIMER_STATE_CALLBACK);
 + if (timer-state != HRTIMER_STATE_CALLBACK) {
 + dump_hrtimer_callinfo(timer);
 + BUG();
 + }
   enqueue_hrtimer(timer, base);
   }
  


--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[PATCH V2] hrtimer: Printing timer info when hitting BUG_ON()

[Chuansheng Liu]

We encounted one BUG_ON() issue at function __run_hrtimer(),
but the panic info is not enough to find out which hrtimer
users use the hrtimer wrongly.
(in this BUG_ON case, it is callback running at the same time
hrtimer_start() is executed on different context.)

We can print basic timer info before BUG(), it is easy to find
out which hrtimer user has fault, the output info is like below:

<3>[   41.118552] timer info: state/3, func/test_timer_cb
<3>[   41.118618] timer stats: pid/786(sh), site/hrtimer_start
<0>[   41.118670] [ cut here ]
<2>[   41.118691] kernel BUG at 
/root/r4_code/hardware/intel/linux-2.6/kernel/hrtimer.c:1260!
<0>[   41.118715] invalid opcode:  [#1] PREEMPT SMP

The infos of callback/state are very helpful for debugging this BUG_ON().

Signed-off-by: Li Fei 
Signed-off-by: liu chuansheng 
---
 kernel/hrtimer.c |   21 -
 1 files changed, 20 insertions(+), 1 deletions(-)

diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
index 6db7a5e..0618eaf 100644
--- a/kernel/hrtimer.c
+++ b/kernel/hrtimer.c
@@ -1204,6 +1204,22 @@ int hrtimer_get_res(const clockid_t which_clock, struct 
timespec *tp)
 }
 EXPORT_SYMBOL_GPL(hrtimer_get_res);
 
+/*
+ * dump_hrtimer_callinfo - print hrtimer information including:
+ * state, callback function, pid and start_site.
+*/
+static void dump_hrtimer_callinfo(struct hrtimer *timer)
+{
+
+   pr_err("timer info: state/%lx, func/%pf\n",
+   timer->state, timer->function);
+
+#ifdef CONFIG_TIMER_STATS
+   pr_err("timer stats: pid/%d(%s), site/%pf\n",
+   timer->start_pid, timer->start_comm, timer->start_site);
+#endif
+}
+
 static void __run_hrtimer(struct hrtimer *timer, ktime_t *now)
 {
struct hrtimer_clock_base *base = timer->base;
@@ -1235,7 +1251,10 @@ static void __run_hrtimer(struct hrtimer *timer, ktime_t 
*now)
 * hrtimer_start_range_ns() or in hrtimer_interrupt()
 */
if (restart != HRTIMER_NORESTART) {
-   BUG_ON(timer->state != HRTIMER_STATE_CALLBACK);
+   if (timer->state != HRTIMER_STATE_CALLBACK) {
+   dump_hrtimer_callinfo(timer);
+   BUG();
+   }
enqueue_hrtimer(timer, base);
}
 
-- 
1.7.0.4



--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[PATCH V2] hrtimer: Printing timer info when hitting BUG_ON()

[Chuansheng Liu]

We encounted one BUG_ON() issue at function __run_hrtimer(),
but the panic info is not enough to find out which hrtimer
users use the hrtimer wrongly.
(in this BUG_ON case, it is callback running at the same time
hrtimer_start() is executed on different context.)

We can print basic timer info before BUG(), it is easy to find
out which hrtimer user has fault, the output info is like below:

3[   41.118552] timer info: state/3, func/test_timer_cb
3[   41.118618] timer stats: pid/786(sh), site/hrtimer_start
0[   41.118670] [ cut here ]
2[   41.118691] kernel BUG at 
/root/r4_code/hardware/intel/linux-2.6/kernel/hrtimer.c:1260!
0[   41.118715] invalid opcode:  [#1] PREEMPT SMP

The infos of callback/state are very helpful for debugging this BUG_ON().

Signed-off-by: Li Fei fei...@intel.com
Signed-off-by: liu chuansheng chuansheng@intel.com
---
 kernel/hrtimer.c |   21 -
 1 files changed, 20 insertions(+), 1 deletions(-)

diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
index 6db7a5e..0618eaf 100644
--- a/kernel/hrtimer.c
+++ b/kernel/hrtimer.c
@@ -1204,6 +1204,22 @@ int hrtimer_get_res(const clockid_t which_clock, struct 
timespec *tp)
 }
 EXPORT_SYMBOL_GPL(hrtimer_get_res);
 
+/*
+ * dump_hrtimer_callinfo - print hrtimer information including:
+ * state, callback function, pid and start_site.
+*/
+static void dump_hrtimer_callinfo(struct hrtimer *timer)
+{
+
+   pr_err(timer info: state/%lx, func/%pf\n,
+   timer-state, timer-function);
+
+#ifdef CONFIG_TIMER_STATS
+   pr_err(timer stats: pid/%d(%s), site/%pf\n,
+   timer-start_pid, timer-start_comm, timer-start_site);
+#endif
+}
+
 static void __run_hrtimer(struct hrtimer *timer, ktime_t *now)
 {
struct hrtimer_clock_base *base = timer-base;
@@ -1235,7 +1251,10 @@ static void __run_hrtimer(struct hrtimer *timer, ktime_t 
*now)
 * hrtimer_start_range_ns() or in hrtimer_interrupt()
 */
if (restart != HRTIMER_NORESTART) {
-   BUG_ON(timer-state != HRTIMER_STATE_CALLBACK);
+   if (timer-state != HRTIMER_STATE_CALLBACK) {
+   dump_hrtimer_callinfo(timer);
+   BUG();
+   }
enqueue_hrtimer(timer, base);
}
 
-- 
1.7.0.4



--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/