Logging Pt.2: Predefined categories and usage examples #2782

uklotzde · 2020-05-12T21:20:19Z

TODO

Merge SoundSourceFFmpeg: Fix decoding of corrupt files / Refactoring & documentation #3073 into master to hide all unrelated changes from the diff

The documentation can be found in logging.h.

Add predefined root and top-level logging categories
Provide a macro for creating custom child categories
Provide 2 reference examples (now using Info instead of Debug logs):
- SoundSourceFFmpeg
- SoundDevicePortAudio
Add missing thread names

SoundDevicePortAudio logs:

Debug [Main]: SoundManager::setupDevices()
Info [Main] mixxx.device.PortAudio: Opening device "default"
Info [Main] mixxx.device.PortAudio: Number of output channels: 2
Info [Main] mixxx.device.PortAudio: Number of input channels: 0
Info [Main] mixxx.device.PortAudio: Requested sample rate: 44100 Hz
Info [Main] mixxx.device.PortAudio: Number of sample frames per buffer: 1024
Info [Main] mixxx.device.PortAudio: Latency per buffer: 23.22 ms
Info [Main] mixxx.device.PortAudio: Opening stream 14
Debug [Controller]: Found "" "" "r1" S/N "" "Interface 0"
Warning [Controller]: USB permissions problem (or device error.) Your account needs write access to USB HID controllers.
[New Thread 0x7ffeb38d1700 (LWP 14515)]
Debug [Controller]: Found "" "" "r1" S/N "" "Interface 1"
Warning [Controller]: USB permissions problem (or device error.) Your account needs write access to USB HID controllers.
Debug [Controller]: Found "" "" "r4624" S/N "" "Interface 0"
Warning [Controller]: USB permissions problem (or device error.) Your account needs write access to USB HID controllers.
Debug [Controller]: Found "" "" "r4624" S/N "" "Interface 1"
Warning [Controller]: USB permissions problem (or device error.) Your account needs write access to USB HID controllers.
Debug [Controller]: Found "" "" "r4624" S/N "" "Interface 2"
Warning [Controller]: USB permissions problem (or device error.) Your account needs write access to USB HID controllers.
Debug [Controller]: ControllerManager::getControllerList
Debug [Controller]: Controller polling stopped.
Debug [Main] mixxx.device.PortAudio: "SoundDeviceId(default, 14)" Opened stream
Info [Main] mixxx.device.PortAudio: Loading dynamic library "libportaudio.so.2"
Debug [Main] mixxx.device.PortAudio: Loaded dynamic library "libportaudio.so.2"
Info [Main] mixxx.device.PortAudio: Enabling real-time scheduling
[New Thread 0x7ffea70d0700 (LWP 14516)]
Debug [Main] mixxx.device.PortAudio: "SoundDeviceId(default, 14)" Stream started
Info [Main] mixxx.device.PortAudio: Actual sample rate: 44100 Hz
Info [Main] mixxx.device.PortAudio: Actual output latency: 46.4399 ms
Info [0x7fff00007720] mixxx.device.PortAudio: SSE: Enabling denormals to zero mode
Info [0x7fff00007720] mixxx.device.PortAudio: SSE: Enabling flush to zero mode
Info [0x7fff00007720] mixxx.device.PortAudio: Denormals to zero mode is working

SoundSourceFFmpeg logs:

