2012-10-29 16:01:53

by Dhaval Giani

[permalink] [raw]
Subject: [BUG] perf report: different reports when run on terminal as opposed to script

Hi,

As part of a class assignment I have to collect some performance
statistics. In order to do so I run

perf record -g <the program I have to profile>

And in another window, I start 200 threads of the load generator
(which is not recorded by perf)

This generates me statistics that I expect to see, and I am happy. As
this is academia and a class assignment, I need to collect information
and analyze it across different setups. Which of course meant I script
this whole thing, which basically is

for i in all possibilities
do
perf record -g <the program I have to profile> &
WAITPID=$!
for j in NR_THREADS
do
<start load generator> &
KILLPID=$!
done
wait $PID
kill $KILLPID
mv perf.data results/perf.data.$i
done

(This is basic pseudo script of what I am doing), which results me
having my profile being topped by _vscanf() and the function which I
was seeing dominating in the older report dropping down to something
like 5% (as opposed to 16-17%)

Have I misunderstood how perf works? Something deeper? I am currently
on 3.6.3. I can update to the latest upstream and report back. Any
debug code is very welcome. I can also make my toy program and the
scripts available for you to try out.

Thanks!
Dhaval


2012-10-29 16:45:55

by Dhaval Giani

[permalink] [raw]
Subject: Re: [BUG] perf report: different reports when run on terminal as opposed to script

On Mon, Oct 29, 2012 at 12:01 PM, Dhaval Giani <[email protected]> wrote:
> Hi,
>
> As part of a class assignment I have to collect some performance
> statistics. In order to do so I run
>
> perf record -g <the program I have to profile>
>
> And in another window, I start 200 threads of the load generator
> (which is not recorded by perf)
>
> This generates me statistics that I expect to see, and I am happy. As
> this is academia and a class assignment, I need to collect information
> and analyze it across different setups. Which of course meant I script
> this whole thing, which basically is
>
> for i in all possibilities
> do
> perf record -g <the program I have to profile> &
> WAITPID=$!
> for j in NR_THREADS
> do
> <start load generator> &
> KILLPID=$!
> done
> wait $PID
> kill $KILLPID
> mv perf.data results/perf.data.$i
> done
>
> (This is basic pseudo script of what I am doing), which results me
> having my profile being topped by _vscanf() and the function which I
> was seeing dominating in the older report dropping down to something
> like 5% (as opposed to 16-17%)
>
> Have I misunderstood how perf works? Something deeper? I am currently
> on 3.6.3. I can update to the latest upstream and report back. Any
> debug code is very welcome. I can also make my toy program and the
> scripts available for you to try out.

I just updated to 6b0cb4eef7bdaa27b8021ea81813fba330a2d94d and I still
see this happen.

Thanks!
Dhaval

2012-10-30 07:42:47

by Namhyung Kim

[permalink] [raw]
Subject: Re: [BUG] perf report: different reports when run on terminal as opposed to script

Hi Dhaval,

On Mon, 29 Oct 2012 12:45:53 -0400, Dhaval Giani wrote:
> On Mon, Oct 29, 2012 at 12:01 PM, Dhaval Giani <[email protected]> wrote:
>> Hi,
>>
>> As part of a class assignment I have to collect some performance
>> statistics. In order to do so I run
>>
>> perf record -g <the program I have to profile>
>>
>> And in another window, I start 200 threads of the load generator
>> (which is not recorded by perf)
>>
>> This generates me statistics that I expect to see, and I am happy. As
>> this is academia and a class assignment, I need to collect information
>> and analyze it across different setups. Which of course meant I script
>> this whole thing, which basically is
>>
>> for i in all possibilities
>> do
>> perf record -g <the program I have to profile> &
>> WAITPID=$!
>> for j in NR_THREADS
>> do
>> <start load generator> &
>> KILLPID=$!
>> done
>> wait $PID

You meant $WAITPID, right?


>> kill $KILLPID

Doesn't it kill the last load generator only?


>> mv perf.data results/perf.data.$i
>> done
>>
>> (This is basic pseudo script of what I am doing), which results me
>> having my profile being topped by _vscanf() and the function which I
>> was seeing dominating in the older report dropping down to something
>> like 5% (as opposed to 16-17%)
>>
>> Have I misunderstood how perf works? Something deeper? I am currently
>> on 3.6.3. I can update to the latest upstream and report back. Any
>> debug code is very welcome. I can also make my toy program and the
>> scripts available for you to try out.
>
> I just updated to 6b0cb4eef7bdaa27b8021ea81813fba330a2d94d and I still
> see this happen.
>
> Thanks!
> Dhaval

2012-10-30 12:05:48

by Dhaval Giani

[permalink] [raw]
Subject: Re: [BUG] perf report: different reports when run on terminal as opposed to script

On Tue, Oct 30, 2012 at 3:42 AM, Namhyung Kim <[email protected]> wrote:
> Hi Dhaval,
>
> On Mon, 29 Oct 2012 12:45:53 -0400, Dhaval Giani wrote:
>> On Mon, Oct 29, 2012 at 12:01 PM, Dhaval Giani <[email protected]> wrote:
>>> Hi,
>>>
>>> As part of a class assignment I have to collect some performance
>>> statistics. In order to do so I run
>>>
>>> perf record -g <the program I have to profile>
>>>
>>> And in another window, I start 200 threads of the load generator
>>> (which is not recorded by perf)
>>>
>>> This generates me statistics that I expect to see, and I am happy. As
>>> this is academia and a class assignment, I need to collect information
>>> and analyze it across different setups. Which of course meant I script
>>> this whole thing, which basically is
>>>
>>> for i in all possibilities
>>> do
>>> perf record -g <the program I have to profile> &
>>> WAITPID=$!
>>> for j in NR_THREADS
>>> do
>>> <start load generator> &
>>> KILLPID=$!
>>> done
>>> wait $PID
>
> You meant $WAITPID, right?
>

