Hi,
I get stack traces like the following:
BUG: using smp_processor_id() in preemptible [00000000] code: init/1
caller is native_sched_clock+0x37/0x6d
Pid: 1, comm: init Not tainted 2.6.35-rc1 #99
Call Trace:
[<ffffffff811c422b>] debug_smp_processor_id+0xd3/0xec
[<ffffffff81008a1e>] native_sched_clock+0x37/0x6d
[<ffffffff811a7bfd>] blk_rq_init+0x92/0x9e
[<ffffffff811a7f2e>] get_request+0x1c8/0x27e
[<ffffffff811a8011>] get_request_wait+0x2d/0x13c
[<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
[<ffffffff81411ea6>] ? add_preempt_count+0xad/0xb1
[<ffffffff811a83b3>] __make_request+0x293/0x3b8
[<ffffffff81099737>] ? mempool_alloc_slab+0x10/0x12
[<ffffffff811a6bc4>] generic_make_request+0x187/0x1ea
[<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
[<ffffffff811a6ce5>] submit_bio+0xbe/0xc7
[<ffffffff810f1f37>] submit_bh+0xef/0x111
[<ffffffff810f4865>] block_read_full_page+0x1ec/0x20c
[<ffffffff810f6815>] ? blkdev_get_block+0x0/0x5e
[<ffffffff81411de6>] ? sub_preempt_count+0x92/0xa5
[<ffffffff810a0500>] ? __lru_cache_add+0x73/0x93
[<ffffffff810f6e81>] blkdev_readpage+0x13/0x15
[<ffffffff8109f981>] __do_page_cache_readahead+0x161/0x194
[<ffffffff8109f9d0>] ra_submit+0x1c/0x20
[<ffffffff8109fc5f>] ondemand_readahead+0x1bb/0x1ce
[<ffffffff810973c9>] ? rcu_read_unlock+0xe/0x29
[<ffffffff8109fd46>] page_cache_sync_readahead+0x38/0x3a
[<ffffffff810993c2>] generic_file_aio_read+0x24d/0x57f
[<ffffffff810cf973>] ? __mem_cgroup_try_charge+0x78/0x46c
[<ffffffff810d2aa0>] do_sync_read+0xc6/0x103
[<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
[<ffffffff810adca5>] ? handle_mm_fault+0x7cb/0x7e5
[<ffffffff810f69c5>] ? block_ioctl+0x32/0x36
[<ffffffff81189fcc>] ? selinux_file_permission+0x57/0xae
[<ffffffff81184524>] ? security_file_permission+0x11/0x13
[<ffffffff810d34af>] vfs_read+0xa6/0x103
[<ffffffff810d35c2>] sys_read+0x45/0x69
[<ffffffff810029ab>] system_call_fastpath+0x16/0x1b
Since with commit 9195291e you call 'set_start_time_ns' from
'blk_rq_init' which in turn calls 'sched_clock' with preempt enabled.
There are other calls to sched_clock in blk-cgroup.c. Maybe they should
be checked as well?
Regards,
David.
On 06/01/2010 12:15 PM, David John wrote:
> Hi,
>
> I get stack traces like the following:
>
> BUG: using smp_processor_id() in preemptible [00000000] code: init/1
> caller is native_sched_clock+0x37/0x6d
> Pid: 1, comm: init Not tainted 2.6.35-rc1 #99
> Call Trace:
> [<ffffffff811c422b>] debug_smp_processor_id+0xd3/0xec
> [<ffffffff81008a1e>] native_sched_clock+0x37/0x6d
> [<ffffffff811a7bfd>] blk_rq_init+0x92/0x9e
> [<ffffffff811a7f2e>] get_request+0x1c8/0x27e
> [<ffffffff811a8011>] get_request_wait+0x2d/0x13c
> [<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
> [<ffffffff81411ea6>] ? add_preempt_count+0xad/0xb1
> [<ffffffff811a83b3>] __make_request+0x293/0x3b8
> [<ffffffff81099737>] ? mempool_alloc_slab+0x10/0x12
> [<ffffffff811a6bc4>] generic_make_request+0x187/0x1ea
> [<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
> [<ffffffff811a6ce5>] submit_bio+0xbe/0xc7
> [<ffffffff810f1f37>] submit_bh+0xef/0x111
> [<ffffffff810f4865>] block_read_full_page+0x1ec/0x20c
> [<ffffffff810f6815>] ? blkdev_get_block+0x0/0x5e
> [<ffffffff81411de6>] ? sub_preempt_count+0x92/0xa5
> [<ffffffff810a0500>] ? __lru_cache_add+0x73/0x93
> [<ffffffff810f6e81>] blkdev_readpage+0x13/0x15
> [<ffffffff8109f981>] __do_page_cache_readahead+0x161/0x194
> [<ffffffff8109f9d0>] ra_submit+0x1c/0x20
> [<ffffffff8109fc5f>] ondemand_readahead+0x1bb/0x1ce
> [<ffffffff810973c9>] ? rcu_read_unlock+0xe/0x29
> [<ffffffff8109fd46>] page_cache_sync_readahead+0x38/0x3a
> [<ffffffff810993c2>] generic_file_aio_read+0x24d/0x57f
> [<ffffffff810cf973>] ? __mem_cgroup_try_charge+0x78/0x46c
> [<ffffffff810d2aa0>] do_sync_read+0xc6/0x103
> [<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
> [<ffffffff810adca5>] ? handle_mm_fault+0x7cb/0x7e5
> [<ffffffff810f69c5>] ? block_ioctl+0x32/0x36
> [<ffffffff81189fcc>] ? selinux_file_permission+0x57/0xae
> [<ffffffff81184524>] ? security_file_permission+0x11/0x13
> [<ffffffff810d34af>] vfs_read+0xa6/0x103
> [<ffffffff810d35c2>] sys_read+0x45/0x69
> [<ffffffff810029ab>] system_call_fastpath+0x16/0x1b
>
> Since with commit 9195291e you call 'set_start_time_ns' from
> 'blk_rq_init' which in turn calls 'sched_clock' with preempt enabled.
> There are other calls to sched_clock in blk-cgroup.c. Maybe they should
> be checked as well?
>
> Regards,
> David.
>
I see this has been reported. Never mind.
Regards,
David.
On Tue, Jun 01 2010, David John wrote:
> On 06/01/2010 12:15 PM, David John wrote:
> > Hi,
> >
> > I get stack traces like the following:
> >
> > BUG: using smp_processor_id() in preemptible [00000000] code: init/1
> > caller is native_sched_clock+0x37/0x6d
> > Pid: 1, comm: init Not tainted 2.6.35-rc1 #99
> > Call Trace:
> > [<ffffffff811c422b>] debug_smp_processor_id+0xd3/0xec
> > [<ffffffff81008a1e>] native_sched_clock+0x37/0x6d
> > [<ffffffff811a7bfd>] blk_rq_init+0x92/0x9e
> > [<ffffffff811a7f2e>] get_request+0x1c8/0x27e
> > [<ffffffff811a8011>] get_request_wait+0x2d/0x13c
> > [<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
> > [<ffffffff81411ea6>] ? add_preempt_count+0xad/0xb1
> > [<ffffffff811a83b3>] __make_request+0x293/0x3b8
> > [<ffffffff81099737>] ? mempool_alloc_slab+0x10/0x12
> > [<ffffffff811a6bc4>] generic_make_request+0x187/0x1ea
> > [<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
> > [<ffffffff811a6ce5>] submit_bio+0xbe/0xc7
> > [<ffffffff810f1f37>] submit_bh+0xef/0x111
> > [<ffffffff810f4865>] block_read_full_page+0x1ec/0x20c
> > [<ffffffff810f6815>] ? blkdev_get_block+0x0/0x5e
> > [<ffffffff81411de6>] ? sub_preempt_count+0x92/0xa5
> > [<ffffffff810a0500>] ? __lru_cache_add+0x73/0x93
> > [<ffffffff810f6e81>] blkdev_readpage+0x13/0x15
> > [<ffffffff8109f981>] __do_page_cache_readahead+0x161/0x194
> > [<ffffffff8109f9d0>] ra_submit+0x1c/0x20
> > [<ffffffff8109fc5f>] ondemand_readahead+0x1bb/0x1ce
> > [<ffffffff810973c9>] ? rcu_read_unlock+0xe/0x29
> > [<ffffffff8109fd46>] page_cache_sync_readahead+0x38/0x3a
> > [<ffffffff810993c2>] generic_file_aio_read+0x24d/0x57f
> > [<ffffffff810cf973>] ? __mem_cgroup_try_charge+0x78/0x46c
> > [<ffffffff810d2aa0>] do_sync_read+0xc6/0x103
> > [<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
> > [<ffffffff810adca5>] ? handle_mm_fault+0x7cb/0x7e5
> > [<ffffffff810f69c5>] ? block_ioctl+0x32/0x36
> > [<ffffffff81189fcc>] ? selinux_file_permission+0x57/0xae
> > [<ffffffff81184524>] ? security_file_permission+0x11/0x13
> > [<ffffffff810d34af>] vfs_read+0xa6/0x103
> > [<ffffffff810d35c2>] sys_read+0x45/0x69
> > [<ffffffff810029ab>] system_call_fastpath+0x16/0x1b
> >
> > Since with commit 9195291e you call 'set_start_time_ns' from
> > 'blk_rq_init' which in turn calls 'sched_clock' with preempt enabled.
> > There are other calls to sched_clock in blk-cgroup.c. Maybe they should
> > be checked as well?
> >
> > Regards,
> > David.
> >
>
> I see this has been reported. Never mind.
This should fix it for now, if you have time to test, then that would
not hurt.
diff --git a/include/linux/blkdev.h b/include/linux/blkdev.h
index 8b7f5e0..09a8402 100644
--- a/include/linux/blkdev.h
+++ b/include/linux/blkdev.h
@@ -1211,14 +1211,23 @@ struct work_struct;
int kblockd_schedule_work(struct request_queue *q, struct work_struct *work);
#ifdef CONFIG_BLK_CGROUP
+/*
+ * This should not be using sched_clock(). A real patch is in progress
+ * to fix this up, until that is in place we need to disable preemption
+ * around sched_clock() in this function and set_io_start_time_ns().
+ */
static inline void set_start_time_ns(struct request *req)
{
+ preempt_disable();
req->start_time_ns = sched_clock();
+ preempt_enable();
}
static inline void set_io_start_time_ns(struct request *req)
{
+ preempt_disable();
req->io_start_time_ns = sched_clock();
+ preempt_enable();
}
static inline uint64_t rq_start_time_ns(struct request *req)
--
Jens Axboe
On 06/01/2010 03:53 PM, Jens Axboe wrote:
> On Tue, Jun 01 2010, David John wrote:
>> On 06/01/2010 12:15 PM, David John wrote:
>>> Hi,
>>>
>>> I get stack traces like the following:
>>>
>>> BUG: using smp_processor_id() in preemptible [00000000] code: init/1
>>> caller is native_sched_clock+0x37/0x6d
>>> Pid: 1, comm: init Not tainted 2.6.35-rc1 #99
>>> Call Trace:
>>> [<ffffffff811c422b>] debug_smp_processor_id+0xd3/0xec
>>> [<ffffffff81008a1e>] native_sched_clock+0x37/0x6d
>>> [<ffffffff811a7bfd>] blk_rq_init+0x92/0x9e
>>> [<ffffffff811a7f2e>] get_request+0x1c8/0x27e
>>> [<ffffffff811a8011>] get_request_wait+0x2d/0x13c
>>> [<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
>>> [<ffffffff81411ea6>] ? add_preempt_count+0xad/0xb1
>>> [<ffffffff811a83b3>] __make_request+0x293/0x3b8
>>> [<ffffffff81099737>] ? mempool_alloc_slab+0x10/0x12
>>> [<ffffffff811a6bc4>] generic_make_request+0x187/0x1ea
>>> [<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
>>> [<ffffffff811a6ce5>] submit_bio+0xbe/0xc7
>>> [<ffffffff810f1f37>] submit_bh+0xef/0x111
>>> [<ffffffff810f4865>] block_read_full_page+0x1ec/0x20c
>>> [<ffffffff810f6815>] ? blkdev_get_block+0x0/0x5e
>>> [<ffffffff81411de6>] ? sub_preempt_count+0x92/0xa5
>>> [<ffffffff810a0500>] ? __lru_cache_add+0x73/0x93
>>> [<ffffffff810f6e81>] blkdev_readpage+0x13/0x15
>>> [<ffffffff8109f981>] __do_page_cache_readahead+0x161/0x194
>>> [<ffffffff8109f9d0>] ra_submit+0x1c/0x20
>>> [<ffffffff8109fc5f>] ondemand_readahead+0x1bb/0x1ce
>>> [<ffffffff810973c9>] ? rcu_read_unlock+0xe/0x29
>>> [<ffffffff8109fd46>] page_cache_sync_readahead+0x38/0x3a
>>> [<ffffffff810993c2>] generic_file_aio_read+0x24d/0x57f
>>> [<ffffffff810cf973>] ? __mem_cgroup_try_charge+0x78/0x46c
>>> [<ffffffff810d2aa0>] do_sync_read+0xc6/0x103
>>> [<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
>>> [<ffffffff810adca5>] ? handle_mm_fault+0x7cb/0x7e5
>>> [<ffffffff810f69c5>] ? block_ioctl+0x32/0x36
>>> [<ffffffff81189fcc>] ? selinux_file_permission+0x57/0xae
>>> [<ffffffff81184524>] ? security_file_permission+0x11/0x13
>>> [<ffffffff810d34af>] vfs_read+0xa6/0x103
>>> [<ffffffff810d35c2>] sys_read+0x45/0x69
>>> [<ffffffff810029ab>] system_call_fastpath+0x16/0x1b
>>>
>>> Since with commit 9195291e you call 'set_start_time_ns' from
>>> 'blk_rq_init' which in turn calls 'sched_clock' with preempt enabled.
>>> There are other calls to sched_clock in blk-cgroup.c. Maybe they should
>>> be checked as well?
>>>
>>> Regards,
>>> David.
>>>
>>
>> I see this has been reported. Never mind.
>
> This should fix it for now, if you have time to test, then that would
> not hurt.
Yes, this works.
Thanks,
David.
On Wed, 2010-06-02 at 18:13 +0530, David John wrote:
> On 06/01/2010 03:53 PM, Jens Axboe wrote:
> > On Tue, Jun 01 2010, David John wrote:
> >> On 06/01/2010 12:15 PM, David John wrote:
> >>> Hi,
> >>>
> >>> I get stack traces like the following:
> >>>
> >>> BUG: using smp_processor_id() in preemptible [00000000] code: init/1
> >>> caller is native_sched_clock+0x37/0x6d
> >>> Pid: 1, comm: init Not tainted 2.6.35-rc1 #99
> >>> Call Trace:
> >>> [<ffffffff811c422b>] debug_smp_processor_id+0xd3/0xec
> >>> [<ffffffff81008a1e>] native_sched_clock+0x37/0x6d
> >>> [<ffffffff811a7bfd>] blk_rq_init+0x92/0x9e
> >>> [<ffffffff811a7f2e>] get_request+0x1c8/0x27e
> >>> [<ffffffff811a8011>] get_request_wait+0x2d/0x13c
> >>> [<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
> >>> [<ffffffff81411ea6>] ? add_preempt_count+0xad/0xb1
> >>> [<ffffffff811a83b3>] __make_request+0x293/0x3b8
> >>> [<ffffffff81099737>] ? mempool_alloc_slab+0x10/0x12
> >>> [<ffffffff811a6bc4>] generic_make_request+0x187/0x1ea
> >>> [<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
> >>> [<ffffffff811a6ce5>] submit_bio+0xbe/0xc7
> >>> [<ffffffff810f1f37>] submit_bh+0xef/0x111
> >>> [<ffffffff810f4865>] block_read_full_page+0x1ec/0x20c
> >>> [<ffffffff810f6815>] ? blkdev_get_block+0x0/0x5e
> >>> [<ffffffff81411de6>] ? sub_preempt_count+0x92/0xa5
> >>> [<ffffffff810a0500>] ? __lru_cache_add+0x73/0x93
> >>> [<ffffffff810f6e81>] blkdev_readpage+0x13/0x15
> >>> [<ffffffff8109f981>] __do_page_cache_readahead+0x161/0x194
> >>> [<ffffffff8109f9d0>] ra_submit+0x1c/0x20
> >>> [<ffffffff8109fc5f>] ondemand_readahead+0x1bb/0x1ce
> >>> [<ffffffff810973c9>] ? rcu_read_unlock+0xe/0x29
> >>> [<ffffffff8109fd46>] page_cache_sync_readahead+0x38/0x3a
> >>> [<ffffffff810993c2>] generic_file_aio_read+0x24d/0x57f
> >>> [<ffffffff810cf973>] ? __mem_cgroup_try_charge+0x78/0x46c
> >>> [<ffffffff810d2aa0>] do_sync_read+0xc6/0x103
> >>> [<ffffffff810306ee>] ? get_parent_ip+0x11/0x42
> >>> [<ffffffff810adca5>] ? handle_mm_fault+0x7cb/0x7e5
> >>> [<ffffffff810f69c5>] ? block_ioctl+0x32/0x36
> >>> [<ffffffff81189fcc>] ? selinux_file_permission+0x57/0xae
> >>> [<ffffffff81184524>] ? security_file_permission+0x11/0x13
> >>> [<ffffffff810d34af>] vfs_read+0xa6/0x103
> >>> [<ffffffff810d35c2>] sys_read+0x45/0x69
> >>> [<ffffffff810029ab>] system_call_fastpath+0x16/0x1b
> >>>
> >>> Since with commit 9195291e you call 'set_start_time_ns' from
> >>> 'blk_rq_init' which in turn calls 'sched_clock' with preempt enabled.
> >>> There are other calls to sched_clock in blk-cgroup.c. Maybe they should
> >>> be checked as well?
> >>>
> >>> Regards,
> >>> David.
> >>>
> >>
> >> I see this has been reported. Never mind.
> >
> > This should fix it for now, if you have time to test, then that would
> > not hurt.
>
> Yes, this works.
I had the same issue, and this patch fixed it for me too.
-- Steve