Camera app takes 1 minute to load

[Jean-Baptiste Lallement]

current build number: 2
device name: krillin
channel: ubuntu-touch/ubuntu-rtm/14.09
last update: 2014-09-24 20:28:13
version version: 2
version ubuntu: 20140924
version device: 20140919-1b3e670
version custom: 1411084873

After a moment with the phone, the camera-app takes up to one minute to load. Immediately after a reboot it just takes a few seconds.

When it happens the spinner is spinning for a few seconds, then everything hangs (UI stops responding, launcher, panel and switcher doesn't work) and after one minute or so the camera eventually starts and shell is back to normal operations.

When it starts happening once, only a reboot makes the camera behave properly again.

[Jean-Baptiste Lallement (jibel)]

logs from /home/phablet/.cache/upstart/

[Jean-Baptiste Lallement (jibel)]

syslog when this happens
====
Sep 26 13:35:34 ubuntu-phablet kernel: [55380.601359] (1)[12860:camera-app]type=1400 audit(1411731334.140:206): apparmor="DENIED" operation="chmod" profile="com.ubuntu.camera_camera_3.0.0.387" name="/run/user/32011/" pid=12860 comm="camera-app" requested_mask="w" denied_mask="w" fsuid=32011 ouid=32011
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.004419] (0)[1554:Binder_1][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045373, 0 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.004507] (0)[1554:Binder_1][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045364, 3e8 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.010059] (0)[898:camera_service][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045373, 0 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.010145] (0)[898:camera_service][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045364, 3e8 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.015923] (1)[4382:Binder_2][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045373, 0 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.016009] (1)[4382:Binder_2][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045364, 3e8 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.022200] (0)[1554:Binder_1][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045373, 0 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.022287] (0)[1554:Binder_1][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045364, 3e8 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.029548] (0)[898:camera_service][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045373, 0 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.029639] (0)[898:camera_service][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045364, 3e8 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.187282] (1)[1554:Binder_1][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045373, 0 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.187340] (1)[1554:Binder_1][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045364, 3e8 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.289895] (1)[12901:3ATHREAD][FM50AF] FM50AF_Open - Start
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.289922] (1)[12901:3ATHREAD][FM50AF] g_sr 5, write common eca3
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.290281] (1)[12901:3ATHREAD][FM50AF] g_sr 5, write common a10d
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.290648] (1)[12901:3ATHREAD][FM50AF] g_sr 5, write common f200
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.291010] (1)[12901:3ATHREAD][FM50AF] g_sr 5, write common dc51
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.291846] (0)[12901:3ATHREAD][FM50AF] FM50AF_Open - End
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.292750] (0)[12901:3ATHREAD][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045373, 0 +
Sep 26 13:35:34 ubuntu-phablet kernel: [55381.292806] (0)[12901:3ATHREAD][KD_CAMERA_FLASHLIGHT]flashlight_ioctl: XXflashlight_ioctl cmd,arg= 80045364, 3e8 +
Sep 26 13:35:34 ubuntu-phablet kernel...

[Jean-Baptiste Lallement (jibel)]

added a unity8 task because the shell must not hang when the camera starts

[kevin gunn (kgunn72)]

You can't expect unity8 to not hang when you've got kernel problems.
that's not realistic.

[Jean-Baptiste Lallement (jibel)]

Still happening on krillin with latest promotion 14.09 #3, please set it to critical.

[Florian Boucault (fboucault)]

@kevin: who said anything about kernel problems?

[Brendan Donegan (brendan-donegan)]

Okay I isolated reproduction steps for this. Basically when the device is booted, run top and see if ubuntu-location and/or posclientd is using 100%(ish) CPU. If it is then the bug should definitely be reproducible, if not then go to system settings and 'Erase & Reset Everything'. Rinse and repeat until you can reproduce the bug.

This seems to indicate the issue is some kind of race condition in ubuntu-location which causes it to get stuck in a hard loop - then it will never respond to the request from the trust store or whatever is talking to it and that will hang until it times out.

[Jean-Baptiste Lallement (jibel)]

I could reproduce on 14.09 #3 after going outside and the phone switch from Wifi to 3G. Then even back on wifi, the camera takes a very long time to load. Only a reboot fixes it.

[Jean-Baptiste Lallement (jibel)]

But it is apparently not the only condition. I'll continue searching a test case.

[Florian Boucault (fboucault)]

For now I'll mitigate that issue greatly by fixing https://bugs.launchpad.net/qtubuntu-sensors/+bug/1377272

[Joe Odukoya (jodukoya)]

This should be considered critical given that:

1 - We will be judged by camera use cases by our launch partners and end users (it has already been highlighted in the feedback from beta testers)

2- Performance is an area we need to be improving across the board.

3 - During this startup period the whole UI freezes (including blocking emergency calls)

[Alexander Sack (asac)]

bumped camera-app task to critical on request by joe/victorp.

[Thomas Voß (thomas-voss)]

While location service or posclientd using a 100% CPU might worsen the situation, I do not think that it is the gist of this bug.
In addition, the syslog pasted in #2 clearly shows that the trust and location frameworks respond promptly:

Sep 26 13:35:37 ubuntu-phablet core::trust::Daemon::Skeleton[2926]: CachedAgent::authenticate_request_with_parameters: Application pid: 12860 Application uid: 32011 Application id: com.ubuntu.camera_camera Cached request: Request(from: com.ubuntu.camera_camera, feature: 0, when: 1411031800823960984, answer: granted)

With:

Sep 26 13:35:34 ubuntu-phablet kernel: [55380.601359] (1)[12860:camera-app]type=1400 audit(1411731334.140:206): apparmor="DENIED" operation="chmod" profile="com.ubuntu.camera_camera_3.0.0.387" name="/run/user/32011/" pid=12860 comm="camera-app" requested_mask="w" denied_mask="w" fsuid=32011 ouid=32011

roughly indicating the start of the app. With that, I remove location-service from the list of affected projects.

As Kevin pointed out: The entire GL pipeline stalling for a few seconds hints towards a deeper underlying issue. The numerous ioctls logged by the camera driver/camera service might give us a good idea of what is going wrong.

If someone manages to reproduce reliably, please add the output of sudo /system/bin/logcat to this bug report. Filing against

[Jean-Baptiste Lallement (jibel)]

logcat from the moment I launched the camera app to the moment it is running, including the time during which unity8 is frozen (more than one minute)

[Thomas Voß (thomas-voss)]

Nothing too obvious is visible from logcat. With that, we should start instrumenting the android CameraService.

[Florian Boucault (fboucault)]

Partial trace points to a lock in libusermetrics when gettext fails for unknown reasons: http://paste.ubuntu.com/8558758/

[Launchpad Janitor (janitor)]

This bug was fixed in the package trust-store - 1.1.0+14.10.20141015-0ubuntu1

---------------
trust-store (1.1.0+14.10.20141015-0ubuntu1) utopic; urgency=low

  [ Ubuntu daily release ]
  * debian/libtrust-store1.symbols: auto-update to released version

  [ thomas-voss ]
  * Add an agent implementation that allows for selectively whitelisting
    certain apps. (LP: #1374577)
  * Do not prompt or cache accesses being issued by the camera app. (LP:
    #1374397)
 -- Ubuntu daily release <email address hidden> Wed, 15 Oct 2014 18:23:41 +0000

[Bill Filler (bfiller)]

Marking camera-app side of the bug invalid. It's been determined that the issue lies with the libusermetrics and it's interaction with getText and unity is causing the hang

[Bill Filler (bfiller)]

attaching logs from Victor on his most recent hang with image 114

[Launchpad Janitor (janitor)]

This bug was fixed in the package libusermetrics - 1.1.1+14.10.20141020-0ubuntu1

---------------
libusermetrics (1.1.1+14.10.20141020-0ubuntu1) utopic; urgency=low

  [ Ubuntu daily release ]
  * debian/libusermetricsoutput1.symbols: auto-update to released
    version
  * debian/libusermetricsinput1.symbols: auto-update to released version

  [ Pete Woods ]
  * Run gettext on a background thread, communicating asynchronously
    (LP: #1374397)
 -- Ubuntu daily release <email address hidden> Mon, 20 Oct 2014 15:19:31 +0000