2009-10-13 12:58:15

by Mike Galbraith

[permalink] [raw]
Subject: [patch] perf_counter tools: remove expensive old debug code from perf top


perf_counter tools: remove expensive old debug code from perf top

Calling gettimeofday() at high frequency is painful for handicapped boxen.
The spot calling gettimeofday() is old unneeded debug code, so remove it.

Signed-off-by: Mike Galbraith <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Reported-by: Ingo Molnar <[email protected]>
LKML-Reference: <new-submission>

---
tools/perf/builtin-top.c | 15 +--------------
1 file changed, 1 insertion(+), 14 deletions(-)

Index: linux-2.6/tools/perf/builtin-top.c
===================================================================
--- linux-2.6.orig/tools/perf/builtin-top.c
+++ linux-2.6/tools/perf/builtin-top.c
@@ -870,8 +870,6 @@ static unsigned int mmap_read_head(struc
return head;
}

-struct timeval last_read, this_read;
-
static void mmap_read_counter(struct mmap_data *md)
{
unsigned int head = mmap_read_head(md);
@@ -879,8 +877,6 @@ static void mmap_read_counter(struct mma
unsigned char *data = md->base + page_size;
int diff;

- gettimeofday(&this_read, NULL);
-
/*
* If we're further behind than half the buffer, there's a chance
* the writer will bite our tail and mess up the samples under us.
@@ -891,14 +887,7 @@ static void mmap_read_counter(struct mma
*/
diff = head - old;
if (diff > md->mask / 2 || diff < 0) {
- struct timeval iv;
- unsigned long msecs;
-
- timersub(&this_read, &last_read, &iv);
- msecs = iv.tv_sec*1000 + iv.tv_usec/1000;
-
- fprintf(stderr, "WARNING: failed to keep up with mmap data."
- " Last read %lu msecs ago.\n", msecs);
+ fprintf(stderr, "WARNING: failed to keep up with mmap data.\n");

/*
* head points to a known good entry, start there.
@@ -906,8 +895,6 @@ static void mmap_read_counter(struct mma
old = head;
}

- last_read = this_read;
-
for (; old != head;) {
event_t *event = (event_t *)&data[old & md->mask];



2009-10-13 13:35:41

by Mike Galbraith

[permalink] [raw]
Subject: [tip:perf/core] perf tools: Remove expensive old debug code from perf top

Commit-ID: f4f0b418188cc7995375acbb54e87c80f21861bd
Gitweb: http://git.kernel.org/tip/f4f0b418188cc7995375acbb54e87c80f21861bd
Author: Mike Galbraith <[email protected]>
AuthorDate: Tue, 13 Oct 2009 14:57:20 +0200
Committer: Ingo Molnar <[email protected]>
CommitDate: Tue, 13 Oct 2009 15:30:15 +0200

perf tools: Remove expensive old debug code from perf top

Calling gettimeofday() at high frequency is painful for handicapped
boxen. The spot calling gettimeofday() is old unneeded debug code,
so remove it.

Reported-by: Ingo Molnar <[email protected]>
Signed-off-by: Mike Galbraith <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Peter Zijlstra <[email protected]>
LKML-Reference: <[email protected]>
Signed-off-by: Ingo Molnar <[email protected]>
---
tools/perf/builtin-top.c | 15 +--------------
1 files changed, 1 insertions(+), 14 deletions(-)

diff --git a/tools/perf/builtin-top.c b/tools/perf/builtin-top.c
index c0f69e8..2d8806b 100644
--- a/tools/perf/builtin-top.c
+++ b/tools/perf/builtin-top.c
@@ -870,8 +870,6 @@ static unsigned int mmap_read_head(struct mmap_data *md)
return head;
}

-struct timeval last_read, this_read;
-
static void mmap_read_counter(struct mmap_data *md)
{
unsigned int head = mmap_read_head(md);
@@ -879,8 +877,6 @@ static void mmap_read_counter(struct mmap_data *md)
unsigned char *data = md->base + page_size;
int diff;

- gettimeofday(&this_read, NULL);
-
/*
* If we're further behind than half the buffer, there's a chance
* the writer will bite our tail and mess up the samples under us.
@@ -891,14 +887,7 @@ static void mmap_read_counter(struct mmap_data *md)
*/
diff = head - old;
if (diff > md->mask / 2 || diff < 0) {
- struct timeval iv;
- unsigned long msecs;
-
- timersub(&this_read, &last_read, &iv);
- msecs = iv.tv_sec*1000 + iv.tv_usec/1000;
-
- fprintf(stderr, "WARNING: failed to keep up with mmap data."
- " Last read %lu msecs ago.\n", msecs);
+ fprintf(stderr, "WARNING: failed to keep up with mmap data.\n");

/*
* head points to a known good entry, start there.
@@ -906,8 +895,6 @@ static void mmap_read_counter(struct mmap_data *md)
old = head;
}

- last_read = this_read;
-
for (; old != head;) {
event_t *event = (event_t *)&data[old & md->mask];

2009-10-13 13:37:56

by Ingo Molnar

[permalink] [raw]
Subject: Re: [patch] perf_counter tools: remove expensive old debug code from perf top


* Mike Galbraith <[email protected]> wrote:

> perf_counter tools: remove expensive old debug code from perf top
>
> Calling gettimeofday() at high frequency is painful for handicapped
> boxen. The spot calling gettimeofday() is old unneeded debug code, so
> remove it.

Thanks!

We still seem to have a performance problem. Just running perf top on a
16-way box:

Performance counter stats for 'perf top -e cycles -c 3000000':

585.694831 task-clock-msecs # 0.113 CPUs
35163 context-switches # 0.060 M/sec
17 CPU-migrations # 0.000 M/sec
20355 page-faults # 0.035 M/sec
1476952962 cycles # 2521.711 M/sec
730770658 instructions # 0.495 IPC
11489471 cache-references # 19.617 M/sec
2055001 cache-misses # 3.509 M/sec

5.169518576 seconds time elapsed

that's 11% of CPU time used on a single CPU - just displaying a measly
16K irqs/sec. Something's not quite right here.

Ingo

2009-10-13 14:42:51

by Mike Galbraith

[permalink] [raw]
Subject: Re: [patch] perf_counter tools: remove expensive old debug code from perf top

On Tue, 2009-10-13 at 15:37 +0200, Ingo Molnar wrote:
> * Mike Galbraith <[email protected]> wrote:
>
> > perf_counter tools: remove expensive old debug code from perf top
> >
> > Calling gettimeofday() at high frequency is painful for handicapped
> > boxen. The spot calling gettimeofday() is old unneeded debug code, so
> > remove it.
>
> Thanks!
>
> We still seem to have a performance problem. Just running perf top on a
> 16-way box:
>
> Performance counter stats for 'perf top -e cycles -c 3000000':
>
> 585.694831 task-clock-msecs # 0.113 CPUs
> 35163 context-switches # 0.060 M/sec
> 17 CPU-migrations # 0.000 M/sec
> 20355 page-faults # 0.035 M/sec
> 1476952962 cycles # 2521.711 M/sec
> 730770658 instructions # 0.495 IPC
> 11489471 cache-references # 19.617 M/sec
> 2055001 cache-misses # 3.509 M/sec
>
> 5.169518576 seconds time elapsed
>
> that's 11% of CPU time used on a single CPU - just displaying a measly
> 16K irqs/sec. Something's not quite right here.

I'll try to figure out why after I do some more wakeup preempt testing.

btw, something broke top annotation (again). Module symbols still
annotate, but vmlinux symbols went south.

-Mike

2009-10-13 14:43:57

by Arnaldo Carvalho de Melo

[permalink] [raw]
Subject: Re: [patch] perf_counter tools: remove expensive old debug code from perf top

Em Tue, Oct 13, 2009 at 04:41:59PM +0200, Mike Galbraith escreveu:
> On Tue, 2009-10-13 at 15:37 +0200, Ingo Molnar wrote:
> > * Mike Galbraith <[email protected]> wrote:
> >
> > > perf_counter tools: remove expensive old debug code from perf top
> > >
> > > Calling gettimeofday() at high frequency is painful for handicapped
> > > boxen. The spot calling gettimeofday() is old unneeded debug code, so
> > > remove it.
> >
> > Thanks!
> >
> > We still seem to have a performance problem. Just running perf top on a
> > 16-way box:
> >
> > Performance counter stats for 'perf top -e cycles -c 3000000':
> >
> > 585.694831 task-clock-msecs # 0.113 CPUs
> > 35163 context-switches # 0.060 M/sec
> > 17 CPU-migrations # 0.000 M/sec
> > 20355 page-faults # 0.035 M/sec
> > 1476952962 cycles # 2521.711 M/sec
> > 730770658 instructions # 0.495 IPC
> > 11489471 cache-references # 19.617 M/sec
> > 2055001 cache-misses # 3.509 M/sec
> >
> > 5.169518576 seconds time elapsed
> >
> > that's 11% of CPU time used on a single CPU - just displaying a measly
> > 16K irqs/sec. Something's not quite right here.
>
> I'll try to figure out why after I do some more wakeup preempt testing.
>
> btw, something broke top annotation (again). Module symbols still
> annotate, but vmlinux symbols went south.

I'll check this one, and I'm profiling perf top as well.

- Arnaldo