From: Matt Mackall <mpm@selenic.com>
To: Ingo Molnar <mingo@elte.hu>
Cc: Rusty Russell <rusty@rustcorp.com.au>,
akpm@linux-foundation.org, Linux-kernel@vger.kernel.org
Subject: Re: Interesting interaction between lguest and CFS
Date: Mon, 4 Jun 2007 13:41:06 -0500 [thread overview]
Message-ID: <20070604184106.GG11115@waste.org> (raw)
In-Reply-To: <20070604175436.GC30274@elte.hu>
On Mon, Jun 04, 2007 at 07:54:36PM +0200, Ingo Molnar wrote:
>
> * Matt Mackall <mpm@selenic.com> wrote:
>
> > With 2.6.22-rc3-mm1, I've got a long-running video transcoding going
> > on. In other windows, I'm compiling, reading email, etc. with no
> > noticeable problems.
> >
> > If I fire up lguest and leave it sitting at a shell prompt for a
> > couple moments, when I return to type something at the prompt, it can
> > take 2-3 seconds for my input to echo. Once it starts responding,
> > typing latency disappears. Suspend the other app and the latency
> > disappears.
> >
> > The system isn't swapping and has basically no I/O load.
>
> could you send me the /proc/PID/sched file of that task which shows this
> 2-3 seconds delay? (if it's a shell and a graphical terminal then please
> send the sched-debug file of both.) I suspect the latency goes away if
> you strace -f the shell task(s)? If not then please send the strace
> output too.
Not sure why the shell task (bash) is interesting here?
gnome-terminal(4177)->bash(4409)->lg(24934)->lguest(24936)->lguest(24944)
(lg is a shell script to launch lguest)
/proc/4177/sched
wait_start : 0
wait_start_fair : 0
exec_start : 0
sleep_start : 53594838106004537
sleep_start_fair : 53575815099165186
block_start : 0
sleep_max : 57476665627
block_max : 18014060106626075
exec_max : 4021419
wait_max : 557161172
last_ran : 0
wait_runtime : 23552233
wait_runtime_overruns : 1864716
wait_runtime_underruns : 310
sum_exec_runtime : 678350336100
clock-delta : 94
cat /proc/4409/sched
wait_start : 0
wait_start_fair : 0
exec_start : 0
sleep_start : 53593602868366272
sleep_start_fair : 53575146154577161
block_start : 0
sleep_max : 2006065218683
block_max : 457256091
exec_max : 3995741
wait_max : 107832482
last_ran : 0
wait_runtime : 23634554
wait_runtime_overruns : 316
wait_runtime_underruns : 9
sum_exec_runtime : 289263702
clock-delta : 83
/proc/24936/sched
wait_start : 0
wait_start_fair : 0
exec_start : 0
sleep_start : 53594765858891273
sleep_start_fair : 53575748785282138
block_start : 0
sleep_max : 21492554
block_max : 27044576
exec_max : 4008057
wait_max : 1253670288
last_ran : 0
wait_runtime : 23955448
wait_runtime_overruns : 270678
wait_runtime_underruns : 1
sum_exec_runtime : 36978464446
clock-delta : 81
/proc/24944/sched
wait_start : 0
wait_start_fair : 0
exec_start : 0
sleep_start : 53594628265104224
sleep_start_fair : 53575623092295018
block_start : 0
sleep_max : 223179035512
block_max : 0
exec_max : 3960054
wait_max : 4334838886
last_ran : 0
wait_runtime : 23959470
wait_runtime_overruns : 1243
wait_runtime_underruns : 15
sum_exec_runtime : 17872418
clock-delta : 81
strace -f doesn't kill the latency, here's an strace:
24936 13:39:44.469329 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:44.469572 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:44.469677 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:44.469765 read(7, 0xbfe6c010, 8) = -1 EINTR (Interrupted system call)
24936 13:39:48.699490 --- SIGUSR1 (User defined signal 1) @ 0 (0) ---
24936 13:39:48.699655 sigreturn() = ? (mask now [])
24936 13:39:48.699842 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.699939 select(4, [0 3], NULL, NULL, {0, 0}) = 1 (in [0], left {0, 0})
24936 13:39:48.700063 write(7, "\1\0\0\0\0\0\0\0", 8) = 5675552
24936 13:39:48.700168 readv(0, [{"sdfsdfsdfsdfsdon\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 256}], 1) = 14
24936 13:39:48.700360 write(7, "\2\0\0\0\3\0\0\0", 8) = 0
24936 13:39:48.700451 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.700547 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.700635 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.700872 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.700962 writev(1, [{"s", 1}], 1) = 1
24936 13:39:48.701200 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.701297 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.701385 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.701495 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.701584 writev(1, [{"d", 1}], 1) = 1
24936 13:39:48.701773 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.701870 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.701957 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.702061 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.702149 writev(1, [{"f", 1}], 1) = 1
24936 13:39:48.702336 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.702431 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.702519 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.702622 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.702710 writev(1, [{"s", 1}], 1) = 1
24936 13:39:48.702898 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.702993 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.703157 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.703264 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.703352 writev(1, [{"d", 1}], 1) = 1
24936 13:39:48.703541 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.703636 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.703724 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.703828 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.703916 writev(1, [{"f", 1}], 1) = 1
24936 13:39:48.704103 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.704198 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.704285 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.704389 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.704476 writev(1, [{"s", 1}], 1) = 1
24936 13:39:48.704662 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.704758 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.704845 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.704948 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.705036 writev(1, [{"d", 1}], 1) = 1
24936 13:39:48.705222 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.705317 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.705405 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.705508 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.705595 writev(1, [{"f", 1}], 1) = 1
24936 13:39:48.705781 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.705877 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.705964 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.706068 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.706155 writev(1, [{"s", 1}], 1) = 1
24936 13:39:48.706341 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.706483 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.706571 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.706675 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.706763 writev(1, [{"d", 1}], 1) = 1
24936 13:39:48.706950 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.707045 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.707221 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.707325 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.707414 writev(1, [{"f", 1}], 1) = 1
24936 13:39:48.707600 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.707695 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.707800 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.707904 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.707992 writev(1, [{"s", 1}], 1) = 1
24936 13:39:48.708177 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.708273 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.708360 read(7, "P\216\304\2\0\0\0\0", 8) = 8
24936 13:39:48.708463 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.708551 writev(1, [{"d", 1}], 1) = 1
24936 13:39:48.708736 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.708832 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.708919 read(7, 0xbfe6c010, 8) = -1 EINTR (Interrupted system call)
24936 13:39:48.951555 --- SIGUSR1 (User defined signal 1) @ 0 (0) ---
24936 13:39:48.951697 sigreturn() = ? (mask now [])
24936 13:39:48.951884 rt_sigprocmask(SIG_BLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.951983 select(4, [0 3], NULL, NULL, {0, 0}) = 0 (Timeout)
24936 13:39:48.952092 rt_sigprocmask(SIG_UNBLOCK, [USR1], NULL, 8) = 0
24936 13:39:48.952184 read(7, <unfinished ...>
--
Mathematics is the supreme nostalgia of our time.
next prev parent reply other threads:[~2007-06-04 18:41 UTC|newest]
Thread overview: 38+ messages / expand[flat|nested] mbox.gz Atom feed top
2007-06-04 17:37 Interesting interaction between lguest and CFS Matt Mackall
2007-06-04 17:54 ` Ingo Molnar
2007-06-04 18:41 ` Matt Mackall [this message]
2007-06-05 7:19 ` Ingo Molnar
2007-06-05 14:03 ` Matt Mackall
2007-06-05 15:14 ` Dmitry Adamushko
2007-06-05 15:41 ` Dmitry Adamushko
2007-06-05 19:50 ` Ingo Molnar
2007-06-06 20:23 ` Matt Mackall
2007-06-08 9:34 ` Ingo Molnar
2007-06-08 10:18 ` Ingo Molnar
2007-06-04 18:11 ` Ingo Molnar
2007-06-04 18:42 ` Matt Mackall
2007-06-04 19:12 ` Ingo Molnar
2007-06-04 19:27 ` Matt Mackall
2007-06-04 19:40 ` Ingo Molnar
2007-06-04 19:59 ` Matt Mackall
2007-06-04 20:13 ` Ingo Molnar
2007-06-04 20:20 ` Ingo Molnar
2007-06-04 20:15 ` James Morris
2007-06-04 20:24 ` Ingo Molnar
2007-06-04 22:58 ` Olof Johansson
2007-06-05 1:02 ` Rusty Russell
2007-06-05 1:24 ` Stephen Rothwell
2007-06-05 2:23 ` Olof Johansson
2007-06-05 0:18 ` Rusty Russell
2007-06-05 2:31 ` Rusty Russell
2007-06-05 4:18 ` Matt Mackall
2007-06-05 4:37 ` Rusty Russell
2007-06-05 13:49 ` Matt Mackall
2007-06-05 19:38 ` Ingo Molnar
2007-06-05 10:43 ` Ingo Molnar
2007-06-05 19:08 ` Ingo Molnar
2007-06-06 20:19 ` Matt Mackall
2007-06-05 2:34 ` Matt Mackall
2007-06-05 7:10 ` Ingo Molnar
2007-06-05 9:23 ` Ingo Molnar
2007-06-05 14:06 ` Matt Mackall
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20070604184106.GG11115@waste.org \
--to=mpm@selenic.com \
--cc=Linux-kernel@vger.kernel.org \
--cc=akpm@linux-foundation.org \
--cc=mingo@elte.hu \
--cc=rusty@rustcorp.com.au \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.