Re: next-20081119: general protection fault: get_next_timer_interrupt()

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[Alexander Beregalov]

2008/11/20 Thomas Gleixner <tglx@linutronix.de>:
> Alexander,
>
> On Wed, 19 Nov 2008, Alexander Beregalov wrote:
>>
>> It is 4way X86_64
>> The kernel does not boot.
>
>> RIP: 0010:[<ffffffff80240061>]  [<ffffffff80240061>]
>> get_next_timer_interrupt+0x11b/0x1f0
>
> Can you please enable:
>
> CONFIG_DEBUG_OBJECTS=y
> CONFIG_DEBUG_OBJECTS_FREE=y
> CONFIG_DEBUG_OBJECTS_TIMERS=Y
>
> and add "debug_objects" to the kernel command line ?

I added these options:

hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
hpet0: 3 comparators, 64-bit 14.318180 MHz counter
ODEBUG: object is on stack, but not annotated
------------[ cut here ]------------
WARNING: at lib/debugobjects.c:251 __debug_object_init+0x2bf/0x36d()
Modules linked in:
Pid: 1, comm: swapper Not tainted 2.6.28-rc5-next-20081119 #9
Call Trace:
 [<ffffffff80236ba7>] warn_on_slowpath+0x58/0x7d
 [<ffffffff804e2584>] ? printk+0x67/0x6b
 [<ffffffff803800bc>] ? __debug_object_init+0x191/0x36d
 [<ffffffff803801ea>] __debug_object_init+0x2bf/0x36d
 [<ffffffff802977c6>] ? compound_order+0x15/0x26
 [<ffffffff803802c5>] debug_object_init+0x14/0x17
 [<ffffffff8023fc77>] init_timer+0x18/0x5b
 [<ffffffff80220821>] hpet_cpuhp_notify+0x93/0x105
 [<ffffffff8022095a>] ? hpet_work+0x0/0x206
 [<ffffffff803d1394>] ? hpet_alloc+0x333/0x38f
 [<ffffffff80257785>] ? trace_hardirqs_on_caller+0x128/0x153
 [<ffffffff802577bd>] ? trace_hardirqs_on+0xd/0xf
 [<ffffffff806cf5f5>] ? hpet_late_init+0x0/0x19e
 [<ffffffff806cf5f5>] ? hpet_late_init+0x0/0x19e
 [<ffffffff806cf75f>] hpet_late_init+0x16a/0x19e
 [<ffffffff806cd7c2>] ? print_all_ICs+0x0/0x540
 [<ffffffff80209058>] _stext+0x58/0x138
 [<ffffffff804e5003>] ? _spin_unlock+0x4a/0x57
 [<ffffffff802de241>] ? proc_register+0x17f/0x193
 [<ffffffff802de37d>] ? create_proc_entry+0x7e/0x94
 [<ffffffff802686e5>] ? register_irq_proc+0xb0/0xcc
 [<ffffffff802d0000>] ? do_usbdevfs_bulk+0xf8/0xfe
 [<ffffffff806c466d>] kernel_init+0x125/0x179
 [<ffffffff804e49ba>] ? trace_hardirqs_on_thunk+0x3a/0x3f
 [<ffffffff8020c899>] child_rip+0xa/0x11
 [<ffffffff8020bd88>] ? restore_args+0x0/0x30
 [<ffffffff806c4548>] ? kernel_init+0x0/0x179
 [<ffffffff8020c88f>] ? child_rip+0x0/0x11
---[ end trace 4eaa2a86a8e2da22 ]---

<...>

scsi0 : LSI SAS based MegaRAID driver
Driver 'sd' needs updating - please use bus_type methods
scsi 0:0:0:0: Direct-Access     ATA      SAMSUNG HE160HJ  0-24 PQ: 0 ANSI: 5
------------[ cut here ]------------
WARNING: at lib/debugobjects.c:215 debug_print_object+0x4f/0x57()
ODEBUG: free active object type: timer_list
Modules linked in:
Pid: 580, comm: scsi_scan_0 Tainted: G        W  2.6.28-rc5-next-20081119 #9
Call Trace:
 [<ffffffff80236b28>] warn_slowpath+0xae/0xd5
 [<ffffffff8037f9e8>] ? debug_check_no_obj_freed+0x75/0x1c8
 [<ffffffff8037f8b1>] debug_print_object+0x4f/0x57
 [<ffffffff8037fa0f>] debug_check_no_obj_freed+0x9c/0x1c8
 [<ffffffff8029c7b2>] kmem_cache_free+0x64/0xc0
 [<ffffffff8036a6e0>] ? blk_release_queue+0x61/0x66
 [<ffffffff8036a6e0>] blk_release_queue+0x61/0x66
 [<ffffffff803760f2>] kobject_release+0x52/0x68
 [<ffffffff803760a0>] ? kobject_release+0x0/0x68
 [<ffffffff80376ec5>] kref_put+0x43/0x4f
 [<ffffffff80375ffa>] kobject_put+0x47/0x4b
 [<ffffffff80368c53>] blk_cleanup_queue+0x57/0x5c
 [<ffffffff803f8729>] scsi_free_queue+0x9/0xb
 [<ffffffff803fd3c7>] scsi_device_dev_release_usercontext+0xdc/0x127
 [<ffffffff803fd2eb>] ? scsi_device_dev_release_usercontext+0x0/0x127
 [<ffffffff802472a8>] execute_in_process_context+0x2a/0x70
 [<ffffffff803fd2e9>] scsi_device_dev_release+0x17/0x19
 [<ffffffff803e03e0>] device_release+0x43/0x68
 [<ffffffff803760f2>] kobject_release+0x52/0x68
 [<ffffffff803760a0>] ? kobject_release+0x0/0x68
 [<ffffffff80376ec5>] kref_put+0x43/0x4f
 [<ffffffff80375ffa>] kobject_put+0x47/0x4b
 [<ffffffff803dfd36>] put_device+0x15/0x17
 [<ffffffff803fa772>] scsi_destroy_sdev+0x48/0x4c
 [<ffffffff803fba05>] scsi_probe_and_add_lun+0xb5d/0xb81
 [<ffffffff803faaba>] ? scsi_alloc_target+0x22b/0x267
 [<ffffffff803fbcb0>] __scsi_scan_target+0x9d/0x598
 [<ffffffff8025767c>] ? trace_hardirqs_on_caller+0x1f/0x153
 [<ffffffff804e39a9>] ? __mutex_lock_common+0x371/0x3be
 [<ffffffff803fc2d9>] ? scsi_scan_host_selected+0xb6/0x133
 [<ffffffff8025767c>] ? trace_hardirqs_on_caller+0x1f/0x153
 [<ffffffff803fc2d9>] ? scsi_scan_host_selected+0xb6/0x133
 [<ffffffff803fc1fd>] scsi_scan_channel+0x52/0x78
 [<ffffffff803fc314>] scsi_scan_host_selected+0xf1/0x133
 [<ffffffff803fc3c6>] ? do_scan_async+0x0/0x127
 [<ffffffff803fc3c1>] do_scsi_scan_host+0x6b/0x70
 [<ffffffff803fc3c6>] ? do_scan_async+0x0/0x127
 [<ffffffff803fc3dd>] do_scan_async+0x17/0x127
 [<ffffffff803fc3c6>] ? do_scan_async+0x0/0x127
 [<ffffffff80249d5d>] kthread+0x49/0x76
 [<ffffffff8020c899>] child_rip+0xa/0x11
 [<ffffffff8020bd88>] ? restore_args+0x0/0x30
 [<ffffffff80249d14>] ? kthread+0x0/0x76
 [<ffffffff8020c88f>] ? child_rip+0x0/0x11
