From mboxrd@z Thu Jan 1 00:00:00 1970 Path: news.gmane.io!.POSTED.blaine.gmane.org!not-for-mail From: Peter Newsgroups: gmane.emacs.help Subject: Upgrade endeavours - the third day Date: Sun, 15 Oct 2023 19:54:06 +0200 Message-ID: Mime-Version: 1.0 Content-Type: text/plain; charset=iso-8859-1 Content-Transfer-Encoding: quoted-printable Injection-Info: ciao.gmane.io; posting-host="blaine.gmane.org:116.202.254.214"; logging-data="35799"; mail-complaints-to="usenet@ciao.gmane.io" To: help-gnu-emacs@gnu.org Original-X-From: help-gnu-emacs-bounces+geh-help-gnu-emacs=m.gmane-mx.org@gnu.org Sun Oct 15 20:02:05 2023 Return-path: Envelope-to: geh-help-gnu-emacs@m.gmane-mx.org Original-Received: from lists.gnu.org ([209.51.188.17]) by ciao.gmane.io with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1qs5RE-0009BU-GM for geh-help-gnu-emacs@m.gmane-mx.org; Sun, 15 Oct 2023 20:02:04 +0200 Original-Received: from localhost ([::1] helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1qs5Q0-0007ei-LI; Sun, 15 Oct 2023 14:00:48 -0400 Original-Received: from eggs.gnu.org ([2001:470:142:3::10]) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1qs5Py-0007eJ-Mv for help-gnu-emacs@gnu.org; Sun, 15 Oct 2023 14:00:46 -0400 Original-Received: from uucp.dinoex.org ([2a0b:f840::12]) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1qs5Pw-0003eG-1u for help-gnu-emacs@gnu.org; Sun, 15 Oct 2023 14:00:46 -0400 Original-Received: from uucp.dinoex.org (uucp.dinoex.org [IPv6:2a0b:f840:0:0:0:0:0:12]) by uucp.dinoex.org (8.17.2/8.17.2) with ESMTPS id 39FI09Lr007769 (version=TLSv1.3 cipher=TLS_AES_256_GCM_SHA384 bits=256 verify=NO) for ; Sun, 15 Oct 2023 20:00:09 +0200 (CEST) (envelope-from pmc@citylink.dinoex.sub.org) X-MDaemon-Deliver-To: Original-Received: (from uucp@localhost) by uucp.dinoex.org (8.17.2/8.17.2/Submit) with UUCP id 39FI09AY007767 for help-gnu-emacs@gnu.org; Sun, 15 Oct 2023 20:00:09 +0200 (CEST) (envelope-from pmc@citylink.dinoex.sub.org) Original-Received: from disp.intra.daemon.contact (disp-e.intra.daemon.contact [IPv6:fd00:0:0:0:0:0:0:112]) by admn.intra.daemon.contact (8.17.1/8.17.1) with ESMTPS id 39FHtd4B039972 (version=TLSv1.3 cipher=TLS_AES_256_GCM_SHA384 bits=256 verify=OK) for ; Sun, 15 Oct 2023 19:55:41 +0200 (CEST) (envelope-from pmc@citylink.dinoex.sub.org) Original-Received: from disp.intra.daemon.contact (localhost [127.0.0.1]) by disp.intra.daemon.contact (8.17.1/8.17.1) with ESMTPS id 39FHs6RW058688 (version=TLSv1.3 cipher=TLS_AES_256_GCM_SHA384 bits=256 verify=NO) for ; Sun, 15 Oct 2023 19:54:06 +0200 (CEST) (envelope-from pmc@citylink.dinoex.sub.org) Original-Received: (from pmc@localhost) by disp.intra.daemon.contact (8.17.1/8.17.1/Submit) id 39FHs6vr058687 for help-gnu-emacs@gnu.org; Sun, 15 Oct 2023 19:54:06 +0200 (CEST) (envelope-from pmc@citylink.dinoex.sub.org) X-Authentication-Warning: disp.intra.daemon.contact: pmc set sender to pmc@citylink.dinoex.sub.org using -f Content-Disposition: inline X-Milter: Spamilter (Reciever: uucp.dinoex.org; Sender-ip: 0:0:2a0b:f840::; Sender-helo: uucp.dinoex.org; ) X-Greylist: Sender passed SPF test, not delayed by milter-greylist-4.6.4 (uucp.dinoex.org [IPv6:2a0b:f840:0:0:0:0:0:12]); Sun, 15 Oct 2023 20:00:11 +0200 (CEST) Received-SPF: pass client-ip=2a0b:f840::12; envelope-from=pmc@citylink.dinoex.sub.org; helo=uucp.dinoex.org X-Spam_score_int: -18 X-Spam_score: -1.9 X-Spam_bar: - X-Spam_report: (-1.9 / 5.0 requ) BAYES_00=-1.9, SPF_HELO_PASS=-0.001, SPF_PASS=-0.001 autolearn=ham autolearn_force=no X-Spam_action: no action X-BeenThere: help-gnu-emacs@gnu.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Users list for the GNU Emacs text editor List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: help-gnu-emacs-bounces+geh-help-gnu-emacs=m.gmane-mx.org@gnu.org Original-Sender: help-gnu-emacs-bounces+geh-help-gnu-emacs=m.gmane-mx.org@gnu.org Xref: news.gmane.io gmane.emacs.help:145295 Archived-At: On the third day, that is, yesterday, things kept nagging me. So I decided to go for the boring endeavour of reading the source. I had tried debugging the day before: while the program ventures to open the menu, kill it so that it writes a core. Some internal function then happens to write a backtrace in the console, and I can read another one out of the corefile. Both are entirely disparate, and neither is much helpful. I cannot easily do live-debugging, because, as mentioned before, the X is mostly blocked during the interesting phase. I tried to move the DISPLAY to another X, but somehow this also didn't work well. So I resorted to the tedious old-fashioned way of inserting printf() into the code, and that got me to something: the stall happens in function set_frame_menubar(). That function gets invoked from x_menu_bar_open_internal() when hitting , and from whoknowswhere when clicking. I ventured on from there, into xmenu.c:set_frame_menubar() line 1036: (in a loop repeated) call to parse_single_submenu() menu.c:parse_single_submenu() line 555: call to single_keymap_panes() menu.c:single_keymap_panes() line 290: call to map_keymap_canonical() keymap.c:map_keymap_canonical() line 615: call to map_keymap_internal() keymap.c:map_keymap_internal() line 565: (in a loop repeated) call to map_keymap_item() keymap.c:map_keymap_item() line 508: indirect call (from menu.c:single_keymap_panes() line 290, param 2) to single_menu_item() menu.c:single_menu_item() line 430: call to single_keymap_panes() -> Ups! We've been there already! Apparently this runs some elaborate indirect and recursive code,=20 and there are too many functions invoked to notice with the bare eye where it delays. I also noticed that this code is run a couple of times, and it is also run before the X window gets created - and then it can be fast! So, putting some profiling into the code was necessary to get further. And then there were some results: =B5s desktop laptop startup 633'359 2'179'629 menu open 1'621'489 254'082 menu close 1'486'825 256'875 with TRUSS desktop laptop startup 1'527'100 3'256'595 menu open 45'586'904 11'912'108 menu close 46'331'740 11'140'115 Tracking it down: accumulated time spent in parse_menu_item(): =B5s desktop laptop startup 194'042 103'867 menu open 1'292'654 117'530 menu close 1'203'057 91'463 Such a difference is in no way explainable with CPU differences. That was about the third day, that is, around 6 AM today.