OSK becomes unusable as taps are delayed by 1-2 seconds and vibration doesn't occur any more (although gestures continue to work)

I think I know that it could be!
I think it's the vibration handler!

After inputting the passcode in the greeter, unity8 prints the following lines *after* the 2 secs delay:
org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

And as noted in the bug description, one of the sympthoms was that vibration stopped working.

I think what happened is that the vibrator handler crashed, and on every tap that requires vibration the system is waiting some timeout for the vibrator to reply to the DBus call before timing out.

Those calls are probably synchronous, hence blocking the UI until a reply is received (do we really have to block the UI to vibrate?). But since the other end is probably dead, the phone stalls until the NoReply answer is received, and only then the UI thread gets back in control again.

I "think" I found the culprit.
http://bazaar.launchpad.net/~phablet-team/platform-api/trunk/view/331/src/ubuntu/application/common/application/sensors/service.cpp#L84

It seems the old feedback plugin was async (see https://code.launchpad.net/~kalikiana/qtubuntu-sensors/feedback/+merge/183456 with https://code.launchpad.net/~kalikiana/qtubuntu-sensors/feedback/+merge/183456/comments/431467 and the reply https://code.launchpad.net/~kalikiana/qtubuntu-sensors/feedback/+merge/183456/comments/431975 )

while the new one is using synchronous dbus calls.
http://bazaar.launchpad.net/~phablet-team/platform-api/trunk/view/331/src/ubuntu/application/common/application/sensors/service.cpp#L84

For some reason it seems the dbus service in my case stopped responding to the requests to enable the vibrator, and that was causing the UI thread to block waiting on a reply on dbus.

The new plugin indeed seems to be synchronous - in the UI Toolkit we merely use HapticsEffect.play(), so nothing to do on that side.

Status changed to 'Confirmed' because the bug affects multiple users.

This change to usensord now checks the app permissions to access the sensor on every tap.
http://bazaar.launchpad.net/~phablet-team/usensord/trunk/revision/26
This should use something like an lru cache with the dbus sender id

@andrea I am not experiencing anything close to a 1 sec delay, not really noticing any delay at all
In the description you mention I had Mir touchspots visualization enabled, can you test without that

@Pat this is a bug I accidentally managed to reproduce, not a constant behaviour.

I don't have a way to reproduce it yet. We "just" have a to find a way for the haptics engine dbus call to block, in my case I'm not sure what made that happen, the dbus call was blocking and then returning NoReply.

I tried killing usensord to reproduce the bug, but that didn't help, dbus just errored instantly with a blabla was not provided by any .service files".

Just tidying up. It's usually better to keep the bug title describing what users see. Especially if your diagnosis is wrong... that title then remains correct.

I'd think it'd be useful to also add the actual problem, so we can look it up later when needed. But I don't mind

Reproduced a few times, need to root cause it

My turbo was affected by this yesterday and reboots didn't seem to fix it. I'm guessing usensord was wedged very quickly after startup, I was receiving lots of SMS messages around the time it happened.

Debugging this morning showed the last process that called usensord was telephony-service-indicator, which handles the notifications for SMS/MMS. The log ended with the initial call from telephony-service-indicator, so it appears usensord never replied to that request and was blocked.

After restarting usensord with upstart in my user session, it started responding like normal. I'm trying to reproduce it again to determine if telephony-service-indicator is the trigger.

fwiw I bombarded usensord with direct dbus requests simultaneously and could not reproduce the issue

#!/bin/bash
i=$1
while [ $i -gt 0 ]; do
    dbus-send --session --print-reply --type=method_call --dest='com.canonical.usensord' /com/canonical/usensord/haptic com.canonical.usensord.haptic.Vibrate uint32:500
    ((i--))
    sleep $2
done

Verified it does not trigger a deadlock on stable using the approach of two simultaneous alarms

One of the threads deadlocks inside the haptic handler (which is 100 lines of go, called every time the user e.g. presses the OSK), on a call to dbus (messageBus.Call()). However, dbus seems to function fine, this looks like an internal failure in usensord.

It seems to be deadlocked after calling messagebus.Call
@enwei can you take a look, set two alarms in the clock app for the same minute to reproduce it

I had a quick look at this (I have ZERO Go knowledge though), the code seems to hang at http://bazaar.launchpad.net/~go-dbus/go-dbus/v1/view/136/dbus.go#L303
i.e. waiting for a reply on replyChan

gdb showed that all threads had an infinite chain of futexsleep() except one, that was waiting on epollwait(), and above epollwait() that had a chain of runtime.netpoll().

Hope that helps

Thanks Pat telling me how to reproduce it.
I have reproduced it. I am trying to figuring out the reason and at the same time I wrote to James for help.

Started from Pat's script and found an easier way to reproduce it (note the final ampersand, which is the trick):

cat ./bombard.sh
#!/bin/bash
i=$1
while [ $i -gt 0 ]; do
    dbus-send --session --print-reply --type=method_call --dest='com.canonical.usensord' /com/canonical/usensord/haptic com.canonical.usensord.haptic.Vibrate uint32:100 &
    ((i--))
done

On my MX4 Arale "./bombard.sh 4" is enough to get usensord stuck

Thanks Andrea. I am using a similar way with that of yours, only four commands executed simultaneously.

#!/bin/bash
dbus-send --session --print-reply --type=method_call --dest='com.canonical.usensord' /com/canonical/usensord/haptic com.canonical.usensord.haptic.Vibrate uint32:100 &
dbus-send --session --print-reply --type=method_call --dest='com.canonical.usensord' /com/canonical/usensord/haptic com.canonical.usensord.haptic.Vibrate uint32:100 &
dbus-send --session --print-reply --type=method_call --dest='com.canonical.usensord' /com/canonical/usensord/haptic com.canonical.usensord.haptic.Vibrate uint32:100 &
dbus-send --session --print-reply --type=method_call --dest='com.canonical.usensord' /com/canonical/usensord/haptic com.canonical.usensord.haptic.Vibrate uint32:100 &

I think this could simulate the operation in clock/alarm
I found the rule is that two or more senders(thread or process) calls the dbus function at the same time.
It freezes at below code,
http://bazaar.launchpad.net/~phablet-team/usensord/trunk/view/head:/haptic/haptic.go#L146

Here is the stracktrace of all the goroutines running at http://bazaar.launchpad.net/~go-dbus/go-dbus/v1/view/136/dbus.go#L302

i.e. I printed the stacktrace of all the goroutines right before the "reply := <- replyChan"

(disclaimer: I have 0 Go knowledge so take my words here with a pinch of salt, the method I used comes from http://stackoverflow.com/a/19094539 )

Hi Zhang, more precisely, it seems at least one of the routines gets stuck at waiting for a reply on replyChan

i.e. line 303 (see above)

another stacktrace, this time dispatchMessage does not appear in the list of the calls, just fyi.

It could be that it had already completed or had not started yet, not sure. Just thought I'd share this trace as well

Additional info:

I built usensord on my laptop using
"go run -race usensord.go"
and that did not show any race condition after usensord stalled.

I also tried "go run -race test.go" using the code from https://golang.org/doc/articles/race_detector.html#Introduction
so I think the race detector setup is working, it's just there isn't any race condition in usensord or go-dbus

My laptop has
go version go1.6.2 linux/amd64

Landing:https://requests.ci-train.ubuntu.com/#/ticket/1930
I verified vivid debian package on below images by creating 6 simultaneous alarms that will ring one minute later.
current build number: 827
device name: krillin
channel: ubuntu-touch/rc-proposed/bq-aquaris.en-proposed
last update: 2016-09-09 23:42:32
version version: 827
version ubuntu: 20160907
version device: 20160606-ab415b2
version custom: 20160831-991-38-18

And the race detector correctly showed the data race in test.go, just not in usensord