Bug 57834

Summary: uru4000 power-up race condition
Product: libfprint Reporter: Timo Teräs <timo.teras>
Component: libfprintAssignee: libfprint-bugs
Status: RESOLVED FIXED QA Contact:
Severity: normal    
Priority: medium CC: bugzilla
Version: unspecified   
Hardware: Other   
OS: All   
i915 platform: i915 features:
Attachments: uru4000: fix race condition on waiting power up irq

Description Timo Teräs 2012-12-03 11:22:41 UTC
The power up state machine has a race condition where it can miss the power-up ack interrupt.

I once in a while get the following debug log:

async:debug [fp_async_enroll_start] starting enrollment
fp:debug [generic_acquire_start] action 1
drv:debug [__ssm_call_handler] 0x1558f728 entering state 0
uru4000:debug [sm_read_regs] read 1 regs at 7
uru4000:debug [sm_read_reg_cb] reg value 3
drv:debug [__ssm_call_handler] 0x1558f728 entering state 1
drv:debug [__ssm_call_handler] 0x1558f728 entering state 3
uru4000:debug [sm_set_hwstat] set 83
drv:debug [__ssm_call_handler] 0x1558f728 entering state 4
drv:debug [__ssm_call_handler] 0x15573f00 entering state 0
drv:debug [__ssm_call_handler] 0x15573f00 entering state 1
uru4000:debug [sm_set_hwstat] set 03
drv:debug [__ssm_call_handler] 0x15573f00 entering state 2
uru4000:debug [sm_read_regs] read 1 regs at 7
uru4000:debug [irq_handler] recv irq type 56aa
uru4000:debug [irq_handler] ignoring interrupt
uru4000:debug [sm_read_reg_cb] reg value 0
drv:debug [__ssm_call_handler] 0x15573f00 entering state 3
drv:debug [fpi_ssm_mark_completed] 0x15573f00 completed with status 0
drv:debug [__ssm_call_handler] 0x1558f728 entering state 5
poll:debug [fpi_timeout_add] in 300ms
poll:debug [get_next_timeout_expiry] next timeout in 0.299984s
poll:debug [get_next_timeout_expiry] next timeout in 0.299902s
poll:debug [get_next_timeout_expiry] next timeout in 0.000771s
poll:debug [get_next_timeout_expiry] next timeout in 0.000621s
poll:debug [get_next_timeout_expiry] next timeout in 0.000555s
poll:debug [get_next_timeout_expiry] next timeout in 0.000437s
poll:debug [get_next_timeout_expiry] next timeout in 0.000361s
poll:debug [get_next_timeout_expiry] next timeout in 0.000297s
poll:debug [get_next_timeout_expiry] next timeout in 0.000185s
poll:debug [get_next_timeout_expiry] next timeout in 0.000110s
poll:debug [get_next_timeout_expiry] next timeout in 0.000045s
poll:debug [get_next_timeout_expiry] first timeout already expired
poll:debug [handle_timeout] 
uru4000:warning [init_scanpwr_timeout] powerup timed out

You can see that the proper irq '56aa' came, but it came before INIT_AWAIT_SCAN_POWER state was entered, and thus it got ignored. The code then just times out and ignores the timeout eventually causing additional delays.

It appears that the ordering of the state machine is wrong, it should first arm the IRQ handler, and only after that start fiddling with the power register that triggers the IRQ.

I'm looking if we could get rid of powerup_run_state() alltogether, but it seems like it'd be better to leave it there. Unless someone gets bright ideas, I'll write a patch to arm the IRQ handler in some earlier step than INIT_AWAIT_SCAN_POWER, and modify the irq handling code to work properly regardless of the step during which it is received.
Comment 1 Timo Teräs 2012-12-04 08:53:22 UTC
Created attachment 70989 [details] [review]
uru4000: fix race condition on waiting power up irq

Suggested fix.
Comment 2 Bastien Nocera 2012-12-04 10:55:44 UTC
Thanks for the patch, tested and pushed.

Attachment 70989 [details] pushed as 7e1646c - uru4000: fix race condition on waiting power up irq

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.