Re: [PATCH] [RFC] profiler updates

On 06/05/2012 06:21 PM, Amos Jeffries wrote:
> I have an incomplete patch to fix bug 1961 (CPU profiler crashing squid
> whenever AIO or other threads are used).

I am not sure whether to treat this as a [PATCH] or [RFC] so I will
treat this as [PREVIEW].

> So far I have a timer class whose constructor/destructor perform the
> timer setup and stats recording. That is attached.

> +void
> +XProfilerNode::stop()
> +{
> + stopped_ = get_tick();

Please make sure that stop() does nothing when called twice. I think you
can use the "running" member for that. Currently, all stop()s will be
called twice.

IIRC, there were a few exceptions where declaring an XProfilerNode
object using old macros did not work because it added two objects with
the same name. Perhaps there are no more such occurrences but just keep
in mind that sometimes you might need to declare or stop XProfilerNodes
manually.

> + if (delta < head->best)
> + head->best = delta;
> + if (delta > head->worst)
> + head->worst = delta;
> + head->summ += delta;
> + head->count++;
> + head->overheads += get_tick() - stopped_;

The above XProfilerNode::stop() code is not thread-safe because multiple
threads may update the same "head" and you are not using atomics for
*head members.

> + hrtime_t overheads;
> int64_t summ;

If "summ" is int64_t then perhaps overheads should be as well? They both
seem to accumulate time values.

> + // init stopped to prevent negative times occuring if anything goes wrong.
> + stopped_ = started_ = get_tick();

Please use "running_" to detect still-running nodes instead of assigning
bogus values in hope to avoid other bogus values.

> + hrtime_t stopped_; ///< when this timer was stopped
> + hrtime_t overheads_; ///< how much time has measurably been spent on profiler internal code.

Do you actually need these two data members?

> + bool running_; ///< whether this timer is still active, or been stopped already
> + hrtime_t started_; ///< when this timer was started

You may want to declare "running_" last. It should not hurt and might
save a few bytes.

Also, please consider removing running_ altogether and use positive
started_ as an "Am I running?" test instead. Inline that test as a
running() method.

> +// explicitly stop the timer. This is now optional.
> +#define PROF_stop(probename) XProfTimer_##probename.stop()

Not only it is optional, it is wasteful and leads to
incomplete/incorrect measurements in many cases.

Please consider removing nearly all PROF_stop() calls from Squid sources
as a separate followup patch. Please do not do it now though, as it will
screw up the pending ACL and bump-server-first patches.

> The old profiler was done in a way which allowed live run-time snapshot
> cachemgr report to be taken without stopping any timers. I've hooked
> these classes into that reporting structure, but at present they will
> result in the snapshots only recording *finished* timers, not the
> currently active incomplete ones.

Not a big deal in most cases, IMHO.

> I'm thinking keeping the stack/list of timers from the old design but
> only using it to dump a list of "currently incomplete" function calls
> instead of using it to add incremental bits of timers to the report.

I am not sure I understand: If you are willing to write thread-safe code
to safely iterate a stack of running timers, then why not report their
time spent so far? It does not add complexity or much overhead after you
are done with the code that safely lists those timers.

> Does anyone have any other inspirational thoughts about how to keep that
> kind of detail peeking using these classes in a multi-threaded soup of
> code?

If you want to prevent iteration of current timers, then you can make
all start() methods increment a global (Starts) by their start time and
all stop methods subtract their start time from that same global. At any
time, to approximate the time already spent in all currently running
timers, you can then:

    expected_minimum_contribution_of_all_running_timers =
      Starts - number_of_running_timers*get_tick();

I am not sure that anticipated addition from running timers is the
information you are looking for though.

HTH,

Alex.
Received on Wed Jun 06 2012 - 22:29:48 MDT