From mboxrd@z Thu Jan 1 00:00:00 1970 Path: news.gmane.io!.POSTED.blaine.gmane.org!not-for-mail From: Andrea Corallo via "Emacs development discussions." Newsgroups: gmane.emacs.devel Subject: Re: Profiling native-compilation Date: Fri, 23 Apr 2021 13:46:26 +0000 Message-ID: References: <83mttpo4rv.fsf@gnu.org> <83im4dnup2.fsf@gnu.org> Reply-To: Andrea Corallo Mime-Version: 1.0 Content-Type: text/plain Injection-Info: ciao.gmane.io; posting-host="blaine.gmane.org:116.202.254.214"; logging-data="36759"; mail-complaints-to="usenet@ciao.gmane.io" User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/28.0.50 (gnu/linux) Cc: emacs-devel@gnu.org To: Eli Zaretskii Original-X-From: emacs-devel-bounces+ged-emacs-devel=m.gmane-mx.org@gnu.org Fri Apr 23 15:47:10 2021 Return-path: Envelope-to: ged-emacs-devel@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 1lZw9G-0009Kc-0c for ged-emacs-devel@m.gmane-mx.org; Fri, 23 Apr 2021 15:47:10 +0200 Original-Received: from localhost ([::1]:41676 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1lZw9F-0006Dj-3h for ged-emacs-devel@m.gmane-mx.org; Fri, 23 Apr 2021 09:47:09 -0400 Original-Received: from eggs.gnu.org ([2001:470:142:3::10]:40646) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1lZw8g-0005i6-5l for emacs-devel@gnu.org; Fri, 23 Apr 2021 09:46:34 -0400 Original-Received: from mx.sdf.org ([205.166.94.24]:51900) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1lZw8d-0001pQ-NE; Fri, 23 Apr 2021 09:46:33 -0400 Original-Received: from mab (ma.sdf.org [205.166.94.33]) by mx.sdf.org (8.15.2/8.14.5) with ESMTPS id 13NDkRnd000642 (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256 bits) verified NO); Fri, 23 Apr 2021 13:46:27 GMT In-Reply-To: <83im4dnup2.fsf@gnu.org> (Eli Zaretskii's message of "Fri, 23 Apr 2021 13:47:53 +0300") Received-SPF: pass client-ip=205.166.94.24; envelope-from=akrl@sdf.org; helo=mx.sdf.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: emacs-devel@gnu.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: "Emacs development discussions." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: emacs-devel-bounces+ged-emacs-devel=m.gmane-mx.org@gnu.org Original-Sender: "Emacs-devel" Xref: news.gmane.io gmane.emacs.devel:268322 Archived-At: Eli Zaretskii writes: >> From: Andrea Corallo >> Cc: emacs-devel@gnu.org >> Date: Fri, 23 Apr 2021 08:45:44 +0000 >> >> AFAIK profiling syncronous native compilation with profile.el should be >> possible but with one caveat that is: we run the final pass in a >> subprocess so we'll loose visibility on that, OTOH we can consider final >> being essentially all libgccjit work. > > The "final pass" being what in this case? which function call > initiates that final pass? `comp-final' >> Maybe that's the reason why you see low percentages? Have you profiled a >> `native-compile' invocation? > > Yes, I've profiled the invocation of native-compile. (Btw, it > signaled an error near the end.) Is there a way to invoke native > compilation in an interactive session while preventing the last pass > from being run in a subprocess? Probably for profiling an hacky way would be binding `byte-native-for-bootstrap' to t. Another variant I think you'll find of interest is to run binding `comp-dry-run' to t in order to exclude final from the run, this way you'll profile essentialy the Lisp part only. I think this should help you in geting a more meaningful result from profile.el. >> > I think this is important because native-compilation is quite slow, >> > and at least I don't have a clear idea where most of that time is >> > spent. Andrea, you said once that most of the time is spent in >> > libgccjit functions, which I find strange, since those are basically >> > parts of GCC code, and I don't think I ever saw such slow compilation >> > times from GCC. >> >> Yes I mentioned that but since we changed the layout of generated code >> for storing immediates GCC got way faster and now the Emacs side is >> about equally responsible for the time spent in compilation. > > Which is why it's important to see where the time is spent, so that we > could work on perhaps speeding it up. I've found some not very recent notes and at the time I measured quite some time spent in SSA renaming `comp-ssa-rename' called by fwprop. We'll see if it's still the case. >> One simple approach to get an idea of where time is spent in the >> compiler is to bind `comp-log-time-report' to get a report pass by pass. > > That's a start, but it doesn't help to identify the hot spots. > >> Running: >> >> === >> (require 'comp) >> (let ((comp-log-time-report t)) >> (native-compile ".../emacs2/lisp/emacs-lisp/byte-opt.el")) >> === >> >> I get: >> >> Done compiling .../.emacs.d/eln-cache/28.0.50-7f3f9b99/byte-opt-9c5f25f5-d2005e8f.eln >> Pass comp-spill-lap took: 0.095720s. >> Pass comp-limplify took: 0.423704s. >> Pass comp-fwprop took: 3.334509s. >> Pass comp-call-optim took: 0.023363s. >> Pass comp-ipa-pure took: 0.000046s. >> Pass comp-add-cstrs took: 0.222719s. >> Pass comp-fwprop took: 2.549254s. >> Pass comp-tco took: 0.000044s. >> Pass comp-fwprop took: 0.256151s. >> Pass comp-remove-type-hints took: 0.025859s. >> Pass comp-final took: 4.268238s. > > That's very fast. I don't think I see such short times. Here's my > result, almost 4 times slower: > > Pass comp-spill-lap took: 1.281250s. > Pass comp-limplify took: 1.500000s. > Pass comp-fwprop took: 11.078125s. > Pass comp-call-optim took: 0.000000s. > Pass comp-ipa-pure took: 0.000000s. > Pass comp-add-cstrs took: 0.625000s. > Pass comp-fwprop took: 8.750000s. > Pass comp-tco took: 0.000000s. > Pass comp-fwprop took: 0.906250s. > Pass comp-remove-type-hints took: 0.000000s. > Pass comp-final took: 27.375000s. > > Note that I ran this in an unoptimized build of Emacs, so any Lisp, > bytecode, and calls into primitives are expected to be between 3 and 4 > times slower than in an optimized build. Yeah as a result I think is expected for an unoptimized build. > How much elapsed time does it take you to compile comp.el itself? On my optimized build it's 1m29sec, that's the slowest compilation unit we have I think. >> I think would be interesting to sort by priority what I think are the >> three main ares to work on the native compiler on the post merge phase: >> compile-time, generated code performance, hardening, documentation. > > They are all equally important, IMO. I hope we can work on them in > parallel. I didn't mean to imply that you personally must work on all > of them (which would then make them more sequential tasks). Sure, I'm quite bad at parallelizing work so some direction for my effort will be appreciated once merge is done and we extinguished any possible fire. Thanks Andrea