[DEV/DEBUG] CM11 debug thread for Falcon

[pinguijxy]

Thank you @Jocker111, the main problem with this issue is that we didn't find (yet) the culprit...

That "Lost RAM" increase, then decrease a little, increase again (on my side at least) and that wouldn't be a real problem if it did not take this enormous amount of RAM as you describe (until now, i never got more than 160MB "lost")

We all need to investigate in different directions to remove false positive and silly hypothesis, and then brain storm a little and see what anyone could find.

So I am able to reproduce the lag and lost RAM as well. I am now checking dumpsys frequently and came to the following.

On Milestone build Lost RAM
Day 1:
444618 kb (after ~1 day)
474107 kb (20min later)
453964 kb (20min later; no app used in between)
~500000 kb (phone becomes unusable and I need to reboot)

Day 2:
-692 kb (after reboot)
148184 kb (after mild use of messaging)
346315 kb (after streaming Spotify)


Apps used:
-WhatsApp
-Facebook
-XDA Premium
-Spotify
-Twitter
-Google Now
-No graphics intense apps
​

I am frequently switching networks and carry my phone with me all the time. I am within the same area but switch between university wifi, friend's places and my home network. I am using the Google Now Launcher (GNL). Disabled the built-in browser.

That is all I can come up with so far. I will keep an eye on the lost RAM and try to connect it more to the Apps I am using. So far the lag (redrawing GNL, app icons aso.) starts ~400000kb lost and the phone gets unresponsive shortly after (I guess ~500000kb; cannot confirm since the terminal doesn't respond anymore). I will note down time and place for future logs.

 

[matmutant]

GPS fix issue

regarding a bug suspicion for GPS, @andyrtr is providing the following infos :

every few minutes GPS signal losses. Signal comes back after some dropout time. That's annoying when doing car navigation with OSMand or waze
[...]
It's an issue I have only with all recent CM11 nightlies with my XT1032.

I'm haven't seen any GPS related bugs since mid february when gps was "fixed" for moto g.

i read the log a little, and extracted the following :

03-18 18:43:55.966 V/de.blitzer.application.BlitzerApplication(7126): GPS-Fix-Detection: GPS_EVENT_SATELLITE_STATUS: 2 / 21 / 255

03-18 18:43:55.974 V/de.blitzer.application.BlitzerApplication(7126): GPS-Fix-Detection: GPS_EVENT_SATELLITE_STATUS: 2 / 21 / 255

03-18 18:43:55.975 V/de.blitzer.application.BlitzerApplication(7126): GPS-Fix-Detection: Location received, but less than 10.0m away.

03-18 18:43:55.985 V/de.blitzer.application.BlitzerApplication(7126): GPS-Fix-Detection: Provider gps changed status to AVAILABLE, satellites: 2

03-18 18:43:55.986 V/de.blitzer.application.BlitzerApplication$CheckSpeedTask$1(7126): Not fast enough, decreasing report button counter

03-18 18:43:55.986 D/Blitzer.De FCD Library(7126): adding new location from gps provider;  long: XXXXXXXXXXX,  lat: XXXXXXXXXXX, bearing: 0.0, accuracy: 58.0

03-18 18:43:56.061 I/GPSInfoHelper(7126): playGPSStatusChange for the status: GPS_PLUS

03-18 18:43:56.061 I/GPSInfoHelper(7126): playGPSStatusChange OptionsHolder: OptionsHolder{online=true, warnSolidCams=true, warnMobileCams=true, warnDangerCams=true, gpsSound=true, voiceSounds=true, logHttpConnections=false, downloadOfStaticDBDone=false, reportSelected=false, lastDistancePerSoundReported=0, lastDistancePerVibrationReported=0, reportButtonAvailable=false, splitScreen=true, supportsLandscape=false, preferPhoneSpeaker=false, speedDisplay=0, behaviourAtClosing=0, noWarningGraphic=0, supportsNoWarningGraphicSelection=false, contributeWhenNotMoving=false, fcdAccountKey='Blitzer.de-Android-free', vibration=false, bluetoothHFPEnabled=false, warningSoundDuringChall=true, useStatsApi=false, maximumAgeOfMobileDBInMilliseconds=43200000, onlineObservers=[]}

03-18 18:43:56.062 I/GPSInfoHelper(7126): playGPSStatusChange GPSStatusHolder: GPSStatusHolder{lastGPSStatusDate=Tue Mar 18 18:43:56 MEZ 2014, lastGPSStatus=GPS_PLUS}

03-18 18:43:56.062 I/GPSInfoHelper(7126): MyMediaPlayer is playing?: false

03-18 18:43:56.062 I/GPSInfoHelper(7126): MyMediaPlayer is looping?: false

Does anybody else have an issue with GPS?

 

[Jocker111]

Hm, that might be interesting (or a false positive)

  359     1012K     300K      61K      56K  /system/bin/servicemanager
  234      940K     316K      49K      44K  /system/bin/batt_health
  535     4192K     376K      36K      28K  /system/bin/subsystem_ramdump
  538      664K      12K       8K       8K  /system/xbin/su
                           ------   ------  ------
                          283337K  240224K  TOTAL

RAM: 901632K total, 24544K free, 1932K buffers, 141116K cached, 1180K shmem, 40764K slab
[email protected]_umts:/ # killall subsystem_ramdump                                 
[email protected]_umts:/ # free                                                      
             total         used         free       shared      buffers
Mem:        901632       876988        24644            0         1932
-/+ buffers:             875056        26576
Swap:       393212        15496       377716
[email protected]_umts:/ # killall servicemanager
[email protected]_umts:/ # free                                                      
             total         used         free       shared      buffers
Mem:        901632       636352       265280            0         2028
-/+ buffers:             634324       267308
Swap:       393212         8060       385152
[email protected]_umts:/ # free                                                      
             total         used         free       shared      buffers
Mem:        901632       829672        71960            0         3688

so killing servicemanager brought back 200mb, but they were filled directly again, and phone does not work now anymore (error message: com.android.systemui has stopped).

Rebooting the phone now, so tomorrow I can try the next round of killing applications

 

[ig0r260892]

lock screen in landscape

0317 build
bug: if I lock the phone while some app is running in landscape mode this is what i get when i try to wake it:

workaround: lock and unlcok and it's back normal

 

[michalurban]

regarding a bug suspicion for GPS

Just fyi ... Myself, I never use GPS, only GSM positioning. And the rambug is still appearing.

 

[ph4zrd]

so killing servicemanager brought back 200mb, but they were filled directly again, and phone does not work now anymore (error message: com.android.systemui has stopped).

Rebooting the phone now, so tomorrow I can try the next round of killing applications

I think it's perfectly normal. Killing servicemanager terminates a lot of other processes that depend on it. Then the OS will try to restart them which fills the memory again.
FYI: Sometimes killing surfaceflinger seems to free ~50 MB of "Lost RAM" in my experience.

I will try some git-revert voodoo on my local repo now.

Would be good if someone can confirm definitely when the bug first happened.
Is there a mirror for older cm builds like 20140224?

 

[Jocker111]

Heureka, I found a way to increase memory usage like hell: Just press the button for unlocking (no need to unlock or anything else).
Just did it 20 times in a row and Lost RAM went up from 50mb to no 150mb.
The only thing I do right now is pressing one button, screen turns on --> memory is lost.
Turning the screen off with the same button, does not seem to change lost memory...

btw: Lost memory increases significantly by about 5mb per cycle

EDIT: Repeated the procedure, I'm now at 500mb lost memory in just a couple of minutes. Killing surfaceflinger did not give back the lost memory, it's still at 430mb (yes some ram came back, but phone is mainly unusable now)

 

[matmutant]

Heureka, I found a way to increase memory usage like hell: Just press the button for unlocking (no need to unlock or anything else).
Just did it 20 times in a row and Lost RAM went up from 50mb to no 150mb.
The only thing I do right now is pressing one button, screen turns on --> memory is lost.
Turning the screen off with the same button, does not seem to change lost memory...

btw: Lost memory increases significantly by about 5mb per cycle

pressing power button to light the screen ?
tried many time, no way to replicate :/ (i mean there is no significant increase of lost memory, i agree it increase, but not that much so i cannot assert this is a cause)
but, which is your unlock method ? patern, face unlock, slide-to-unlock ? ... ? what kind of widget do you have on lockscreen ?

there are so much things that can be user-modified...


edit :
Lost RAM 176763kB (add a pic at 180000+ kB)
uptime : 1 day 10hrs 30 minutes

 

[Jocker111]

Yes pressing the power button to light the screen.

I guess I have a pretty standard setup in the lock screen. I can see the WiFi icon, the battery charging icon, the mobile connectivity icon, the Xabber icon, and the Adb debug icon in the notification bar.

Then there is the digital clock with the current weather for my location, and the unlock method is pattern unlock, i.e. I see 3x3 field of these circles.

Still reproducable here... Thats the output of one full cycle from logcat (full cycle = power button --> screen turns on --> power button --> screen turns off)

03-19 08:55:26.436: I/PowerManagerService(977): Waking up from sleep...
03-19 08:55:26.437: D/Sensors(977): AccelerationSensor: Set Sensors state 0x1
03-19 08:55:26.437: D/Sensors(977): AccelerationSensor: set delay 66
03-19 08:55:26.438: D/Sensors(977): AccelerationSensor: set delay 66
03-19 08:55:26.438: D/Sensors(977): AccelerationSensor: set delay 66
03-19 08:55:26.474: E/Sensors(977): CT406 set ALS poll interval: 1000
03-19 08:55:26.487: E/Sensors(977): CT406 set ALS poll interval: 1000
03-19 08:55:26.488: E/Mot8226 PowerHAL(977): Error opening /sys/devices/system/cpu/cpufreq/interactive/target_loads: No such file or directory
03-19 08:55:26.488: E/Mot8226 PowerHAL(977): Error opening /sys/devices/system/cpu/cpufreq/interactive/go_hispeed_load: No such file or directory
03-19 08:55:26.488: D/SurfaceFlinger(359): Screen acquired, type=0 flinger=0xb778a4e0
03-19 08:55:26.488: D/qdhwcomposer(359): hwc_blank: Unblanking display: 0
03-19 08:55:26.839: D/qdhwcomposer(359): hwc_blank: Done unblanking display: 0
03-19 08:55:26.848: D/SurfaceControl(977): Excessive delay in unblankDisplay() while turning screen on: 357ms
03-19 08:55:26.917: W/ActivityManager(977): getAssistContextExtras failed: no resumed activity
03-19 08:55:26.942: I/WindowManager(977): Lock screen displayed!
03-19 08:55:26.984: D/audio_hw_primary(364): adev_set_parameters: enter: screen_state=on
03-19 08:55:26.987: D/wpa_supplicant(1311): RX ctrl_iface - hexdump(len=11): 53 49 47 4e 41 4c 5f 50 4f 4c 4c
03-19 08:55:26.987: D/wpa_supplicant(1311): wlan0: Control interface command 'SIGNAL_POLL'
03-19 08:55:26.990: D/YouTube MDX(2461): Recieved intent android.intent.action.SCREEN_ON
03-19 08:55:26.999: D/wpa_supplicant(1311): nl80211: survey data missing!
03-19 08:55:27.001: D/wpa_supplicant(1311): RX ctrl_iface - hexdump(len=23): 44 52 49 56 45 52 20 53 45 54 53 55 53 50 45 4e 44 4d 4f 44 45 20 30
03-19 08:55:27.001: D/wpa_supplicant(1311): wlan0: Control interface command 'DRIVER SETSUSPENDMODE 0'
03-19 08:55:27.021: D/wpa_supplicant(1311): wpa_driver_nl80211_driver_cmd SETSUSPENDMODE 0 len = 0, 4096
03-19 08:55:28.909: I/PowerManagerService(977): Going to sleep by user request...
03-19 08:55:28.989: D/SurfaceFlinger(359): Screen released, type=0 flinger=0xb778a4e0
03-19 08:55:28.989: D/qdhwcomposer(359): hwc_blank: Blanking display: 0
03-19 08:55:29.001: D/Sensors(977): AccelerationSensor: Set Sensors state 0x0
03-19 08:55:29.288: D/qdhwcomposer(359): hwc_blank: Done blanking display: 0
03-19 08:55:29.288: D/SurfaceControl(977): Excessive delay in blankDisplay() while turning screen off: 299ms
03-19 08:55:29.318: E/Mot8226 PowerHAL(977): Error opening /sys/devices/system/cpu/cpufreq/interactive/target_loads: No such file or directory
03-19 08:55:29.318: E/Mot8226 PowerHAL(977): Error opening /sys/devices/system/cpu/cpufreq/interactive/go_hispeed_load: No such file or directory
03-19 08:55:29.422: D/audio_hw_primary(364): adev_set_parameters: enter: screen_state=off
03-19 08:55:29.425: D/wpa_supplicant(1311): RX ctrl_iface - hexdump(len=23): 44 52 49 56 45 52 20 53 45 54 53 55 53 50 45 4e 44 4d 4f 44 45 20 31
03-19 08:55:29.425: D/wpa_supplicant(1311): wlan0: Control interface command 'DRIVER SETSUSPENDMODE 1'
03-19 08:55:29.429: D/YouTube(2461): apps.youtube.app.prefetch.g.onReceive:366 Received: android.intent.action.SCREEN_OFF
03-19 08:55:29.431: D/YouTube MDX(2461): Recieved intent android.intent.action.SCREEN_OFF
03-19 08:55:29.441: D/wpa_supplicant(1311): wpa_driver_nl80211_driver_cmd SETSUSPENDMODE 1 len = 0, 4096

 

[hydromän]

With 18/03 Not perfect, but a way better for me

Gesendet von meinem Moto G mit Tapatalk

 

[Jocker111]

Changing Lock Screen settings to None (i.e. no screen security at all, the problem is still persistent)

The logcat output for one screen turn on is:

03-19 09:12:01.656: I/PowerManagerService(994): Waking up from sleep...
03-19 09:12:01.665: E/Sensors(994): CT406 set ALS poll interval: 1000
03-19 09:12:01.669: E/Sensors(994): CT406 set ALS poll interval: 1000
03-19 09:12:01.669: D/Sensors(994): AccelerationSensor: Set Sensors state 0x1
03-19 09:12:01.669: D/Sensors(994): AccelerationSensor: set delay 66
03-19 09:12:01.670: D/Sensors(994): AccelerationSensor: set delay 66
03-19 09:12:01.670: D/Sensors(994): AccelerationSensor: set delay 66
03-19 09:12:01.679: D/YouTube(2318): apps.youtube.app.prefetch.g.onReceive:366 Received: android.intent.action.USER_PRESENT
03-19 09:12:01.683: I/WindowManager(994): No lock screen! windowToken=null
03-19 09:12:01.687: E/Mot8226 PowerHAL(994): Error opening /sys/devices/system/cpu/cpufreq/interactive/target_loads: No such file or directory
03-19 09:12:01.687: E/Mot8226 PowerHAL(994): Error opening /sys/devices/system/cpu/cpufreq/interactive/go_hispeed_load: No such file or directory
03-19 09:12:01.687: D/SurfaceFlinger(361): Screen acquired, type=0 flinger=0xb8d8e4e0
03-19 09:12:01.687: D/qdhwcomposer(361): hwc_blank: Unblanking display: 0
03-19 09:12:02.033: D/qdhwcomposer(361): hwc_blank: Done unblanking display: 0
03-19 09:12:02.040: D/SurfaceControl(994): Excessive delay in unblankDisplay() while turning screen on: 352ms
03-19 09:12:02.107: I/ActivityManager(1457): Timeline: Activity_idle id: [email protected] time:260228
03-19 09:12:02.175: D/audio_hw_primary(368): adev_set_parameters: enter: screen_state=on
03-19 09:12:02.179: D/YouTube MDX(2318): Recieved intent android.intent.action.SCREEN_ON

Also tried to close ALL apps (i.e. going to Settings --> Apps --> closed all apps listed there), still problem persists. Every time I press the power button the lost memory increases...

The youtube message from above can also be ignored, since I uninstalled now youtube but, the problem did not disappear... Will try with a complete freshly flashed

 

[matmutant]

03-19 09:12:01.687: E/Mot8226 PowerHAL(994): Error opening /sys/devices/system/cpu/cpufreq/interactive/target_loads: No such file or directory
03-19 09:12:01.687: E/Mot8226 PowerHAL(994): Error opening /sys/devices/system/cpu/cpufreq/interactive/go_hispeed_load: No such file or directory

what's the result of this line using ONDEMAND governor ?

 

[Jocker111]

I was by that time on the ondemand governor...

 

[matmutant]

I was by that time on the ondemand governor...

:-\
i don't know if PowerHAL has anything to do with our "Lost RAM" issue, but it does have a problem

 

[Jocker111]

Ok, just flashed a completely fresh CM11-nightly http://download.cyanogenmod.com/get/jenkins/62515/cm-11-20140319-NIGHTLY-falcon.zip


The RAM bug is directly there after a fresh install... no customization done yet, no apps installed, nothing... (nothing is not completely true, since I had to enter the settings --> About Phone --> Unlock developer mode --> Allow USB debugging in the developer settings)

How does it show up:
- Pressing the power button
- The screen turns on
- An animation starts (circle from the lock in the middle to the outside)
- Ram is lost
- Pressing the power button
- Screen turns off

How does it not show off (or rarely):
- Pressing the power button
- The screen turns on
- The animation starts
- The animation does NOT finish before the power button is pressed again
- The screen turns off
- No RAM is lost (or very rarely some memory is lost)

This leads me to the conclusion, that it must be something that is happening after the ScreenOn animation actually finishes.

Fresh install and I'm able to fill the Lost RAM to 350mb in about 2min by just pressing the power button...

Logcat message, when I press the power button to turn on the screen:

03-24 10:24:45.991: I/PowerManagerService(1246): Waking up from sleep...
03-24 10:24:45.992: D/Sensors(1246): AccelerationSensor: Set Sensors state 0x1
03-24 10:24:45.992: D/Sensors(1246): AccelerationSensor: set delay 66
03-24 10:24:45.992: D/Sensors(1246): AccelerationSensor: set delay 66
03-24 10:24:45.993: D/Sensors(1246): AccelerationSensor: set delay 66
03-24 10:24:46.010: E/Sensors(1246): CT406 set ALS poll interval: 1000
03-24 10:24:46.019: E/Sensors(1246): CT406 set ALS poll interval: 1000
03-24 10:24:46.020: E/Mot8226 PowerHAL(1246): Error opening /sys/devices/system/cpu/cpufreq/interactive/target_loads: No such file or directory
03-24 10:24:46.020: E/Mot8226 PowerHAL(1246): Error opening /sys/devices/system/cpu/cpufreq/interactive/go_hispeed_load: No such file or directory
03-24 10:24:46.021: D/SurfaceFlinger(385): Screen acquired, type=0 flinger=0xb84ab4e0
03-24 10:24:46.021: D/qdhwcomposer(385): hwc_blank: Unblanking display: 0
03-24 10:24:46.360: D/qdhwcomposer(385): hwc_blank: Done unblanking display: 0
03-24 10:24:46.362: D/SurfaceControl(1246): Excessive delay in unblankDisplay() while turning screen on: 341ms
03-24 10:24:46.400: I/WindowManager(1246): Lock screen displayed!

Governor is still ondemand (didn't change it actually)

In my oppinion it is not the PowerHAL problem, because of the above observation, that fast power-button pressing does not loose memory, so there must be a time delay on what happens. Only the last three messages are really delayed in time, the rest is happening directly after pressing the power button

 

[angellgtz]

I can reproduce the bug by turning on the screen like @Jocker111 and its very fast how the lost ram increase : O

Enviado desde mi Moto G mediante Tapatalk

 

[matmutant]

Analysis seems good, but i cannot replicate, i followed your protocol step after step
Though lost RAM is increasing until reaching 180000+ and then decreases or stays there (note i'm using CM11-20140317-Nightly on top of PinkKernel-exp-20140317, Intelliactive gov, fiops, intelliplug and Ecomode enabled, multicore power saving, KSM enabled ==> i use Performance Control app shared by @pinkflozd )

Could you please try using same kind of settings ?

 

[Jocker111]

No change. Installed pink kernel 20140317 and set everything as you said. right now I have 270mb lost ram. No change at all with these settings / this kernel

 

[pinguijxy]

Analysis seems good, but i cannot replicate, i followed your protocol step after step
Though lost RAM is increasing until reaching 180000+ and then decreases or stays there (note i'm using CM11-20140317-Nightly on top of PinkKernel-exp-20140317, Intelliactive gov, fiops, intelliplug and Ecomode enabled, multicore power saving, KSM enabled ==> i use Performance Control app shared by @pinkflozd )

Could you please try using same kind of settings ?

No change. Installed pink kernel 20140317 and set everything as you said. right now I have 270mb lost ram. No change at all with these settings / this kernel

Seems like it is some kind of device related difference. I am using the German o2 version and have the RAM bug. I think it is the xt1032.


Sent from my Moto G using XDA Premium 4 mobile app

 

[Jocker111]

I'm also using the XT1032