bug#11822: 24.1; emacsclient terminal mode captures escape characters as text

[Ken Raeburn <raeburn@permabit.com>]

I've chased the sluggishness down a little further.

I'm using

   emacsclient -c -a "" -n

to pop up a new frame.

If I attach the Emacs process under GDB during the delay while I wait 
for the new frame to be fully displayed, the call stack tends to look 
like this:

#0  0x00007fa626cc18d8 in poll () from /lib/libc.so.6
#1  0x00007fa6265d98ca in ?? () from /usr/lib/libxcb.so.1
#2  0x00007fa6265dbc0c in xcb_wait_for_reply () from /usr/lib/libxcb.so.1
#3  0x00007fa62a0a7613 in _XReply () from /usr/lib/libX11.so.6
#4  0x00007fa62a0831a5 in XAllocColor () from /usr/lib/libX11.so.6
#5  0x00000000004b621c in x_alloc_nearest_color_1 (dpy=0x7fff726fdc40, 
cmap=1, color=0xffffffffffffffff) at xterm.c:1730
#6  0x00000000004cb023 in x_defined_color (f=0x52fff50, 
color_name=<optimized out>, color=0x7fff726fde70, alloc_p=1) at xfns.c:613
#7  0x00000000004a9adc in load_color (f=0x7fff726fdc40, face=0x53e7b70, 
name=102599361, target_index=LFACE_FOREGROUND_INDEX) at xfaces.c:1336
#8  0x00000000004abc53 in load_face_colors (attrs=<optimized out>, 
face=<optimized out>, f=<optimized out>) at xfaces.c:1422
#9  realize_x_face (attrs=<optimized out>, cache=<optimized out>) at 
xfaces.c:5629
#10 realize_face (cache=0x3e3ec30, attrs=0x7fff726fdfe0, 
former_face_id=<optimized out>) at xfaces.c:5501
#11 0x00000000004b0eed in realize_named_face (f=<optimized out>, 
symbol=<optimized out>, id=7) at xfaces.c:5473
#12 0x00000000004b1145 in realize_basic_faces (f=0x52fff50) at xfaces.c:5295
#13 0x00000000004b17cd in recompute_basic_faces (f=0x52fff50) at 
xfaces.c:839
#14 0x000000000043938d in init_iterator (it=0x7fff726fe1e0, w=0x56d0850, 
charpos=-1, bytepos=-1, row=0x0, base_face_id=DEFAULT_FACE_ID) at 
xdisp.c:2618
#15 0x000000000044962b in x_consider_frame_title (frame=<optimized out>) 
at xdisp.c:10972
#16 0x0000000000449774 in prepare_menu_bars () at xdisp.c:11031
#17 0x0000000000455b95 in redisplay_internal () at xdisp.c:12944
#18 0x0000000000456575 in redisplay_preserve_echo_area 
(from_where=1919933504) at xdisp.c:13560
#19 0x00000000005b3288 in Fdelete_process (process=69478117) at 
process.c:796
#20 0x000000000056c9fc in Ffuncall (nargs=<optimized out>, 
args=<optimized out>) at eval.c:3002
#21 0x00000000005a6ef5 in exec_byte_code (bytestr=<optimized out>, 
vector=<optimized out>, maxdepth=<optimized out>, 
args_template=<optimized out>, nargs=104812360, args=0x33a5) at 
bytecode.c:785
...

Lisp Backtrace:
"delete-process" (0x72700b50)
"server-delete-client" (0x72700ce0)
0x4c33b60 PVEC_COMPILED
"funcall" (0x72700e40)
0x4bde3c0 PVEC_COMPILED
"funcall" (0x72701260)
"server-execute" (0x727016b8)
0x4e59700 PVEC_COMPILED
0x4a72ac0 PVEC_COMPILED
"funcall" (0x72701970)
"server-execute-continuation" (0x72701de8)
...

Sometimes it's XParseColor instead of XAllocColor.

When I pop up a new frame, it appears that recompute_basic_faces is 
called three times for the new frame, and once for each existing one:

Breakpoint 3, recompute_basic_faces (f=0x4d75e00) at xfaces.c:835
835    {
(gdb) c
Continuing.

Breakpoint 3, recompute_basic_faces (f=0x4d75e00) at xfaces.c:835
835    {
(gdb)
Continuing.

Breakpoint 3, recompute_basic_faces (f=0x4d75e00) at xfaces.c:835
835    {
(gdb)
Continuing.

Breakpoint 3, recompute_basic_faces (f=0x61a7090) at xfaces.c:835
835    {
(gdb)
Continuing.

Breakpoint 3, recompute_basic_faces (f=0x698a7c0) at xfaces.c:835
835    {
(gdb)
Continuing.

...

I also noticed that the remote frame (in this case, 0x52fff50, which 
happens to be the one shown in the C stack trace above, is displayed 
over SSH + VPN + a slow net connection) takes quite a bit longer to 
process before moving on to the next recompute_basic_faces call.  I've 
been using this Emacs process actively today, including creating a few 
new frames, but haven't touched the frame displayed remotely since at 
least last night, possibly longer.  Yet this recompute_basic_faces work 
still gets done each time.


If I try creating a new tty frame, the stack trace is a bit different:

#0  0x00007fa626cc18d8 in poll () from /lib/libc.so.6
#1  0x00007fa6265d98ca in ?? () from /usr/lib/libxcb.so.1
#2  0x00007fa6265dbc0c in xcb_wait_for_reply () from /usr/lib/libxcb.so.1
#3  0x00007fa62a0a7613 in _XReply () from /usr/lib/libX11.so.6
#4  0x00007fa62a08fb11 in XParseColor () from /usr/lib/libX11.so.6
#5  0x00000000004cafa4 in x_defined_color (f=0x52fff50, 
color_name=<optimized out>, color=0x7fff726fe430, alloc_p=1) at xfns.c:611
#6  0x00000000004a9adc in load_color (f=0x7fff726fe210, face=0x4b738f0, 
name=102599489, target_index=LFACE_BACKGROUND_INDEX) at xfaces.c:1336
#7  0x00000000004abc38 in load_face_colors (attrs=<optimized out>, 
face=<optimized out>, f=<optimized out>) at xfaces.c:1421
#8  realize_x_face (attrs=<optimized out>, cache=<optimized out>) at 
xfaces.c:5629
#9  realize_face (cache=0x3e3ec30, attrs=0x7fff726fe5a0, 
former_face_id=<optimized out>) at xfaces.c:5501
#10 0x00000000004b0eed in realize_named_face (f=<optimized out>, 
symbol=<optimized out>, id=10) at xfaces.c:5473
#11 0x00000000004b1181 in realize_basic_faces (f=0x52fff50) at xfaces.c:5298
#12 0x00000000004b17cd in recompute_basic_faces (f=0x52fff50) at 
xfaces.c:839
#13 0x000000000043938d in init_iterator (it=0x7fff726fe7a0, w=0x56d0850, 
charpos=-1, bytepos=-1, row=0x0, base_face_id=DEFAULT_FACE_ID) at 
xdisp.c:2618
#14 0x000000000044962b in x_consider_frame_title (frame=<optimized out>) 
at xdisp.c:10972
#15 0x0000000000449774 in prepare_menu_bars () at xdisp.c:11031
#16 0x0000000000455b95 in redisplay_internal () at xdisp.c:12944
#17 0x0000000000503359 in read_char (commandflag=<optimized out>, 
nmaps=<optimized out>, maps=0x0, prev_event=<optimized out>, 
used_mouse_menu=<optimized out>, end_time=<optimized out>) at 
keyboard.c:2448
#18 0x000000000059416c in read_filtered_event (no_switch_frame=0, 
ascii_required=0, error_nonascii=0, input_method=0, seconds=<optimized 
out>) at lread.c:621
#19 0x000000000056c9d9 in Ffuncall (nargs=<optimized out>, 
args=<optimized out>) at eval.c:3009
#20 0x00000000005a6ef5 in exec_byte_code (bytestr=<optimized out>, 
vector=<optimized out>, maxdepth=<optimized out>, 
args_template=<optimized out>, nargs=104812360, args=0x33a5) at 
bytecode.c:785
...

Lisp Backtrace:
"read-event" (0x727014a8)
"terminal-init-xterm" (0x72701688)
"tty-run-terminal-initialization" (0x72701848)
"tty-create-frame-with-faces" (0x72701a08)
"make-frame" (0x72701bf0)
"server-create-tty-frame" (0x72701df0)
0x5f64d20 PVEC_COMPILED
...

But either way, we get into the display code and it thinks it's got to 
do the color/face setup all over again for the remote display.

That seems to be where the delay is coming from.  If, in fact, the Lisp 
code supporting the xterm type is sending its escape sequence before all 
of this is triggered, that would certainly explain why it times out and 
the response sequence winds up added to the buffer content.

Ken