Re: [PATCH] [RFC] profiler updates

On 07.06.2012 10:29, Alex Rousskov wrote:
> 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.
>

Added a PROF_restart(X) macro.

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

Ok, for now this is the second major TODO.
I'm torn between GCC __sync_* and C++11 atomic_* types.

There is maybe a wrapper compat layer needed temporarily I think.

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

Done.

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

Replaced using started_ as suggested below.

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

stopped_ we don't. overheads_ is to account for timer management cycles
which need to be reported as they may inflate very-short timer runs.
Rather than estimating removals and adjusting the actual details I'm
planning to just report the total running time and the overheads
wastage.
  If we find it useless or difficult to use it can be dropped as well.

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

Done.

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

Will do after these core changes are finalized.

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

Ack. The few worrying ones are the "unaccounted" and other long-lived
operations which I'm going to swap to being time in main() and time in
main loop.

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

I was wondering if its worth the effort to write that thread-safe
iteration, or if anyone has a better idea such as ...

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

Hmm. Per-type this is exactly what I'm looking for. Thank you.

Amos
Received on Thu Jun 07 2012 - 01:25:45 MDT