[Bug 41199] [patch] Enhance logging system

[bugzilla-daemon at freedesktop.org]

https://bugs.freedesktop.org/show_bug.cgi?id=41199

--- Comment #8 from Olli Salli <ollisal at gmail.com> 2011-09-28 05:07:57 PDT ---
(In reply to comment #6)
> I see at least 2 problems that add a lot of complexity in comparison to the
> first approach:
> 
> 1) enableDebug returns a Tp::Debug by value, and this means that (depending on
>    the compiler?) a copy of the object is created and then destroyed the first
>    one destroyed when it goes out of scope. Therefore having a hook in the
>    destructor of Tp::Debug means that the callback will be called at least
>    twice (once per copy of the Tp::Debug)

Ahm, true, I overlooked this initial instance existing (and no, it doesn't
depend on the compiler, the copy constructor and dtor being invoked when
returning a non-POD value is a C++ language requirement AFAIK). As an empty
debug message doesn't make sense, this could be alternatively solved by just
skipping the callback invocation if the debug message is empty in the dtor. Of
course, at the moment, the tp-qt4 <version> prefix is initially streamed to the
debug object so it's non-empty already in enabledDebug(), but that could change
- just prepend it to the string when forwarding to the callback instead
(requires implementing the dtor in the .cpp, having access to
config-version.h).

> 
> 2) Tp::Debug will have to store internally the QString. This QDebug(QString*)
>    ctor doesn't allow to set a QtMsgType so it will have to be stored in
>    Tp::Debug as well. The QDebug(QString*) constructor requires that the string
>    is constructed before the QDebug in Tp::Debug ctors. Copy constructor and
>    operator= cannot simply copy the QDebug* but must copy these as well. 
>    Moreover they cannot copy the QDebug because the stream of the second will
>    point at the QString in the first whose life might be shorter. It should
>    create a new QDebug to its own QString and feed it with the other
> Tp::Debug's
>    QString.

Yeah, my first hunch would be the string as a by-value member, and the QDebug
(like now) as heap - then the string both is initialized first and deleted
later. Copy ctor needs to copy the string (in initializer list preferably) and
construct a new QDebug for the new instance, just like it does now.

QDebug needs to be heap-allocated in any case because it has been shown to have
a very significant construction and destruction overhead (involving calls to
get the current system time etc for whichever reason?!), which must be able to
skipped completely when debug is disabled at runtime. For reference, this
overhead is what causes the tp-qt4 unit tests to run about 10% faster when
debug is disabled at runtime vs if it's enabled, and within 1% of how fast it
runs if debug is disabled at compile time and all the debug operator<< calls
get inlined to nothing.

This performance factor is actually rather important, because logging has found
to be a major contributor to battery mobile drain etc whenever we get woken up
for some event, print a debug for it but otherwise handle it relatively
cheaply.

> 
> Anyway I tried to do it, but to keep the things as simple as possible, I
> stored everything in a refcounted struct and kept a Tp::SharedPtr in Tp::Debug
> class.
> The callback function is called by the struct dtor instead of by Tp::Debug
> dtor.
> Anyway I'm not sure if I can use the Tp::SharedPtr here... is there any reason
> why I shouldn't?

I see no functional problem with using Tp::SharedPtr, but it will add a
performance overhead (both due to the added level of memory access indirection,
and maintaining the reference count). This overhead must be avoided at least
for the case where debug is disabled at runtime, but please investigate whether
the solution with moving the prefix to the callback invocation time and
skipping the initial empty debug message invocation would be clean enough, as
it wouldn't need this overhead at all even with debug enabled.

The initial empty QString being copied is essentially free (the one in the
instance local to enabledDebug()/enabledWarning()) as it'll be a Null QString,
which doesn't need even the shared data refcount operations, rather than just
an empty but non-null string (which does). That is, if the prefixing is moved
to the point in time where the callback is invoked.

> 
> Branch:
> https://gitorious.org/drdanz-telepathy-kde/telepathy-qt4/commits/logging_enhancement2
> 
> (if you change your mind and decide that you like the QDebug approach more I
> updated the logging_enhancement branch fixing the name of the function pointer
> type)

Sorry, but I won't change my mind, having realized the drawback of losing the
debug message boundaries implied in the approach that requires you to use
QIODevice.

If you find the approach I suggested above for avoiding the need for a
reference counting scheme too convoluted after implementing it, here's a few
improvements needed for the current reference-counted implementation:
 - You don't need the current Debug copy ctor and operator= at all, they're
exactly what the compiler would (perhaps more efficiently) generate for you. I
believe you need them for any non-SharedPtr approach, though.
 - Debug::Private needs to be exported, because inline functions in Debug (that
is, the ctors, the operator= and the dtor) use it, and hence tp-qt4-farsight
needs to be able to link to it them (as the code invoking the ctor and dtor
will then be in the tp-qt4-farsight library binary). Please attempt a build
with export directive based symbol visibility enabled and all the
tp-qt4-farsight deps installed with any approach to verify you got these things
right.
 - An another way to solve the above issue: move the ctor and dtor
implementations of Private to be inline in the -internal.h. Then there are no
symbols generated for the Private class in the tp-qt4 main library at all, and
then you can make the class NO_EXPORT. This requires the use of a small
exported utility function digging the static debug callback variable out of the
library though, like I suggested before. This would additionally make the dtor
invocations able to be inlined wherever debug is used, and hence faster.
 - For clarity, Q_DISABLE_COPY Private, because copying it would mess it up
(the first copy would delete the shared qdebug pointer and the second would
still keep the same pointer, which'd dangle). With a shared pointer scheme for
holding the Private, you don't need it to be copiable at all, so this is not a
problem.
 - const QString& is not tp-qt4 style, const QString & is, even when there is
no param name
 - I believe all the && p->debug branches are useless in the debug functions,
as a Private instance always has a non-null Debug. You can verify by running
this under make lcov-check with debug enabled and disabled at runtime - with
debug and warnings enabled, the action is always invoked, and with them
disabled the if condition short-circuits out already because the Private
pointer is null

Otherwise looks good. It gave me an idea though, which makes me feel even
better about the "only add the tp-qt4 DEBUG prefix when invoking the callback"
approach. If we do that, we could pass the library name, the version and the
debug message in separate params - and allow the receiver to build whichever
format out of it they want (including the current, by using the message type
param as well for printing DEBUG/WARNING).

That avoids a string copy + concatenation from our side for each debug message
forwarded, but also allows the receiver to handle them separately. For example,
it might be useful to omit the prefix, when you're going to push them to a
tp-qt4 specific log category, perhaps even further split to debug/warning,
already preserving this information. This'd allow you to enable/disable tp-qt4
debugs and warnings separately from KDebugDialog for each application
separately, and not have redundant crap in the debug printouts.

-- 
Configure bugmail: https://bugs.freedesktop.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.