---[ end trace 4eaa2a86a8e2da22 ]---
<...>
ata2: port disabled. ignoring.
scsi: waiting for bus probes to complete ...
WARNING: at lib/debugobjects.c:215 debug_print_object+0x4f/0x57()
ODEBUG: free active object type: timer_list
Modules linked in:
Pid: 580, comm: scsi_scan_0 Tainted: G        W  2.6.28-rc5-next-20081119 #9
Call Trace:
 [<ffffffff80236b28>] warn_slowpath+0xae/0xd5
 [<ffffffff803925b9>] ? write_vga+0x18/0x4e
 [<ffffffff8037f9e8>] ? debug_check_no_obj_freed+0x75/0x1c8
 [<ffffffff8037f8b1>] debug_print_object+0x4f/0x57
 [<ffffffff8037fa0f>] debug_check_no_obj_freed+0x9c/0x1c8
 [<ffffffff8029c7b2>] kmem_cache_free+0x64/0xc0
 [<ffffffff8036a6e0>] ? blk_release_queue+0x61/0x66
 [<ffffffff8036a6e0>] blk_release_queue+0x61/0x66
 [<ffffffff803760f2>] kobject_release+0x52/0x68
 [<ffffffff803760a0>] ? kobject_release+0x0/0x68
 [<ffffffff80376ec5>] kref_put+0x43/0x4f
 [<ffffffff80375ffa>] kobject_put+0x47/0x4b
 [<ffffffff80368c53>] blk_cleanup_queue+0x57/0x5c
 [<ffffffff803f8729>] scsi_free_queue+0x9/0xb
 [<ffffffff803fd3c7>] scsi_device_dev_release_usercontext+0xdc/0x127
 [<ffffffff803fd2eb>] ? scsi_device_dev_release_usercontext+0x0/0x127
 [<ffffffff802472a8>] execute_in_process_context+0x2a/0x70
 [<ffffffff803fd2e9>] scsi_device_dev_release+0x17/0x19
 [<ffffffff803e03e0>] device_release+0x43/0x68
 [<ffffffff803760f2>] kobject_release+0x52/0x68
 [<ffffffff803760a0>] ? kobject_release+0x0/0x68
 [<ffffffff80376ec5>] kref_put+0x43/0x4f
 [<ffffffff80375ffa>] kobject_put+0x47/0x4b
 [<ffffffff803dfd36>] put_device+0x15/0x17
 [<ffffffff803fa772>] scsi_destroy_sdev+0x48/0x4c
 [<ffffffff803fba05>] scsi_probe_and_add_lun+0xb5d/0xb81
 [<ffffffff803faaba>] ? scsi_alloc_target+0x22b/0x267
 [<ffffffff803fbcb0>] __scsi_scan_target+0x9d/0x598
 [<ffffffff8025767c>] ? trace_hardirqs_on_caller+0x1f/0x153
 [<ffffffff804e39a9>] ? __mutex_lock_common+0x371/0x3be
 [<ffffffff803fc2d9>] ? scsi_scan_host_selected+0xb6/0x133
 [<ffffffff8025767c>] ? trace_hardirqs_on_caller+0x1f/0x153
 [<ffffffff803fc2d9>] ? scsi_scan_host_selected+0xb6/0x133
 [<ffffffff803fc1fd>] scsi_scan_channel+0x52/0x78
 [<ffffffff803fc314>] scsi_scan_host_selected+0xf1/0x133
 [<ffffffff803fc3c6>] ? do_scan_async+0x0/0x127
 [<ffffffff803fc3c1>] do_scsi_scan_host+0x6b/0x70
 [<ffffffff803fc3c6>] ? do_scan_async+0x0/0x127
 [<ffffffff803fc3dd>] do_scan_async+0x17/0x127
 [<ffffffff803fc3c6>] ? do_scan_async+0x0/0x127
 [<ffffffff80249d5d>] kthread+0x49/0x76
 [<ffffffff8020c899>] child_rip+0xa/0x11
 [<ffffffff8020bd88>] ? restore_args+0x0/0x30
 [<ffffffff80249d14>] ? kthread+0x0/0x76
 [<ffffffff8020c88f>] ? child_rip+0x0/0x11
---[ end trace 4eaa2a86a8e2da22 ]---

<...>

BUG: using smp_processor_id() in preemptible [00000000] code: init-early.sh/741
caller is sock_prot_inuse_add+0x24/0x42
Pid: 741, comm: init-early.sh Tainted: G        W  2.6.28-rc5-next-20081119 #9
Call Trace:
 [<ffffffff8037f622>] debug_smp_processor_id+0xca/0xe0
 [<ffffffff8046ab5b>] sock_prot_inuse_add+0x24/0x42
 [<ffffffff804bb124>] unix_create1+0x161/0x176
 [<ffffffff804bb196>] unix_create+0x5d/0x68
 [<ffffffff80469368>] __sock_create+0x114/0x17e
 [<ffffffff80469420>] sock_create+0x2d/0x2f
 [<ffffffff80469623>] sys_socket+0x29/0x5c
 [<ffffffff8020b74b>] system_call_fastpath+0x16/0x1b
BUG: using smp_processor_id() in preemptible [00000000] code: init-early.sh/741
caller is sock_prot_inuse_add+0x24/0x42
Pid: 741, comm: init-early.sh Tainted: G        W  2.6.28-rc5-next-20081119 #9
Call Trace:

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[Thomas Gleixner]

Alexander,

On Fri, 21 Nov 2008, Alexander Beregalov wrote:

> 2008/11/20 Thomas Gleixner <tglx@linutronix.de>:
> > Alexander,
> >
> > On Wed, 19 Nov 2008, Alexander Beregalov wrote:
> >>
> >> It is 4way X86_64
> >> The kernel does not boot.
> >
> >> RIP: 0010:[<ffffffff80240061>]  [<ffffffff80240061>]
> >> get_next_timer_interrupt+0x11b/0x1f0
> >
> > Can you please enable:
> >
> > CONFIG_DEBUG_OBJECTS=y
> > CONFIG_DEBUG_OBJECTS_FREE=y
> > CONFIG_DEBUG_OBJECTS_TIMERS=Y
> >
> > and add "debug_objects" to the kernel command line ?
> 
> I added these options:

Thanks.
 
> hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
> hpet0: 3 comparators, 64-bit 14.318180 MHz counter
> ODEBUG: object is on stack, but not annotated

ok, that's homework for me.

> scsi0 : LSI SAS based MegaRAID driver
> Driver 'sd' needs updating - please use bus_type methods
> scsi 0:0:0:0: Direct-Access     ATA      SAMSUNG HE160HJ  0-24 PQ: 0 ANSI: 5
> ------------[ cut here ]------------
> WARNING: at lib/debugobjects.c:215 debug_print_object+0x4f/0x57()
> ODEBUG: free active object type: timer_list

That's the cause for your boot crash. The scsi/blk code is freeing a
page which contains an active timer, so the timer code references gone
memory. You triggered it because DEBUG_PAGEALLOC unmaps the page when
it's freed.

James, or other scsi experts please.

> Modules linked in:
> Pid: 580, comm: scsi_scan_0 Tainted: G        W  2.6.28-rc5-next-20081119 #9
> Call Trace:
>  [<ffffffff80236b28>] warn_slowpath+0xae/0xd5
>  [<ffffffff8037f9e8>] ? debug_check_no_obj_freed+0x75/0x1c8
>  [<ffffffff8037f8b1>] debug_print_object+0x4f/0x57
>  [<ffffffff8037fa0f>] debug_check_no_obj_freed+0x9c/0x1c8
>  [<ffffffff8029c7b2>] kmem_cache_free+0x64/0xc0
>  [<ffffffff8036a6e0>] ? blk_release_queue+0x61/0x66
>  [<ffffffff8036a6e0>] blk_release_queue+0x61/0x66
>  [<ffffffff803760f2>] kobject_release+0x52/0x68
>  [<ffffffff803760a0>] ? kobject_release+0x0/0x68
>  [<ffffffff80376ec5>] kref_put+0x43/0x4f
>  [<ffffffff80375ffa>] kobject_put+0x47/0x4b
>  [<ffffffff80368c53>] blk_cleanup_queue+0x57/0x5c
>  [<ffffffff803f8729>] scsi_free_queue+0x9/0xb
>  [<ffffffff803fd3c7>] scsi_device_dev_release_usercontext+0xdc/0x127
>  [<ffffffff803fd2eb>] ? scsi_device_dev_release_usercontext+0x0/0x127
>  [<ffffffff802472a8>] execute_in_process_context+0x2a/0x70
>  [<ffffffff803fd2e9>] scsi_device_dev_release+0x17/0x19
>  [<ffffffff803e03e0>] device_release+0x43/0x68
>  [<ffffffff803760f2>] kobject_release+0x52/0x68
>  [<ffffffff803760a0>] ? kobject_release+0x0/0x68
>  [<ffffffff80376ec5>] kref_put+0x43/0x4f
>  [<ffffffff80375ffa>] kobject_put+0x47/0x4b
>  [<ffffffff803dfd36>] put_device+0x15/0x17
>  [<ffffffff803fa772>] scsi_destroy_sdev+0x48/0x4c
>  [<ffffffff803fba05>] scsi_probe_and_add_lun+0xb5d/0xb81
>  [<ffffffff803faaba>] ? scsi_alloc_target+0x22b/0x267
>  [<ffffffff803fbcb0>] __scsi_scan_target+0x9d/0x598
>  [<ffffffff8025767c>] ? trace_hardirqs_on_caller+0x1f/0x153
>  [<ffffffff804e39a9>] ? __mutex_lock_common+0x371/0x3be
>  [<ffffffff803fc2d9>] ? scsi_scan_host_selected+0xb6/0x133
>  [<ffffffff8025767c>] ? trace_hardirqs_on_caller+0x1f/0x153
>  [<ffffffff803fc2d9>] ? scsi_scan_host_selected+0xb6/0x133
>  [<ffffffff803fc1fd>] scsi_scan_channel+0x52/0x78
>  [<ffffffff803fc314>] scsi_scan_host_selected+0xf1/0x133
>  [<ffffffff803fc3c6>] ? do_scan_async+0x0/0x127
>  [<ffffffff803fc3c1>] do_scsi_scan_host+0x6b/0x70
>  [<ffffffff803fc3c6>] ? do_scan_async+0x0/0x127
>  [<ffffffff803fc3dd>] do_scan_async+0x17/0x127
>  [<ffffffff803fc3c6>] ? do_scan_async+0x0/0x127
>  [<ffffffff80249d5d>] kthread+0x49/0x76
>  [<ffffffff8020c899>] child_rip+0xa/0x11
>  [<ffffffff8020bd88>] ? restore_args+0x0/0x30
>  [<ffffffff80249d14>] ? kthread+0x0/0x76
>  [<ffffffff8020c88f>] ? child_rip+0x0/0x11
> ---[ end trace 4eaa2a86a8e2da22 ]---
> <...>
> ata2: port disabled. ignoring.
> scsi: waiting for bus probes to complete ...
> WARNING: at lib/debugobjects.c:215 debug_print_object+0x4f/0x57()
> ODEBUG: free active object type: timer_list

