Re: Potential deadlock in operf when using --pid

Sorry, I sent wrong source code.  I am attaching the right one.


Regards,
Rei Odaira

2015-10-01 18:32 GMT-05:00 大平怜 <[email protected]>:

> 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>
#include <stdint.h>
#include <string.h>
#include <pthread.h>

static int num_ops;
static pthread_t *thr_array;


static void *
thr_main(void *arg)
{
  int i;
  int sum = 0;

  for (i = 0; i < num_ops; i++) {
    sum += i;
  }

  return (void *)(intptr_t)sum;
}

static void
spawn_thread(int thr)
{
  int ret;

  ret = pthread_create(&thr_array[thr], NULL, thr_main, NULL);
  if (ret != 0) {
    fprintf(stderr, "pthread_create: %s\n", strerror(ret));
    exit(1);
  }
}

static void
join_thread(int thr)
{
  int ret;

  ret = pthread_join(thr_array[thr], NULL);
  if (ret != 0) {
    fprintf(stderr, "pthread_join: %s\n", strerror(ret));
    exit(1);
  }
}

int
main(int argc, char *argv[])
{
  int num_spawns;
  int num_threads;
  int thr;
  int thr_saved;
  int ret;
  int spawn_count;

  if (argc != 4) {
    fprintf(stderr, "Usage: oprofile_multithread_test <number of spawns> <number of threads> <number of operations per thread>\n");
    exit(1);
  }

  num_spawns = atoi(argv[1]);
  num_threads = atoi(argv[2]);
  num_ops = atoi(argv[3]);
  if (num_threads < 1) {
    fprintf(stderr, "Number of threads must be positive.\n");
    exit(1);
  }

  thr_array = malloc(sizeof(pthread_t) * num_threads);
  if (thr_array == NULL) {
    fprintf(stderr, "Cannot allocate thr_array\n");
    exit(1);
  }

  spawn_count = 0;
  for (thr = 0; thr < num_threads; thr++) {
    spawn_thread(thr);
    spawn_count++;
  }

  thr = 0;
  while  (num_spawns < 0 ? 1 /* infinite loop */ : spawn_count < num_spawns) {
    join_thread(thr);
    spawn_thread(thr);
    thr = (thr + 1) % num_threads;
    spawn_count++;
  }

  thr_saved = thr;
  do {
    join_thread(thr);
    thr = (thr + 1) % num_threads;    
  } while (thr != thr_saved);

  free(thr_array);
}