Fork us on GitHub Follow us on Facebook Follow us on Twitter

#700 closed defect (fixed)

Deadlock between devman and locsrv

Reported by: Ondra Hlavatý Owned by: Jakub Jermář
Priority: major Milestone:
Component: helenos/srv/locsrv Version:
Keywords: deadlock ipc Cc:
Blocker for: Depends on:
See also:

Description

In yet undiscovered conditions, a deadlock while booting occurs. The kernel is still alive, but devman is stuck and the compositor won't start. It does happen quite frequently on "bad" builds, but "bad" build happens very sparsely. It seems to be a result of a race condition. Also, level of optimization is related - it happens more on optimized builds, never happened with -O0.

In the attached image, you can see the waiting IPC calls. We already discussed on this on IRC and mailing list, but then it happened once again, so here you have the bug report.

There is a cycle, which I haven't noticed at first. It is probably the cause of the deadlock, but I'm not able to identify the root cause myself.

Of course, there is a possibility that our xhci driver is causing it. But in every case, faulty driver should not block devman.

Attachments (4)

helenos-deadlock.svg (12.5 KB) - added by Ondra Hlavatý 19 months ago.
IPC state in the deadlock
ipc.log (10.6 KB) - added by Jakub Jermář 19 months ago.
kconsole log with the output of the ipc command for the essential tasks
tasks.log (3.0 KB) - added by Jakub Jermář 19 months ago.
List of all running tasks
console.log (11.8 KB) - added by Jakub Jermář 19 months ago.
Console output up to the hang

Download all attachments as: .zip

Change History (10)

Changed 19 months ago by Ondra Hlavatý

Attachment: helenos-deadlock.svg added

IPC state in the deadlock

comment:1 Changed 19 months ago by Jakub Jermář

Component: helenos/unspecifiedhelenos/srv/loc
Owner: set to Jakub Jermář
Priority: minormajor
Status: newassigned

With some effort, I was able to reproduce this issue. I get a similar picture of the waiting processes, see the attached log from kconsle for details.

Changed 19 months ago by Jakub Jermář

Attachment: ipc.log added

kconsole log with the output of the ipc command for the essential tasks

Changed 19 months ago by Jakub Jermář

Attachment: tasks.log added

List of all running tasks

Changed 19 months ago by Jakub Jermář

Attachment: console.log added

Console output up to the hang

comment:2 Changed 19 months ago by Jakub Jermář

From the ipc log, I have reconstructed the wait graph.

  1. devman sends DRIVER_DEV_ADD(1024) to ps2mouse
  2. ps2mouse sends DEVMAN_ADD_FUNCTION(1025) to devman
  3. devman grabs device_tree.rwlock in fun_online()
  4. devman enters loc_register_tree_function() and loc_service_register(); sends LOC_SERVICE_REGISTER(1027) to locsrv followed by IPC_M_DATA_WRITE(7); the connection to locsrv is "serialized" and so it uses only a single phone
  5. locsrv does not reply to the LOC_SERVICE_REGISTER request because the fibril which is handling connections from devman is itself blocked
  6. locsrv itself has 4 active LOC_EVENT_CAT_CHANGE(1024) calls to ethip; these had all been sent one after another by drivers that already added themselves into a category, but we don't see them now because event change notifications happen after enlisting in a category is completed (ie. after the request is answered).
  7. ethip is itself not answering any of the four LOC_EVENT_CAT_CHANGE calls from locsrv and blocks on NIC_SET_STATE(NIC_STATE_ACTIVE) to e1k
  8. e1k sends HW_RES_ENABLE_INTERRUPT for IRQ 11 to pciintel
  9. pciintel sends IPC_CONNECT_ME_TO(2) to ns which in turn forwards it to devman
  10. devman tries to handle the call in devman_connection_device(), but gets blocked on the device_tree.rwlock which was locked in step 3 by fun_online()
Last edited 19 months ago by Jakub Jermář (previous) (diff)

comment:3 Changed 19 months ago by Jakub Jermář

So it looks like a driver registered itself in a category at locsrv. This resulted in a "category changed event" notification which transitively depended on devman and its ability to grab the device_tree.rwlock, but in the meantime devman started another request which grabbed device_tree.rwlock and was waiting for the locsrv connection fibril to handle its LOC_SERVICE_REGISTER request. locsrv was thus waiting for devman and devman was waiting for locsrv.

comment:4 Changed 19 months ago by Jakub Jermář

Summary: Randomly occuring IPC deadlock on bootDeadlock between devman and locsrv

comment:5 Changed 19 months ago by Jakub Jermář

I suspect this became reproducible when the interrupt controller drivers were DDFified. Before that pciintel would not go through devman when enabling the interrupt.

In order to fix this, three things are needed:

  1. locsrv needs to be able to process multiple exchanges from devman in parallel, so the devman-to-locsrv exchange type will need to be upgraded to parallel from the current serial;
  2. devman needs to be careful not to end exchanges with locsrv before it receives the answer, otherwise another request might reuse the old phone instead of using a new one, which would again lead to the present deadlock;
  3. the locsrv connection fibril can get blocked even after answering the call from devman in loc_category_change_event() if the limit of maximum async calls per phone (currently 4, see IPC_MAX_ASYNC_CALLS) was reached; we basically need to make sure that when the call is answered the fibril will not block otherwise we will still be getting this deadlock.

As for 3., we might either change the code to return error instead of blocking the fibril if there are more than IPC_MAX_ASYNC_CALLS per phone or try to answer LOC_SERVICE_ADD_TO_CAT only after loc_category_change_event() returns.

comment:6 Changed 19 months ago by Jakub Jermář

Resolution: fixed
Status: assignedclosed
Note: See TracTickets for help on using tickets.