Same as above.

> BUG: using smp_processor_id() in preemptible [00000000] code: init-early.sh/741
> caller is sock_prot_inuse_add+0x24/0x42
> Pid: 741, comm: init-early.sh Tainted: G        W  2.6.28-rc5-next-20081119 #9
> Call Trace:
>  [<ffffffff8037f622>] debug_smp_processor_id+0xca/0xe0
>  [<ffffffff8046ab5b>] sock_prot_inuse_add+0x24/0x42
>  [<ffffffff804bb124>] unix_create1+0x161/0x176
>  [<ffffffff804bb196>] unix_create+0x5d/0x68
>  [<ffffffff80469368>] __sock_create+0x114/0x17e
>  [<ffffffff80469420>] sock_create+0x2d/0x2f
>  [<ffffffff80469623>] sys_socket+0x29/0x5c
>  [<ffffffff8020b74b>] system_call_fastpath+0x16/0x1b

Dave ???

Thanks,

	tglx

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[James Bottomley]

On Mon, 2008-11-24 at 18:43 +0100, Thomas Gleixner wrote:
> > scsi0 : LSI SAS based MegaRAID driver
> > Driver 'sd' needs updating - please use bus_type methods
> > scsi 0:0:0:0: Direct-Access     ATA      SAMSUNG HE160HJ  0-24 PQ: 0 ANSI: 5
> > ------------[ cut here ]------------
> > WARNING: at lib/debugobjects.c:215 debug_print_object+0x4f/0x57()
> > ODEBUG: free active object type: timer_list
> 
> That's the cause for your boot crash. The scsi/blk code is freeing a
> page which contains an active timer, so the timer code references gone
> memory. You triggered it because DEBUG_PAGEALLOC unmaps the page when
> it's freed.
> 
> James, or other scsi experts please.
> 
> > Modules linked in:
> > Pid: 580, comm: scsi_scan_0 Tainted: G        W  2.6.28-rc5-next-20081119 #9
> > Call Trace:
> >  [<ffffffff80236b28>] warn_slowpath+0xae/0xd5
> >  [<ffffffff8037f9e8>] ? debug_check_no_obj_freed+0x75/0x1c8
> >  [<ffffffff8037f8b1>] debug_print_object+0x4f/0x57
> >  [<ffffffff8037fa0f>] debug_check_no_obj_freed+0x9c/0x1c8
> >  [<ffffffff8029c7b2>] kmem_cache_free+0x64/0xc0
> >  [<ffffffff8036a6e0>] ? blk_release_queue+0x61/0x66
> >  [<ffffffff8036a6e0>] blk_release_queue+0x61/0x66
> >  [<ffffffff803760f2>] kobject_release+0x52/0x68
> >  [<ffffffff803760a0>] ? kobject_release+0x0/0x68
> >  [<ffffffff80376ec5>] kref_put+0x43/0x4f
> >  [<ffffffff80375ffa>] kobject_put+0x47/0x4b
> >  [<ffffffff80368c53>] blk_cleanup_queue+0x57/0x5c
> >  [<ffffffff803f8729>] scsi_free_queue+0x9/0xb
> >  [<ffffffff803fd3c7>] scsi_device_dev_release_usercontext+0xdc/0x127
> >  [<ffffffff803fd2eb>] ? scsi_device_dev_release_usercontext+0x0/0x127
> >  [<ffffffff802472a8>] execute_in_process_context+0x2a/0x70
> >  [<ffffffff803fd2e9>] scsi_device_dev_release+0x17/0x19
> >  [<ffffffff803e03e0>] device_release+0x43/0x68
> >  [<ffffffff803760f2>] kobject_release+0x52/0x68
> >  [<ffffffff803760a0>] ? kobject_release+0x0/0x68
> >  [<ffffffff80376ec5>] kref_put+0x43/0x4f
> >  [<ffffffff80375ffa>] kobject_put+0x47/0x4b
> >  [<ffffffff803dfd36>] put_device+0x15/0x17
> >  [<ffffffff803fa772>] scsi_destroy_sdev+0x48/0x4c
> >  [<ffffffff803fba05>] scsi_probe_and_add_lun+0xb5d/0xb81
> >  [<ffffffff803faaba>] ? scsi_alloc_target+0x22b/0x267
> >  [<ffffffff803fbcb0>] __scsi_scan_target+0x9d/0x598
> >  [<ffffffff8025767c>] ? trace_hardirqs_on_caller+0x1f/0x153
> >  [<ffffffff804e39a9>] ? __mutex_lock_common+0x371/0x3be
> >  [<ffffffff803fc2d9>] ? scsi_scan_host_selected+0xb6/0x133
> >  [<ffffffff8025767c>] ? trace_hardirqs_on_caller+0x1f/0x153
> >  [<ffffffff803fc2d9>] ? scsi_scan_host_selected+0xb6/0x133
> >  [<ffffffff803fc1fd>] scsi_scan_channel+0x52/0x78
> >  [<ffffffff803fc314>] scsi_scan_host_selected+0xf1/0x133
> >  [<ffffffff803fc3c6>] ? do_scan_async+0x0/0x127
> >  [<ffffffff803fc3c1>] do_scsi_scan_host+0x6b/0x70
> >  [<ffffffff803fc3c6>] ? do_scan_async+0x0/0x127
> >  [<ffffffff803fc3dd>] do_scan_async+0x17/0x127
> >  [<ffffffff803fc3c6>] ? do_scan_async+0x0/0x127
> >  [<ffffffff80249d5d>] kthread+0x49/0x76
> >  [<ffffffff8020c899>] child_rip+0xa/0x11
> >  [<ffffffff8020bd88>] ? restore_args+0x0/0x30
> >  [<ffffffff80249d14>] ? kthread+0x0/0x76
> >  [<ffffffff8020c88f>] ? child_rip+0x0/0x11
> > ---[ end trace 4eaa2a86a8e2da22 ]---

