system call log interpretation

[syahaz]

Dear all,

I would like to seek your help in interpreting the system call log file in android, if you have any experience in doing it.  For your information, I’m using the strace to dump the log of an application.

 

The example is as follows:

 

syscall_983042(0x47a8e074, 0x47a8e078, 0, 0xfff, 0x4086d118, 0x47a8e074, 0x47a4a905, 0xf0002, 0, 0x47a8e078, 0xfc46f7bc, 0x413d4630, 0, 0xbeb43678, 0x40841ac3, 0x40011454, 0x40000010, 0x47a8e074, 0xb691, 0, 0x7461642f, 0x61642f61, 0x632f6174, 0x682e6d6f, 0x63646e61, 0x2e746e65, 0x7478656e, 0x2f736d73, 0x755f6368, 0x61, 0, 0) = 0

 

Appreciate your feedback.

 

Thank you.

[Tim Bird]

This doesn't make any sense. You are using a bunch of words together
that correspond to different systems. I have no idea what a
"system call log file" is.

You can get an strace dump, using the strace command (which uses
the ptrace system call. You could get the log from the kernel,
which might be instrumented to return system call information.
You can obtain syscall call information from ftrace. Finally,
you could be getting the Android logs for the processes on your
system.

However, the output above bears no resemblance to any of these
4 different sources of system information. In particular
it doesn't look like strace output.

One does not use strace to dumo the log of an application.
One uses strace to trace the system calls of an application.
One uses logcat to dumo the log of an application, and dmesg
to dump the log of the kernel.

Can you describe what you are doing (or trying to do) in
greater detail?
-- Tim

=============================
Tim Bird
Architecture Group Chair, CE Workgroup of the Linux Foundation
Senior Staff Engineer, Sony Network Entertainment
=============================

[sya...@gmail.com]

Hi,

Thanks for responding to my email.

Firstly, I've to admit that I'm new to this Android stuff. Hope you can bear with me.

What I'm trying to do is to study on system call used by an application, in this case a SMS application that I installed in an emulator.
I want to know the what are the system calls involved when I use the application to send and receive the SMS.

What I've done :

1) I installed the android sdk together with a third party SMS application
2) I used the adb shell to get the PID and dump the strace output to a file. The command I used:
" strace -e trace=open,read -p 834 -v -o handcent2.txt"

The full strace dump is as attached.

I've difficulty in understanding the output and now based on your feedback I'm not sure whether this is the actual output of strace or not.

Hope you can give some guidance.

Thank you.

[Tim Bird]

On 09/26/2012 08:08 AM, sya...@gmail.com wrote:
> Hi,
>
> Thanks for responding to my email.
>
> Firstly, I've to admit that I'm new to this Android stuff. Hope you can bear with me.
>
> What I'm trying to do is to study on system call used by an application, in this case a SMS application that I installed in an emulator.
> I want to know the what are the system calls involved when I use the application to send and receive the SMS.
>
> What I've done :
>
> 1) I installed the android sdk together with a third party SMS application
> 2) I used the adb shell to get the PID and dump the strace output to a file. The command I used:
> " strace -e trace=open,read -p 834 -v -o handcent2.txt"
>
> The full strace dump is as attached.
>
> I've difficulty in understanding the output and now based on your feedback I'm not sure whether this is the actual output of strace or not.
>
> Hope you can give some guidance.

Where did you get the strace program that you used for this dump?

This syscall_983042() doesn't look like anything I've seen before.
My experience is that the strace code in AOSP is a bit dated --
it had at least one syscall incorrectly named when I looked at it
a few years ago.
But in that case the name was just wrong (and, of course the
argument/results decode was then wrong as well). In your case,
the name and decode seem completely bogus. (There is no syscall
number 983042 on ARM - trust me. :-)

Maybe this is something funky like a futex.

Can you try the strace using -tt and see what the timing is between
calls? Sometimes futexes and/or gettimeofday are called a whole lot, and often
in short intervals.

The other thing to do is to look at the strace source code, and see
where this syscall_983042 name is coming from. I suspect from the decode
that this is what strace does when it doesn't know what the heck it just
saw. (So, this might be another indication that this is from an
out-of-date strace implementation.) But, assuming the decode wasn't
completely botched, it looks like the syscall is returning success.
If this isn't the thing you are looking for, then maybe you can just
'grep -v' it, and ignore it for your analysis.

I hope this is helpful.

[Takuo Koguchi]

As already suggested by Glenn, syscall_983042 seems to be an ARM private cacheflush syscall. The number is assigned in arch/arm/include/asm/unistd.h
In the case of EABI, __ARM_NR_cacheflush is 0x0f0002(=982042)
/*
* The following SWIs are ARM private.
*/
#define __ARM_NR_BASE (__NR_SYSCALL_BASE+0x0f0000) #define __ARM_NR_breakpoint (__ARM_NR_BASE+1)
#define __ARM_NR_cacheflush (__ARM_NR_BASE+2)
#define __ARM_NR_usr26 (__ARM_NR_BASE+3)
#define __ARM_NR_usr32 (__ARM_NR_BASE+4)
#define __ARM_NR_set_tls (__ARM_NR_BASE+5)

