Playing with FTRACE option on my Xperia Arc S

FTRACE allow you to see how the kernel functions are executed and interacts, and correlate it with the userspace command.

Although SonyEricsson (YOU ARE AWESOME and thank for the feature!!) provided the instruction on how to build the kernel:

http://developer.sonyericsson.com/wp/2011/05/06/how-to-build-a-linux-kernel/

I don’t have to recompile the kernel, as the default kernel already can do FTRACE.

First if you have to use “adb” and USB to connect to your Xperia Arc S first (follow instructions here: http://developer.android.com/guide/developing/tools/adb.html).

Next (assuming you have rooted the phone – instructions you can follow the zergRush method: http://forum.xda-developers.com/showthread.php?t=1312859).

Next list the directory “/sys/kernel”:

# ls -l
-r--r--r-- root root 4096 2011-12-29 17:05 uevent_seqnum
-rw-r--r-- root root 4096 2011-12-29 17:05 uevent_helper
-rw-r--r-- root root 4096 2011-12-29 17:05 profiling
drwxr-xr-x root root 2011-12-29 16:01 debug
drwxr-xr-x root root 2011-12-29 15:42 ipv4
drwxr-xr-x root root 2011-12-29 17:05 mm
drwxr-xr-x root root 2011-12-29 14:54 hdmi_sii_kset
drwxr-xr-x root root 2011-12-29 17:05 pmem_regions


“cd debug” and you will see there is nothing mounted there.

So explicitly mount debugfs using this instruction:

mount -t debugfs nodev /sys/kernel/debug


Then from the /sys/kernel/debug/tracing directory you can read a file “README” as reproduced here:

tracing mini-HOWTO:

# mount -t debugfs nodev /sys/kernel/debug

# cat /sys/kernel/debug/tracing/available_tracers
wakeup preemptirqsoff preemptoff irqsoff function sched_switch nop

# cat /sys/kernel/debug/tracing/current_tracer
nop
# echo sched_switch > /sys/kernel/debug/tracing/current_tracer
# cat /sys/kernel/debug/tracing/current_tracer
sched_switch
# cat /sys/kernel/debug/tracing/trace_options
noprint-parent nosym-offset nosym-addr noverbose
# echo print-parent > /sys/kernel/debug/tracing/trace_options
# echo 1 /sys/kernel/debug/tracing/tracing_enabled
# cat /sys/kernel/debug/tracing/trace > /tmp/trace.txt
# echo 0 > /sys/kernel/debug/tracing/tracing_enabled
#

Oh yes, these are the steps to enable ftrace momentarily for each userspace command. And finally “echo 0” is to disable it.

In the above, /tmp directory does not exists on the Android phone, so you have to change that to /data directory.

Showing a snippet of the output below:

# tracer: sched_switch
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
sh-3679 [000] 7060.191467: 3679:120:S + [000] 3679:120:S sh
sh-3679 [000] 7060.191498: 3679:120:S ==> [000] 0:120:R <idle>
<idle>-0 [000] 7060.197906: 0:120:R + [000] 4:120:S events/0
<idle>-0 [000] 7060.197937: 0:120:R ==> [000] 4:120:R events/0
events/0-4 [000] 7060.197968: 4:120:R + [000] 196:120:S adbd
events/0-4 [000] 7060.197968: 4:120:S ==> [000] 196:120:R adbd
adbd-196 [000] 7060.198090: 196:120:R + [000] 3483:120:S adbd
adbd-196 [000] 7060.198151: 196:120:S ==> [000] 3483:120:R adbd
adbd-3483 [000] 7060.198181: 3483:120:R + [000] 196:120:S adbd
adbd-3483 [000] 7060.198273: 3483:120:S ==> [000] 196:120:R adbd
adbd-196 [000] 7060.198303: 196:120:S ==> [000] 0:120:R <idle>
<idle>-0 [000] 7060.198608: 0:120:R + [000] 3484:120:S adbd
<idle>-0 [000] 7060.198639: 0:120:R ==> [000] 3484:120:R adbd
adbd-3484 [000] 7060.198669: 3484:120:R + [000] 196:120:S adbd
adbd-3484 [000] 7060.198730: 3484:120:S ==> [000] 196:120:R adbd
adbd-196 [000] 7060.198761: 196:120:R + [000] 3483:120:S adbd
adbd-196 [000] 7060.198822: 196:120:S ==> [000] 3483:120:R adbd
adbd-3483 [000] 7060.198822: 3483:120:S ==> [000] 0:120:R <idle>
<idle>-0 [000] 7060.397919: 0:120:R + [000] 70:120:S kondemand/0
<idle>-0 [000] 7060.397949: 0:120:R + [000] 99:120:S yaffs-bg-1
<idle>-0 [000] 7060.397949: 0:120:R + [000] 102:120:S yaffs-bg-1
<idle>-0 [000] 7060.398010: 0:120:R ==> [000] 70:120:R kondemand/0
kondemand/0-70 [000] 7060.398041: 70:120:S ==> [000] 99:120:R yaffs-bg-1
yaffs-bg-1-99 [000] 7060.398102: 99:120:S ==> [000] 102:120:R yaffs-bg-1
yaffs-bg-1-102 [000] 7060.398102: 102:120:S ==> [000] 0:120:R <idle>
<idle>-0 [000] 7060.437866: 0:120:R + [000] 101:120:S yaffs-bg-1
<idle>-0 [000] 7060.437927: 0:120:R ==> [000] 101:120:R yaffs-bg-1
yaffs-bg-1-101 [000] 7060.437927: 101:120:S ==> [000] 0:120:R <idle>


Well, what is the problem here:

In my PC’s Linux kernel, ftrace output is as follows:

# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
Xorg-4565 [000] 3936.307434: native_set_pte <-kmap_atomic_prot_pfn
Xorg-4565 [000] 3936.307435: arch_flush_lazy_mmu_mode <-kmap_atomic_prot_pfn
Xorg-4565 [000] 3936.307435: __copy_from_user_ll_nocache_nozero <-i915_gem_pwrite_ioctl
Xorg-4565 [000] 3936.307435: iounmap_atomic <-i915_gem_pwrite_ioctl
Xorg-4565 [000] 3936.307435: native_set_pte_at <-iounmap_atomic
Xorg-4565 [000] 3936.307436: native_flush_tlb_single <-iounmap_atomic
Xorg-4565 [000] 3936.307436: i915_gem_object_unpin <-i915_gem_pwrite_ioctl
Xorg-4565 [000] 3936.307436: mutex_unlock <-i915_gem_pwrite_ioctl
Xorg-4565 [000] 3936.307437: sys_ioctl <-sysenter_do_call
Xorg-4565 [000] 3936.307438: fget_light <-sys_ioctl
Xorg-4565 [000] 3936.307438: security_file_ioctl <-sys_ioctl
Xorg-4565 [000] 3936.307438: cap_file_ioctl <-security_file_ioctl
Xorg-4565 [000] 3936.307438: do_vfs_ioctl <-sys_ioctl
Xorg-4565 [000] 3936.307438: vfs_ioctl <-do_vfs_ioctl
Xorg-4565 [000] 3936.307439: drm_ioctl <-vfs_ioctl
Xorg-4565 [000] 3936.307439: drm_ut_debug_printk <-drm_ioctl
Xorg-4565 [000] 3936.307439: _copy_from_user <-drm_ioctl
Xorg-4565 [000] 3936.307439: _cond_resched <-_copy_from_user
Xorg-4565 [000] 3936.307439: i915_gem_pwrite_ioctl <-drm_ioctl
Xorg-4565 [000] 3936.307440: drm_gem_object_lookup <-i915_gem_pwrite_ioctl
Xorg-4565 [000] 3936.307440: _raw_spin_lock <-drm_gem_object_lookup
Xorg-4565 [000] 3936.307440: mutex_lock <-i915_gem_pwrite_ioctl
Xorg-4565 [000] 3936.307440: _cond_resched <-mutex_lock
Xorg-4565 [000] 3936.307440: i915_gem_object_pin <-i915_gem_pwrite_ioctl
Xorg-4565 [000] 3936.307441: i915_gem_object_set_to_gtt_domain <-i915_gem_pwrite_ioctl
Xorg-4565 [000] 3936.307441: i915_gem_object_flush_gpu_write_domain <-i915_gem_object_set_to_gtt_domain
Xorg-4565 [000] 3936.307441: i915_gem_object_wait_rendering <-i915_gem_object_set_to_gtt_domain


From above I can easily followed the course of the kernel function traversed for a single process “Xorg”.

Looking at the tracing option:

# cat /sys/kernel/debug/tracing/trace_options
print-parent
nosym-offset
nosym-addr
noverbose
noraw
nohex
nobin
noblock
nostacktrace
nosched-tree
trace_printk
noftrace_preempt
nobranch
annotate
nouserstacktrace
nosym-userobj
noprintk-msg-only
context-info
nolatency-format
sleep-time
graph-time


Perhaps that was the trouble, now we change the option a little:

echo stacktrace > /sys/kernel/debug/tracing/trace_options

echo sym-addr > /sys/kernel/debug/tracing/trace_options

echo sym-offset > /sys/kernel/debug/tracing/trace_options

echo verbose > /sys/kernel/debug/tracing/trace_options


And wow, now the verbosity is very high:

# tracer: sched_switch
#
klogrouter-131 [000] 15427.358765: 131:120:R + [000] 1007:120:S logcat
klogrouter-131 [000] 15427.358765: <stack trace>
=> __wake_up_common+0x34/0x78 <800c8d80>
=> __wake_up+0x3c/0x88 <800cf4a0>
=> logger_aio_write+0x374/0x388 <803d4dcc>
=> do_sync_readv_writev+0xb0/0xfc <8014bd64>
=> do_readv_writev+0xac/0x1a8 <8014c448>
=> vfs_writev+0x5c/0x68 <8014c5a0>
=> sys_writev+0x3c/0x68 <8014c678>
=> ret_fast_syscall+0x0/0x2c <80035f80>
klogrouter-131 [000] 15427.358826: 131:120:R ==> [000] 1007:120:R logcat
klogrouter-131 [000] 15427.358826: <stack trace>
=> logger_aio_write+0x374/0x388 <803d4dcc>
=> do_sync_readv_writev+0xb0/0xfc <8014bd64>
=> do_readv_writev+0xac/0x1a8 <8014c448>
=> vfs_writev+0x5c/0x68 <8014c5a0>
=> sys_writev+0x3c/0x68 <8014c678>
=> ret_fast_syscall+0x0/0x2c <80035f80>
logcat-1007 [000] 15427.358948: 1007:120:S ==> [000] 131:120:R klogrouter
logcat-1007 [000] 15427.358948: <stack trace>
=> poll_schedule_timeout+0x38/0x58 <8015b014>
=> do_select+0x46c/0x4a0 <8015bba0>
=> core_sys_select+0x264/0x31c <8015be38>
=> sys_select+0xdc/0xfc <8015c1f8>
=> ret_fast_syscall+0x0/0x2c <80035f80>
klogrouter-131 [000] 15427.359039: 131:120:R + [000] 1007:120:S logcat
klogrouter-131 [000] 15427.359039: <stack trace>
=> __wake_up_common+0x34/0x78 <800c8d80>
=> __wake_up+0x3c/0x88 <800cf4a0>
=> logger_aio_write+0x374/0x388 <803d4dcc>
=> do_sync_readv_writev+0xb0/0xfc <8014bd64>
=> do_readv_writev+0xac/0x1a8 <8014c448>
=> vfs_writev+0x5c/0x68 <8014c5a0>


More details here:

http://pastebin.com/6TLRihHR

How to write a kernel module on Android (Sony Ericsson Xperia Arc S)

I wrote and tested the code on my Sony Ericsson Xperia Arc S and it works (in general in should work for any Android phone).

Connecting via adb and USB, and “su” to root, the “lsmod” listed all the kernel module (in general, the article at http://developer.sonyericsson.com/wp/2011/05/06/how-to-build-a-linux-kernel/ gave a very good coverage of what to do in Linux kernel compilation for SonyEricsson phone):

# lsmod
android_module 654 0 - Live 0x7f007000 (P)
sdio 16532 0 - Live 0x7f000000


“android_module” was the one I had inserted via “insmod android_module.ko”.

Here’s how to do it:

First the original program was copied from:

http://rechtzeit.wordpress.com/2011/03/21/77/

Or reproduced as follows:

android_module.c:

#include"linux/module.h"
#include"linux/kernel.h"
//replace the "" with angular brackets
int init_module(void)
{
printk(KERN_INFO "Hello android kernel...\n");
return 0;
}

void cleanup_module(void)
{
printk(KERN_INFO "Goodbye android kernel...\n");
}


And the file “Makefile” is:

obj-m += android_module.o

all:
make -C /home/tteikhua/android/sony_ericsson_src/58/kernel/ M=$(PWD) modules
clean:
make -C /home/tteikhua/android/sony_ericsson_src/58/kernel/ M=$(PWD) clean


The directory where the kernel is located (“-C” above) is where I had downloaded the SonyEricsson kernel image from here:

http://developer.sonyericsson.com/wportal/devworld/downloads/download/30a2181182tarbz2?cc=gb&lc=en

And the following command will use the Makefile from above:

ARCH=arm CROSS_COMPILE=/opt/CodeSourcery/Sourcery_G++_Lite/bin/arm-none-linux-gnueabi- make


As shown above, the cross compiler I had used is from CodeSourcery.

And after “insmod android_module.ko” you can see the debugging message in “dmesg” output:

<6>[11184.063507] Hello android kernel...
<7>[11619.209655] msmrtc_timeremote_set_time: 11/29/2011 10:09:36 (04)
<6>[11619.210418] RPC CALL -- TOD TIME UPDATE: ttick = 404244221
<6>[11619.210418] stamp=52910543933046785, freq = 0
<7>[11619.211578] msmrtc_tod_proc_result: 12/29/2011 10:09:36 (03)
<6>[11619.211578] rs30000048 rs30000048.262144: setting system clock to 2011-12-29 10:09:36 UTC (1325153376)
<6>[11662.112365] device rmnet0 left promiscuous mode
<6>[11662.112579] device rmnet0 entered promiscuous mode
<6>[11669.958221] device rmnet0 left promiscuous mode
<6>[11669.958435] device rmnet0 entered promiscuous mode
<7>[11698.181060] msmrtc_timeremote_set_time: 11/29/2011 10:10:55 (04)
<6>[11698.187622] RPC CALL -- TOD TIME UPDATE: ttick = 406832008
<6>[11698.187652] stamp=52910548228014081, freq = 0
<7>[11698.193939] msmrtc_tod_proc_result: 12/29/2011 10:10:55 (03)
<6>[11698.194030] rs30000048 rs30000048.262144: setting system clock to 2011-12-29 10:10:55 UTC (1325153455)
<6>[11814.442901] bq27520 0-0055: bq27520_handle_soc_worker() capacity=97 (100) flags=0x229 ctrl_status=0x28b soh_state=0x3, valid=1
<6>[11984.057373] Goodbye android kernel...
#


And the “Goodbye” is when “rmmod android_module” is executed. In between are debugging message from other components in the kernel.

How to dump memory of any running processes in Android (rooted)

First download and untar the Android NDK (in my case it is r7 version).

Next untar the “dump_android_memory.tgz” (which can be downloaded from http://groups.google.com/group/embeddednewbies/attach/03ee7f77fae48976/dump_android_memory.tgz?part=2) and copy the entire directory “dump_android_memory” under the “samples” subdirectory.

“cd” to that directory, and execute “export NDK_PROJECT_PATH=`pwd`”.

Then execute “../../ndk-build” as follows (ie, just execute the “ndk-build” that comes with the NDK download):

After compilation look for the file:

./libs/armeabi/dump_android_memory

And then “file” to view the binary file type:

file libs/armeabi/dump_android_memory
libs/armeabi/dump_android_memory: ELF 32-bit LSB executable, ARM, version 1 (SYSV), dynamically linked (uses shared libs), stripped

Now this is a ELF file successfully compiled and created by NDK.

Copy the dump_android_memory binary to your Android devices via “adb push”. (details not shown). Assuming “adb” is in your $PATH, connect into your android device:

adb push dump_android_memory /data

adb shell

(“su” will be necessary to escalate to root if it is a real Android device)

Inside the Android device, run as root (“su”) to execute the command “chmod 4755 dump_android_memory” to setuid the executeable.

# chmod 4755 /data/dump_android_memory

# /data/dump_android_memory
/data/dump_android_memory <pid> <start_address> <total_words>
where <start_address> is in hexadecimal (remember the “0x” in front is
needed – by sscanf()

Finding where is the starting address to dump (for efficiency), using pid=37 as an example:

# cat /proc/37/maps
00008000-00028000 r-xp 00000000 00:01 24 /sbin/adbd
00028000-00029000 rwxp 00020000 00:01 24 /sbin/adbd
00029000-00034000 rwxp 00029000 00:00 0 [heap]
10000000-10001000 ---p 10000000 00:00 0
10001000-10100000 rwxp 10001000 00:00 0
40000000-40008000 r-xs 00000000 00:07 188
/dev/ashmem/system_properties (deleted)
40008000-40009000 r-xp 40008000 00:00 0
40009000-4000a000 ---p 40009000 00:00 0
4000a000-40109000 rwxp 4000a000 00:00 0
40109000-4010a000 ---p 40109000 00:00 0
4010a000-40209000 rwxp 4010a000 00:00 0
bed45000-bed5a000 rwxp befeb000 00:00 0 [stack]


Now you can dump the memory of any live process using the command “dump_android_memory <pid> <start_address> <total_words_to_dump>” where words are measure in counts of 4 bytes, and start_address must be entered in hexadecimal format as “0x12345678”.

Dumping 10 words:

# /data/dump_android_memory 37 0x00008000 10

464c457f 10101 0 0
280002 1 80a0 34

Dumping 100 words:

# /data/dump_android_memory 37 0x00008000 100

464c457f 10101 0 0
280002 1 80a0 34
20998 5000002 200034 280003
e000f 70000001 1e198 26198
26198 1460 1460 4
4 1 0 8000
8000 1f5f8 1f5f8 5
1000 1 20000 28000
28000 8e4 787c 6
1000 0 0 0
e1a0000d e3a01000 e28f2004 e28f3004
ea006730 ea006737 28000 28008
28014 2801c e1a00000 e1a00000
f005b510 bd10ffa1 f013b510 bd10ff51
6803b510 2b001c04 6840d005 68626058
60136064 1c206024 f0013008 6a60fa35
d0012800 ff3cf013 28006aa0 f013d001
6ae0ff37 d0032800 31301c21 fb64f001
f0131c20 bd10ff2d f7ffb510 bd10ffd9
4657b5f8 b4c04646 4e154d14 447d1c07
468859ab 681c4692 d014429c 1c386a61
f92af00f d10a2800 46406aa1 f924f00f
d1042800 2b006ae3 4553d001 6824d009
429c59ab 2001d1ea bc0c4240 469a4690
1c20bdf8 ffacf7ff e7f62000 2043a #


Hope it helps.