Debug [AnalyzerThread 0 #1] mixxx.source.FFmpeg: Opened stream for decoding { index 0 | id 0 | codec_type 1 | codec_id 86017 | channels 2 | channel_layout 3 | channel_layout (fixed) 3 | format 8 | sample_rate 44100 | bit_rate 320000 | frame_size 1152 | initial_padding 0 | trailing_padding 0 | seek_preroll 0 | start_time 353600 | duration 2794291200 | nb_frames 0 | time_base 1 / 14112000 }
Debug [AnalyzerThread 0 #1] mixxx.source.FFmpeg: Lead-in frames [0 -> 1105)
[mp3float @ 0x7ffee0066f40] Could not update timestamps for skipped samples.
Debug [AnalyzerThread 0 #1]: AnalysisDAO fetched 0 analyses, 0 bytes for track 306621 in 0 ms
Debug [AnalyzerThread 0 #1]: Skipping AnalyzerEbur128
Debug [AnalyzerThread 0 #1]: AnalyzerBeats preference settings:

src/soundio/sounddeviceportaudio.h

Holzhaus · 2020-05-13T10:13:09Z

src/util/logging.cpp

@@ -17,6 +16,18 @@
 #include "controllers/controllerdebug.h"
 #include "util/assert.h"

+Q_LOGGING_CATEGORY(mixxxLog, MIXXX_LOGGING_CATEGORY_ROOT)
+
+Q_LOGGING_CATEGORY(mixxxLogConfig, MIXXX_LOGGING_CATEGORY_CONFIG)


Is there any advantage from defining them all in one place?
Personally, I think all these macros look ugly.

I'd prefer this:

bool Highscore::load(const QString &filepath) { QLoggingCategory fcIo("fc.io"); qCDebug(fcIo) << "Loading highscore ..."; QFile file(filepath); if (!file.open(QIODevice::ReadOnly | QIODevice::Text)) { qCWarning(fcIo) << "Could not open file " << filepath << "!"; return; } // ... }

[...]

QLoggingCategory represents a category in code, in this case it's "fc.io". It's not a one to one mapping though ... you can have multiple instances representing the same category.

Source: https://www.qt.io/blog/2014/03/11/qt-weekly-1-categorized-logging

The idea was to group the logs under some predefined top-level categories to allow basic filtering without needing to know all child categories. The custom macro MIXXX_LOGGING_CATEGORY_PARENT_CHILD establishes a naming convention.

The macros Q_DECLARE_LOGGING_CATEGORY/Q_LOGGING_CATEGORY help to find all categories that are available, even if they are only defined locally inside a .cpp file and not intended to be reused.

The idea was to group the logs under some predefined top-level categories to allow basic filtering without needing to know all child categories. The custom macro MIXXX_LOGGING_CATEGORY_PARENT_CHILD establishes a naming convention.

I thought this is done implicitly by separating the category name with dots.
And filtering can be done like this:

QT_LOGGING_RULES="mixxx.engine.controls.*=true"

The macros Q_DECLARE_LOGGING_CATEGORY/Q_LOGGING_CATEGORY help to find all categories that are available, even if they are only defined locally inside a .cpp file and not intended to be reused.

So you can list all categories via command line? Or do you mean by grepping through the source?

@uklotzde can you elaborate?

I don't like to introduce a custom macro. But so far I didn't have any idea how to achieve this in a better way.

We could put all category strings in a single header file and then include them from there. That way you only need to seach-replace in a single file.

With this restriction the macros could be avoided.

After 2nd thought: Not viable. A huge global file that might contain a separate logging category for each module (comprising 1 or a few .cpp files) is unmaintainable.

How is a user supposed to chose the correct one? Even the list of predefined top-level logging categories in logging.h is long already.

Hmm. I also thought about this and I'm not even sure we need this global list or the macros. When we define the logging category inside the source file, like this it becomes much easier to find the correct logging category to enable debug messages for:

QLoggingCategory logcat("device.soundsource.portaudio");

You're right that it becomes a bit tedious to restructure logging categories later on if the fully qualified names are spread across the code base like this, but it's still possible to mass-replace them in a bash one-liner using find/grep/sed. And I don' t think we want to restructure them that often, and the instant visibility of the full logging category name when reading the source file is very convenient and outweighs this potential issue IMHO.

Holzhaus · 2020-06-29T16:31:00Z

src/sources/soundsourceffmpeg.cpp

@@ -79,15 +79,15 @@ inline int64_t getStreamStartTime(const AVStream& avStream) {
    auto start_time = avStream.start_time;
    if (start_time == AV_NOPTS_VALUE) {
        // This case is not unlikely, e.g. happens when decoding WAV files.
-#if ENABLE_TRACING
-        kLogger.trace()
+#if ENABLE_TRACE_LOG


Can't we get rid of this?

I don't think this makes a notable performance improvement:

Note: Arguments aren't processed if the debug output for that category is not enabled, so don't rely on any side effects.

Qt does not provided a detailed trace level, only debug. Until the default log level has been switched from debug to info we cannot avoid this conditional compilation to avoid log spam.

And even then log messages in real-time threads need to be disabled at compile time by using conditional compilation. That's the reason why I also picked an example from the sound device code.

Why do we need something more detailed than debug? IMHO it makes more sense to switch on debug messages for the logging category you're interested in and use INFO for everything else by default.

Why do they need to be disabled in RT code? If arguments aren't processed if debug logging is disabled (as the documentation states), shouldn't this just cause one additional conditional branch per log statement? That should be OK even in performance-critical code, right?

String operations are too slow for realtime code.

The logs we are talking about in the real-time code are only used for tracing execution paths in the callback loop during development. These are invoked frequently and should not be compiled into any executable version, even if they would be real-time safe.

The Qt logging facilities will have some performance impact at runtime. And they have been designed for general purpose desktop UI applications, not for performance critical code.

I will add a global define to enable verbose debug logs like in SoundSourceFFmpeg. These could be enabled permanently once we have switched the default log level from Debug to Info.

The local defines for trace logs in SoundDevicePortAudio are still needed as explained. I will try to add a reference to this example as blueprint.

Holzhaus · 2020-06-29T16:47:22Z

src/util/logging.cpp

@@ -17,6 +16,18 @@
 #include "controllers/controllerdebug.h"
 #include "util/assert.h"

+Q_LOGGING_CATEGORY(mixxxLog, MIXXX_LOGGING_CATEGORY_ROOT)
+
+Q_LOGGING_CATEGORY(mixxxLogConfig, MIXXX_LOGGING_CATEGORY_CONFIG)


We could put all category strings in a single header file and then include them from there. That way you only need to seach-replace in a single file.

Be-ing · 2020-07-04T05:41:27Z

src/util/logging.h

+Q_DECLARE_LOGGING_CATEGORY(mixxxLogEngine)
+#define MIXXX_LOGGING_CATEGORY_ENGINE \
+    MIXXX_LOGGING_CATEGORY_PARENT_CHILD(MIXXX_LOGGING_CATEGORY_ROOT, "engine")
+


Suggested change

/// Base logging category for effects

Q_DECLARE_LOGGING_CATEGORY(mixxxLogEffects)

#define MIXXX_LOGGING_CATEGORY_ENGINE \

MIXXX_LOGGING_CATEGORY_PARENT_CHILD(MIXXX_LOGGING_CATEGORY_ROOT, "effects")

I can then use this in #2618 after this is merged.

Be-ing · 2020-07-04T05:44:32Z

src/util/logging.h

+/// Base logging category for scripting
+Q_DECLARE_LOGGING_CATEGORY(mixxxLogScript)
+#define MIXXX_LOGGING_CATEGORY_SCRIPT \
+    MIXXX_LOGGING_CATEGORY_PARENT_CHILD(MIXXX_LOGGING_CATEGORY_ROOT, "script")


Suggested change

/// Base logging category for scripting

Q_DECLARE_LOGGING_CATEGORY(mixxxLogScript)

#define MIXXX_LOGGING_CATEGORY_SCRIPT \

MIXXX_LOGGING_CATEGORY_PARENT_CHILD(MIXXX_LOGGING_CATEGORY_ROOT, "script")

/// Base logging category for controllers

Q_DECLARE_LOGGING_CATEGORY(mixxxLogController)

#define MIXXX_LOGGING_CATEGORY_SCRIPT \

MIXXX_LOGGING_CATEGORY_PARENT_CHILD(MIXXX_LOGGING_CATEGORY_ROOT, "controller")

There is info logged by the controller system apart from scripts. ControllerEngine could create a mixxx.controller.CONTROLLERNAME.script subcategory for messages from the script.

Be-ing · 2020-07-04T05:48:07Z

src/util/logging.h

+/// in your local repo while debugging. Disable it before submitting a pull
+/// request. Use qCDebug() for these trace logs.


Suggested change

/// in your local repo while debugging. Disable it before submitting a pull

/// request. Use qCDebug() for these trace logs.

/// in your local repo while debugging. Disable it before committing.

/// Use qCDebug() for these trace logs.

Be-ing · 2020-07-04T05:51:29Z

src/util/logging.h

+/// Base logging category for hardware I/O sound devices
+Q_DECLARE_LOGGING_CATEGORY(mixxxLogDevice)
+#define MIXXX_LOGGING_CATEGORY_DEVICE \
+    MIXXX_LOGGING_CATEGORY_PARENT_CHILD(MIXXX_LOGGING_CATEGORY_ROOT, "device")


Suggested change

/// Base logging category for hardware I/O sound devices

Q_DECLARE_LOGGING_CATEGORY(mixxxLogDevice)

#define MIXXX_LOGGING_CATEGORY_DEVICE \

MIXXX_LOGGING_CATEGORY_PARENT_CHILD(MIXXX_LOGGING_CATEGORY_ROOT, "device")

/// Base logging category for hardware I/O sound devices

Q_DECLARE_LOGGING_CATEGORY(mixxxLogAudioDevice)

#define MIXXX_LOGGING_CATEGORY_DEVICE \

MIXXX_LOGGING_CATEGORY_PARENT_CHILD(MIXXX_LOGGING_CATEGORY_ROOT, "audiodevice")

"Device" by itself could mean lots of things.

# Conflicts: # src/sources/soundsourceffmpeg.cpp

- Document and illustrate all steps in detail - Verify assumptions by debug assertions

# Conflicts: # src/sources/soundsourceffmpeg.cpp

ywwg · 2020-10-16T22:25:42Z

Can we have an update on this PR? Do people like where it is going? What do we need to do to make it not a draft?

uklotzde · 2020-10-16T22:33:26Z

I am not able to continue working on this until other PRs have been finished and merged.

# Conflicts: # src/soundio/sounddeviceportaudio.cpp # src/soundio/sounddeviceportaudio.h # src/sources/soundsourceffmpeg.cpp # src/sources/soundsourceffmpeg.h

github-actions · 2021-01-25T00:50:40Z

This PR is marked as stale because it has been open 90 days with no activity.

uklotzde · 2021-02-23T18:43:28Z

I am tired to work on C++ code and don't plan to revive this PR.

uklotzde · 2021-02-23T18:46:40Z

I will delete the corresponding branches in my fork eventually to get rid of the cognitive load.

uklotzde added 5 commits May 12, 2020 22:27

Predefine base Mixxx logging categories

11cffc3

Use category logging for SoundSourceFFmpeg

2e6d157

Use category logging for SoundDevicePortAudio

594ea15

Add logging example references in documentation

deb2613

Initialize thread names for better logging messages

2cf3ced

uklotzde added this to the 2.4.0 milestone May 12, 2020

Be-ing reviewed May 12, 2020

View reviewed changes

src/soundio/sounddeviceportaudio.h Outdated Show resolved Hide resolved

Holzhaus reviewed May 13, 2020

View reviewed changes

Holzhaus added the code quality label May 27, 2020

uklotzde added 6 commits June 5, 2020 12:37

Merge branch '2.3' of git@github.com:mixxxdj/mixxx.git

0319a5f

Merge branch 'master' into logging

3f1940e

Merge branch 'master' into logging

38237d0

Merge branch 'master' into logging

c85ba9f

Merge branch 'master' into logging

b82dcb5

Merge branch 'master' into logging

f1b46c2

Holzhaus reviewed Jun 29, 2020

View reviewed changes

uklotzde added 3 commits June 29, 2020 23:30

Merge branch 'master' of git@github.com:mixxxdj/mixxx.git into logging

88bd51a

Introduce global define for verbose debug logging

6829109

Add warning about trace logging in real-time code

2aade96

Holzhaus mentioned this pull request Jun 29, 2020

Create a util file for Qt Logging Categories #2905

Closed

Be-ing reviewed Jul 4, 2020

View reviewed changes

Merge branch 'master' into logging

e2b331d

# Conflicts: # src/sources/soundsourceffmpeg.cpp

uklotzde mentioned this pull request Jul 12, 2020

SoundSourceFFmpeg: Fix debug assert and offset/range calculation #2931

Merged

uklotzde added 4 commits July 12, 2020 18:05

Merge branch 'master' into logging

199e58e

Merge branch 'master' into logging

a1b5011

Merge branch 'master' into logging

f2a3b3d

Merge branch 'master' into logging

d37835a

# Conflicts: # src/sources/soundsourceffmpeg.cpp

uklotzde added 3 commits August 11, 2020 12:05

Merge branch 'master' into logging

48acdd4

Merge branch 'master' into logging

1470040

Merge branch 'master' into logging

6e8e20a

Be-ing mentioned this pull request Aug 30, 2020

Changing tempos support #2930

Draft

uklotzde mentioned this pull request Sep 2, 2020

Replace qWarning() with qInfo() #3065

Closed

uklotzde added 4 commits September 3, 2020 22:27

Replace log level Trace with Debug

8bbbbd7

SoundSourceFFmpeg: Rename variables and reformat code

8e4da35

SoundSourceFFmpeg: Reorder and document decoding loop body

169a721

- Document and illustrate all steps in detail - Verify assumptions by debug assertions

Fix debug assertion when decoding corrupt file

aaf1709

uklotzde mentioned this pull request Sep 3, 2020

SoundSourceFFmpeg: Fix decoding of corrupt files / Refactoring & documentation #3073

Merged

uklotzde added 3 commits September 3, 2020 23:13

Merge branch 'master' into logging

f970322

Merge branch '2.3' into logging

a5daf5b

Merge branch '2.3_ffmpeg' into logging

fc45620

# Conflicts: # src/sources/soundsourceffmpeg.cpp

uklotzde marked this pull request as draft September 4, 2020 07:04

uklotzde mentioned this pull request Oct 12, 2020

Library: Add last_played_at column #3140

Merged

Be-ing changed the base branch from master to main October 23, 2020 23:23

Merge branch 'main' into logging

1a885a2

# Conflicts: # src/soundio/sounddeviceportaudio.cpp # src/soundio/sounddeviceportaudio.h # src/sources/soundsourceffmpeg.cpp # src/sources/soundsourceffmpeg.h

github-actions bot added the stale Stale issues that haven't been updated for a long time. label Jan 25, 2021

uklotzde closed this Feb 23, 2021

uklotzde deleted the logging branch March 17, 2021 17:58

mixxxbot mentioned this pull request Aug 22, 2022

Create global info message display & logging function #5422

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging Pt.2: Predefined categories and usage examples #2782

Logging Pt.2: Predefined categories and usage examples #2782

uklotzde commented May 12, 2020 •

edited

Holzhaus May 13, 2020

uklotzde May 13, 2020

Holzhaus May 27, 2020

Holzhaus Jun 11, 2020

Holzhaus Jun 20, 2020

uklotzde Jun 20, 2020

Holzhaus Jun 29, 2020

uklotzde Jun 29, 2020

uklotzde Jun 29, 2020

Holzhaus Jun 29, 2020 •

edited

Holzhaus Jun 29, 2020

uklotzde Jun 29, 2020

Holzhaus Jun 29, 2020 •

edited

Be-ing Jun 29, 2020

uklotzde Jun 29, 2020

uklotzde Jun 29, 2020

Holzhaus Jun 29, 2020

Be-ing Jul 4, 2020

Be-ing Jul 4, 2020

Be-ing Jul 4, 2020

Be-ing Jul 4, 2020

ywwg commented Oct 16, 2020

uklotzde commented Oct 16, 2020

github-actions bot commented Jan 25, 2021

uklotzde commented Feb 23, 2021

uklotzde commented Feb 23, 2021

+/// Base logging category for effects
+Q_DECLARE_LOGGING_CATEGORY(mixxxLogEffects)
+#define MIXXX_LOGGING_CATEGORY_ENGINE \
+    MIXXX_LOGGING_CATEGORY_PARENT_CHILD(MIXXX_LOGGING_CATEGORY_ROOT, "effects")

		/// in your local repo while debugging. Disable it before submitting a pull
		/// request. Use qCDebug() for these trace logs.

Logging Pt.2: Predefined categories and usage examples #2782

Logging Pt.2: Predefined categories and usage examples #2782

Conversation

uklotzde commented May 12, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Holzhaus Jun 29, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Holzhaus Jun 29, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ywwg commented Oct 16, 2020

uklotzde commented Oct 16, 2020

github-actions bot commented Jan 25, 2021

uklotzde commented Feb 23, 2021

uklotzde commented Feb 23, 2021

uklotzde commented May 12, 2020 •

edited

Holzhaus Jun 29, 2020 •

edited

Holzhaus Jun 29, 2020 •

edited