Using "-c" and CTRL+C

Fri May 9 10:42:02 UTC 2014

I think I've located my problem - it's a question of choosing the right
pid. I'm debugging a multi-threaded application, and "ps" doesn't show the
pid for each thread, whereas htop does. Choosing the pid of a specific
thread causes strace to give me the statistics I'm looking for.

So it seems that if I run "strace -c" on a pid that is blocked in a system
call, it doesn't print statistics at all. It's a little misleading; maybe
it should print out statistics, and just show that 100% of the time it was
in that call. Or maybe it can't detect the current call if strace was
started after the call was made?

Either way, definitely operator error on my part.

- Bud

On Fri, May 9, 2014 at 10:13 AM, Bud Millwood <budm at weird-solutions.com>wrote:

> Hi Dmitry, thanks for replying:
>
> I'm not using the -l1 option. I see this behavior on both Ubuntu
> 12.10/x86-64 and CentOS 6.3/x86-64.
>
> If I kill the target process, it always works correctly. The problem is if
> I use CTRL-C to detach from the target process. Eventually I managed to get
> it to produce the statistical output, as shown below. I used it for a few
> hours, then left the terminal open over night, and the next day it was not
> printing the output again. So it looks like this:
>
> $ sudo strace -p 31457 -c
> Process 31457 attached - interrupt to quit
> ^CProcess 31457 detached
> $ sudo strace -p 31457 -c
> Process 31457 attached - interrupt to quit
> ^CProcess 31457 detached
> $ sudo strace -c -p 31457  <-- NOTE CHANGING COMMAND LINE ARGS ORDER
> Process 31457 attached - interrupt to quit
> ^CProcess 31457 detached
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ----------------
>  75.38    0.047831          66       730           poll
>  24.62    0.015622          20       793           sendto
>   0.00    0.000000           0        39           ioctl
>   0.00    0.000000           0        39           select
>   0.00    0.000000           0       769           recvfrom
>   0.00    0.000000           0       107        29 futex
> ------ ----------- ----------- --------- --------- ----------------
> 100.00    0.063453                  2477        29 total
>
> After this it worked for a while *regardless* of the order of the command
> line arguments. And then after 24 hours, it doesn't work again at all,
> *regardless* of command line argument order. So I just can't reproduce it
> reliably.
>
> - I thought it might be because there were no system calls in the target
> process - that the target was blocked in one call, such as "select", but
> that's not the case.
> - I tried sending SIGINT and SIGTERM to the strace process from another
> terminal, both signals cause the process to simply exit the same as if I
> pressed CTRL-C, i.e. no data printed.
>
> - Bud
>
>
>
>
>
> On Thu, May 8, 2014 at 11:11 PM, Dmitry V. Levin <ldv at altlinux.org> wrote:
>
>> Hi,
>>
>> On Wed, May 07, 2014 at 04:54:40PM +0200, Bud Millwood wrote:
>> > Hi all, I'm not on this list but I'll keep an eye out for a response
>> > to this message.
>> >
>> > In the past I noticed that if I ran "strace -c" against a process, I
>> > could press CTRL-C and strace would print out the statistics it had
>> > collected so far, then exit. It now seems to just exit without
>> > printing any of the statistics.
>>
>> Strange, it works for me, both in simple and in -p mode.
>> For example:
>>
>> $ strace -c cat & sleep 1 && kill -INT $!
>> [1] 19981
>> Process 19985 detached
>> % time     seconds  usecs/call     calls    errors syscall
>> ------ ----------- ----------- --------- --------- ----------------
>> $  27.65    0.000060           8         8           mmap
>>  14.29    0.000031           8         4           mprotect
>>  10.14    0.000022           6         4           fstat
>>   7.83    0.000017           9         2           open
>>   7.83    0.000017           4         4           brk
>>   6.45    0.000014           7         2         1 read
>>   5.53    0.000012          12         1         1 access
>>   5.07    0.000011           6         2           fadvise64
>>   4.61    0.000010           5         2           close
>>   4.61    0.000010          10         1           munmap
>>   3.69    0.000008           8         1           execve
>>   2.30    0.000005           5         1           arch_prctl
>> ------ ----------- ----------- --------- --------- ----------------
>> 100.00    0.000217                    32         2 total
>> [1]+  Done                    strace -c cat
>>
>> $ sleep 2 && sleep 2 & sleep 1; strace -cp $! & sleep 2 && kill -INT $!
>> [1] 19986
>> [2] 19989
>> Process 19986 attached
>> Process 19986 detached
>> % time     seconds  usecs/call     calls    errors syscall
>> ------ ----------- ----------- --------- --------- ----------------
>> $  80.77    0.000710         355         2         1 wait4
>>  15.81    0.000139         139         1           clone
>>   2.62    0.000023           4         6           rt_sigprocmask
>>   0.46    0.000004           2         2           rt_sigaction
>>   0.34    0.000003           3         1           rt_sigreturn
>> ------ ----------- ----------- --------- --------- ----------------
>> 100.00    0.000879                    12         1 total
>> [2]+  Done                    strace -cp $!
>> [1]-  Done                    sleep 2 && sleep 2
>>
>> You aren't using -I1 option, are you?
>>
>>
>> --
>> ldv
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.strace.io/pipermail/strace-devel/attachments/20140509/c7d2f15e/attachment.html>