Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

[Stefan Monnier]

>   (profiler-report-render-calltree-1): Call them "CPU samples",
>   not "Time (ms)", since they are not milliseconds now (and
>   never really were).

They were (or close enough) since each sample was weighted according to
current_sampling_interval.

We can't preserve this weighting while switching to nanoseconds, since
that would bump quickly into wrap-around country on 32bit hosts.

As you now don't preserve the weighting, we have the new problem that
starting/stopping/starting/stopping won't count correctly if
profiler-sampling-interval is modified between the two profiler-start.


        Stefan

Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

[Paul Eggert]

On 10/02/2012 06:20 AM, Stefan Monnier wrote:
> They were (or close enough) since each sample was weighted according to
> current_sampling_interval.

On Windows they weren't.  Apparently the sampling interval there
is actually 15 ms, even though we pretended it was 1 ms.

> we have the new problem that
> starting/stopping/starting/stopping won't count correctly if
> profiler-sampling-interval is modified between the two profiler-start.

True.  That's partly why the profiler report
now says "CPU samples".  Truth in advertising....

Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

[Eli Zaretskii]

> Date: Tue, 02 Oct 2012 09:37:36 -0700
> From: Paul Eggert <eggert@cs.ucla.edu>
> Cc: emacs-devel@gnu.org
> 
> On 10/02/2012 06:20 AM, Stefan Monnier wrote:
> > They were (or close enough) since each sample was weighted according to
> > current_sampling_interval.
> 
> On Windows they weren't.  Apparently the sampling interval there
> is actually 15 ms, even though we pretended it was 1 ms.

Which AFAIK is (was) a bug in profiler: it cannot assume that what it
asked setitimer will actually be obeyed.  To see what interval is
actually being loaded into the timer, one needs to call getitimer
after setitimer returns.

> > we have the new problem that
> > starting/stopping/starting/stopping won't count correctly if
> > profiler-sampling-interval is modified between the two profiler-start.
> 
> True.  That's partly why the profiler report
> now says "CPU samples".  Truth in advertising....

We can still translate that to time units, if we store the actual used
CPU time with each sample, not the count of the theoretical sampling
period.  I believe on Posix systems this boils down to calling
clock_gettime with the correct timer ID (and there are equivalent APIs
on MS-Windows).  Then we could satisfy Stefan's design goal of having
compatible profiles with different sampling period.  As a nice bonus,
this will also handle more accurate the situation whereby the system
is heavily loaded, and therefore SIGPROF is delivered with a
significant delay.

Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

[Paul Eggert]

On 10/02/2012 10:03 AM, Eli Zaretskii wrote:
> To see what interval is actually being loaded into the timer, one
> needs to call getitimer after setitimer returns.

Yes, that would have been an improvement.  But it still wouldn't have
been right, as on many platforms (including mine) the actual sampling
interval differs from what timer_gettime / getitimer reports.  With a
CPU thread timer I can set the sampling interval to 1 ns (!), and
timer_gettime reports that it's 1 ns, but it's actually ~1 ms because
that's how thread scheduling works.  I believe the behavior
for this sort thing depends on which clock we're using, but I haven't
investigated it further.

> We can still translate that to time units, if we store the actual used
> CPU time with each sample, not the count of the theoretical sampling
> period.  I believe on Posix systems this boils down to calling
> clock_gettime with the correct timer ID

Yes, that should help, but I expect it'd slow things down.  On many
hosts clock_gettime is reasonably slow because it involves a system
call and whatnot.  In particular the realtime clock can be a
huge can of worms, due to multithreading and the desire to have
a consistent clock across threads, stuff that we don't care about
here but clock_gettime sometimes has to care about.

More generally, there is often a performance penalty in trying to get
the time precisely, and in profiling it's often more useful to get
the time quickly than to get it precisely.

Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

[Eli Zaretskii]

> Date: Tue, 02 Oct 2012 13:52:40 -0700
> From: Paul Eggert <eggert@cs.ucla.edu>
> CC: monnier@iro.umontreal.ca, emacs-devel@gnu.org
> 
> On 10/02/2012 10:03 AM, Eli Zaretskii wrote:
> > To see what interval is actually being loaded into the timer, one
> > needs to call getitimer after setitimer returns.
> 
> Yes, that would have been an improvement.  But it still wouldn't have
> been right, as on many platforms (including mine) the actual sampling
> interval differs from what timer_gettime / getitimer reports.  With a
> CPU thread timer I can set the sampling interval to 1 ns (!), and
> timer_gettime reports that it's 1 ns, but it's actually ~1 ms because
> that's how thread scheduling works.

Does getitimer report correct values for reasonable intervals, though?
If it does, that will be good enough for our needs.

> > We can still translate that to time units, if we store the actual used
> > CPU time with each sample, not the count of the theoretical sampling
> > period.  I believe on Posix systems this boils down to calling
> > clock_gettime with the correct timer ID
> 
> Yes, that should help, but I expect it'd slow things down.  On many
> hosts clock_gettime is reasonably slow because it involves a system
> call and whatnot.

We could call clock_gettime once in 10 or 100 samples, say.  Its
results are cumulative, so for short periods of time, like 0.1 or 1
sec, they are still suitable for converting sample numbers to CPU
times, by assuming uniform CPU percentage over that period.

> More generally, there is often a performance penalty in trying to get
> the time precisely, and in profiling it's often more useful to get
> the time quickly than to get it precisely.

Yes, but showing a vague "number of samples" is hardly useful enough.
Maybe we should do the above as an option, and see if it's good enough
and preferred.

Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

[Paul Eggert]

On 10/02/2012 02:17 PM, Eli Zaretskii wrote:

> Does getitimer report correct values for reasonable intervals, though?

