1041488 - [Dolphin][USB Storage] Dolphin's USB storage takes 16.54 seconds to be detected

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: Gaia::Settings, defect, P2)

Description

[William Hsu [:whsu]]

* Description:
  After enabling the USB storage of Dolphin device, it takes 16.54 seconds to be detected.
  Attach the Buri and Tarako's data. FYI.
  - Buri(v1.4) - 3.47 seconds
  - Tarako - 6.31 seconds

* Reproduction steps:
  1. Launch the settings app
  2. Go to "Storage" -> "Media storage"
  3. Toggle "Share using USB"
  4. Toggle "USB storage"
  5. Check how long will it be detected.

* Expected result:
  Result should be similar to/better than Tarako device.

* Actual result:
  USB storage takes 16.54 seconds to be detected.

* Reproduction build: V1.4 (Dolphin)
 - Gaia      5c9e1e4131d3ac8915ed88b72bb66dc7d97be6a0
 - Gecko     a9ee8ae4cca454deb67405fe07de84e713834e05
 - BuildID   20140707144650
 - Version   30.0

Comment 1

[William Hsu [:whsu]]

I saw the logs.
--- -- - --- -- - --- -- - --- -- - --- -- - --- -- - --- -- - --- -- -
I/AutoMounter(  111): Changing mode from 'Disable' to 'Enable'
D/Vold    (   95): Volume sdcard0 state changing 4 (Mounted) -> 5 (Unmounting)
D/gralloc.scx15(  111): alloc_device_alloc w:256, h:256, format:2 usage:0x133 start
D/gralloc.scx15(  111): the flag 0x4 and the vadress is 0xb114c000 and the size is 0x40000
D/gralloc.scx15(  111): alloc_device_alloc handle:0xaf89be80 end err is 0
D/WCND    (   97): is_cp2_alive_ok: open polling interface: /dev/spipe_wcn0, fd = 11
D/WCND    (   97): is_cp2_alive_ok: loop: /dev/spipe_wcn0 is OK
D/ENGPC   (  119): parse_event: event { 'change', '/devices/platform/sprd-battery.0/power_supply/battery', 'power_supply', '' }
D/ENGPC   (  131): parse_event: event { 'change', '/devices/platform/sprd-battery.0/power_supply/battery', 'power_supply', '' }
D/batterysrv(   98): write 25
D/batterysrv(   98):  to /productinfo/.save_capacity 
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 9, action 0)
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 8, action 0)
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 7, action 0)
D/WCND    (   97): is_cp2_alive_ok: open polling interface: /dev/spipe_wcn0, fd = 11
D/WCND    (   97): is_cp2_alive_ok: loop: /dev/spipe_wcn0 is OK
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 6, action 0)
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 5, action 0)
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 4, action 0)
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 3, action 0)
D/WCND    (   97): is_cp2_alive_ok: open polling interface: /dev/spipe_wcn0, fd = 11
D/WCND    (   97): is_cp2_alive_ok: loop: /dev/spipe_wcn0 is OK
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 2, action 1)
D/ENGPC   (  119): parse_event: event { 'remove', '/devices/virtual/bdi/0:24', 'bdi', '' }
D/ENGPC   (  131): parse_event: event { 'remove', '/devices/virtual/bdi/0:24', 'bdi', '' }
D/Vold    (   95): Volume sdcard0 state changing 5 (Unmounting) -> 1 (Idle-Unmounted)
I/AutoMounter(  111): UpdateState: Volume sdcard0 is nsIVolume::STATE_IDLE
I/AutoMounterSetting(  111): Changing status from 'Disabled' to 'Enabled'

--- -- - --- -- - --- -- - --- -- - --- -- - --- -- - --- -- - --- -- -
Is it a root cause?
- W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 6, action 0)

Comment 2

[thomas tsai]

HiJames: Is it possible that logging is writing to sd card? Can you find one to study why it takes so long to umount sd card. thanks!

Comment 3

[James Zhang (Spreadtrum)]

Maybe it cause by slog, lianxiang, can you check this log?

Comment 4

[Zhou Lianxiang]

I/VolumeManager(  113): Volume sdcard0: changing state from Mounted to Unmounting (4 observers)
E/        (  873): check_available_volume: statfs /storage/sdcard0 return err! [107]
I/Vold    (   95): /mnt/secure/asec sucessfully unmounted
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 9, action 0)
E/ProcessKiller(   95): Process /system/bin/slog (873) has open file /storage/sdcard0/slog/2014-07-29-06-30-05/kernel/0-kernel-06-30-06.log
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 8, action 0)
E/ProcessKiller(   95): Process /system/bin/slog (873) has open file /storage/sdcard0/slog/2014-07-29-06-30-05/kernel/0-kernel-06-30-06.log
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 7, action 0)
E/ProcessKiller(   95): Process /system/bin/slog (873) has open file /storage/sdcard0/slog/2014-07-29-06-30-05/kernel/0-kernel-06-30-06.log
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 6, action 0)
E/ProcessKiller(   95): Process /system/bin/slog (873) has open file /storage/sdcard0/slog/2014-07-29-06-30-05/kernel/0-kernel-06-30-06.log
E/        (  873): check_available_volume: statfs /storage/sdcard0 return err! [107]
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 5, action 0)
E/ProcessKiller(   95): Process /system/bin/slog (873) has open file /storage/sdcard0/slog/2014-07-29-06-30-05/kernel/0-kernel-06-30-06.log
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 4, action 0)
E/ProcessKiller(   95): Process /system/bin/slog (873) has open file /storage/sdcard0/slog/2014-07-29-06-30-05/kernel/0-kernel-06-30-06.log
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 3, action 0)
E/ProcessKiller(   95): Process /system/bin/slog (873) has open file /storage/sdcard0/slog/2014-07-29-06-30-05/kernel/0-kernel-06-30-06.log
W/Vold    (   95): Failed to unmount /storage/sdcard0 (Device or resource busy, retries 2, action 1)
E/ProcessKiller(   95): Process /system/bin/slog (873) has open file /storage/sdcard0/slog/2014-07-29-06-30-05/kernel/0-kernel-06-30-06.log
I/Vold    (   95): /storage/sdcard0 sucessfully unmounted
I/Vold    (   95): /mnt/media_rw/sdcard0 sucessfully unmounted
I/Vold    (   95): /mnt/media_rw/sdcard0 unmounted successfully
-----------
I got the above log, it shows that the the slog block the umount.
There is no retry after I stop slog.

It will take usleep(1000*1000) every retry, so those retries will take about 10s.
Maybe the Umount function is too soft to kill it until retry 8 or 9 times.

"stop slog" can avoid the long wait.

Comment 5

[Wayne Chang [:wchang]]

please ensure slog is disabled when shipping

Comment 6

[Zhou Lianxiang]

(In reply to Wayne Chang [:wchang] from comment #5)
> please ensure slog is disabled when shipping

There's no slog on the user version.

Comment 7

[thomas tsai]

So should this bug be closed without fixed?

Comment 8

[BMO Automation]

Firefox OS is not being worked on