yes. grrr. I changed the name here to WAITPID for it to be clear and
that was a fail. (I blame the cold)

>
>>> kill $KILLPID
>
> Doesn't it kill the last load generator only?
>
>

Well, this was a bug in me typing the pseudo code. the actual script
does "$KILLPID $!"

Dhaval

2012-10-31 07:12:31

by Namhyung Kim

[permalink] [raw]
Subject: Re: [BUG] perf report: different reports when run on terminal as opposed to script

On Tue, 30 Oct 2012 08:05:45 -0400, Dhaval Giani wrote:
> On Tue, Oct 30, 2012 at 3:42 AM, Namhyung Kim <[email protected]> wrote:
>> Hi Dhaval,
>>
>> On Mon, 29 Oct 2012 12:45:53 -0400, Dhaval Giani wrote:
>>> On Mon, Oct 29, 2012 at 12:01 PM, Dhaval Giani <[email protected]> wrote:
>>>> Hi,
>>>>
>>>> As part of a class assignment I have to collect some performance
>>>> statistics. In order to do so I run
>>>>
>>>> perf record -g <the program I have to profile>
>>>>
>>>> And in another window, I start 200 threads of the load generator
>>>> (which is not recorded by perf)
>>>>
>>>> This generates me statistics that I expect to see, and I am happy. As
>>>> this is academia and a class assignment, I need to collect information
>>>> and analyze it across different setups. Which of course meant I script
>>>> this whole thing, which basically is
>>>>
>>>> for i in all possibilities
>>>> do
>>>> perf record -g <the program I have to profile> &
>>>> WAITPID=$!
>>>> for j in NR_THREADS
>>>> do
>>>> <start load generator> &
>>>> KILLPID=$!
>>>> done
>>>> wait $PID
>>
>> You meant $WAITPID, right?
>>
>
> yes. grrr. I changed the name here to WAITPID for it to be clear and
> that was a fail. (I blame the cold)
>
>>
>>>> kill $KILLPID
>>
>> Doesn't it kill the last load generator only?
>>
>>
>
> Well, this was a bug in me typing the pseudo code. the actual script
> does "$KILLPID $!"

Okay, so I suspect that it might be affected by the autogroup scheduling
feature since you said running load generators in another window - I
guess it's a terminal. How about running them with setsid?

Thanks,
Namhyung

2012-10-31 22:15:42

by Dhaval Giani

[permalink] [raw]
Subject: Re: [BUG] perf report: different reports when run on terminal as opposed to script

On Wed, Oct 31, 2012 at 3:12 AM, Namhyung Kim <[email protected]> wrote:
> On Tue, 30 Oct 2012 08:05:45 -0400, Dhaval Giani wrote:
>> On Tue, Oct 30, 2012 at 3:42 AM, Namhyung Kim <[email protected]> wrote:
>>> Hi Dhaval,
>>>
>>> On Mon, 29 Oct 2012 12:45:53 -0400, Dhaval Giani wrote:
>>>> On Mon, Oct 29, 2012 at 12:01 PM, Dhaval Giani <[email protected]> wrote:
>>>>> Hi,
>>>>>
>>>>> As part of a class assignment I have to collect some performance
>>>>> statistics. In order to do so I run
>>>>>
>>>>> perf record -g <the program I have to profile>
>>>>>
>>>>> And in another window, I start 200 threads of the load generator
>>>>> (which is not recorded by perf)
>>>>>
>>>>> This generates me statistics that I expect to see, and I am happy. As
>>>>> this is academia and a class assignment, I need to collect information
>>>>> and analyze it across different setups. Which of course meant I script
>>>>> this whole thing, which basically is
>>>>>
>>>>> for i in all possibilities
>>>>> do
>>>>> perf record -g <the program I have to profile> &
>>>>> WAITPID=$!
>>>>> for j in NR_THREADS
>>>>> do
>>>>> <start load generator> &
>>>>> KILLPID=$!
>>>>> done
>>>>> wait $PID
>>>
>>> You meant $WAITPID, right?
>>>
>>
>> yes. grrr. I changed the name here to WAITPID for it to be clear and
>> that was a fail. (I blame the cold)
>>
>>>
>>>>> kill $KILLPID
>>>
>>> Doesn't it kill the last load generator only?
>>>
>>>
>>
>> Well, this was a bug in me typing the pseudo code. the actual script
>> does "$KILLPID $!"
>
> Okay, so I suspect that it might be affected by the autogroup scheduling
> feature since you said running load generators in another window - I
> guess it's a terminal. How about running them with setsid?
>

Why would that affect the data collection for the program being
profiled? The time spent (since it is a compute intensive program) in
various functions shouldn't change, correct? (Unless I am missing
something).

/me goes and tries it out

Hmm. OK, so that doesn't help. Still the same.

Thanks!
Dhaval