Android Dalvik and ART GC(Garbage Collection) logs Analysis

Hello Guys!!! Hope you all are doing well.!!!!!!

Today I am going to discuss GC logs analysis in android. In my previous blog we have discuss android general log analysis. But today topic is concentrated on GC log analysis.
Memory utilization in Android device(let say mobile phone device) is utterly important topic from the beginning of time. Now a day We have high end mobile phone with much memory(RAM) compare to initial day. But still Memory utilization on the mobile app has a significant impact on the customer experience.

Let assume If any app creates a lot of objects during uses, then Garbage Collection (GC) process will be triggered frequently to evict unused objects. As we know Garbage Collection is an automatic process in Android/Java to free-up unused memory, however, frequent Garbage Collection consumes a lot of CPU + it will also pause the app. Frequent pauses can junk the app (i.e. stuttering, juddering, or halting).
Whenever a GC event runs, a log line is printed in the run-time log messages. So by closely monitoring run-time logs or say collected logs file we can understand how many objects by an app is creating, how frequently Garbage collection is triggered, how much time it takes to complete, how much memory is reclaimed after every event.
GC log line format varies based on whether app runs on Dalvik VM or Android Run Time (ART).This is how a typical ART GC log line will look:-

1                                                         2                                                         3

07-01 16:00:44.690: I/art(801): Explicit concurrent mark sweep GC freed 65595(3MB) 

                                     4                                                      5                                    6

AllocSpace objects, 9(4MB) LOS objects, 34% free, 38MB/58MB, paused 1.195ms total 

    7

87.219ms

#	Field	Value	Description
1	Timestamp	07-01 16:00:44.690	Timestamp at which this Garbage Collection event ran
2	GC Reason	Explicit	Reason why Garbage Collection event was triggered.‘Explicit’ indicates that garbage collection was explicitly requested by an app, for example, by calling gc() or gc(). Please refer Below for different types of GC Reasons.
3	GC Name	concurrent mark sweep	ART has various different GCs which can get run. In this case, ‘Concurrent Mark Sweep’ indicates – a whole heap collector which frees collects all spaces other than the image space.  Please refer below for different types of GC Names.
4	Objects freed	65595(3MB)	Amount of objects garbage collected from non-large objects space. Totally 65595 unique objects, whose cumulative size of 3mb is garbage collected (i.e. freed) in this event.
5	Large objects freed	9(4MB)	Amount of objects garbage collected from Large objects space. Totally 9 unique objects, whose cumulative size of 4mb is garbage collected (i.e. freed)
6	Heap usage	38MB/58MB	38mb of objects is alive after this particular GC event. Total allocated heap size for this application is 58mb.
7	GC Pause Time	1.195ms	During certain phases of GC event, the application is paused. In this GC event, pause time is 1.195ms. During pause time, application freezes. One should target for low pause time.
8	GC Total Time	87.219ms	Amount of time this GC event took to complete. It includes the GC Pause time as well.

GC Reason
What triggered the GC and what kind of collection it is.
Concurrent
A concurrent GC that does not suspend app threads. This GC runs in a background thread and does not prevent allocations.
Alloc
The GC was initiated because your app attempted to allocate memory when your heap was already full. In this case, the garbage collection occurred in the allocating thread.
Explicit
The garbage collection was explicitly requested by an app, for example, by calling gc() or gc(). Like Dalvik, in ART the best practice is that you trust the GC and avoid requesting explicit GCs, if possible. Explicit GCs are discouraged because they block the allocating thread and unnecessarily waste CPU cycles. Explicit GCs could also cause jank (stuttering, juddering, or halting in the app) if they cause other threads to get preempted.
NativeAlloc
The collection was caused by native memory pressure from native allocations such as Bitmaps or RenderScript allocation objects.
CollectorTransition
The collection was caused by a heap transition; this is caused by changing the GC strategy at run time (such as when the app changes between pause perceptible states). Collector transitions consist of copying all the objects from a free-list backed space to a bump pointer space (or visa versa).
This occurs only on low RAM device prior to Android 8.0 when an app changes process states from a pause perceptible state (such as when the app is in the foreground, where the user can preceive a GC pause) to a non pause perceptible state (or visa versa).
HomogeneousSpaceCompact
Homogeneous space compaction is free-list space to free-list space compaction which usually occurs when an app is moved to a pause imperceptible process state. The main reasons for doing this are reducing RAM usage and defragmenting the heap.
DisableMovingGc
This is not a real GC reason, but a note that collection was blocked due to use of GetPrimitiveArrayCritical. while concurrent heap compaction is occurring. In general, the use of GetPrimitiveArrayCritical is strongly discouraged due to its restrictions on moving collectors.
HeapTrim
This is not a GC reason, but a note that collection was blocked until a heap trim finished.