The strace command used here has no knowledge about the syscall and seems to print the contents of registers from R0. syscall_983042(0x47a8e074, 0x47a8e078, 0, 0xfff, 0x4086d118, 0x47a8e074, 0x47a4a905, 0xf0002, 0, 0x47a8e078, 0xfc46f7bc, 0x413d4630, 0, 0xbeb43678, 0x40841ac3, 0x40011454, 0x40000010, 0x47a8e074, 0xb691, 0, 0x7461642f, 0x61642f61, 0x632f6174, 0x682e6d6f, 0x63646e61, 0x2e746e65, 0x7478656e, 0x2f736d73, 0x755f6368, 0x61, 0, 0) = 0
The syscall number 0xf0002 is stored in R7 as expected.

ARM private cacheflush syscall actually takes only 3 args, start(0x47a8e074), end(0x47a8e078), flags(0). 0 is the only valid value for the syscall.

So the log entry says, the application requested to write back 4 bytes of data to the memory and it succeded. Hope this will help.

Takuo

2012/09/26 22:41 "Tim Bird" <tim....@am.sony.com>:

--
unsubscribe: android-kerne...@googlegroups.com
website: http://groups.google.com/group/android-kernel

[Tim Bird]

On 09/26/2012 07:35 PM, Takuo Koguchi wrote:
> As already suggested by Glenn, syscall_983042 seems to be an ARM private cacheflush syscall. The number is assigned in arch/arm/include/asm/unistd.h
> In the case of EABI, __ARM_NR_cacheflush is 0x0f0002(=982042)
> /*
> * The following SWIs are ARM private.
> */
> #define __ARM_NR_BASE (__NR_SYSCALL_BASE+0x0f0000) #define __ARM_NR_breakpoint (__ARM_NR_BASE+1)
> #define __ARM_NR_cacheflush (__ARM_NR_BASE+2)
> #define __ARM_NR_usr26 (__ARM_NR_BASE+3)
> #define __ARM_NR_usr32 (__ARM_NR_BASE+4)
> #define __ARM_NR_set_tls (__ARM_NR_BASE+5)
>
> The strace command used here has no knowledge about the syscall and seems to print the contents of registers from R0. syscall_983042(0x47a8e074, 0x47a8e078, 0, 0xfff, 0x4086d118, 0x47a8e074,
> 0x47a4a905, 0xf0002, 0, 0x47a8e078, 0xfc46f7bc, 0x413d4630, 0, 0xbeb43678, 0x40841ac3, 0x40011454, 0x40000010, 0x47a8e074, 0xb691, 0, 0x7461642f, 0x61642f61, 0x632f6174, 0x682e6d6f, 0x63646e61,
> 0x2e746e65, 0x7478656e, 0x2f736d73, 0x755f6368, 0x61, 0, 0) = 0
> The syscall number 0xf0002 is stored in R7 as expected.
>
> ARM private cacheflush syscall actually takes only 3 args, start(0x47a8e074), end(0x47a8e078), flags(0). 0 is the only valid value for the syscall.
>
> So the log entry says, the application requested to write back 4 bytes of data to the memory and it succeded. Hope this will help.

Well, you learn something new every day!

I didn't know ARM *had* private syscalls. Thanks for this info.

BTW - this is used in the bionic routine cacheflush(), located
in bionic/libc/arch-arm/syscalls/cacheflush.S
I couldn't find any callers of cacheflush() in bionic.

It's also called via the syscall() syscall in valgrind, but with cursory
poking about I couldn't find any other references in AOSP.

Presumably the original app knows what it's doing, or some library
routine is invoking this. It seems like a lot of overhead to go to the
kernel to guarantee a cache flush. Maybe this is related to some kind
of user-space locking primitive.

Interesting diversion...

[sya...@gmail.com]

Hi all,

Thank you for the responses.

I'll try to read more on the related matters.

-----Original Message-----
From: android...@googlegroups.com
[mailto:android...@googlegroups.com] On Behalf Of Tim Bird
Sent: Friday, 28 September, 2012 2:49 AM
To: android...@googlegroups.com
Cc: Takuo Koguchi
Subject: Re: [android-kernel] system call log interpretation

[Mahdieh Kazemipour]

I want to use strace whit adb shell
but when I type Strace whit -o or -e option
no output  get me
and only show "-" charachter for type!
and after mintus I type "Ctrl+C" and exit from adb!!
why??

can you explain using of strace at android step by step??