ec locking issue

ec locking issue

[Dominik Brodowski]

Hi,

Current kernels (e.g. 2.6.20-git-as-of-yesterday) don't boot for me, and
it seems like ACPI is the cause: the last thing I can see in the log is

swapper/1 is trying to acquire lock
	&ec->lock

but task is already holding lock
	&ec->lock

Snippets from the call trace:

acpi_ec_transaction
acpi_ec_read
acpi_ec_space_handler
acpi_ev_address_space_dispatch
acpi_ex_access_region
acpi_ex_field_datum_
acpi_ex_extract_from_field
...
acpi_ex_ns_evaluate
acpi_ev_execute_reg_method
acpi_ev_reg_run
acpi_ns_walk_namespace
acpi_ev_execute_reg_methods
acpi_install_address_space_handler
acpi_ec_start
acpi_start_single_object
acpi_device_probe
really_probe
...
bus_add_driver
...
acpi_ec_init



Ideas? Patches?

Thanks,
	Dominik

Re: ec locking issue

[Alexey Starikovskiy]

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

Hi,

ec is locked only in acpi_ec_transaction, and it is only once in your 
stack.
I doubt that this patch could change something, but worth a try...
Is bisect finds something?

Regards,
    Alex.
Dominik Brodowski wrote:
> Hi,
>
> Current kernels (e.g. 2.6.20-git-as-of-yesterday) don't boot for me, and
> it seems like ACPI is the cause: the last thing I can see in the log is
>
> swapper/1 is trying to acquire lock
> 	&ec->lock
>
> but task is already holding lock
> 	&ec->lock
>
> Snippets from the call trace:
>
> acpi_ec_transaction
> acpi_ec_read
> acpi_ec_space_handler
> acpi_ev_address_space_dispatch
> acpi_ex_access_region
> acpi_ex_field_datum_
> acpi_ex_extract_from_field
> ...
> acpi_ex_ns_evaluate
> acpi_ev_execute_reg_method
> acpi_ev_reg_run
> acpi_ns_walk_namespace
> acpi_ev_execute_reg_methods
> acpi_install_address_space_handler
> acpi_ec_start
> acpi_start_single_object
> acpi_device_probe
> really_probe
> ...
> bus_add_driver
> ...
> acpi_ec_init
>
>
>
> Ideas? Patches?
>
> Thanks,
> 	Dominik
> -
> To unsubscribe from this list: send the line "unsubscribe linux-acpi" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>   