GC Name
ART has various different GCs which can get run.
Concurrent mark sweep (CMS)
A whole heap collector which frees collects all spaces other than the image space.
Concurrent partial mark sweep
A mostly whole heap collector which collects all spaces other than the image and zygote spaces.
Concurrent sticky mark sweep
A generational collector which can only free objects allocated since the last GC. This garbage collection is run more often than a full or partial mark sweep since it is faster and has lower pauses.
Marksweep + semispace
A non concurrent, copying GC used for heap transitions as well as homogeneous space compaction (to defragement the heap).

Now We can discuss about Dalvik GC Log anlysis. 
This is how a typical Dalvik GC log line will look like:-

Below table summarizes each field in detail:

#	Field	Value	Description
1	Timestamp	07-01 15:56:19.815	Timestamp at which this Garbage Collection event ran
2	GC Reason	GC CONCURRENT	Reason why Garbage Collection event was triggered. Please refer below for different types of GC Reasons.
3	Objects freed	7078K	Amount of objects garbage collected. Totally 7078kb of objects are garbage collected (i.e. freed) in this event.
4	Heap usage	52464K/ 89052K	52464kb of objects are alive after this particular GC event. Total allocated heap size for this app is 89052 kb.
5	GC Pause Time	14ms+4ms	During certain phases of GC event, application is paused. In this GC event, pause time is 18 ms (i.e. 14 + 4 ms). During pause time, application freezes. One should target for low pause time.
6	GC Total Time	96ms	Amount of time this GC event took to complete. It includes the GC Pause time as well.

Dalvik GC Reason
What triggered the GC and what kind of collection it is. Reasons that might appear include:
GC_CONCURRENT
A concurrent GC that frees up memory as your heap begins to fill up.
GC_FOR_MALLOC
A GC was caused because your app attempted to allocate memory when your heap was already full, so the system had to stop your app and reclaim memory.
GC_HPROF_DUMP_HEAP
A GC that occurs when you request to create an HPROF file to analyze your heap.
GC_EXPLICIT
An explicit GC, such as when you call gc() (which you should avoid calling and instead trust the GC to run when needed).
GC_EXTERNAL_ALLOC
This happens only on API level 10 and lower (newer versions allocate everything in the Dalvik heap). A GC for externally allocated memory (such as the pixel data stored in native memory or NIO byte buffers)

As We all feel analyzing every single GC log line is very tedious work. So this is the obvious question "is there any tool for it ?" And the answer is Yes!!!!. We have few option:

• Use Android Studio inbuilt tool
• Use free online tools such as GCeasy.io

GCeasy.io – a universal Garbage collection log analyzer, to analyze Android GC logs. You can just upload the Android GC Logs to this tool. Tool parses GC log and generates report instantly. Report contains interactive graphs and insightful metrics.

So Hope this article address your Android GC log analysis understanding better. Please provide your feedback in  blog comment box.

Thanks

Saurabh

Happy Coding!!!!

Know Android Logs Analysis

Hello Guys !!! Hope you all doing well !!!
Today I am going to discuss a very hot topic in Android Development life cycle and it is 

