Re: [PATCH v2 1/6] TTY: serial, remove BTM from wait_until_sent

From: Andreas Bombe
Date: Tue Aug 09 2011 - 21:09:46 EST

On Mon, Aug 08, 2011 at 03:21:22PM +0200, Jiri Slaby wrote:
> On 07/19/2011 02:35 AM, Andreas Bombe wrote:
> > On Thu, Jul 14, 2011 at 02:35:10PM +0200, Jiri Slaby wrote:
> >> This should also fix the issue Andreas is seeing (BTM in comparison to
> >> BKL doesn't have any hidden functionality like unlocking during
> >> sleeping).
> >
> > I tested the patch series and it does not appear to make a difference
> > for the internal (16550A) serial ports on my system. Also, I am still
> > unclear on why it freezes the X display during the timeout period.
>
> Sorry for the delay. Could you attach output of sysrq-t when this
> happens? I mean with a kernel patched by my patch.

I did my simple test on ttyS0 again: "stty -F /dev/ttyS0 crtscts" then
"echo >/dev/ttyS0". I attached the gzipped sysrq-t list in case you need
the complete output. This is just the process while it is trying to
close the device (bash's internal echo):

[ 321.948012] bash S ffff8800bcc85e80 0 4000 2828 0x00000000
[ 321.948012] ffff880127079c38 0000000000000046 ffff880127079c50 0000000100002fff
[ 321.948012] ffff880127079fd8 0000000000011fc0 ffff880127079fd8 0000000000011fc0
[ 321.948012] ffff8801270dde80 ffff8800bcc85e80 ffff880127079c38 0000000100002fff
[ 321.948012] Call Trace:
[ 321.948012] [<ffffffff813cdf2e>] schedule_timeout+0xb5/0xf2
[ 321.948012] [<ffffffff8104ae2b>] ? call_timer_fn+0x154/0x154
[ 321.948012] [<ffffffff81255d60>] tty_wait_until_sent+0xa3/0xec
[ 321.948012] [<ffffffff8105a190>] ? __init_waitqueue_head+0x46/0x46
[ 321.948012] [<ffffffff81268c05>] uart_close+0x12b/0x243
[ 321.948012] [<ffffffff81250454>] ? __tty_fasync+0x5c/0x124
[ 321.948012] [<ffffffff81251a00>] tty_release+0x1d3/0x4d7
[ 321.948012] [<ffffffff813cfbd8>] ? _raw_spin_unlock+0x43/0x51
[ 321.948012] [<ffffffff8110db81>] ? dput+0xfe/0x11d
[ 321.948012] [<ffffffff810fdc86>] __fput+0x107/0x1a2
[ 321.948012] [<ffffffff810fdd36>] fput+0x15/0x17
[ 321.948012] [<ffffffff810fb014>] filp_close+0x69/0x75
[ 321.948012] [<ffffffff81109654>] sys_dup3+0x12b/0x153
[ 321.948012] [<ffffffff811096d5>] sys_dup2+0x59/0x60
[ 321.948012] [<ffffffff813d0a12>] system_call_fastpath+0x16/0x1b


[ 321.948012] Sched Debug Version: v0.10, 3.1.0-rc1+ser-00011-g37ed45d #87
[ 321.948012] ktime : 321967.638593
[ 321.948012] sched_clk : 321738.307013
[ 321.948012] cpu_clk : 321948.012318
[ 321.948012] jiffies : 4294972787
[ 321.948012] sched_clock_stable : 0
[ 321.948012]
[ 321.948012] sysctl_sched
[ 321.948012] .sysctl_sched_latency : 12.000000
[ 321.948012] .sysctl_sched_min_granularity : 1.500000
[ 321.948012] .sysctl_sched_wakeup_granularity : 2.000000
[ 321.948012] .sysctl_sched_child_runs_first : 0
[ 321.948012] .sysctl_sched_features : 15471
[ 321.948012] .sysctl_sched_tunable_scaling : 1 (logaritmic)
[ 321.948012]
[ 321.948012] cpu#0, 3166.466 MHz
[ 321.948012] .nr_running : 2
[ 321.948012] .load : 1927
[ 321.948012] .nr_switches : 181895
[ 321.948012] .nr_load_updates : 28885
[ 321.948012] .nr_uninterruptible : 58
[ 321.948012] .next_balance : 4294.972819
[ 321.948012] .curr->pid : 11
[ 321.948012] .clock : 321964.006925
[ 321.948012] .cpu_load[0] : 1927
[ 321.948012] .cpu_load[1] : 1743
[ 321.948012] .cpu_load[2] : 1400
[ 321.948012] .cpu_load[3] : 1137
[ 321.948012] .cpu_load[4] : 871
[ 321.948012] .yld_count : 20444
[ 321.948012] .sched_switch : 0
[ 321.948012] .sched_count : 203439
[ 321.948012] .sched_goidle : 58617
[ 321.948012] .avg_idle : 1000000
[ 321.948012] .ttwu_count : 112788
[ 321.948012] .ttwu_local : 63063
[ 321.948012]
[ 321.948012] cfs_rq[0]:/autogroup-58
[ 321.948012] .exec_clock : 995.435149
[ 321.948012] .MIN_vruntime : 962.061080
[ 321.948012] .min_vruntime : 962.061080
[ 321.948012] .max_vruntime : 962.061080
[ 321.948012] .spread : 0.000000
[ 321.948012] .spread0 : -22090.643266
[ 321.948012] .nr_spread_over : 0
[ 321.948012] .nr_running : 1
[ 321.948012] .load : 1024
[ 321.948012] .load_avg : 6435.076254
[ 321.948012] .load_period : 6.287393
[ 321.948012] .load_contrib : 1004
[ 321.948012] .load_tg : 1140
[ 321.948012] .se->exec_start : 321727.319580
[ 321.948012] .se->vruntime : 23059.712463
[ 321.948012] .se->sum_exec_runtime : 995.837577
[ 321.948012] .se->statistics.wait_start : 321964.006925
[ 321.948012] .se->statistics.sleep_start : 0.000000
[ 321.948012] .se->statistics.block_start : 0.000000
[ 321.948012] .se->statistics.sleep_max : 0.000000
[ 321.948012] .se->statistics.block_max : 0.000000
[ 321.948012] .se->statistics.exec_max : 4.000979
[ 321.948012] .se->statistics.slice_max : 2.977407
[ 321.948012] .se->statistics.wait_max : 8.300527
[ 321.948012] .se->statistics.wait_sum : 309.360276
[ 321.948012] .se->statistics.wait_count : 8489
[ 321.948012] .se->load.weight : 903
[ 321.948012]
[ 321.948012] cfs_rq[0]:/
[ 321.948012] .exec_clock : 20767.422942
[ 321.948012] .MIN_vruntime : 23059.712463
[ 321.948012] .min_vruntime : 23052.704346
[ 321.948012] .max_vruntime : 23059.712463
[ 321.948012] .spread : 0.000000
[ 321.948012] .spread0 : 0.000000
[ 321.948012] .nr_spread_over : 73
[ 321.948012] .nr_running : 2
[ 321.948012] .load : 1927
[ 321.948012] .load_avg : 0.000000
[ 321.948012] .load_period : 0.000000
[ 321.948012] .load_contrib : 0
[ 321.948012] .load_tg : 0
[ 321.948012]
[ 321.948012] rt_rq[0]:
[ 321.948012] .rt_nr_running : 0
[ 321.948012] .rt_throttled : 0
[ 321.948012] .rt_time : 0.000000
[ 321.948012] .rt_runtime : 950.000000
[ 321.948012]
[ 321.948012] runnable tasks:
[ 321.948012] task PID tree-key switches prio exec-runtime sum-exec sum-sleep
[ 321.948012] ----------------------------------------------------------------------------------------------------------
[ 321.948012] R kworker/0:1 11 23052.704346 13969 120 23052.704346 555.720586 321027.845811 /
[ 321.948012] alsa-sink 3110 962.061080 4307 120 962.061080 1411.254175 258698.264923 /autogroup-58
[ 321.948012]
[ 321.948012] cpu#1, 3166.466 MHz
[ 321.948012] .nr_running : 0
[ 321.948012] .load : 0
[ 321.948012] .nr_switches : 206709
[ 321.948012] .nr_load_updates : 30117
[ 321.948012] .nr_uninterruptible : -58
[ 321.948012] .next_balance : 4294.972776
[ 321.948012] .curr->pid : 0
[ 321.948012] .clock : 321846.477751
[ 321.948012] .cpu_load[0] : 947
[ 321.948012] .cpu_load[1] : 481
[ 321.948012] .cpu_load[2] : 282
[ 321.948012] .cpu_load[3] : 183
[ 321.948012] .cpu_load[4] : 133
[ 321.948012] .yld_count : 26864
[ 321.948012] .sched_switch : 0
[ 321.948012] .sched_count : 233886
[ 321.948012] .sched_goidle : 75296
[ 321.948012] .avg_idle : 1000000
[ 321.948012] .ttwu_count : 96142
[ 321.948012] .ttwu_local : 60872
[ 321.948012]
[ 321.948012] cfs_rq[1]:/autogroup-58
[ 321.948012] .exec_clock : 1096.255751
[ 321.948012] .MIN_vruntime : 0.000001
[ 321.948012] .min_vruntime : 1043.264049
[ 321.948012] .max_vruntime : 0.000001
[ 321.948012] .spread : 0.000000
[ 321.948012] .spread0 : -22009.440297
[ 321.948012] .nr_spread_over : 0
[ 321.948012] .nr_running : 0
[ 321.948012] .load : 0
[ 321.948012] .load_avg : 894.748356
[ 321.948012] .load_period : 6.572338
[ 321.948012] .load_contrib : 136
[ 321.948012] .load_tg : 1140
[ 321.948012] .se->exec_start : 321808.596733
[ 321.948012] .se->vruntime : 20943.081256
[ 321.948012] .se->sum_exec_runtime : 1096.712219
[ 321.948012] .se->statistics.wait_start : 0.000000
[ 321.948012] .se->statistics.sleep_start : 0.000000
[ 321.948012] .se->statistics.block_start : 0.000000
[ 321.948012] .se->statistics.sleep_max : 0.000000
[ 321.948012] .se->statistics.block_max : 0.000000
[ 321.948012] .se->statistics.exec_max : 4.042092
[ 321.948012] .se->statistics.slice_max : 1.274462
[ 321.948012] .se->statistics.wait_max : 11.013496
[ 321.948012] .se->statistics.wait_sum : 303.941198
[ 321.948012] .se->statistics.wait_count : 8528
[ 321.948012] .se->load.weight : 2
[ 321.948012]
[ 321.948012] cfs_rq[1]:/autogroup-53
[ 321.948012] .exec_clock : 5152.934351
[ 321.948012] .MIN_vruntime : 0.000001
[ 321.948012] .min_vruntime : 10693.441896
[ 321.948012] .max_vruntime : 0.000001
[ 321.948012] .spread : 0.000000
[ 321.948012] .spread0 : -12359.262450
[ 321.948012] .nr_spread_over : 81
[ 321.948012] .nr_running : 0
[ 321.948012] .load : 0
[ 321.948012] .load_avg : 124.928296
[ 321.948012] .load_period : 6.455088
[ 321.948012] .load_contrib : 19
[ 321.948012] .load_tg : 19
[ 321.948012] .se->exec_start : 321807.916228
[ 321.948012] .se->vruntime : 20936.418846
[ 321.948012] .se->sum_exec_runtime : 5153.129023
[ 321.948012] .se->statistics.wait_start : 0.000000
[ 321.948012] .se->statistics.sleep_start : 0.000000
[ 321.948012] .se->statistics.block_start : 0.000000
[ 321.948012] .se->statistics.sleep_max : 0.000000
[ 321.948012] .se->statistics.block_max : 0.000000
[ 321.948012] .se->statistics.exec_max : 4.032091
[ 321.948012] .se->statistics.slice_max : 7.996020
[ 321.948012] .se->statistics.wait_max : 32.784820
[ 321.948012] .se->statistics.wait_sum : 839.992046
[ 321.948012] .se->statistics.wait_count : 55429
[ 321.948012] .se->load.weight : 2
[ 321.948012]
[ 321.948012] cfs_rq[1]:/
[ 321.948012] .exec_clock : 18512.679083
[ 321.948012] .MIN_vruntime : 0.000001
[ 321.948012] .min_vruntime : 20943.081256
[ 321.948012] .max_vruntime : 0.000001
[ 321.948012] .spread : 0.000000
[ 321.948012] .spread0 : -2109.623090
[ 321.948012] .nr_spread_over : 91
[ 321.948012] .nr_running : 0
[ 321.948012] .load : 0
[ 321.948012] .load_avg : 0.000000
[ 321.948012] .load_period : 0.000000
[ 321.948012] .load_contrib : 0
[ 321.948012] .load_tg : 0
[ 321.948012]
[ 321.948012] rt_rq[1]:
[ 321.948012] .rt_nr_running : 0
[ 321.948012] .rt_throttled : 0
[ 321.948012] .rt_time : 0.000000
[ 321.948012] .rt_runtime : 950.000000
[ 321.948012]
[ 321.948012] runnable tasks:
[ 321.948012] task PID tree-key switches prio exec-runtime sum-exec sum-sleep
[ 321.948012] ----------------------------------------------------------------------------------------------------------
[ 321.948012]
[ 321.948012] INFO: lockdep is turned off.

--
Andreas Bombe

Attachment: dmesg.sysrqt-complete.gz
Description: Binary data