Re: Potential deadlock in operf when using --pid

Hi Will,

How about the attached test program?  This almost always causes the problem
in my environment.

> gcc -o oprofile_multithread_test oprofile_multithread_test.c -lpthread
> ./oprofile_multithread_test
Usage: oprofile_multithread_test <number of spawns> <number of threads>
<number of operations per thread>
> ./oprofile_multithread_test -1 16 100000

In this example, oprofile_multithread_test spawns threads infinitely but
runs maximum 16 threads simultaneously.  Each thread performs addition
100000 times and then completes.  Please use ^C to end this program if you
specify -1 to the number of spawns.

If you profile this program with operf --pid, I expect you will not be able
to finish operf by a single ^C.


Regards,
Rei Odaira

2015-10-01 15:42 GMT-05:00 William Cohen <[email protected]>:

> On 09/30/2015 06:07 PM, 大平怜 wrote:
> > Hello again,
> >
> > When using --pid, I have occasionally seen operf does not end by hitting
> ^C once. By hitting ^C multiple times, operf ends with error messages:
>
> Hi,
>
> I tried to replicate this on my local machine, but haven't seen it occur
> yet.  How often does it happen?  Also does it make a difference when the
> event sampling rate is changed?  There is just one monitored process and it
> isn't spawning new processes?
>
> >
> > -----
> > operf --events=CPU_CLK_UNHALTED:100000000:0:1:1 --pid `pgrep -f
> CassandraDaemon`
> > Kernel profiling is not possible with current system config.
> > Set /proc/sys/kernel/kptr_restrict to 0 to collect kernel samples.
> > operf: Press Ctl-c or 'kill -SIGINT 18042' to stop profiling
> > operf: Profiler started
> > ^C^Cwaitpid for operf-record process failed: Interrupted system call
> > ^Cwaitpid for operf-read process failed: Interrupted system call
> > Error running profiler
> > -----
> >
> > I am using the master branch in the git repository.
> >
> > Here is what I found:
> > The operf-read process was waiting for a read of a sample ID from the
> operf-record process to return:
> > (gdb) bt
> > #0  0x00007fd90e0fa480 in __read_nocancel ()
> >     at ../sysdeps/unix/syscall-template.S:81
> > #1  0x0000000000412999 in read (__nbytes=8, __buf=0x7ffddc82b620,
> >     __fd=<optimized out>) at
> /usr/include/x86_64-linux-gnu/bits/unistd.h:44
> > #2  __handle_fork_event (event=0x98e860) at operf_utils.cpp:125
> > #3  OP_perf_utils::op_write_event (event=event@entry=0x98e860,
> >     sample_type=<optimized out>) at operf_utils.cpp:834
> > #4  0x0000000000417250 in operf_read::convertPerfData (
> >     this=this@entry=0x648000 <operfRead>) at operf_counter.cpp:1147
> > #5  0x000000000040a4cb in convert_sample_data () at operf.cpp:947
> > #6  0x0000000000407482 in _run () at operf.cpp:625
> > #7  main (argc=4, argv=0x7ffddc82be48) at operf.cpp:1539
> >
> > The operf-record process was waiting for a write of sample data to the
> operf-read process to complete.  Why did the write of the sample data
> block?  My guess is that the sample_data_pipe was full:
> > (gdb) bt
> > #0  0x00007fbe0dc9f4e0 in __write_nocancel ()
> >     at ../sysdeps/unix/syscall-template.S:81
> > #1  0x000000000040cd0e in OP_perf_utils::op_write_output (output=6,
> >     buf=0x7fbe0e4e5140, size=32) at operf_utils.cpp:989
> > #2  0x000000000040d605 in OP_perf_utils::op_get_kernel_event_data (
> >     md=0xd3c7f0, pr=pr@entry=0xd07900) at operf_utils.cpp:1443
> > #3  0x000000000041bc12 in operf_record::recordPerfData (this=0xd07900)
> >     at operf_counter.cpp:846
> > #4  0x00000000004098b8 in start_profiling () at operf.cpp:402
> > #5  0x0000000000406305 in _run () at operf.cpp:596
> > #6  main (argc=4, argv=0x7ffdc6fcde58) at operf.cpp:1539
> >
> > As a result, when I hit ^C, the operf main process sent SIGUSR1 to the
> operf-record process, in which the write returned with EINTR and simply got
> retried. Since the operf-record process did not end, the operf main process
> waited at waitpid(2) forever.
> >
> > Do you think my guess makes sense?  What would be a fundamental
> solution?  Simply extending the pipe size would not be appropriate....
>
> I am wondering if there are any other nuggets of information that can be
> gathered by using "--verbose debug,misc" and other "--verbose" variations
> on the operf command line.  It would be worthwhile to take a close look at
> the code in operf.cpp and see how ctl-c is being handled.  There could be a
> problem with the order that things are shutdown, causing the problem.  I
> noticed around line 406 and  of operf.cpp there is the following code:
>
> catch (const runtime_error & re) {
>                         /* If the user does ctl-c, the operf-record
> process may get interrupted
>                          * in a system call, causing problems with writes
> to the sample data pipe.
>                          * So we'll ignore such errors unless the user
> requests debug info.
>                          */
>                         if (!ctl_c || (cverb << vmisc)) {
>                                 cerr << "Caught runtime_error: " <<
> re.what() << endl;
>                                 exit_code = EXIT_FAILURE;
>                         }
>                         goto fail_out;
>                 }
>
> -Will
>
>
>
>

------------------------------------------------------------------------------

_______________________________________________
oprofile-list mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/oprofile-list

#include <stdio.h>
#include <stdlib.h>