Logs Analysis.
As an Android developer, all of you know Logs analysis is a phase of development and we encounter it time to time.
But Log Analysis is main challenging thing for code maintainer or Support Engineer. 

Once Any Android product launched in market and customer start using it. Then real scenario bugs/issue start coming and it is main Job for Support Engineer/Project maintenance engineer to analysed the Bug/issue with provided set of logs. 

                        All we know “How It is challenging”.
So today I am going to shed some light on it. First We start with type of Log available on Android Eco-system :- 

• Application Log 
• System Log
• Event Log
• Radio Log

Android logging system consists of:

• a kernel driver and kernel buffers for storing log messages 
• C, C++ and Java classes for making log entries and accessing the log messages 
• Logcat (a standalone program for viewing log messages )
• DDMS (ability to view and filter the log messages from the host machine)

Android Log Buffer/container

• main - the main application log 
• events - for system event information 
• radio - for radio and phone-related information 
• system - a log for low-level system messages and debugging

overview of  Android logging System (image by Tetsuyuki Kobabayshi, of Kyoto Microcomputer Co.)

What Log message contains:-

Each message in the log consists of 

• A tag indicating the part of the system or application that the message came from
• A timestamp (at what time this message came)
• The message log level (or priority of the event represented by the message) and 
• The log message itself(detail description of error or exception or information etc)

What Each Log Type Contains:-

1. Application log

• use android.util.Log class methods  to write messages of different priority into the log
• Java classes declare their tag statically as a string, which they pass to the log method
• The log method used indicates the message "severity" (or log level)
• Messages can be filtered by tag or priority when the logs are processed by retrieval tools (logcat)

2. System log 

• Use the android.util.Slog class to write message with different priority with its associated messages
• Many Android framework classes utilize the system log to keep their messages separate from (possibly noisy) application log messages
• A formatted message is delivered through the C/C++ library down to the kernel driver, which stores the message in the appropriate buffer(system buffer)

3. Event log

• Event logs messages are created using android.util.EventLog class, which create binary-formatted log messages. 
• Log entries consist of binary tag codes, followed by binary parameters. 
• The message tag codes are stored on the system at: /system/etc/event-log-tags. 
• Each message has the string for the log message, as well as codes indicating the values associated with (stored with) that entry.

4. Radio log

• Used for radio and phone(modem) related information
• Log entries consist of binary tags code and message for Network info
• Logging system automatically routes messages with specific tags into the radio buffer

Log format on Android

below is common log format in android

tv_sec   tv_nsec     priority     pid    tid     tag     messageLen       Message

tag: log tag
tv_sec & tv_nsec: the timestamp of the log messages
pid: the process id of where log messages come from
tid: the thread id
Priority value is one of the following character values, ordered from lowest to highest priority:
V — Verbose (lowest priority)*
D — Debug*
I — Info*
W — Warning*
E — Error*
F — Fatal*
S — Silent (highest priority, on which nothing is ever printed)

Log-File locations
There are several directories where logs (including those from crashes) stores and it are not standardized(i.e. some may be ROM-specific). I am putting some of common here.

• /data/anr : Dalvik writes stack traces here on ANR, i.e. "Application Not Responding" aka "Force-Close"
• /data/dontpanic : contains some crash logs including traces
• /data/kernelpanics :- Stores "kernel panic" related logs
• /data/tombstones :- may hold several tombstone_nn files (nn is a number from 0 to 10 and after 10 again repeat it)

'Log' command line tool
To capture Logs from the android devices/emulator Below is the some command line tool. In real life project there are log capture application/tool used to capture the logs on user device and shared it back to Developer/maintainer for analysis .