[-- Attachment #2: ec_unlock_mutex_in_error_path.patch --]
[-- Type: text/plain, Size: 483 bytes --]

diff --git a/drivers/acpi/ec.c b/drivers/acpi/ec.c
index 743ce27..8f5aaf7 100644
--- a/drivers/acpi/ec.c
+++ b/drivers/acpi/ec.c
@@ -280,8 +280,10 @@ static int acpi_ec_transaction(struct ac
 	mutex_lock(&ec->lock);
 	if (ec->global_lock) {
 		status = acpi_acquire_global_lock(ACPI_EC_UDELAY_GLK, &glk);
-		if (ACPI_FAILURE(status))
+		if (ACPI_FAILURE(status)) {
+			mutex_unlock(&ec->lock);
 			return -ENODEV;
+		}
 	}
 
 	/* Make sure GPE is enabled before doing transaction */

Re: ec locking issue

[Len Brown]

On Thursday 15 February 2007 15:16, Alexey Starikovskiy wrote:
> Hi,
> 
> ec is locked only in acpi_ec_transaction, and it is only once in your 
> stack.
> I doubt that this patch could change something, but worth a try...
> Is bisect finds something?
> 
> Regards,
>     Alex.
> Dominik Brodowski wrote:
> > Hi,
> >
> > Current kernels (e.g. 2.6.20-git-as-of-yesterday) don't boot for me, and
> > it seems like ACPI is the cause: the last thing I can see in the log is
> >
> > swapper/1 is trying to acquire lock
> > 	&ec->lock
> >
> > but task is already holding lock
> > 	&ec->lock
> >
> > Snippets from the call trace:
> >
> > acpi_ec_transaction
> > acpi_ec_read
> > acpi_ec_space_handler
> > acpi_ev_address_space_dispatch
> > acpi_ex_access_region
> > acpi_ex_field_datum_
> > acpi_ex_extract_from_field
> > ...
> > acpi_ex_ns_evaluate
> > acpi_ev_execute_reg_method
> > acpi_ev_reg_run
> > acpi_ns_walk_namespace
> > acpi_ev_execute_reg_methods
> > acpi_install_address_space_handler
> > acpi_ec_start
> > acpi_start_single_object
> > acpi_device_probe
> > really_probe
> > ...
> > bus_add_driver
> > ...
> > acpi_ec_init

Alexey,
Thanks for the fix -- it is applied.

Dominik,
Did this fix help, or is the problem elsehwere?

thanks,
-Len


commit c24e912b61b1ab2301c59777134194066b06465c
Author: Alexey Starikovskiy <alexey.y.starikovskiy@linux.intel.com>
Date:   Thu Feb 15 23:16:18 2007 +0300

    ACPI: ec: add unlock in error path
    
    Signed-off-by: Alexey Starikovskiy <alexey.y.starikovskiy@linux.intel.com>
    Signed-off-by: Len Brown <len.brown@intel.com>

diff --git a/drivers/acpi/ec.c b/drivers/acpi/ec.c
index 743ce27..8f5aaf7 100644
--- a/drivers/acpi/ec.c
+++ b/drivers/acpi/ec.c
@@ -280,8 +280,10 @@ static int acpi_ec_transaction(struct acpi_ec *ec, u8 command,
 	mutex_lock(&ec->lock);
 	if (ec->global_lock) {
 		status = acpi_acquire_global_lock(ACPI_EC_UDELAY_GLK, &glk);
-		if (ACPI_FAILURE(status))
+		if (ACPI_FAILURE(status)) {
+			mutex_unlock(&ec->lock);
 			return -ENODEV;
+		}
 	}
 
 	/* Make sure GPE is enabled before doing transaction */

Re: ec locking issue

[Dominik Brodowski]

Hi,

On Fri, Feb 16, 2007 at 12:54:55PM -0500, Len Brown wrote:
> > > acpi_ec_transaction
> > > acpi_ec_read
> > > acpi_ec_space_handler
> > > acpi_ev_address_space_dispatch
> > > acpi_ex_access_region
> > > acpi_ex_field_datum_
> > > acpi_ex_extract_from_field
> > > ...
> > > acpi_ex_ns_evaluate
> > > acpi_ev_execute_reg_method
> > > acpi_ev_reg_run
> > > acpi_ns_walk_namespace
> > > acpi_ev_execute_reg_methods
> > > acpi_install_address_space_handler
> > > acpi_ec_start
> > > acpi_start_single_object
> > > acpi_device_probe
> > > really_probe
> > > ...
> > > bus_add_driver
> > > ...
> > > acpi_ec_init
> 
> Alexey,
> Thanks for the fix -- it is applied.
> 
> Dominik,
> Did this fix help, or is the problem elsehwere?

Unfortunately, this doesn't solve the issue for me -- now I get a panic with
EIP at __list_add+0x2d/0x60, with the call trace being

	...
	die
	do_page_fault
	error_code
	__mutex_lock_slowpath
	mutex_lock
	acpi_ec_transaction

and then the same as above... Will try it out with lockdep disabled.

	Dominik

Re: ec locking issue

[Dominik Brodowski]

Hi,

On Mon, Feb 19, 2007 at 08:44:31AM -0500, Dominik Brodowski wrote:
> On Fri, Feb 16, 2007 at 12:54:55PM -0500, Len Brown wrote:
> > > > acpi_ec_transaction
> > > > acpi_ec_read
> > > > acpi_ec_space_handler
> > > > acpi_ev_address_space_dispatch
> > > > acpi_ex_access_region
> > > > acpi_ex_field_datum_
> > > > acpi_ex_extract_from_field
> > > > ...
> > > > acpi_ex_ns_evaluate
> > > > acpi_ev_execute_reg_method
> > > > acpi_ev_reg_run
> > > > acpi_ns_walk_namespace
> > > > acpi_ev_execute_reg_methods
> > > > acpi_install_address_space_handler
> > > > acpi_ec_start
> > > > acpi_start_single_object
> > > > acpi_device_probe
> > > > really_probe
> > > > ...
> > > > bus_add_driver
> > > > ...
> > > > acpi_ec_init
> > 
> > Alexey,
> > Thanks for the fix -- it is applied.
> > 
> > Dominik,
> > Did this fix help, or is the problem elsehwere?
> 
> Unfortunately, this doesn't solve the issue for me -- now I get a panic with
> EIP at __list_add+0x2d/0x60, with the call trace being
> 
> 	...
> 	die
> 	do_page_fault
> 	error_code
> 	__mutex_lock_slowpath
> 	mutex_lock
> 	acpi_ec_transaction
> 
> and then the same as above... Will try it out with lockdep disabled.

No, doesn't seem to be lockdep-related; same issue continues. "acpi=off"
fixes the issue, though, of course...

Thanks,
	Dominik

Re: ec locking issue

[Alexey Starikovskiy]

Dominik Brodowski wrote:
> Hi,
>
> On Mon, Feb 19, 2007 at 08:44:31AM -0500, Dominik Brodowski wrote:
>   
>> On Fri, Feb 16, 2007 at 12:54:55PM -0500, Len Brown wrote:
>>     
>>>>> acpi_ec_transaction
>>>>> acpi_ec_read
>>>>> acpi_ec_space_handler
>>>>> acpi_ev_address_space_dispatch
>>>>> acpi_ex_access_region
>>>>> acpi_ex_field_datum_
>>>>> acpi_ex_extract_from_field
>>>>> ...
>>>>> acpi_ex_ns_evaluate
>>>>> acpi_ev_execute_reg_method
>>>>> acpi_ev_reg_run
>>>>> acpi_ns_walk_namespace
>>>>> acpi_ev_execute_reg_methods
>>>>> acpi_install_address_space_handler
>>>>> acpi_ec_start
>>>>> acpi_start_single_object
>>>>> acpi_device_probe
>>>>> really_probe
>>>>> ...
>>>>> bus_add_driver
>>>>> ...
>>>>> acpi_ec_init
>>>>>           
>>> Alexey,
>>> Thanks for the fix -- it is applied.
>>>
>>> Dominik,
>>> Did this fix help, or is the problem elsehwere?
>>>       
>> Unfortunately, this doesn't solve the issue for me -- now I get a panic with
>> EIP at __list_add+0x2d/0x60, with the call trace being
>>
>> 	...
>> 	die
>> 	do_page_fault
>> 	error_code
>> 	__mutex_lock_slowpath
>> 	mutex_lock
>> 	acpi_ec_transaction
>>
>> and then the same as above... Will try it out with lockdep disabled.
>>     
>
> No, doesn't seem to be lockdep-related; same issue continues. "acpi=off"
> fixes the issue, though, of course...
>
> Thanks,
> 	Dominik
>   

Dominik,
Could you send your acpidump and full dmesg please?

Thanks,
    Alex.

Re: ec locking issue

[Dominik Brodowski]

Hi,

On Tue, Feb 20, 2007 at 09:24:36PM +0300, Alexey Starikovskiy wrote:
> >On Mon, Feb 19, 2007 at 08:44:31AM -0500, Dominik Brodowski wrote:
> >  
> >>On Fri, Feb 16, 2007 at 12:54:55PM -0500, Len Brown wrote:
> >>    
> >>>>>acpi_ec_transaction
> >>>>>acpi_ec_read
> >>>>>acpi_ec_space_handler
> >>>>>acpi_ev_address_space_dispatch
> >>>>>acpi_ex_access_region
> >>>>>acpi_ex_field_datum_
> >>>>>acpi_ex_extract_from_field
> >>>>>...
> >>>>>acpi_ex_ns_evaluate
> >>>>>acpi_ev_execute_reg_method
> >>>>>acpi_ev_reg_run
> >>>>>acpi_ns_walk_namespace
> >>>>>acpi_ev_execute_reg_methods
> >>>>>acpi_install_address_space_handler
> >>>>>acpi_ec_start
> >>>>>acpi_start_single_object
> >>>>>acpi_device_probe
> >>>>>really_probe
> >>>>>...
> >>>>>bus_add_driver
> >>>>>...
> >>>>>acpi_ec_init
> >>>>>          
> >>>Alexey,
> >>>Thanks for the fix -- it is applied.
> >>>
> >>>Dominik,
> >>>Did this fix help, or is the problem elsehwere?
> >>>      
> >>Unfortunately, this doesn't solve the issue for me -- now I get a panic 
> >>with
> >>EIP at __list_add+0x2d/0x60, with the call trace being
> >>
> >>	...
> >>	die
> >>	do_page_fault
> >>	error_code
> >>	__mutex_lock_slowpath
> >>	mutex_lock
> >>	acpi_ec_transaction
> >>
> >>and then the same as above... Will try it out with lockdep disabled.
> >>    
> >
> >No, doesn't seem to be lockdep-related; same issue continues. "acpi=off"
> >fixes the issue, though, of course...
> >
> >Thanks,
> >	Dominik
> >  
> 
> Dominik,
> Could you send your acpidump and full dmesg please?

http://userweb.kernel.org/~brodo/acpidump.binary
http://userweb.kernel.org/~brodo/acpidump.txt
http://userweb.kernel.org/~brodo/acpi-dmsg.txt

Hope this helps,
	Dominik

Re: ec locking issue

[Alexey Starikovskiy]

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

Dominik Brodowski wrote:
> Hi,
>
> On Tue, Feb 20, 2007 at 09:24:36PM +0300, Alexey Starikovskiy wrote:
>   
>>> On Mon, Feb 19, 2007 at 08:44:31AM -0500, Dominik Brodowski wrote:
>>>  
>>>       
>>>> On Fri, Feb 16, 2007 at 12:54:55PM -0500, Len Brown wrote:
>>>>    
>>>>         
>>>>>>> acpi_ec_transaction
>>>>>>> acpi_ec_read
>>>>>>> acpi_ec_space_handler
>>>>>>> acpi_ev_address_space_dispatch
>>>>>>> acpi_ex_access_region
>>>>>>> acpi_ex_field_datum_
>>>>>>> acpi_ex_extract_from_field
>>>>>>> ...
>>>>>>> acpi_ex_ns_evaluate
>>>>>>> acpi_ev_execute_reg_method
>>>>>>> acpi_ev_reg_run
>>>>>>> acpi_ns_walk_namespace
>>>>>>> acpi_ev_execute_reg_methods
>>>>>>> acpi_install_address_space_handler
>>>>>>> acpi_ec_start
>>>>>>> acpi_start_single_object
>>>>>>> acpi_device_probe
>>>>>>> really_probe
>>>>>>> ...
>>>>>>> bus_add_driver
>>>>>>> ...
>>>>>>> acpi_ec_init
>>>>>>>          
>>>>>>>               
>>>>> Alexey,
>>>>> Thanks for the fix -- it is applied.
>>>>>
>>>>> Dominik,
>>>>> Did this fix help, or is the problem elsehwere?
>>>>>      
>>>>>           
>>>> Unfortunately, this doesn't solve the issue for me -- now I get a panic 
>>>> with
>>>> EIP at __list_add+0x2d/0x60, with the call trace being
>>>>
>>>> 	...
>>>> 	die
>>>> 	do_page_fault
>>>> 	error_code
>>>> 	__mutex_lock_slowpath
>>>> 	mutex_lock
>>>> 	acpi_ec_transaction
>>>>
>>>> and then the same as above... Will try it out with lockdep disabled.
>>>>    
>>>>         
>>> No, doesn't seem to be lockdep-related; same issue continues. "acpi=off"
>>> fixes the issue, though, of course...
>>>
>>> Thanks,
>>> 	Dominik
>>>  
>>>       
>> Dominik,
>> Could you send your acpidump and full dmesg please?
>>     
>
> http://userweb.kernel.org/~brodo/acpidump.binary
> http://userweb.kernel.org/~brodo/acpidump.txt
> http://userweb.kernel.org/~brodo/acpi-dmsg.txt
>
> Hope this helps,
> 	Dominik
>   
Thanks.
I start to think, that ec is either not fully initialized or freed by 
the time acpi_ec_start is called... Please try if the following patch 
changes something.

Alex.

[-- Attachment #2: 1.diff --]
[-- Type: text/x-patch, Size: 1305 bytes --]

diff --git a/drivers/acpi/ec.c b/drivers/acpi/ec.c
index 16c4ede..b0161fa 100644
--- a/drivers/acpi/ec.c
+++ b/drivers/acpi/ec.c
@@ -92,13 +92,13 @@ static struct acpi_driver acpi_ec_driver
 
 /* If we find an EC via the ECDT, we need to keep a ptr to its context */
 static struct acpi_ec {
+	struct mutex lock;
 	acpi_handle handle;
 	unsigned long uid;
 	unsigned long gpe;
 	unsigned long command_addr;
 	unsigned long data_addr;
 	unsigned long global_lock;
-	struct mutex lock;
 	atomic_t query_pending;
 	wait_queue_head_t wait;
 } *ec_ecdt;
@@ -618,14 +618,12 @@ static int acpi_ec_add(struct acpi_devic
 
 	ec->handle = device->handle;
 	ec->uid = -1;
-	mutex_init(&ec->lock);
 	atomic_set(&ec->query_pending, 0);
 	if (acpi_ec_mode == EC_INTR) {
 		init_waitqueue_head(&ec->wait);
 	}
 	strcpy(acpi_device_name(device), ACPI_EC_DEVICE_NAME);
 	strcpy(acpi_device_class(device), ACPI_EC_CLASS);
-	acpi_driver_data(device) = ec;
 
 	/* Use the global lock for all EC transactions? */
 	acpi_evaluate_integer(ec->handle, "_GLK", NULL, &ec->global_lock);
@@ -661,6 +659,9 @@ static int acpi_ec_add(struct acpi_devic
 			  acpi_device_name(device), acpi_device_bid(device),
 			  (u32) ec->gpe));
 
+	mutex_init(&ec->lock);
+	acpi_driver_data(device) = ec;
+
 	if (!first_ec)
 		first_ec = device;
 

Re: ec locking issue

[Dominik Brodowski]

Hi,

On Wed, Feb 21, 2007 at 01:07:25AM +0300, Alexey Starikovskiy wrote:
> Dominik Brodowski wrote:
> >Hi,
> >
> >On Tue, Feb 20, 2007 at 09:24:36PM +0300, Alexey Starikovskiy wrote:
> >  
> >>>On Mon, Feb 19, 2007 at 08:44:31AM -0500, Dominik Brodowski wrote:
> >>> 
> >>>      
> >>>>On Fri, Feb 16, 2007 at 12:54:55PM -0500, Len Brown wrote:
> >>>>   
> >>>>        
> >>>>>>>acpi_ec_transaction
> >>>>>>>acpi_ec_read
> >>>>>>>acpi_ec_space_handler
> >>>>>>>acpi_ev_address_space_dispatch
> >>>>>>>acpi_ex_access_region
> >>>>>>>acpi_ex_field_datum_
> >>>>>>>acpi_ex_extract_from_field
> >>>>>>>...
> >>>>>>>acpi_ex_ns_evaluate
> >>>>>>>acpi_ev_execute_reg_method
> >>>>>>>acpi_ev_reg_run
> >>>>>>>acpi_ns_walk_namespace
> >>>>>>>acpi_ev_execute_reg_methods
> >>>>>>>acpi_install_address_space_handler
> >>>>>>>acpi_ec_start
> >>>>>>>acpi_start_single_object
> >>>>>>>acpi_device_probe
> >>>>>>>really_probe
> >>>>>>>...
> >>>>>>>bus_add_driver
> >>>>>>>...
> >>>>>>>acpi_ec_init
> >>>>>>>         
> >>>>>>>              
> >>>>>Alexey,
> >>>>>Thanks for the fix -- it is applied.
> >>>>>
> >>>>>Dominik,
> >>>>>Did this fix help, or is the problem elsehwere?
> >>>>>     
> >>>>>          
> >>>>Unfortunately, this doesn't solve the issue for me -- now I get a panic 
> >>>>with
> >>>>EIP at __list_add+0x2d/0x60, with the call trace being
> >>>>
> >>>>	...
> >>>>	die
> >>>>	do_page_fault
> >>>>	error_code
> >>>>	__mutex_lock_slowpath
> >>>>	mutex_lock
> >>>>	acpi_ec_transaction
> >>>>
> >>>>and then the same as above... Will try it out with lockdep disabled.
> >>>>   
> >>>>        
> >>>No, doesn't seem to be lockdep-related; same issue continues. "acpi=off"
> >>>fixes the issue, though, of course...
> >>>
> >>>Thanks,
> >>>	Dominik
> >>> 
> >>>      
> >>Dominik,
> >>Could you send your acpidump and full dmesg please?
> >>    
> >
> >http://userweb.kernel.org/~brodo/acpidump.binary
> >http://userweb.kernel.org/~brodo/acpidump.txt
> >http://userweb.kernel.org/~brodo/acpi-dmsg.txt
> >
> >Hope this helps,
> >	Dominik
> >  
> Thanks.
> I start to think, that ec is either not fully initialized or freed by 
> the time acpi_ec_start is called... Please try if the following patch 
> changes something.

No change, unfortunately.

Thanks,
	Dominik