Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
On 08 Jan 2014, at 10:12, Koehne Kai kai.koe...@digia.com wrote:
You can then use it like that:
If (qtCoreIo().isDebugEnabled()) {
QString x = expensive();
qCDebug(qtCoreIo) Expensive: x;
}
Anyhow, note that qCDebug(qtCoreIo) expands to
for (bool enabled = qtCoreIo().isDebugEnabled(); Q_UNLIKELY(enabled); enabled
= false)
QMessageLogger(__FILE__, __LINE__, Q_FUNC_INFO,
qtCoreIo().categoryName()).debug()
Out of curiosity: is there a reason you use 'for' and not an 'if' statement?
so this should be needed only if your 'expensive' operations aren't behind
the anyway.
Also, what's the overhead of a qCDebug for a disabled category? Qt should
never emit debug warnings in its default configuration, so we're talking
about
many hits to that.
The overhead for a non-enabled qCDebug is basically a function call + one
boolean check (isDebugEnabled() will be inlined).
If code size or performance is a problem for certain critical code sections,
you could also use a full macro, like:
qCDebug(category, a b some string);
This construct looks rather strange or even ugly, but has the advantage that it
can be completely compiled away.
Regards,
Kurt
___
Development mailing list
Development@qt-project.org
http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
-Original Message-
From: development-bounces+kai.koehne=digia@qt-project.org
[...]
As a blueprint I've started a patch for a 'qt.core.io' category:
https://codereview.qt-project.org/#change,74862,patchset=1
Andre raised concerns about the (runtime/space) overhead of the QDebug
streaming style, compared to the printf style. Here are some conclusions (gcc
4.8, release build, CONFIG+=c++11) ...
RUNTIME OVERHEAD
I did a quick benchmark where I did following variants in a QBENCHMARK
(category was enabled, to output was generated to a file. I had to patch
qtestlib to not intercept the qWarning output...):
void CatLogBench::qWarningPrintf1() { QBENCHMARK { qWarning(Hi there); } }
void CatLogBench::qWarningPrintf2() { QBENCHMARK { qWarning(%s, Hi there);
} }
void CatLogBench::qWarningStream() { QBENCHMARK { qWarning() Hi there; } }
void CatLogBench::qCWarningStream() { QBENCHMARK { qCWarning(cat) Hi
there; } }
void CatLogBench::qCWarningPrintf() { QBENCHMARK { qCWarning(cat, Hi there);
} }
(the last one is a new variant enabled by
https://codereview.qt-project.org/#change,75029 .)
And here are the results:
PASS : CatLogBench::qWarningPrintf1()
RESULT : CatLogBench::qWarningPrintf1():
0.0010 msecs per iteration (total: 67, iterations: 65536)
PASS : CatLogBench::qWarningPrintf2()
RESULT : CatLogBench::qWarningPrintf2():
0.0013 msecs per iteration (total: 90, iterations: 65536)
PASS : CatLogBench::qWarningStream()
RESULT : CatLogBench::qWarningStream():
0.0016 msecs per iteration (total: 54, iterations: 32768)
PASS : CatLogBench::qCWarningStream()
RESULT : CatLogBench::qCWarningStream():
0.0018 msecs per iteration (total: 59, iterations: 32768)
PASS : CatLogBench::qCWarningPrintf()
RESULT : CatLogBench::qCWarningPrintf():
0.0010 msecs per iteration (total: 69, iterations: 65536)
PASS : CatLogBench::cleanupTestCase()
Totals: 7 passed, 0 failed, 0 skipped
So, there is of course some measurable overhead, but I wouldn't say it
disqualifies the streaming variant per se :)
BINARY SIZE
On to the binary size. I removed the QBENCHMARK macro and disassembled the gcc
output. Here it shows that QDebug is completely inlined, the streaming operator
variants do indeed generate a hell lot of instructions ! But since this is
quite a bogus metric here are the size increase of Qt5Core with, and without
the core.io patch included (again a release non-developer build with gcc 4.8.2):
-rwxr-xr-x 1 kkoehne users 5311213 Jan 10 12:55 libQt5Core.so.5.3.0.original
-rwxr-xr-x 1 kkoehne users 5357104 Jan 10 12:58 libQt5Core.so.5.3.0_patch
So the overhead is measurable.
Given these concerns, I'd like to propose adding a printf style overload to
qCDebug:
https://codereview.qt-project.org/#change,75029
Note the patch is fairly ugly because we're gracefully handling the case where
the toolchain doesn't respect Q_COMPILER_VARIADIC_MACROS, I'll post a second
mail about this soon ...
Regards
Kai
___
Development mailing list
Development@qt-project.org
http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
Koehne Kai wrote:
-Original Message-
From: development-bounces+kai.koehne=digia@qt-project.org
[...]
As a blueprint I've started a patch for a 'qt.core.io' category:
https://codereview.qt-project.org/#change,74862,patchset=1
Andre raised concerns about the (runtime/space) overhead of the
QDebug streaming style, compared to the printf style.
Here are some conclusions (gcc 4.8, release build, CONFIG+=c++11) ...
RUNTIME OVERHEAD
I did a quick benchmark where I did following variants in a
QBENCHMARK (category was enabled, to output was generated
to a file. I had to patch qtestlib to not intercept the qWarning output...):
void CatLogBench::qWarningPrintf1() { QBENCHMARK { qWarning(Hi there); } }
void CatLogBench::qWarningPrintf2() { QBENCHMARK { qWarning(%s, Hi
there); } }
void CatLogBench::qWarningStream() { QBENCHMARK { qWarning() Hi there; }
}
void CatLogBench::qCWarningStream() { QBENCHMARK { qCWarning(cat) Hi
there; } }
void CatLogBench::qCWarningPrintf() { QBENCHMARK { qCWarning(cat, Hi
there); } }
(the last one is a new variant enabled by
https://codereview.qt-project.org/#change,75029 .)
And here are the results:
PASS : CatLogBench::qWarningPrintf1()
RESULT : CatLogBench::qWarningPrintf1():
0.0010 msecs per iteration (total: 67, iterations: 65536)
PASS : CatLogBench::qWarningPrintf2()
RESULT : CatLogBench::qWarningPrintf2():
0.0013 msecs per iteration (total: 90, iterations: 65536)
PASS : CatLogBench::qWarningStream()
RESULT : CatLogBench::qWarningStream():
0.0016 msecs per iteration (total: 54, iterations: 32768)
PASS : CatLogBench::qCWarningStream()
RESULT : CatLogBench::qCWarningStream():
0.0018 msecs per iteration (total: 59, iterations: 32768)
PASS : CatLogBench::qCWarningPrintf()
RESULT : CatLogBench::qCWarningPrintf():
0.0010 msecs per iteration (total: 69, iterations: 65536)
PASS : CatLogBench::cleanupTestCase()
Totals: 7 passed, 0 failed, 0 skipped
So, there is of course some measurable overhead, but I wouldn't say it
disqualifies the streaming variant per se :)
BINARY SIZE
On to the binary size. I removed the QBENCHMARK macro and disassembled the gcc
output. Here it shows that QDebug is completely inlined, the streaming operator
variants do indeed generate a hell lot of instructions ! But since this is
quite a bogus metric here are the size increase of Qt5Core with, and without
the core.io patch included (again a release non-developer build with gcc 4.8.2):
-rwxr-xr-x 1 kkoehne users 5311213 Jan 10 12:55 libQt5Core.so.5.3.0.original
-rwxr-xr-x 1 kkoehne users 5357104 Jan 10 12:58 libQt5Core.so.5.3.0_patch
So the overhead is measurable.
Given these concerns, I'd like to propose adding a printf style overload to
qCDebug:
https://codereview.qt-project.org/#change,75029
Note the patch is fairly ugly because we're gracefully handling the case where
the toolchain doesn't respect Q_COMPILER_VARIADIC_MACROS, I'll post a second
mail about this soon ...
Regards
Kai
___
Development mailing list
Development@qt-project.org
http://lists.qt-project.org/mailman/listinfo/development
___
Development mailing list
Development@qt-project.org
http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
Grr... OWA. And here are the results: PASS : CatLogBench::qWarningPrintf1() RESULT : CatLogBench::qWarningPrintf1(): 0.0010 msecs per iteration (total: 67, iterations: 65536) PASS : CatLogBench::qWarningPrintf2() RESULT : CatLogBench::qWarningPrintf2(): 0.0013 msecs per iteration (total: 90, iterations: 65536) PASS : CatLogBench::qWarningStream() RESULT : CatLogBench::qWarningStream(): 0.0016 msecs per iteration (total: 54, iterations: 32768) PASS : CatLogBench::qCWarningStream() RESULT : CatLogBench::qCWarningStream(): 0.0018 msecs per iteration (total: 59, iterations: 32768) PASS : CatLogBench::qCWarningPrintf() RESULT : CatLogBench::qCWarningPrintf(): 0.0010 msecs per iteration (total: 69, iterations: 65536) PASS : CatLogBench::cleanupTestCase() Totals: 7 passed, 0 failed, 0 skipped So, there is of course some measurable overhead, but I wouldn't say it disqualifies the streaming variant per se :) This indicates an overhead of 30%, or 80%. In core functionality. While this does not immediately disqualify the approach, there needs to be some kind of benefit to compensate. So far I am not seeing that. BINARY SIZE On to the binary size. I removed the QBENCHMARK macro and disassembled the gcc output. Here it shows that QDebug is completely inlined, the streaming operator variants do indeed generate a hell lot of instructions ! But since this is quite a bogus metric here are the size increase of Qt5Core with, and without the core.io patch included (again a release non-developer build with gcc 4.8.2): -rwxr-xr-x 1 kkoehne users 5311213 Jan 10 12:55 libQt5Core.so.5.3.0.original -rwxr-xr-x 1 kkoehne users 5357104 Jan 10 12:58 libQt5Core.so.5.3.0_patch So the overhead is measurable. Given these concerns, I'd like to propose adding a printf style overload to qCDebug: https://codereview.qt-project.org/#change,75029 Note the patch is fairly ugly because we're gracefully handling the c ase where the toolchain doesn't respect Q_COMPILER_VARIADIC_MACROS, I'll post a second mail about this soon ... What about post-poning the whoie idea until we can rely on variadic macros? Regards, Andre' ___ Development mailing list Development@qt-project.org http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
On sexta-feira, 10 de janeiro de 2014 12:04:23, Koehne Kai wrote: And here are the results: PASS : CatLogBench::qWarningPrintf1() RESULT : CatLogBench::qWarningPrintf1(): 0.0010 msecs per iteration (total: 67, iterations: 65536) PASS : CatLogBench::qWarningPrintf2() RESULT : CatLogBench::qWarningPrintf2(): 0.0013 msecs per iteration (total: 90, iterations: 65536) PASS : CatLogBench::qWarningStream() RESULT : CatLogBench::qWarningStream(): 0.0016 msecs per iteration (total: 54, iterations: 32768) PASS : CatLogBench::qCWarningStream() RESULT : CatLogBench::qCWarningStream(): 0.0018 msecs per iteration (total: 59, iterations: 32768) PASS : CatLogBench::qCWarningPrintf() RESULT : CatLogBench::qCWarningPrintf(): 0.0010 msecs per iteration (total: 69, iterations: 65536) PASS : CatLogBench::cleanupTestCase() Totals: 7 passed, 0 failed, 0 skipped So, there is of course some measurable overhead, but I wouldn't say it disqualifies the streaming variant per se For more statistically-valid benchmark results: 1) make sure the total run time is at least half a second per test function (those ran for 50 ms) 2) make sure the CPU is locked to performance mode and Turbo is disabled: # tee performance /sys/devices/system/cpu/cpu*/cpufreq/scaling_governor # cut -f2 -d' ' /sys/devices/system/cpu/cpu0/cpufreq/scaling_available_frequencies | \ tee /sys/devices/system/cpu/cpu*/cpufreq/scaling_max_freq (doesn't work on Linux 3.12 with the new intel_idle driver) 3) you may want to run with the perf counter on Linux to get actual CPU cycles. Pass -minimumtotal to a suitable value to get a runtime of half a second. 4) Run it 6 to 10 times and average out. Use the -csv logger mode so you can easily import into a spreadsheet. https://codereview.qt-project.org/74321 -- Thiago Macieira - thiago.macieira (AT) intel.com Software Architect - Intel Open Source Technology Center signature.asc Description: This is a digitally signed message part. ___ Development mailing list Development@qt-project.org http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
Koehne Kai wrote:
On quinta-feira, 9 de janeiro de 2014 07:28:07, Koehne Kai wrote:
if qCWarning() would expand to an if (myCategory().isEnabled()) ...
That's why it would have to expand to if (!myCategory().isEnabled()) {} else
Well, we can't, since the arguments are not part of the macro :) That
would end up with s.th. lie
if (!myCategory().isEnabled()) { QMessageLogger(__FILE__, __LINE__,
__FUNCTION__).debug() {} else {} Hello World;
which doesn't compile.
This is only a problem because you insist on creating partial statements
with the macro instead of full statements.
If the streaming syntax would be
qFoo(myCategory(), a b c);
instead of
qFoo(myCategory()) a b c;
there's no else to worry about, and it would also solve the problem of
a compile time null stream:
#define qFoo(stream, stuff) /*nothing*/
We had this discussion before.
Andre'
___
Development mailing list
Development@qt-project.org
http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
From: Poenitz Andre
Koehne Kai wrote:
On quinta-feira, 9 de janeiro de 2014 07:28:07, Koehne Kai wrote:
if qCWarning() would expand to an if (myCategory().isEnabled()) ...
That's why it would have to expand to if (!myCategory().isEnabled()) {} else
Well, we can't, since the arguments are not part of the macro :) That
would end up with s.th. lie
if (!myCategory().isEnabled()) { QMessageLogger(__FILE__, __LINE__,
__FUNCTION__).debug() {} else {} Hello World;
which doesn't compile.
This is only a problem because you insist on creating partial statements
with the macro instead of full statements.
True.
If the streaming syntax would be
qFoo(myCategory(), a b c);
instead of
qFoo(myCategory()) a b c;
there's no else to worry about,
Right, but I can't say that I prefer the first syntax over the second, all the
contrary.
and it would also solve the problem of
a compile time null stream:
#define qFoo(stream, stuff) /*nothing*/
Well, right now it resolves to
'while (false) QMessageLogger::noDebug() ', which is the same in effect,
isn't it?
We had this discussion before.
Could be :)
Kai
___
Development mailing list
Development@qt-project.org
http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
On 8 January 2014 09:35, Koehne Kai kai.koe...@digia.com wrote: - Current #ifdef's, environment variables etc should be replaced with an unconditional qCDebug/qCWarning/qCCritical That's not doable in 100% of the cases, f.i. if one has to compile extra code to get the debug information that needs to be printed. Also, what's the overhead of a qCDebug for a disabled category? Qt should never emit debug warnings in its default configuration, so we're talking about many hits to that. -- Giuseppe D'Angelo ___ Development mailing list Development@qt-project.org http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
-Original Message-
From: Giuseppe D'Angelo [mailto:dange...@gmail.com]
Sent: Wednesday, January 08, 2014 9:54 AM
To: Koehne Kai
Cc: development@qt-project.org
Subject: Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
On 8 January 2014 09:35, Koehne Kai kai.koe...@digia.com wrote:
- Current #ifdef's, environment variables etc should be replaced with
an unconditional qCDebug/qCWarning/qCCritical
That's not doable in 100% of the cases, f.i. if one has to compile extra code
to
get the debug information that needs to be printed.
You can then use it like that:
If (qtCoreIo().isDebugEnabled()) {
QString x = expensive();
qCDebug(qtCoreIo) Expensive: x;
}
Anyhow, note that qCDebug(qtCoreIo) expands to
for (bool enabled = qtCoreIo().isDebugEnabled(); Q_UNLIKELY(enabled); enabled =
false)
QMessageLogger(__FILE__, __LINE__, Q_FUNC_INFO,
qtCoreIo().categoryName()).debug()
so this should be needed only if your 'expensive' operations aren't behind the
anyway.
Also, what's the overhead of a qCDebug for a disabled category? Qt should
never emit debug warnings in its default configuration, so we're talking about
many hits to that.
The overhead for a non-enabled qCDebug is basically a function call + one
boolean check (isDebugEnabled() will be inlined).
Regards
Kai
--
Giuseppe D'Angelo
___
Development mailing list
Development@qt-project.org
http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
-Original Message- From: development-bounces+kai.koehne=digia@qt-project.org [mailto:development-bounces+kai.koehne=digia@qt-project.org] On Behalf Of Koehne Kai Sent: Wednesday, January 08, 2014 10:13 AM To: Giuseppe D'Angelo Cc: development@qt-project.org Subject: Re: [Development] Let's get rid of qDebug/qWarning/qCritical! -Original Message- From: Giuseppe D'Angelo [mailto:dange...@gmail.com] Sent: Wednesday, January 08, 2014 9:54 AM To: Koehne Kai Cc: development@qt-project.org Subject: Re: [Development] Let's get rid of qDebug/qWarning/qCritical! On 8 January 2014 09:35, Koehne Kai kai.koe...@digia.com wrote: - Current #ifdef's, environment variables etc should be replaced with an unconditional qCDebug/qCWarning/qCCritical That's not doable in 100% of the cases, f.i. if one has to compile extra code to get the debug information that needs to be printed. Ah, sorry, you meant overhead for additional code. Yeah, you're of course right that there might be code in critical code paths etc where it still makes sense to keep an #ifdef. But I doubt that we've a lot of cases like this. Regards Kai ___ Development mailing list Development@qt-project.org http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
I have a controversial proposition: make qDebug/qWarning/qCritical support logging category and deprecate qCDebug/qCWarning/qCCritical [1]. [1] https://codereview.qt-project.org/#change,74889 Regards, Konstantin 2014/1/8 Koehne Kai kai.koe...@digia.com -Original Message- From: development-bounces+kai.koehne=digia@qt-project.org [mailto:development-bounces+kai.koehne=digia@qt-project.org] On Behalf Of Koehne Kai Sent: Wednesday, January 08, 2014 10:13 AM To: Giuseppe D'Angelo Cc: development@qt-project.org Subject: Re: [Development] Let's get rid of qDebug/qWarning/qCritical! -Original Message- From: Giuseppe D'Angelo [mailto:dange...@gmail.com] Sent: Wednesday, January 08, 2014 9:54 AM To: Koehne Kai Cc: development@qt-project.org Subject: Re: [Development] Let's get rid of qDebug/qWarning/qCritical! On 8 January 2014 09:35, Koehne Kai kai.koe...@digia.com wrote: - Current #ifdef's, environment variables etc should be replaced with an unconditional qCDebug/qCWarning/qCCritical That's not doable in 100% of the cases, f.i. if one has to compile extra code to get the debug information that needs to be printed. Ah, sorry, you meant overhead for additional code. Yeah, you're of course right that there might be code in critical code paths etc where it still makes sense to keep an #ifdef. But I doubt that we've a lot of cases like this. Regards Kai ___ Development mailing list Development@qt-project.org http://lists.qt-project.org/mailman/listinfo/development ___ Development mailing list Development@qt-project.org http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
-Original Message- From: Konstantin Ritt [mailto:ritt...@gmail.com] Sent: Wednesday, January 08, 2014 10:39 AM To: Koehne Kai Cc: Giuseppe D'Angelo; development@qt-project.org Subject: Re: [Development] Let's get rid of qDebug/qWarning/qCritical! I have a controversial proposition: make qDebug/qWarning/qCritical support logging category and deprecate qCDebug/qCWarning/qCCritical [1]. [1] https://codereview.qt-project.org/#change,74889 Originally I wasn't too happy about the qCX names, either. Anyhow, they were introduced to satisfy two demands: a) we want to keep source compatibility for existing uses of qDebug() a) the runtime costs for logging to a category/level that's not enabled should be minimal I guess it's clear we can't break a). To satisfy b), qCDebug expands to a pre-check that skips any evaluation of args etc. If we want to keep qDebug we'd have to accept that arguments are evaluated (we could try to avoid too expensive operations though by putting logic in operator()'s . Personally, I'm happy to trade the slight awkwardness of the qCDebug name for the benefit of not having to worry too much about potential overhead. What you and André also seem to suggest is to keep the printf style . That's actually trivial to add to qCDebug and friends if we require support for variadic macros ... qcompilerdetection.h seems to indicate that variadic macros are supported in GCC=4.3, MSVC=2005 and Intel12. IMO that sounds like we could make it a hard requirement? Regards Kai ___ Development mailing list Development@qt-project.org http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
-Original Message- Subject: Re: [Development] Let's get rid of qDebug/qWarning/qCritical! [...] What you and André also seem to suggest is to keep the printf style . That's actually trivial to add to qCDebug and friends if we require support for variadic macros ... qcompilerdetection.h seems to indicate that variadic macros are supported in GCC=4.3, MSVC=2005 and Intel12. Should be Intel=12.0. Actually the check is __cplusplus=201103L || __INTEL_COMPILER= 1200 ___ Development mailing list Development@qt-project.org http://lists.qt-project.org/mailman/listinfo/development
Re: [Development] Let's get rid of qDebug/qWarning/qCritical!
-Original Message-
From: Kurt Pattyn [mailto:kurt.pat...@icloud.com]
On 08 Jan 2014, at 10:12, Koehne Kai kai.koe...@digia.com wrote:
You can then use it like that:
If (qtCoreIo().isDebugEnabled()) {
QString x = expensive();
qCDebug(qtCoreIo) Expensive: x; }
Anyhow, note that qCDebug(qtCoreIo) expands to
for (bool enabled = qtCoreIo().isDebugEnabled(); Q_UNLIKELY(enabled);
enabled = false) QMessageLogger(__FILE__, __LINE__, Q_FUNC_INFO,
qtCoreIo().categoryName()).debug()
Out of curiosity: is there a reason you use 'for' and not an 'if' statement?
Imagine what would happen with the following code
if (somethingserioushappened)
qCWarning(myCategory) Serious issue!;
else
qCDebug(myCategory) Everything's fine :);
if qCWarning() would expand to an if (myCategory().isEnabled()) ...
so this should be needed only if your 'expensive' operations aren't behind
the anyway.
Also, what's the overhead of a qCDebug for a disabled category? Qt
should never emit debug warnings in its default configuration, so
we're talking about many hits to that.
The overhead for a non-enabled qCDebug is basically a function call + one
boolean check (isDebugEnabled() will be inlined).
If code size or performance is a problem for certain critical code sections,
you
could also use a full macro, like:
qCDebug(category, a b some string);
This construct looks rather strange or even ugly, but has the advantage that
it
can be completely compiled away.
If you want to compile it away there's already QT_NO_DEBUG_OUTPUT, which
changes the definition of qCDebug to
while (false) QMessageLogger().noDebug()
which I expect every compiler worth its name to optimize away :)
Regards
Kai
___
Development mailing list
Development@qt-project.org
http://lists.qt-project.org/mailman/listinfo/development
