From: Jens Axboe on
On Thu, Sep 10 2009, Ingo Molnar wrote:
>
> * Jens Axboe <jens.axboe(a)oracle.com> wrote:
>
> > On Thu, Sep 10 2009, Jens Axboe wrote:
> > > On Thu, Sep 10 2009, Peter Zijlstra wrote:
> > > > On Wed, 2009-09-09 at 14:20 +0200, Jens Axboe wrote:
> > > > >
> > > > > One thing I also noticed is that when I have logged in, I
> > > > > run xmodmap manually to load some keymappings (I always tell
> > > > > myself to add this to the log in scripts, but I
> > > > > suspend/resume this laptop for weeks at the time and forget
> > > > > before the next boot). With the stock kernel, xmodmap will
> > > > > halt X updates and take forever to run. With BFS, it
> > > > > returned instantly. As I would expect.
> > > >
> > > > Can you provide a little more detail (I'm a xmodmap n00b), how does one
> > > > run xmodmap and maybe provide your xmodmap config?
> > >
> > > Will do, let me get the notebook and strace time it on both bfs and
> > > mainline.
> >
> > Here's the result of running perf stat xmodmap .xmodmap-carl on
> > the notebook. I have attached the .xmodmap-carl file, it's pretty
> > simple. I have also attached the output of strace -o foo -f -tt
> > xmodmap .xmodmap-carl when run on 2.6.31-rc9.
> >
> > 2.6.31-rc9-bfs210
> >
> > Performance counter stats for 'xmodmap .xmodmap-carl':
> >
> > 153.994976 task-clock-msecs # 0.990 CPUs (scaled from 99.86%)
> > 0 context-switches # 0.000 M/sec (scaled from 99.86%)
> > 0 CPU-migrations # 0.000 M/sec (scaled from 99.86%)
> > 315 page-faults # 0.002 M/sec (scaled from 99.86%)
> > <not counted> cycles
> > <not counted> instructions
> > <not counted> cache-references
> > <not counted> cache-misses
> >
> > 0.155573406 seconds time elapsed
>
> (Side question: what hardware is this - why are there no hw
> counters? Could you post the /proc/cpuinfo?)

Sure, attached. It's a Thinkpad x60, core duo. Nothing fancy. The perf
may be a bit dated.

I went to try -tip btw, but it crashes on boot. Here's the backtrace,
typed manually, it's crashing in queue_work_on+0x28/0x60.

Call Trace:
queue_work
schedule_work
clocksource_mark_unstable
mark_tsc_unstable
check_tsc_sync_source
native_cpu_up
relay_hotcpu_callback
do_forK_idle
_cpu_up
cpu_up
kernel_init
kernel_thread_helper

> > Performance counter stats for 'xmodmap .xmodmap-carl':
> >
> > 8.529265 task-clock-msecs # 0.001 CPUs
> > 23 context-switches # 0.003 M/sec
> > 1 CPU-migrations # 0.000 M/sec
> > 315 page-faults # 0.037 M/sec
> > <not counted> cycles
> > <not counted> instructions
> > <not counted> cache-references
> > <not counted> cache-misses
> >
> > 11.804293482 seconds time elapsed
>
> Thanks - so we context-switch 23 times - possibly to Xorg. But 11
> seconds is extremely long. Will try to reproduce it.

There's also the strace info with timings. Xorg is definitely involved,
during those 11s things stop updating completely.

--
Jens Axboe

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Jens Axboe on
On Thu, Sep 10 2009, Ingo Molnar wrote:
>
> * Jens Axboe <jens.axboe(a)oracle.com> wrote:
>
> > On Thu, Sep 10 2009, Peter Zijlstra wrote:
> > > On Wed, 2009-09-09 at 14:20 +0200, Jens Axboe wrote:
> > > >
> > > > One thing I also noticed is that when I have logged in, I run xmodmap
> > > > manually to load some keymappings (I always tell myself to add this to
> > > > the log in scripts, but I suspend/resume this laptop for weeks at the
> > > > time and forget before the next boot). With the stock kernel, xmodmap
> > > > will halt X updates and take forever to run. With BFS, it returned
> > > > instantly. As I would expect.
> > >
> > > Can you provide a little more detail (I'm a xmodmap n00b), how
> > > does one run xmodmap and maybe provide your xmodmap config?
> >
> > Will do, let me get the notebook and strace time it on both bfs
> > and mainline.
>
> A 'perf stat' comparison would be nice as well - that will show us
> events strace doesnt show, and shows us the basic scheduler behavior
> as well.
>
> A 'full' trace could be done as well via trace-cmd.c (attached), if
> you enable:
>
> CONFIG_CONTEXT_SWITCH_TRACER=y
>
> and did something like:
>
> trace-cmd -s xmodmap ... > trace.txt

trace.txt attached. Steven, you seem to go through a lot of trouble to
find the debugfs path, yet at the very end do:

> system("cat /debug/tracing/trace");

which doesn't seem quite right :-)

--
Jens Axboe

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Jens Axboe on
On Wed, Sep 09 2009, Ingo Molnar wrote:
> At least in my tests these latencies were mainly due to a bug in
> latt.c - i've attached the fixed version.

What bug? I don't see any functional change between the version you
attach and the current one.

--
Jens Axboe

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Jens Axboe on
On Thu, Sep 10 2009, Jens Axboe wrote:
> trace.txt attached.

Now it really is, I very much need a more clever MUA to help me with
these things :-)

--
Jens Axboe

From: Ingo Molnar on

* Jens Axboe <jens.axboe(a)oracle.com> wrote:

> On Wed, Sep 09 2009, Ingo Molnar wrote:
> > At least in my tests these latencies were mainly due to a bug in
> > latt.c - i've attached the fixed version.
>
> What bug? I don't see any functional change between the version
> you attach and the current one.

Here's the diff of what i fixed yesterday over the last latt.c
version i found in this thread. The poll() thing is the significant
one.

Ingo

--- latt.c.orig
+++ latt.c
@@ -39,6 +39,7 @@ static unsigned int verbose;
struct stats
{
double n, mean, M2, max;
+ int max_pid;
};

static void update_stats(struct stats *stats, unsigned long long val)
@@ -85,22 +86,6 @@ static double stddev_stats(struct stats
return sqrt(variance);
}

-/*
- * The std dev of the mean is related to the std dev by:
- *
- * s
- * s_mean = -------
- * sqrt(n)
- *
- */
-static double stddev_mean_stats(struct stats *stats)
-{
- double variance = stats->M2 / (stats->n - 1);
- double variance_mean = variance / stats->n;
-
- return sqrt(variance_mean);
-}
-
struct stats delay_stats;

static int pipes[MAX_CLIENTS*2][2];
@@ -212,7 +197,7 @@ static unsigned long usec_since(struct t
static void log_delay(unsigned long delay)
{
if (verbose) {
- fprintf(stderr, "log delay %8lu usec\n", delay);
+ fprintf(stderr, "log delay %8lu usec (pid %d)\n", delay, getpid());
fflush(stderr);
}

@@ -300,7 +285,7 @@ static int __write_ts(int i, struct time
return write(fd, ts, sizeof(*ts)) != sizeof(*ts);
}

-static long __read_ts(int i, struct timespec *ts)
+static long __read_ts(int i, struct timespec *ts, pid_t *cpids)
{
int fd = pipes[2*i+1][0];
struct timespec t;
@@ -309,11 +294,14 @@ static long __read_ts(int i, struct time
return -1;

log_delay(usec_since(ts, &t));
+ if (verbose)
+ fprintf(stderr, "got delay %ld from child %d [pid %d]\n", usec_since(ts, &t), i, cpids[i]);

return 0;
}

-static int read_ts(struct pollfd *pfd, unsigned int nr, struct timespec *ts)
+static int read_ts(struct pollfd *pfd, unsigned int nr, struct timespec *ts,
+ pid_t *cpids)
{
unsigned int i;

@@ -322,7 +310,7 @@ static int read_ts(struct pollfd *pfd, u
return -1L;
if (pfd[i].revents & POLLIN) {
pfd[i].events = 0;
- if (__read_ts(i, &ts[i]))
+ if (__read_ts(i, &ts[i], cpids))
return -1L;
nr--;
}
@@ -368,7 +356,6 @@ static void run_parent(pid_t *cpids)
srand(1234);

do {
- unsigned long delay;
unsigned pending_events;

do_rand_sleep();
@@ -404,17 +391,17 @@ static void run_parent(pid_t *cpids)
*/
pending_events = clients;
while (pending_events) {
- int evts = poll(ipfd, clients, 0);
+ int evts = poll(ipfd, clients, -1);

if (evts < 0) {
do_exit = 1;
break;
} else if (!evts) {
- /* printf("bugger2\n"); */
+ printf("bugger2\n");
continue;
}

- if (read_ts(ipfd, evts, t1)) {
+ if (read_ts(ipfd, evts, t1, cpids)) {
do_exit = 1;
break;
}
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/