Re: BUG: using smp_processor_id() in preemptible [00000000] code: icedove-bin/5449

[Ingo Molnar <mingo@elte.hu>]

* Peter Zijlstra <peterz@infradead.org> wrote:

> On Mon, 2010-05-24 at 05:03 +0200, Piotr Hosowicz wrote:
> > [  720.313607] BUG: using smp_processor_id() in preemptible [00000000] code: icedove-bin/5449
> > [  720.313612] caller is native_sched_clock+0x3c/0x68
> > [  720.313616] Pid: 5449, comm: icedove-bin Tainted: P            2.6.34-20100524-0407 #1
> > [  720.313618] Call Trace:
> > [  720.313624]  [<ffffffff811a533b>] debug_smp_processor_id+0xc7/0xe0
> > [  720.313629]  [<ffffffff81009b87>] native_sched_clock+0x3c/0x68
> > [  720.313634]  [<ffffffff81009a4d>] sched_clock+0x9/0xd
> > [  720.313637]  [<ffffffff811823ec>] blk_rq_init+0x92/0x9d
> > [  720.313641]  [<ffffffff81184227>] get_request+0x1bf/0x2c7
> > [  720.313646]  [<ffffffff8118435c>] get_request_wait+0x2d/0x19d 
> 
> This comes from wreckage in the blk tree..
> 
> ---
> commit 9195291e5f05e01d67f9a09c756b8aca8f009089
> Author: Divyesh Shah <dpshah@google.com>
> Date:   Thu Apr 1 15:01:41 2010 -0700
> 
>     blkio: Increment the blkio cgroup stats for real now
>     
>     We also add start_time_ns and io_start_time_ns fields to struct request
>     here to record the time when a request is created and when it is
>     dispatched to device. We use ns uints here as ms and jiffies are
>     not very useful for non-rotational media.
>     
>     Signed-off-by: Divyesh Shah<dpshah@google.com>
>     Signed-off-by: Jens Axboe <jens.axboe@oracle.com>
> ---
> 
> +#ifdef CONFIG_BLK_CGROUP
> +static inline void set_start_time_ns(struct request *req)
> +{
> +	req->start_time_ns = sched_clock();
> +}
> +
> +static inline void set_io_start_time_ns(struct request *req)
> +{
> +	req->io_start_time_ns = sched_clock();
> +}
> +#else
> +static inline void set_start_time_ns(struct request *req) {}
> +static inline void set_io_start_time_ns(struct request *req) {}
> +#endif
> 
> ---
> 
> Clearly nobody tested this, and its terribly broken to boot.
> 
> I guess they want something like:
> 
> ---
> Subject: sched_clock: Add local_clock()
> From: Peter Zijlstra <a.p.zijlstra@chello.nl>
> Date: Tue May 25 10:48:51 CEST 2010
> 
> For people who otherwise get to write: cpu_clock(smp_processor_id()),
> there is now: local_clock().

This doesnt fix the whole issue. cpu_clock() is local, while the measurements 
done in the blk code are global ...

While the warning is fixed this way, the far more serious issue is still 
there: time can go backwards if two points of time measurement are on 
different CPUs and can mess up the statistics with negative values, etc...

	Ingo