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

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

[Mike Galbraith]

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 <efault@gmx.de>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Reported-by: Ingo Molnar <mingo@elte.hu>
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];
 

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

[tip-bot for Mike Galbraith]

Commit-ID:  f4f0b418188cc7995375acbb54e87c80f21861bd
Gitweb:     http://git.kernel.org/tip/f4f0b418188cc7995375acbb54e87c80f21861bd
Author:     Mike Galbraith <efault@gmx.de>
AuthorDate: Tue, 13 Oct 2009 14:57:20 +0200
Committer:  Ingo Molnar <mingo@elte.hu>
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 <mingo@elte.hu>
Signed-off-by: Mike Galbraith <efault@gmx.de>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
LKML-Reference: <1255438640.7173.1.camel@marge.simson.net>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
 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];
 

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

[Ingo Molnar]

* Mike Galbraith <efault@gmx.de> 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

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

[Mike Galbraith]

On Tue, 2009-10-13 at 15:37 +0200, Ingo Molnar wrote:
> * Mike Galbraith <efault@gmx.de> 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

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

[Arnaldo Carvalho de Melo]

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 <efault@gmx.de> 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