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

Advertisements

Leave a Reply

Please log in using one of these methods to post your comment:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: