Subject: Re: bug#21473: 24.5; very slow tooltip display to sort-of-slow remote display

From: Ken Raeburn <[email-masked]>
Date: Thu, 01 Oct 2015 06:01:35 -0400

Eli Zaretskii <[email-masked]> writes:

> Let me be sure I understand: these XSync calls in the case of popping
> up a tooltip, are mostly due to color allocation?  Or is there other
> unnecessary face-related traffic that needs to be addressed?

No, the color allocations and XSync calls are two separate causes of
delay, each contributing round trips to the server. The XSync calls are
mostly due to error-trapping code (not in color lookup or allocation).

To pick one example, x_set_mouse_color does a sequence like this:

  x_catch_errors
    Calls XSync to make sure we've processed errors from previously sent
    requests, then pushes an x_error_message_stack structure onto a
    stack.
  XCreateFontCursor(x-pointer-shape or XC_xterm)
    Returns a value but this is a locally-assigned number, not an
    indication of success.
  x_check_errors("bad text pointer cursor")
    Calls XSync to make sure any error from XCreateFontCursor is
    received and processed.
  XCreateFontCursor(x-nontext-pointer-shape or XC_left_ptr)
  x_check_errors("bad nontext pointer cursor")
  XCreateFontCursor(x-hourglass-pointer-shape or XC_watch)
  x_check_errors(...etc...)
  XCreateFontCursor(x-mode-pointer-shape or XC_xterm)
  x_check_errors(...etc...)
  Several more XCreateFontCursor calls in a row.
  x_check_errors(...more generic message...)
  x_uncatch_errors
    Calls XSync to make sure we've received errors from any request sent
    since the last x_catch_errors or x_check_errors, and pops it off the
    stack.

We do all of this in "x_set_mouse_color" because the cursor color is a
property of the cursor object, so we create new cursors, set their
colors, and then start using them in place of the old ones.

So that's seven XSync calls, seven round trips, to make sure we catch
any X server errors returned for this code and turn them into
appropriate error messages.

(Fun fact: Setting x-hourglass-pointer-shape to a bad value like 999 or
"asdf" will prevent the tooltip frame from being created. Or any other X
frame.)

It's possible to look up the serial number of the next request to be
sent to the server (XNextRequest), and the error handler gets a data
structure that includes the serial number of the failing request
(error_event->serial). So with some more work we could correlate one or
more received errors with the requests we sent and pick which one we
wanted to report on. (We'd have to deal with XCreateFontCursor
potentially sending more than one X protocol request.) We'd still need
an XSync at the end of the sequence to flush any pending errors.

It occurs to me that maybe we can get rid of the XSync in
x_catch_errors, if we record in the x_error_message_stack structure the
serial number for the first request for which errors should be recorded
there, using XNextRequest. If the error handler sees an older serial
number in the error-event structure, then it looks at the next entry in
the stack and tries again. Something similar may work for
x_uncatch_errors too.

Getting back to the trace from my test run, another case I see is
x_real_pos_and_offsets. (Called when handle_one_xevent gets
ConfigureNotify, presumably for the tooltip window.) It uses XQueryTree
to walk up the window hierarchy to the root; the loop uses
x_had_errors_p (which calls XSync) each time. It also calls
XTranslateCoordinates and then x_had_errors_p. And XGetWindowProperty
followed by x_had_errors_p.

Since these routines normally return data from the server, if they get
errors back, is it ever possible for them to return to their caller
without having invoked the error handler on the error event structure?
Have the error callback delayed somehow? Looking at some old xfree86
sources online (the first I found), I don't think so, and I have a tough
time imagining how a robust package could be built otherwise.

If we can rely on it, then in x_real_pos_and_offsets, immediately after
functions like XQueryTree, XTranslateCoordinates, XGetWindowProperty,
and XGetGeometry, we shouldn't need to call XSync to check whether
errors happened. I don't know if there would be a better way to convey
that information than extra arguments to the error-trapping routines,
though.

