Re: And another thing...
Maynard Johnson <[email protected]>
| Newsgroups | gmane.linux.oprofile |
|---|---|
| Message-ID | <[email protected]> |
On 08/01/2014 10:42 AM, Maynard Johnson wrote:
> On 07/31/2014 12:10 PM, Maynard Johnson wrote:
>> On 07/30/2014 05:26 PM, Maynard Johnson wrote:
>>> On 07/30/2014 12:06 PM, Andrew Haley wrote:
>>>> I kept getting "now trying to kill convert pid..." error messages.
>>>> Turns out that there is only a 5s wait for the daemon to terminate,
>>>> which is nowhere near long enough if you have lot of symbols.
>>> Andrew, what were you profiling when you saw this? Unfortunately, the term "convert" is used for two different tasks in the internal workings of operf. First, we have the perf_events-formatted data from the kernel being converted to oprofile sample file format. Second, we run the opjitconv to convert any JVM jitdump files to ELF files. It is the latter task for which you are seeing this message. I agree the fixed time limit is not ideal. I'm guessing you are profiling lots of JVMs to see this message. When profiling a large busy system, the conversion of perf-format data to oprofile sample file format can cause noticeable overhead, and you might want to think about using the --lazy-conversion option in that case.
>>>
>>> As for the patch, I'm not sure I want to change one hard-coded time limit for another. I'll give this some thought.
>> Andrew,
>> I *did* give this some more thought today . . . and realized my analysis above was wrong. Below is a more complete analysis.
>>
>> Unless operf is run with --lazy-conversion, a separate process (the "convert pid" as referred to in the message; 'operf_read_pid' as referred to in the code) is forked to read perf_events-formatted kernel data from a pipe. The pipe writer is another oprofile process -- operf_record_pid -- which is reading the actual kernel data. The operf_read_pid converts this data to oprofile sample files. This conversion process is fairly expensive, so it's not unusual for it to take a little while after profiling stops for it to complete. And the more samples there are (i.e., the longer the profile runs), the longer while it will take. When profiling stops, we call _kill_operf_read_pid and the 5 second timeout begins, waiting for operf_read_pid to finish its conversion. You have obviously bum
ped up against that timeout big time. Having a hard-coded timeout was a bad idea; we should always allow that conversion process to finish. I will post a patch that will show status of con!
v!
> er!
> Andrew . . . I posted a patch to the oprofile-list ("[PATCH] operf main process improperly killing conversion process") to address this issue. Please give it a test drive when you have the time.
Hi, Andrew,
If you can still reproduce the original problem, I would appreciate if you could apply this patch and test if resolves the situation.
Thanks.
-Maynard
>
> Thanks.
> -Maynard
>> sion (prin
>> t a "." for each second of work).
>>
>> Thanks for reporting this.
>>
>> -Maynard
>>
>>>
>>> -Maynard
>>>>
>>>> This fixed it, but a fixed time limit seems wrong:
>>>>
>>>> diff --git a/pe_profiling/operf.cpp b/pe_profiling/operf.cpp
>>>> index 51f55a5..b12aadf 100644
>>>> --- a/pe_profiling/operf.cpp
>>>> +++ b/pe_profiling/operf.cpp
>>>> @@ -492,10 +492,10 @@ static end_code_t _kill_operf_read_pid(end_code_t rc)
>>>> int option = WNOHANG;
>>>> int wait_rc;
>>>> gettimeofday(&tv, NULL);
>>>> - if (tv.tv_sec > start_time_sec + 5) {
>>>> + if (tv.tv_sec > start_time_sec + 45) {
>>>> keep_trying = false;
>>>> option = 0;
>>>> - cerr << "now trying to kill convert pid..." << endl;
>>>> + cerr << "now trying to kill convert pid 45s..." << endl;
>>>>
>>>> if (kill(operf_read_pid, SIGUSR1) < 0) {
>>>> perror("Attempt to stop operf-read process failed");
>>>>
>>>> Andrew.
>>>>
------------------------------------------------------------------------------
Infragistics Professional
Build stunning WinForms apps today!
Reboot your WinForms applications with our WinForms controls.
Build a bridge from your legacy apps to the future.
http://pubads.g.doubleclick.net/gampad/clk?id=153845071&iu=/4140/ostg.clktrk