Well, not sure.  Most likely candidate is the new block timer code.
What seems to be happening is that the queue is being released with
either an outstanding request (refcounting problem) or ticking timer
with no work (block timer problem).  The way scanning works is that we
create a request queue for each device we probe and then delete it again
if nothing appears after the bus settle time.   The argument against
this is that it should show up on every scanned bus.  However, these are
getting rarer; I was just about to write that I hadn't seen it when I
remembered that all my SCSI testing systems are currently running
hotplug reporting busses (i.e. don't do scanning).  However,
fortunately, I've also booted voyager recently which does use parallel
SCSI and doesn't see this either, so it could also be megaraid_sas
specific.

Could you turn on SCSI logging so we can see the sequences.  Probably
since this is boot time, just enable all logging:

echo 0xffffffff > /sys/module/scsi_mod/parameters/scsi_logging_level

(kernel must be compiled with CONFIG_SCSI_LOGGING=y

James

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[Thomas Gleixner]

On Mon, 24 Nov 2008, James Bottomley wrote:
> On Mon, 2008-11-24 at 18:43 +0100, Thomas Gleixner wrote:
> > > scsi0 : LSI SAS based MegaRAID driver
> > > Driver 'sd' needs updating - please use bus_type methods
> > > scsi 0:0:0:0: Direct-Access     ATA      SAMSUNG HE160HJ  0-24 PQ: 0 ANSI: 5
> > > ------------[ cut here ]------------
> > > WARNING: at lib/debugobjects.c:215 debug_print_object+0x4f/0x57()
> > > ODEBUG: free active object type: timer_list
> > 
> > That's the cause for your boot crash. The scsi/blk code is freeing a
> > page which contains an active timer, so the timer code references gone
> > memory. You triggered it because DEBUG_PAGEALLOC unmaps the page when
> > it's freed.
> > 
> > James, or other scsi experts please.
> 
> Well, not sure.  Most likely candidate is the new block timer code.
> What seems to be happening is that the queue is being released with
> either an outstanding request (refcounting problem) or ticking timer
> with no work (block timer problem).  The way scanning works is that we
> create a request queue for each device we probe and then delete it again
> if nothing appears after the bus settle time.   The argument against
> this is that it should show up on every scanned bus.  However, these are
> getting rarer; I was just about to write that I hadn't seen it when I
> remembered that all my SCSI testing systems are currently running
> hotplug reporting busses (i.e. don't do scanning).  However,
> fortunately, I've also booted voyager recently which does use parallel
> SCSI and doesn't see this either, so it could also be megaraid_sas
> specific.

Yeah, block could it be as well. Jens, Mike ?

One note about not seeing it: We have had such bugs before where the
page was freed but not touched and the timer survived w/o tripping the
system over. Alexander noticed because of DEBUG_PAGEALLOC and you can
also see it by enabling debugobjects, which will give you the nice
backtrace.

CONFIG_DEBUG_OBJECTS=y
CONFIG_DEBUG_OBJECTS_FREE=y
CONFIG_DEBUG_OBJECTS_TIMERS=Y

and add "debug_objects" to the kernel command line.
 
> Could you turn on SCSI logging so we can see the sequences.  Probably
> since this is boot time, just enable all logging:
> 
> echo 0xffffffff > /sys/module/scsi_mod/parameters/scsi_logging_level
> 
> (kernel must be compiled with CONFIG_SCSI_LOGGING=y
> 
> James
> 
> 

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[Mike Anderson]

Thomas Gleixner <tglx@linutronix.de> wrote:
> > Well, not sure.  Most likely candidate is the new block timer code.
> > What seems to be happening is that the queue is being released with
> > either an outstanding request (refcounting problem) or ticking timer
> > with no work (block timer problem).  The way scanning works is that we
> > create a request queue for each device we probe and then delete it again
> > if nothing appears after the bus settle time.   The argument against
> > this is that it should show up on every scanned bus.  However, these are
> > getting rarer; I was just about to write that I hadn't seen it when I
> > remembered that all my SCSI testing systems are currently running
> > hotplug reporting busses (i.e. don't do scanning).  However,
> > fortunately, I've also booted voyager recently which does use parallel
> > SCSI and doesn't see this either, so it could also be megaraid_sas
> > specific.
> 
> Yeah, block could it be as well. Jens, Mike ?

I added a comment to bug 12020 on Thursday about a few other systems that
where seeing the signature shown in bug 12020. It appeared from debug that
there where a few paths that where adding timers for requests that where
not expected.

http://bugzilla.kernel.org/show_bug.cgi?id=12020

It would be good to know if the debug patch below effects your problem as while.

If it does we need to investigated a solution to resolve not adding a
timer for these requests.

-andmike
--
Michael Anderson
andmike@linux.vnet.ibm.com



blk: blk_add_timer debug patch

[DEBUG] Debug only patch.

Debug patch to blk_add_timer to not start timer for request that do not
have the REQ_STARTED flag set.

Signed-off-by: Mike Anderson <andmike@linux.vnet.ibm.com>
---
 block/blk-timeout.c |    3 +++
 1 files changed, 3 insertions(+), 0 deletions(-)

diff --git a/block/blk-timeout.c b/block/blk-timeout.c
index 69185ea..4389391 100644
--- a/block/blk-timeout.c
+++ b/block/blk-timeout.c
@@ -177,6 +177,9 @@ void blk_add_timer(struct request *req)
 	BUG_ON(!list_empty(&req->timeout_list));
 	BUG_ON(test_bit(REQ_ATOM_COMPLETE, &req->atomic_flags));
 
+	if (!(req->cmd_flags & REQ_STARTED))
+		return;
+
 	if (req->timeout)
 		req->deadline = jiffies + req->timeout;
 	else {
-- 
1.5.6.5

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[Thomas Gleixner]

On Mon, 24 Nov 2008, Mike Anderson wrote:
> Thomas Gleixner <tglx@linutronix.de> wrote:
> > Yeah, block could it be as well. Jens, Mike ?
> 
> I added a comment to bug 12020 on Thursday about a few other systems that
> where seeing the signature shown in bug 12020. It appeared from debug that
> there where a few paths that where adding timers for requests that where
> not expected.
> 
> http://bugzilla.kernel.org/show_bug.cgi?id=12020
> 
> It would be good to know if the debug patch below effects your problem as while.
> 
> If it does we need to investigated a solution to resolve not adding a
> timer for these requests.

Wrong. 

The problem is not a timer which is armed in the first place.

The problem is an armed timer which is not canceled before the data
structure which contains it is freed.

So not arming the timer will probably prevent this particular scan
problem, but it does not solve the general wreckage of freeing a data
structure with a possibly armed timer in it.

You need to fix the code path which frees the data structure which
contains the timer and cancel the timer _before_ freeing the data
structure.

Thanks,

	tglx

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[malahal]

Thomas Gleixner [tglx@linutronix.de] wrote:
> > where seeing the signature shown in bug 12020. It appeared from debug that
> > there where a few paths that where adding timers for requests that where
> > not expected.
> > 
> > http://bugzilla.kernel.org/show_bug.cgi?id=12020
> > 
> > It would be good to know if the debug patch below effects your problem as while.
> > 
> > If it does we need to investigated a solution to resolve not adding a
> > timer for these requests.
> 
> Wrong. 
> 
> The problem is not a timer which is armed in the first place.

No, this could be a problem if such a timer is not dis-armed! As fas as
I know, the queue timer will be dis-armed in end_that_request_last() if
needed. Do we know end_that_request_last() gets called for every request
queued?

> The problem is an armed timer which is not canceled before the data
> structure which contains it is freed.
> 
> So not arming the timer will probably prevent this particular scan
> problem, but it does not solve the general wreckage of freeing a data
> structure with a possibly armed timer in it.
> 
> You need to fix the code path which frees the data structure which
> contains the timer and cancel the timer _before_ freeing the data
> structure.

Agreed but the timer is armed when a request is sent and is dis-armed
when it is completed. Essentially there should NOT be any active
timer(s) when you try to free the request queue. In other words, the
code which frees the data structure (request queue) is correct and there
is no need to cancel the timer there!

--Malahal.

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[malahal]

Thomas Gleixner [tglx@linutronix.de] wrote:
> On Mon, 24 Nov 2008, Mike Anderson wrote:
> > Thomas Gleixner <tglx@linutronix.de> wrote:
> > > Yeah, block could it be as well. Jens, Mike ?
> > 
> > I added a comment to bug 12020 on Thursday about a few other systems that
> > where seeing the signature shown in bug 12020. It appeared from debug that
> > there where a few paths that where adding timers for requests that where
> > not expected.
> > 
> > http://bugzilla.kernel.org/show_bug.cgi?id=12020
> > 
> > It would be good to know if the debug patch below effects your problem as while.
> > 
> > If it does we need to investigated a solution to resolve not adding a
> > timer for these requests.

The block timer code calls del_timer(), should it call del_timer_sync()?
It is possible although unlikely that you are hitting del_timer_sync vs
del_timer problem in the block timeout code. Can only be seen on SMP
systems though!

--Malahal.

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[Stephen Rothwell]

[-- Attachment #1: Type: text/plain, Size: 1786 bytes --]

On Mon, 24 Nov 2008 16:09:02 -0800 malahal@us.ibm.com wrote:
>
> Thomas Gleixner [tglx@linutronix.de] wrote:
> > On Mon, 24 Nov 2008, Mike Anderson wrote:
> > > Thomas Gleixner <tglx@linutronix.de> wrote:
> > > > Yeah, block could it be as well. Jens, Mike ?
> > > 
> > > I added a comment to bug 12020 on Thursday about a few other systems that
> > > where seeing the signature shown in bug 12020. It appeared from debug that
> > > there where a few paths that where adding timers for requests that where
> > > not expected.
> > > 
> > > http://bugzilla.kernel.org/show_bug.cgi?id=12020
> > > 
> > > It would be good to know if the debug patch below effects your problem as while.
> > > 
> > > If it does we need to investigated a solution to resolve not adding a
> > > timer for these requests.
> 
> The block timer code calls del_timer(), should it call del_timer_sync()?
> It is possible although unlikely that you are hitting del_timer_sync vs
> del_timer problem in the block timeout code. Can only be seen on SMP
> systems though!

Is this still a problem in next-20081121? In that tree, the block commit
"block: leave the request timeout timer running even on an empty list"
was changed to add this:

diff --git a/block/blk-core.c b/block/blk-core.c
index 04267d6..44f547c 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -391,6 +391,7 @@ EXPORT_SYMBOL(blk_stop_queue);
 void blk_sync_queue(struct request_queue *q)
 {
 	del_timer_sync(&q->unplug_timer);
+	del_timer_sync(&q->timeout);
 	kblockd_flush_work(&q->unplug_work);
 }
 EXPORT_SYMBOL(blk_sync_queue);

After I spent some time bisecting a boot failure in PowerPC.
-- 
Cheers,
Stephen Rothwell                    sfr@canb.auug.org.au
http://www.canb.auug.org.au/~sfr/

[-- Attachment #2: Type: application/pgp-signature, Size: 197 bytes --]

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[malahal]

Stephen Rothwell [sfr@canb.auug.org.au] wrote:
> > The block timer code calls del_timer(), should it call del_timer_sync()?
> > It is possible although unlikely that you are hitting del_timer_sync vs
> > del_timer problem in the block timeout code. Can only be seen on SMP
> > systems though!
> 
> Is this still a problem in next-20081121? In that tree, the block commit
> "block: leave the request timeout timer running even on an empty list"
> was changed to add this:
> 
> diff --git a/block/blk-core.c b/block/blk-core.c
> index 04267d6..44f547c 100644
> --- a/block/blk-core.c
> +++ b/block/blk-core.c
> @@ -391,6 +391,7 @@ EXPORT_SYMBOL(blk_stop_queue);
>  void blk_sync_queue(struct request_queue *q)
>  {
>  	del_timer_sync(&q->unplug_timer);
> +	del_timer_sync(&q->timeout);
>  	kblockd_flush_work(&q->unplug_work);
>  }
>  EXPORT_SYMBOL(blk_sync_queue);

I was looking at the Linux tree. Clearly same problem doesn't exist with
the above commit! I wonder why kblockd_flush_work() is called after the
del_timer_sync(). It makes sense to cancel the work and then shutdown
the timer(s). I doubt if you are running into this problem though.

-Malahal.

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[Jens Axboe]

On Mon, Nov 24 2008, malahal@us.ibm.com wrote:
> Stephen Rothwell [sfr@canb.auug.org.au] wrote:
> > > The block timer code calls del_timer(), should it call del_timer_sync()?
> > > It is possible although unlikely that you are hitting del_timer_sync vs
> > > del_timer problem in the block timeout code. Can only be seen on SMP
> > > systems though!
> > 
> > Is this still a problem in next-20081121? In that tree, the block commit
> > "block: leave the request timeout timer running even on an empty list"
> > was changed to add this:
> > 
> > diff --git a/block/blk-core.c b/block/blk-core.c
> > index 04267d6..44f547c 100644
> > --- a/block/blk-core.c
> > +++ b/block/blk-core.c
> > @@ -391,6 +391,7 @@ EXPORT_SYMBOL(blk_stop_queue);
> >  void blk_sync_queue(struct request_queue *q)
> >  {
> >  	del_timer_sync(&q->unplug_timer);
> > +	del_timer_sync(&q->timeout);
> >  	kblockd_flush_work(&q->unplug_work);
> >  }
> >  EXPORT_SYMBOL(blk_sync_queue);
> 
> I was looking at the Linux tree. Clearly same problem doesn't exist with
> the above commit! I wonder why kblockd_flush_work() is called after the
> del_timer_sync(). It makes sense to cancel the work and then shutdown
> the timer(s). I doubt if you are running into this problem though.

If the kernel tested doesn't include the above fix, it'll surely go
boom. Can someone verify that this is the case?

-- 
Jens Axboe

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[malahal]

Jens Axboe [jens.axboe@oracle.com] wrote:
> On Mon, Nov 24 2008, malahal@us.ibm.com wrote:
> > Stephen Rothwell [sfr@canb.auug.org.au] wrote:
> > > > The block timer code calls del_timer(), should it call del_timer_sync()?
> > > > It is possible although unlikely that you are hitting del_timer_sync vs
> > > > del_timer problem in the block timeout code. Can only be seen on SMP
> > > > systems though!
> > > 
> > > Is this still a problem in next-20081121? In that tree, the block commit
> > > "block: leave the request timeout timer running even on an empty list"
> > > was changed to add this:
> > > 
> > > diff --git a/block/blk-core.c b/block/blk-core.c
> > > index 04267d6..44f547c 100644
> > > --- a/block/blk-core.c
> > > +++ b/block/blk-core.c
> > > @@ -391,6 +391,7 @@ EXPORT_SYMBOL(blk_stop_queue);
> > >  void blk_sync_queue(struct request_queue *q)
> > >  {
> > >  	del_timer_sync(&q->unplug_timer);
> > > +	del_timer_sync(&q->timeout);
> > >  	kblockd_flush_work(&q->unplug_work);
> > >  }
> > >  EXPORT_SYMBOL(blk_sync_queue);
> > 
> > I was looking at the Linux tree. Clearly same problem doesn't exist with
> > the above commit! I wonder why kblockd_flush_work() is called after the
> > del_timer_sync(). It makes sense to cancel the work and then shutdown
> > the timer(s). I doubt if you are running into this problem though.
> 
> If the kernel tested doesn't include the above fix, it'll surely go
> boom. Can someone verify that this is the case?

Just looked, next-20081119 doesn't have the above fix. It is included in
next-20081120. Also note that the above fix is only partially copied,
there is other part that removed deleting the timer when there are no
outstanding requests.

--Malahal.

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[Alexander Beregalov]

2008/11/25  <malahal@us.ibm.com>:
> Jens Axboe [jens.axboe@oracle.com] wrote:
>> On Mon, Nov 24 2008, malahal@us.ibm.com wrote:
>> > Stephen Rothwell [sfr@canb.auug.org.au] wrote:
>> > > > The block timer code calls del_timer(), should it call del_timer_sync()?
>> > > > It is possible although unlikely that you are hitting del_timer_sync vs
>> > > > del_timer problem in the block timeout code. Can only be seen on SMP
>> > > > systems though!
>> > >
>> > > Is this still a problem in next-20081121? In that tree, the block commit
>> > > "block: leave the request timeout timer running even on an empty list"
>> > > was changed to add this:
>> > >
>> > > diff --git a/block/blk-core.c b/block/blk-core.c
>> > > index 04267d6..44f547c 100644
>> > > --- a/block/blk-core.c
>> > > +++ b/block/blk-core.c
>> > > @@ -391,6 +391,7 @@ EXPORT_SYMBOL(blk_stop_queue);
>> > >  void blk_sync_queue(struct request_queue *q)
>> > >  {
>> > >   del_timer_sync(&q->unplug_timer);
>> > > + del_timer_sync(&q->timeout);
>> > >   kblockd_flush_work(&q->unplug_work);
>> > >  }
>> > >  EXPORT_SYMBOL(blk_sync_queue);
>> >
>> > I was looking at the Linux tree. Clearly same problem doesn't exist with
>> > the above commit! I wonder why kblockd_flush_work() is called after the
>> > del_timer_sync(). It makes sense to cancel the work and then shutdown
>> > the timer(s). I doubt if you are running into this problem though.
>>
>> If the kernel tested doesn't include the above fix, it'll surely go
>> boom. Can someone verify that this is the case?
>
> Just looked, next-20081119 doesn't have the above fix. It is included in
> next-20081120. Also note that the above fix is only partially copied,
> there is other part that removed deleting the timer when there are no
> outstanding requests.
>
Yes, I can not reproduce it anymore on linux-next 1121 and newer. (I
did not try 1120)
It seems the fix works pretty good.
Is it still needed and reasonable  to investigate the problem on next-20081119?
Unfortunately I do not have much time for it.

All these problems have gone away on next-1125 except ODEBUG warning on HPET.

Re: next-20081119: general protection fault: get_next_timer_interrupt()

[Jens Axboe]

On Tue, Nov 25 2008, Alexander Beregalov wrote:
> 2008/11/25  <malahal@us.ibm.com>:
> > Jens Axboe [jens.axboe@oracle.com] wrote:
> >> On Mon, Nov 24 2008, malahal@us.ibm.com wrote:
> >> > Stephen Rothwell [sfr@canb.auug.org.au] wrote:
> >> > > > The block timer code calls del_timer(), should it call del_timer_sync()?
> >> > > > It is possible although unlikely that you are hitting del_timer_sync vs
> >> > > > del_timer problem in the block timeout code. Can only be seen on SMP
> >> > > > systems though!
> >> > >
> >> > > Is this still a problem in next-20081121? In that tree, the block commit
> >> > > "block: leave the request timeout timer running even on an empty list"
> >> > > was changed to add this:
> >> > >
> >> > > diff --git a/block/blk-core.c b/block/blk-core.c
> >> > > index 04267d6..44f547c 100644
> >> > > --- a/block/blk-core.c
> >> > > +++ b/block/blk-core.c
> >> > > @@ -391,6 +391,7 @@ EXPORT_SYMBOL(blk_stop_queue);
> >> > >  void blk_sync_queue(struct request_queue *q)
> >> > >  {
> >> > >   del_timer_sync(&q->unplug_timer);
> >> > > + del_timer_sync(&q->timeout);
> >> > >   kblockd_flush_work(&q->unplug_work);
> >> > >  }
> >> > >  EXPORT_SYMBOL(blk_sync_queue);
> >> >
> >> > I was looking at the Linux tree. Clearly same problem doesn't exist with
> >> > the above commit! I wonder why kblockd_flush_work() is called after the
> >> > del_timer_sync(). It makes sense to cancel the work and then shutdown
> >> > the timer(s). I doubt if you are running into this problem though.
> >>
> >> If the kernel tested doesn't include the above fix, it'll surely go
> >> boom. Can someone verify that this is the case?
> >
> > Just looked, next-20081119 doesn't have the above fix. It is included in
> > next-20081120. Also note that the above fix is only partially copied,
> > there is other part that removed deleting the timer when there are no
> > outstanding requests.
> >
> Yes, I can not reproduce it anymore on linux-next 1121 and newer. (I
> did not try 1120) It seems the fix works pretty good.  Is it still
> needed and reasonable  to investigate the problem on next-20081119?
> Unfortunately I do not have much time for it.

No, you don't have to investigate further. This was a known bug that is
fixed in -next and mainline basically right after next-20081119.

> 
> All these problems have gone away on next-1125 except ODEBUG warning
> on HPET.

-- 
Jens Axboe