No, I'm afraid it does the same thing for larger intervals that it
does for tiny ones.  That is, it doesn't tell you the interval
that is actually used.

> We could call clock_gettime once in 10 or 100 samples, say.

Why bother?  Call it once at the start of the run, and
once at the end.  That's enough to give us an average.

> showing a vague "number of samples" is hardly useful enough.

It'd be easy to replace "CPU samples" with something like
"CPU samples (10 ms)", to give users a feel for what
the nominal sample size is.  And we can simply reset the
counters to zero in the rare cases where the user changes
the sampling interval, so that we needn't worry about
mixing interval sizes in the statistics.

Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

[Eli Zaretskii]

> Date: Tue, 02 Oct 2012 22:00:13 -0700
> From: Paul Eggert <eggert@cs.ucla.edu>
> CC: monnier@iro.umontreal.ca, emacs-devel@gnu.org
> 
> On 10/02/2012 02:17 PM, Eli Zaretskii wrote:
> 
> > Does getitimer report correct values for reasonable intervals, though?
> 
> No, I'm afraid it does the same thing for larger intervals that it
> does for tiny ones.  That is, it doesn't tell you the interval
> that is actually used.

Too bad, I thought modern Posix implementations are cleaner.

At least at some point in the past (Jul 1999, according to 'cvs
annotate'), some configure-time tests or maybe some Unix program
expected setitimer to round up the small time values to the smallest
supported values.  I know that because I coded that logic into the
DJGPP implementation of 'setitimer', with a comment which says:

 /* Posix systems expect timer values smaller than the resolution of
    the system clock be rounded up to the clock resolution.  */

> > We could call clock_gettime once in 10 or 100 samples, say.
> 
> Why bother?  Call it once at the start of the run, and
> once at the end.  That's enough to give us an average.

This will certainly be better than no time at all, although it could
skew the results in some situations.  E.g., imagine that 30% of the
elapsed time that passed while profiling Emacs got very little or no
CPU time -- this could potentially identify some innocent function as
a hot spot, just because Emacs was stuck in it, waiting to be
scheduled.

> > showing a vague "number of samples" is hardly useful enough.
> 
> It'd be easy to replace "CPU samples" with something like
> "CPU samples (10 ms)", to give users a feel for what
> the nominal sample size is.

I think using even a single measurement from clock_gettime will be
much better.

So how about a new primitive that would return the information from
clock_gettime (or getrusage, if clock_gettime is not available), which
profiler.el could then use to convert timer ticks into seconds?

Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

[Paul Eggert]

On 10/03/2012 10:18 AM, Eli Zaretskii wrote:

> imagine that 30% of the elapsed time that passed while profiling
> Emacs got very little or no CPU time

It's supposed to be a CPU time profiler, so that shouldn't
be a problem.  Granted, hosts that don't profile CPU time
(and where we fall back on real-time) will provide inaccurate
numbers in that situation, but they're already way-inaccurate
so it doesn't really matter.

> So how about a new primitive that would return the information from
> clock_gettime (or getrusage, if clock_gettime is not available), which
> profiler.el could then use to convert timer ticks into seconds?

That should work.  I would like to add an optional argument
to current-time, to specify which clock we want.  But isn't
this sort of thing something that we need to delay until later?
Aren't we in a feature freeze?

Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

[Eli Zaretskii]

> Date: Wed, 03 Oct 2012 10:29:21 -0700
> From: Paul Eggert <eggert@cs.ucla.edu>
> CC: monnier@iro.umontreal.ca, emacs-devel@gnu.org
> 
> > So how about a new primitive that would return the information from
> > clock_gettime (or getrusage, if clock_gettime is not available), which
> > profiler.el could then use to convert timer ticks into seconds?
> 
> That should work.  I would like to add an optional argument
> to current-time, to specify which clock we want.  But isn't
> this sort of thing something that we need to delay until later?
> Aren't we in a feature freeze?

THis is a bugfix ;-)  Anyway, that's for Stefan and Chong to decide.
E.g., the inclusion of inotify support is still being considered,
AFAIU.

Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

[Stefan Monnier]

> Which AFAIK is (was) a bug in profiler: it cannot assume that what it
> asked setitimer will actually be obeyed.  To see what interval is
> actually being loaded into the timer, one needs to call getitimer
> after setitimer returns.

If enough systems are able to return a different value in getitimer than
set in setitimer, then it would be good to do that (and signal an error
or at least output a message if the return value is different).

> I believe on Posix systems this boils down to calling clock_gettime
> with the correct timer ID (and there are equivalent APIs on
> MS-Windows).

That would be a nice approach, indeed, when CLOCK_PROCESS/THREAD_CPUTIME_ID
is supported.  We still need to worry about wraparound: counting ms
gives us a wraparound after 512M ms = 512ks =~ 5 days, which seems
acceptable, but anything finer would not fly without a good solution to
the wraparound.

> Then we could satisfy Stefan's design goal of having
> compatible profiles with different sampling period.

It's not terribly important, but it is desirable.


        Stefan

Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

[Paul Eggert]

On 10/02/2012 07:05 PM, Stefan Monnier wrote:
> We still need to worry about wraparound

It should be easy to avoid wraparound by accumulating
an EMACS_TIME value instead of an integer counter.
That's good for at least 70 years, and would support
even nanosecond resolution.

The current hash tables require that we accumulate in an
Emacs object, but we could simply use a hash table that is
tuned for the job instead.  This would also let us avoid
the QUIT problem.

Re: [Emacs-diffs] /srv/bzr/emacs/trunk r110342: Count overruns when profiling; change units to ns.

[Stefan Monnier]

> The current hash tables require that we accumulate in an
> Emacs object, but we could simply use a hash table that is
> tuned for the job instead.

I'm not interested to go in that direction (been there, done that).


        Stefan