Re: [PATCH] debugs-refactor, v1

On 18 Feb 2014, at 00:44, Alex Rousskov <rousskov_at_measurement-factory.com> wrote:

> On 02/17/2014 02:46 PM, Kinkie wrote:
>
>> the attached patch aims at simplifying debug, making it also more effective.
>
> It would be better to finish the discussion regarding the future of
> debugging before making debugging-focused changes IMO.

This effort is only about making the existing debugging interface more consistent (its refactoring was apparently stopped midway through), and removing some unused code. This will benefit the eventual debugging-related changes as well since there will be fewer corner cases to address.

>> It:
>> - removes some of the API cruft (ctx_enter, ctx_exit, BuildPrefixInit)
>> - shuffles the remaining public functions to static members of Debug
>> - fixes clients still relying on old_debug (thanks to Amos)
>> - implements a compatibility wrapper for std::mutex (not all compilers
>> we care about implement it yet) relying on pthread mutexes if needed.
>> - increases the efficiency of debugs() message creation by reducing
>> the number of data copies
>> - the new debugs() call is reentrant and threadsafe on all platforms,
>> not just windows
>
>> It's been build- and run- tested on ubuntu raring; it's being tested
>> in the build farm as we speak; it's possible that as results from that
>> come in some small changes will be needed, but the API is hopefully
>> fixed.
>>
>> Feature branch at lp:~squid/squid/debugs-refactor.
>
> Have you verified your performance improvements claims? The patch may
> remove some copying, but it also adds mutex overheads (one of two very
> different kinds, depending on ./configure outcome?). It would be
> interesting to see which overheads are heavier. If you have not verified
> those claims, perhaps it would be prudent to at least augment those
> claims as unverified and far from obvious.

You are right. It _does_ eliminate some copying. It is not something on the critical path - unless running at ALL,9 the fast path is the one where output is not even accumulated - that one critical part of the original API was carefully kept.

> The biggest problems with this patch are at the end of this email (sorry
> -- moving quoted stuff is difficult).
>
>
>> -#if defined(LOCKCOUNT_DEBUG)
>> - old_debug(0,1)("Incrementing this %p from count %u\n",this,count_);
>> +#if LOCKCOUNT_DEBUG
>> + debugs(0, 8, "Incrementing this " << reinterpret_cast<const void *>(this) << "from count " <<
>
> Missing space before "from".
>
>
>> +/**
>> + * Write out the SSL session details.
>> + */
>> +static std::string
>> +debugDisplaySslContext(SSL *ssl)
>
> Avoid the overhead of creating std::string if possible. const char * may
> work better.
>
>
>> + debugs(83, 4, debugDisplaySslContext(ssl) << "");
>
> What is the purpose of logging ""?
>
>
>> /* for shutting_down flag in xassert() */
>> #include "globals.h"
>>
>> +
>> char *Debug::debugOptions = NULL;
>> int Debug::override_X = 0;
>
> Please avoid non-changes.
>
>
>> +static Mutex printlock;
>
> Please avoid using phreads if Squid does not need them.

This raises an interesting question: how do I detect if these are needed?

>
>> +static Mutex printlock;
> ...
>> +Debug::Print(const std::string & logline)
>> {
> ...
>> + printlock.lock();
> ...
>> + printlock.unlock();
>> +}
>
> AFAICT, your implementation will freeze Squid forever when debugs() is
> called recursively. If true, this would be a major regression not worth
> any of the claimed improvements.

It shouldn't, because the Print method (as only used by debugs() is serialized: input is accumulated before calling it, so any recursion should happen before it is invoked. This means that recursive debugs() are called depth-first but that's the way things are already.

> We need debugs() not to crash when used reentrantly, but we do not
> really want to pay much for "great" reentrant support because reentrant
> calls are rare and one can usually figure out what happened anyway even
> if the resulting debugging strings are messy. Strict locking (with
> waiting) is the wrong solution here.

The locking is only used when outputting, to avoid races mixing output lines. Is it worth it? I can't be sure: the current code has a platform-specific mutex in place on windows only and that's where I took the need from. Advice is welcome.

> Perhaps I am missing some global dependency/context here, but if you
> want to improve the common-case debugging efficiency and simplify
> things, please do not force all debugging through mutexes, especially
> through pthread mutexes. Something went wrong here. Perhaps you are
> correctly solving the wrong problem, not sure:

Well, the current code uses a very verbose mutex, but on windows only for some reason (see above)

>
>>> - the new debugs() call is reentrant and threadsafe on all platforms,
>>> not just windows
>
> Thread safety is great, but we should not penalize 99% of Squid
> installations (those that do not use threads). AFAICT, your
> implementation applies that penalty to all installations.
>
>
>> +std::string
>> +LogLinePreamble()
>> +{
>> + std::string rv(debugLogTime());
>> + rv.append(debugLogKid());
>> + rv.append("| ");
>> + return rv;
>> +}
>
> If the above code stays, please reserve string space before appending
> stuff to it. I do not think it should stay though:
>
> To avoid adding performance overheads of allocating strings, appending
> to them, and copying them on return (when std::string does not CoW), you
> should not log the result of LogLinePreamble() but log a LinePreamble
> manipulator or object instead. A LinePreamble manipulator/object can
> write each preamble item directly into the debugging stream, without any
> overheads.

Ok, I'll look into that.

> See Raw class as an example, but since yours will not need any class
> members, you probably do not need a class object. Your LinePreamble can
> be a stream manipulator like std::endl.
>
>
>> - std::ostream &_dbo=Debug::getDebugOut(); \
>> + std::ostringstream dbss; \
>
> To minimize overheads, it would be great to have a reusable debugging
> stream with large pre-allocated storage backing except for rare
> reentrant/recursive calls that will trigger creation of "back up"
> dynamic streams. The old interface/approach would facilitate that kind
> of optimization. I do not recommend removing it.

.. does it? Maybe it facilitates but it doesn't really seem to be used. The code is currently spaghetti.
This refactoring makes it at least clearer (also, remember performance here is not critical as the string stream only gets created on the non-common case).

>> void
>> Adaptation::Ecap::Host::closeDebug(std::ostream *debug)
>> {
>> - if (debug)
>> - Debug::finishDebug();
>> }
>
> Can you explain what happened here? Is eCAP adapter debugging not
> supported any more?

The debugging happens via debugs() which each does the equivalent of finishDebug().
This call simply terminates the debugging transaction and exports the things which were accumulated elsewhere, and should not be needed anymore.
If any debugging is removed due to this change, it's a mistake and must be corrected.

Thanks!
        Kinkie
Received on Tue Feb 18 2014 - 06:16:09 MST