Below are the _XReply call stacks (with counts) I found once I worked up
my color handling changes. There were 61 XSync calls in all, this time.
This was for moving the mouse into the frame to the mode line (with
focus elsewhere), and waiting for the tooltip to pop up.

      5 _XReply « XSync « x_check_errors « x_set_mouse_color « x_set_frame_parameters « x_default_parameter « x_create_tip_frame « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « call1 « timer_check_2 « timer_check « readable_events « get_input_pending
      4 _XReply « XSync « x_had_errors_p « x_real_pos_and_offsets « x_real_positions « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      2 _XReply « XTranslateCoordinates « x_real_pos_and_offsets « x_real_positions « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      2 _XReply « XSync « x_uncatch_errors « x_real_pos_and_offsets « x_real_positions « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      2 _XReply « XSync « x_uncatch_errors « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « font_open_by_spec « font_open_by_name « x_default_font_parameter « x_create_tip_frame « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall
      2 _XReply « XSync « x_uncatch_errors « get_current_wm_state « x_net_wm_state « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      2 _XReply « XSync « x_had_errors_p « x_wm_supports « do_ewmh_fullscreen « x_check_fullscreen « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      2 _XReply « XSync « x_had_errors_p « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « font_open_by_spec « font_open_by_name « x_default_font_parameter « x_create_tip_frame « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall
      2 _XReply « XSync « x_catch_errors « x_real_pos_and_offsets « x_real_positions « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      2 _XReply « XSync « x_catch_errors « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « font_open_by_spec « font_open_by_name « x_default_font_parameter « x_create_tip_frame « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall
      2 _XReply « XSync « x_catch_errors « get_current_wm_state « x_net_wm_state « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      2 _XReply « XQueryTree « x_real_pos_and_offsets « x_real_positions « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      2 _XReply « XListFonts « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « font_open_by_spec « font_open_by_name « x_default_font_parameter « x_create_tip_frame « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « call1
      2 _XReply « XGetWindowProperty « x_real_pos_and_offsets « x_real_positions « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      2 _XReply « XGetWindowProperty « get_current_wm_state « x_net_wm_state « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      2 _XReply « XGetGeometry « x_real_pos_and_offsets « x_real_positions « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      1 _XReply « XSync « x_uncatch_errors « x_wm_supports « do_ewmh_fullscreen « x_check_fullscreen « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      1 _XReply « XSync « x_uncatch_errors « x_set_mouse_color « x_set_frame_parameters « x_default_parameter « x_create_tip_frame « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « call1 « timer_check_2 « timer_check « readable_events « get_input_pending
      1 _XReply « XSync « x_uncatch_errors « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « realize_x_face « realize_face « lookup_face « x_supports_face_attributes_p « Fdisplay_supports_face_attributes_p « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « call2 « x_create_tip_frame « Fx_show_tip « Ffuncall
      1 _XReply « XSync « x_uncatch_errors « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « realize_x_face « realize_face « lookup_face « face_at_string_position « note_mode_line_or_margin_highlight « note_mouse_highlight « note_mouse_movement « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « kbd_buffer_get_event « read_event_from_main_queue « read_decoded_event_from_main_queue « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2
      1 _XReply « XSync « x_uncatch_errors « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « realize_x_face « realize_face « lookup_face « face_at_buffer_position « handle_face_prop « handle_stop « start_display « try_window « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply
      1 _XReply « XSync « x_uncatch_errors « get_current_wm_state « do_ewmh_fullscreen « x_check_fullscreen « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      1 _XReply « XSync « x_sync « x_wm_supports « do_ewmh_fullscreen « x_check_fullscreen « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      1 _XReply « XSync « x_had_errors_p « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « realize_x_face « realize_face « lookup_face « x_supports_face_attributes_p « Fdisplay_supports_face_attributes_p « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « call2 « x_create_tip_frame « Fx_show_tip « Ffuncall
      1 _XReply « XSync « x_had_errors_p « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « realize_x_face « realize_face « lookup_face « face_at_string_position « note_mode_line_or_margin_highlight « note_mouse_highlight « note_mouse_movement « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « kbd_buffer_get_event « read_event_from_main_queue « read_decoded_event_from_main_queue « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2
      1 _XReply « XSync « x_had_errors_p « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « realize_x_face « realize_face « lookup_face « face_at_buffer_position « handle_face_prop « handle_stop « start_display « try_window « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply
      1 _XReply « XSync « x_catch_errors « x_wm_supports « do_ewmh_fullscreen « x_check_fullscreen « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      1 _XReply « XSync « x_catch_errors « x_set_mouse_color « x_set_frame_parameters « x_default_parameter « x_create_tip_frame « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « call1 « timer_check_2 « timer_check « readable_events « get_input_pending
      1 _XReply « XSync « x_catch_errors « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « realize_x_face « realize_face « lookup_face « x_supports_face_attributes_p « Fdisplay_supports_face_attributes_p « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « call2 « x_create_tip_frame « Fx_show_tip « Ffuncall
      1 _XReply « XSync « x_catch_errors « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « realize_x_face « realize_face « lookup_face « face_at_string_position « note_mode_line_or_margin_highlight « note_mouse_highlight « note_mouse_movement « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « kbd_buffer_get_event « read_event_from_main_queue « read_decoded_event_from_main_queue « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2
      1 _XReply « XSync « x_catch_errors « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « realize_x_face « realize_face « lookup_face « face_at_buffer_position « handle_face_prop « handle_stop « start_display « try_window « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply
      1 _XReply « XSync « x_catch_errors « get_current_wm_state « do_ewmh_fullscreen « x_check_fullscreen « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      1 _XReply « XQueryPointer « compute_tip_xy « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « call1 « timer_check_2 « timer_check « readable_events « get_input_pending « detect_input_pending_run_timers « wait_reading_process_output « sit_for « read_char
      1 _XReply « XParseColor « x_parse_color « x_defined_color « x_decode_color « x_set_background_color « x_set_frame_parameters « x_default_parameter « x_create_tip_frame « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « call1 « timer_check_2 « timer_check
      1 _XReply « XListFonts « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « realize_x_face « realize_face « lookup_face « x_supports_face_attributes_p « Fdisplay_supports_face_attributes_p « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « call2 « x_create_tip_frame « Fx_show_tip « Ffuncall « exec_byte_code
      1 _XReply « XListFonts « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « realize_x_face « realize_face « lookup_face « face_at_string_position « note_mode_line_or_margin_highlight « note_mouse_highlight « note_mouse_movement « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « kbd_buffer_get_event « read_event_from_main_queue « read_decoded_event_from_main_queue « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch
      1 _XReply « XListFonts « xfont_list_pattern « xfont_list « font_list_entities « font_find_for_lface « font_load_for_lface « realize_x_face « realize_face « lookup_face « face_at_buffer_position « handle_face_prop « handle_stop « start_display « try_window « Fx_show_tip « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « run_hook_with_args « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « Fapply « Ffuncall
      1 _XReply « XGetWindowProperty « x_wm_supports « do_ewmh_fullscreen « x_check_fullscreen « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      1 _XReply « XGetWindowProperty « get_current_wm_state « do_ewmh_fullscreen « x_check_fullscreen « handle_one_xevent « XTread_socket « gobble_input « handle_async_input « process_pending_signals « xg_select « wait_reading_process_output « sit_for « read_char « read_key_sequence « command_loop_1 « internal_condition_case « command_loop_2 « internal_catch « command_loop « recursive_edit_1 « Frecursive_edit « main
      1 _XReply « XGetSelectionOwner « Fx_selection_exists_p « Ffuncall « exec_byte_code « Ffuncall « Fapply « Ffuncall « exec_byte_code « Ffuncall « exec_byte_code « funcall_lambda « Ffuncall « eval_sub « Feval « internal_condition_case_1 « menu_item_eval_property « parse_tool_bar_item « process_tool_bar_item « map_keymap_item « map_keymap_internal « map_keymap « tool_bar_items « update_tool_bar « prepare_menu_bars « redisplay_internal « redisplay_preserve_echo_area « read_char « read_key_sequence « command_loop_1