Closed Bug 923753 Opened 12 years ago Closed 7 years ago

[OTA] Unpacking the downloaded update takes too long

Categories

(Firefox OS Graveyard :: Gaia::System, defect)

Product:
Firefox OS Graveyard
Component:
Gaia::System
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(b2g18 affected)

Status:
RESOLVED WONTFIX
Tracking Flags:
Tracking Status
b2g18 --- affected

People

(Reporter: whimboo, Unassigned)

Details

Gecko http://hg.mozilla.org/releases/mozilla-b2g18/rev/c630289d6388 Gaia 735d9f7871d4352989c54ce7143c8a0163f3418f BuildID 20131003041201 Version 18.0 Device Unagi In the past couple of days I have seen again that the process to unpack an downloaded update takes way too long. As of today I had to do it twice given than an already downloaded update from some days ago was in the queue. For both updates I had to wait about 15 and 25 minutes until the phone unpacked them. That sounds way too long for a zip file of 58MB in size.
So it only took 70 seconds for me. The updater (which does the uncompressing) runs as a separate process and has a very low priority. If there are other apps running which consume most of the CPU, then that would delay the uncompressing.
There might have been other apps running the first time I did the upgrade, but after the first restart and until starting the next upgrade I haven't opened any other application. Not sure if it makes a difference when you turn off the screen. And whenever I'm connecting the phone via USB with my laptop and run adb, I cannot reproduce this problem.
(In reply to Henrik Skupin (:whimboo) from comment #2) > There might have been other apps running the first time I did the upgrade, > but after the first restart and until starting the next upgrade I haven't > opened any other application. Not sure if it makes a difference when you > turn off the screen. And whenever I'm connecting the phone via USB with my > laptop and run adb, I cannot reproduce this problem. ok - that's really useful to know. If I had to guess, I'd be inclined to think that the procssor is entering some type of low power mode. I was able to reproduce a definite slowdown with the USB cable unplugged (it took 4 minutes instead of 70 seconds). With USB cable disconnected and screen off, it took 70 seconds With USB cable disconnected, and leaving the screen on during the entire update, it took 40 seconds to uncompress. With USB cable connected and leaving screen on it took 90 seconds to uncompress With USB cable connected and turning the screen off, it took 60 seconds So it doesn't seem to be directly related to the screen on/off (although there seems to be some impact). I haven't been able to reproduce the 4 minute problem again. I was plugging and unplugging the usb cable to check progress, and also switched between homescreeen/notification/settings as well (when I encountered the 4 minute uncompress). I'm still suspecting that the homescreen or settings app (or something) is consuming CPU and slowing down the updater. Do you have any logcats? The updater prints out progress to logcat that looks like: Progress [ ==== ] Progress [ ===== ] Progress [ ====== ] I was determining my times by taking the difference between the first progress message and the "Finished applying update" message.
I will try daily now to replicate that problem with the OTA update. AFAIR whenever I had this problem I also noticed that the hardware button to turn off/on the phone didn't cause any reaction when pressed. That's similar to an issue we thought to have been fixed a couple of months ago. So it is not fixed for me, and might be an indication that something is indeed running very slowly.
Now that you mention it, I think that when I experienced the 4 minute download, I was also seeing an unresponsive power button. We probably need to implement a monitor daemon of some type which detects high-cpu usage apps and reports them.
I got this non-responsive power button right now. So I plugged in the USB cable and ran the top command via adb shell. So 80% of the cpu load is spent for the updater process: 3359 0 80% S 2 6488K 4864K fg root /data/local/updates/0/updater 993 0 5% S 47 207232K 65480K fg root /system/b2g/b2g As you mentioned it has a lower priority and it should not affect the response time of the phone, but I wonder if that might not be fully true and it indeed causes a problem. I also checked the logcat while the USB cable was plugged in: 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ = ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ == ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ === ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ==== ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ===== ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ====== ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ======= ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ======== ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ========= ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ========== ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ =========== ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ============ ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ============= ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ============== ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ =============== ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ================ ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ================= ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ================== ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ =================== ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ==================== ] 10-09 11:10:42.390 I/GeckoUpdater( 3359): Progress [ ===================== ] 10-09 11:10:45.393 E/GeckoConsole( 993): [JavaScript Error: "ReferenceError: IccHelper is not defined" {file: "app://system.gaiamobile.org/shared/js/mobile_operator.js" line: 9}] 10-09 11:10:46.194 I/GeckoUpdater( 3359): Progress [ ====================== ] 10-09 11:10:46.384 I/GeckoUpdater( 3359): Progress [ ======================= ] 10-09 11:10:48.486 I/GeckoUpdater( 3359): Progress [ ======================== ] 10-09 11:10:51.779 I/GeckoUpdater( 3359): Progress [ ========================= ] 10-09 11:10:53.001 I/GeckoUpdater( 3359): Progress [ ========================== ] 10-09 11:10:54.112 I/GeckoUpdater( 3359): Progress [ =========================== ] 10-09 11:11:09.797 I/Gecko ( 993): 10-09 11:11:09.797 I/Gecko ( 993): ###!!! [Parent][AsyncChannel] Error: Channel error: cannot send/recv 10-09 11:11:09.797 I/Gecko ( 993): 10-09 11:11:09.847 I/Gecko ( 993): [Parent 993] WARNING: waitpid failed pid:2877 errno:10: file ../../../gecko/ipc/chromium/src/base/process_util_posix.cc, line 260 10-09 11:11:11.859 I/Gecko ( 993): [Parent 993] WARNING: waitpid failed pid:2877 errno:10: file ../../../gecko/ipc/chromium/src/base/process_util_posix.cc, line 260 10-09 11:11:11.859 I/Gecko ( 993): [Parent 993] WARNING: Failed to deliver SIGKILL to 2877!(3).: file ../../../gecko/ipc/chromium/src/chrome/common/process_watcher_posix_sigchld.cc, line 118 10-09 11:11:16.584 I/GeckoUpdater( 3359): Progress [ ============================ ] 10-09 11:11:17.024 I/GeckoUpdater( 3359): Progress [ ============================= ] 10-09 11:11:17.415 I/GeckoUpdater( 3359): Progress [ ============================== ] 10-09 11:11:21.888 E/GeckoConsole( 993): [JavaScript Error: "ReferenceError: IccHelper is not defined" {file: "app://system.gaiamobile.org/shared/js/mobile_operator.js" line: 9}] 10-09 11:11:22.818 I/GeckoUpdater( 3359): Progress [ =============================== ] 10-09 11:11:33.283 I/GeckoUpdater( 3359): Progress [ ================================ ] 10-09 11:11:42.808 E/GeckoConsole( 993): [JavaScript Error: "ReferenceError: IccHelper is not defined" {file: "app://system.gaiamobile.org/shared/js/mobile_operator.js" line: 9}] 10-09 11:11:48.720 E/GeckoConsole( 993): [JavaScript Error: "ReferenceError: IccHelper is not defined" {file: "app://system.gaiamobile.org/shared/js/mobile_operator.js" line: 9}] 10-09 11:11:56.838 I/GeckoUpdater( 3359): Progress [ ================================= ] 10-09 11:11:57.449 I/GeckoUpdater( 3359): Progress [ ================================== ] 10-09 11:12:01.873 I/GeckoUpdater( 3359): Progress [ =================================== ] 10-09 11:12:02.373 I/GeckoUpdater( 3359): Progress [ ==================================== ] 10-09 11:12:02.383 I/GeckoUpdater( 3359): Progress [ ===================================== ] 10-09 11:12:02.393 I/GeckoUpdater( 3359): Progress [ ====================================== ] 10-09 11:12:12.684 E/GeckoConsole( 993): [JavaScript Error: "ReferenceError: IccHelper is not defined" {file: "app://system.gaiamobile.org/shared/js/mobile_operator.js" line: 9}] 10-09 11:12:39.760 E/GeckoConsole( 993): [JavaScript Error: "ReferenceError: IccHelper is not defined" {file: "app://system.gaiamobile.org/shared/js/mobile_operator.js" line: 9}] 10-09 11:12:51.491 I/GeckoUpdater( 3359): Progress [ ======================================= ] 10-09 11:12:52.102 I/GeckoUpdater( 3359): Progress [ ======================================== ] 10-09 11:12:52.252 I/GeckoUpdater( 3359): Progress [ ========================================= ] 10-09 11:12:52.883 I/GeckoUpdater( 3359): Progress [ ========================================== ] 10-09 11:12:54.855 I/GeckoUpdater( 3359): Progress [ =========================================== ] 10-09 11:12:56.316 I/GeckoUpdater( 3359): Progress [ ============================================ ] 10-09 11:12:56.556 I/GeckoUpdater( 3359): Progress [ ============================================= ] 10-09 11:12:56.586 I/GeckoUpdater( 3359): Progress [ ============================================== ] 10-09 11:12:56.817 I/GeckoUpdater( 3359): Progress [ =============================================== ] 10-09 11:12:56.837 I/GeckoUpdater( 3359): Progress [ ================================================ ] 10-09 11:12:57.447 I/GeckoUpdater( 3359): Progress [ ================================================= ] 10-09 11:12:57.447 I/GeckoUpdater( 3359): Progress [ ================================================== ] This time the unpacking took 2:17 minutes. But most likely because I disconnected the phone at 11:10:54.112 and re-connected it to USB before 11:12:51.491. As you can see here we have a single unpack step in nearly 40 seconds. I assume if I wouldn't have plugged my phone to the USB port, this step or a follow-up one would have taken longer. Whenever I see it again, I will not have my phone plugged into the USB port before the Restart button appears. I hope that will give us better timing information.
What I find interesting, is that if you look at the timestamps on the updater Progress logs, then for the most part, they're 2 seconds or less apart. In a normal run, I see a single place where there is about a 30 second gap in the progress (I'm hypothesizing that this is where libxul.so is unpacked). In your logcat, The big gaps seem to be where some child process dies and also where a bunch of error messages about IccHelper are occuring. I'm guessing that to get to the bottom of this, we'll need to collect some stats like what top does, but just while we're uncompressing.
That will make it hard given that I was never able to see this problem when I had USB connected. Something nice would be a terminal application for firefox os which I could run while the updater is unzipping the package. Not sure what else I could do.
So I was fast enough to see this time what's most likely causing our system to not respond. As it looks like we have a massive cpu spike for the b2g process before launching the updater. Right after the update has been downloaded, I hit the power button a couple of times without any response. So I quickly plugged in my USB cable and issued 'adb shell top'. Here the output of the first three updates: PID PR CPU% S #THR VSS RSS PCY UID Name 107 0 81% S 47 227308K 80860K fg root /system/b2g/b2g 1755 0 2% D 1 0K 0K fg root kworker/u:0 4107 0 2% S 13 66872K 21188K fg app_4107 /system/b2g/plugin-container 4145 0 1% R 1 1052K 408K fg root top PID PR CPU% S #THR VSS RSS PCY UID Name 4148 0 66% S 2 6488K 4872K fg root /data/local/updates/0/updater 107 0 13% S 47 227308K 80716K fg root /system/b2g/b2g 4145 0 2% R 1 1056K 412K fg root top 28 0 1% S 1 0K 0K fg root kswapd0 PID PR CPU% S #THR VSS RSS PCY UID Name 4148 0 81% S 2 6488K 3616K fg root /data/local/updates/0/updater 107 0 4% S 47 226924K 80040K fg root /system/b2g/b2g 4145 0 1% R 1 1056K 412K fg root top That means that when our core b2g process is heavily loaded, we do no longer respond to the hardware keys. I think that is definitely something which should be improved, and which should not happen. Not sure how deep this is connected to the slowish unpacking of the downloaded update later. So I will check that part most likely tomorrow with the next served update.
It would also be useful to also try top -t (IIRC) which shows the threads within a process.
Somehow I don't get any new update since Oct 11th for my Unagi @ 1.1. Not sure why. Anyone an idea?
I heard that they might be turning off unagi updates. Maybe this finally came about.
I tried with a keon device and I can reproduce it too. If the screen is on at this time, everything hangs and not only the hardware buttons. I wonder if we should separate this out to a new bug. But even with the -t option to top we do not get the detailed information given that b2g is already the thread: $ adb shell top -t User 94%, System 5%, IOW 0%, IRQ 0% User 290 + Nice 7 + Sys 17 + Idle 0 + IOW 0 + IRQ 0 + SIRQ 0 = 314 PID TID PR CPU% S VSS RSS PCY UID Thread Proc 107 107 0 85% R 210852K 72372K fg root b2g /system/b2g/b2g 107 271 0 8% S 210852K 72372K fg root Compositor /system/b2g/b2g 720 720 0 1% R 1088K 476K fg root top top 712 713 0 1% R 6088K 4544K fg root updater /data/local/updates/0/updater
Well that tell us that whatever is consuming the CPU is on the main thread (TID=PID == main thread)
So the next thing to do would be to see if we can grab a profile. ./profile.sh start doestn't work (b2g is restarted as soon as the adb session goes away), so I think we'd need to edit /system/bin/b2g.sh to achieve this. You'd need to add export MOZ_PROFILER_STARTUP=1 somewhere in b2g.sh (probably near the end) before the last line (the exec call). Instructions for editing b2g.sh can be found here: https://developer.mozilla.org/en-US/docs/Mozilla/Firefox_OS/Debugging/Customizing_the_b2g.sh_script
Dave, where do I find this profile.sh? Do I have to use it or can I also use the remote profiler started via my desktop Firefox? Also isn't b2g.sh replaced with an update?
profile.sh can be found in the root of a B2G source tree. https://github.com/mozilla-b2g/B2G/blob/master/profile.sh Our update only updates files in /system/b2g b2g.sh is actually located in /system/bin so it isn't part of an OTA update.
Firefox OS is not being worked on
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.