• adb logcat (shows all type logs for current android system
• adb logcat -v threadtime (it will include date and time) 
• adb logcat -v threadtime > logfile.txt (Store logs in logfile.txt) 

Useful filter patterns
You can use below filter in your adb command to filter logs. You can also use this filter to search your logs file(logs provided by user device). 

• adb logcat -f <output_file>  Save all logs into a file 
• adb logcat "*:E"  Get all errors and fatals
• adb logcat | grep -i "foo.example." #get all logs related to “foo.example.*” tagname
• adb logcat "application_or_tag_name:*" "*:S"  Get all logs by application name 
• adb logcat -b events "gsm_service_state_change" "*:S"  Get all GSM state changes 
• adb logcat -b radio Get all Radio events 

Log Analysis 
Till now we get all the fundamental exposure of Android Logging System. Now the time to analyse the logs coming from your application or end user. Here we can divide log analysis in two part

1. Debug Log :- logs file coming during development and testing phase
2. Production Log:- Logs file coming directly from end user. 

So guess which one  is difficult Production one Right?  So what is the best approach to debug and get the desire info from the captured logs.  As I discuss above, We can do it  by using 

• "Useful Filter Patterns" and
• By using Some Tool (example LogRabit, GoogleLogTool and SonyLogTool)

So in the last Android log analysis is a continuous learning and utilizing your experience process. Personally I analysed logs via relevant filter and tool with my past experience. 

But one thing is good Every android analysis (end user issue/bug log) gives you a new learning and experience. So keep it doing and enjoy your life as a coder and maintainer of android system😎😎😎

Please put your comments in comment box. It will energize me a lot. 

Thanks

Saurabh

Happy Coding!!!!

Know RRO (Runtime Resource Overlay) in Android AOSP

Hello Guys hope you all doing well.  !!!!

Today I am going to discuss a very important android resource framework.

Run-time Resource Overlay as it name suggest, it is resource overlay and it can be applied at run-time. I may guess not many of you know about it and google never advertise this AOSP resource framework. Android operating system has had this theming framework (RRO) built into AOSP for a few years now. With the help of RRO, we can quickly create themes that can change the look and feel of almost every app that's installed on an Android device.
As for example: - system user interface components, including navigation bar, status bar, notifications tray, and quick settings tray, themselves belong to an app, you can change their looks too. And the best part about it is that you don't have to write any Java code whatsoever for this RRO. 
What's the catch, you ask? Well, this framework(RRO) can be used only by privileged apps i.e. apps that are installed in a location that can be accessed only by the root user, or by someone who's (like us 😎) creating a custom ROM.
RRO work Mechanisms

• Android app's business logic is written in Java or Kotlin and its user interface is primarily created using XML files. 
• A well-written Android app will have separate XML resources that define its layouts, colors, strings, and attributes.
• The RRO framework, as its name suggests, lets us overlay those XML resources with your own custom XML resources. 
• It's not limited to just XML resources, It also allows you to change an app's drawables and fonts.

RRO Project Contain

• An app that uses the RRO framework usually doesn't contain any Java code. 
• It is composed only of XML files and, if necessary, fonts and images.
• Like all Android apps, it must be a valid and signed APK.

Customize the Build with RRO
By using RRO or say resource overlays, we can customize android os product at build time. So that same same Android OS behave differently in different device. Resource overlays specify resource files that are applied on top of the defaults.  To use resource overlays, we have to modify the project buildfile to set PRODUCT_PACKAGE_OVERLAYS to a path relative to our top-level directory. The most commonly customized settings are contained in the file frameworks/base/core/res/res/config.xml. To set up a resource overlay on this file, add the overlay directory to the project buildfile, as follows:
PRODUCT_PACKAGE_OVERLAYS := device/DEVICE_IMPLEMENTER/DEVICE_NAME/overlay

or

PRODUCT_PACKAGE_OVERLAYS := vendor/VENDOR_NAME/overlay

Then, add an overlay file to the directory, for example:

vendor/foobar/overlay/frameworks/base/core/res/res/config.xml

Any strings or string arrays found in the overlay config.xml file replace those found in the original file.

Build a Product with overlay
for organizing the source files for our device(custom ROM), generally we have to deal with makesfile as for example 

• device.mk
• device-vendor.mk
• AndroidProducts.mk
• BoardConfig.mk and 
• vendorsetup.sh. 

For more detail we can take Android Developer site as reference.

Example project to modify Quick setting tray

Step 1. Create a new project

I am using Linux(ubuntu) system and CLI is my favorite . So run the following command to create a new project 

mkdir MyOverlays && cd MyOverlays

touch AndroidManifest.xml

• manifest file must contain the package name of our application
• we are creating overlays for quick setting, so we must use com.android.systemui as the target package name

<?xml version="1.0" encoding="utf-8"?>

<manifest

    xmlns:android="http://schemas.android.com/apk/res/android"

    package="com.tutsplus.myoverlays">

    <overlay android:targetPackage="com.android.systemui"

             android:priority="1"/>

</manifest>

Step 2. Create a Theme
Actually we are creating a overlay for existing quick setting. Here is some point to keep in mind:-

• To overlay a resource of the target application, our application must have a resource with the same name. 
• To change the colors of the target application, we have to overlay its colors.xml file with our own colors.xml file.
• We can keep only those details that we want to change
• In this example we want to change the background color of the quick settings tray from the default blue-grey to a deep orange.
• The value of the color is specified in the res/values/colors.xml file of the system UI app. 
• you can take a look at the file on the official Android Git repository or androidxref

To change the color, we must now create a res/values/colors.xml file in our project.

mkdir -p res/values

touch res/values/colors.xml

Inside the colors.xml file, to change the background color of the tray, we must target a color named system_primary_color. Therefore, add the following XML to the file:

<?xml version="1.0" encoding="utf-8"?>

<resources>

    <color name="system_primary_color">#FFBF360C</color>

                                <!-- deep orange 900 -->

</resources>

Our simple theme is ready! If you want to, you can add more <color> tags to the file to change other colors of the system UI.

Step 3. Generate an APK
This is the last step, in this step we have to create .apk file. Android Studio automatically create .apk file for your application. But for our command line project we use AAPT(Android Asset Packaging Tool) which is a part of the Android SDK.

aapt package -M AndroidManifest.xml -S res/ \

    -I ~/Android/Sdk/platforms/android-23/android.jar \

    -F myoverlays.apk.u

In the above command, you can see that I've chosen to name the APK file myoverlays.apk.u.  That's because our APK is currently both unsigned and unaligned.

To sign our generated .apk, We use the jarsigner tool. For now, we are signing it with the default Android debug keystore. But for custom ROM development we use platform key for signing.

jarsigner -keystore ~/.android/debug.keystore \

        myoverlays.apk.u androiddebugkey

Finally, we must align—and thus optimize—the APK using the zipalign tool. As inputs, the tool expects the names of the unaligned and aligned APKs, along with a number that specifies the alignment boundaries. As of 2017, the number can be nothing else but 4.

zipalign 4 myoverlays.apk.u myoverlays.apk

Step 4. Install the APK

• To install an APK that uses the RRO framework, we must simply place it inside the /system/vendor/overlay directory. 
• The directory, by default, belongs to a read-only filesystem and is only accessible to the root user. 
• If you are a custom ROM developer(😎), or have rooted your Android device, you should have no trouble installing the APK.

however, I'll be showing you how to install the APK on an emulator. Start an emulator in the writable filesystem mode using the emulator command-line tool.

emulator -avd Nexus_5X_API_23 -writable-system
adb tool to gain root privileges on the emulator
adb root
adb remount

The /system/vendor/overlay directory doesn't exist on the emulator. We must create it manually

adb shell

mkdir -p /system/vendor/overlay

exit

Finally, push the APK to the directory using adb
adb push myoverlays.apk /system/vendor/overlay
Wait for a few seconds for Android to detect and install the APK, and then restart the emulator for the theme to take effect. After the restart, if you pull down the quick settings tray, you should be able to see the theme in action.This is the way we can create a new resource overlay or edit existing one. 


 Thanks
Saurabh 
Happy Coding!!!!!