Profiling native-compilation

Profiling native-compilation

[Eli Zaretskii]

I tried to profile the code involved in native-compilation using
profiler.el, but the results seem to omit most of the functions
involved in that: the percents shown in the resulting profile are very
low, which seems to hint that most of the CPU time is spent in places
that profiler.el cannot identify.

Is it possible to use profiler.el to produce a meaningful profile of
native-compilation?  If yes, how does one go about setting up such
profiling?  And if this is not currently possible, why isn't it, and
can we do something to make the situation better?  For example, for at
least two C functions that are important to see in the profile -- GC
and redisplay -- we did arrange to be shown in the profile.  So if the
problem is that most of the time is spent inside C code, perhaps we
could do something similar in comp.c?

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.  So I guess there's more here than meets the eye, and
I think we should work on getting a clear idea where the time is
spent, so that we could improve it.  For example, if indeed libgccjit
is the main sink, we should ask the respective GCC developers to speed
it up.

Thanks.

Re: Profiling native-compilation

[Andrea Corallo via Emacs development discussions.]

Eli Zaretskii <eliz@gnu.org> writes:

> I tried to profile the code involved in native-compilation using
> profiler.el, but the results seem to omit most of the functions
> involved in that: the percents shown in the resulting profile are very
> low, which seems to hint that most of the CPU time is spent in places
> that profiler.el cannot identify.
>
> Is it possible to use profiler.el to produce a meaningful profile of
> native-compilation?


> If yes, how does one go about setting up such
> profiling?  And if this is not currently possible, why isn't it, and
> can we do something to make the situation better?  For example, for at
> least two C functions that are important to see in the profile -- GC
> and redisplay -- we did arrange to be shown in the profile.  So if the
> problem is that most of the time is spent inside C code, perhaps we
> could do something similar in comp.c?

Hi Eli,

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.

Maybe that's the reason why you see low percentages? Have you profiled a
`native-compile' invocation?

> 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.

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.

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.

> So I guess there's more here than meets the eye, and
> I think we should work on getting a clear idea where the time is
> spent, so that we could improve it.  For example, if indeed libgccjit
> is the main sink, we should ask the respective GCC developers to speed
> it up.

Agree there is certainly room for ATM unexplored improvements, IIRC
consing and GC have a considerable factor in the Emacs side of the
compilation.

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.

Thanks

  Andrea

Re: Profiling native-compilation

[Andrea Corallo via Emacs development discussions.]

Andrea Corallo via "Emacs development discussions."
<emacs-devel@gnu.org> writes:

[...]

> 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:
  ^^^
  four
> compile-time, generated code performance, hardening, documentation.

BTW to get an idea, I know is not defined but very roughly how much time
do we have before the 28 release branch is cut?  To get a feeling of how
much and what we can hope to fit into.

Thanks

  Andrea

Re: Profiling native-compilation

[Eli Zaretskii]

> From: Andrea Corallo <akrl@sdf.org>
> 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?

> 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?

> > 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.

> 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.

How much elapsed time does it take you to compile comp.el itself?

> 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).

Thanks.

Re: Profiling native-compilation

[Eli Zaretskii]

> From: Andrea Corallo <akrl@sdf.org>
> Cc: Eli Zaretskii <eliz@gnu.org>
> Date: Fri, 23 Apr 2021 08:57:55 +0000
> 
> BTW to get an idea, I know is not defined but very roughly how much time
> do we have before the 28 release branch is cut?  To get a feeling of how
> much and what we can hope to fit into.

Hard to say, but I think at least a year, including the pretest phase.

Re: Profiling native-compilation

[Eli Zaretskii]

> Date: Fri, 23 Apr 2021 13:48:43 +0300
> From: Eli Zaretskii <eliz@gnu.org>
> Cc: emacs-devel@gnu.org
> 
> > From: Andrea Corallo <akrl@sdf.org>
> > Cc: Eli Zaretskii <eliz@gnu.org>
> > Date: Fri, 23 Apr 2021 08:57:55 +0000
> > 
> > BTW to get an idea, I know is not defined but very roughly how much time
> > do we have before the 28 release branch is cut?  To get a feeling of how
> > much and what we can hope to fit into.
> 
> Hard to say, but I think at least a year, including the pretest phase.

Sorry, I missed the part about cutting the release branch.  That would
be sooner, perhaps 8 months from now?  But it also depends on what
other features we will want to include.  For example, if we decide to
include the pgtk branch, it could take more (I have no clear idea how
ready that branch is for landing, and I have the impression that the
branch is not tested by enough people, nowhere near the native-comp
branch).

Re: Profiling native-compilation

[Andrea Corallo via Emacs development discussions.]

Eli Zaretskii <eliz@gnu.org> writes:

>> From: Andrea Corallo <akrl@sdf.org>
>> 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