Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

logging: Add support for QT_MESSAGE_PATTERN env var #3204

Merged
merged 7 commits into from
Oct 24, 2020

Conversation

Holzhaus
Copy link
Member

This allows customizing the output of the log messages. The default should look almost exactly as before (except that the message type is lowercase).

If you want to customize, you can do that by setting the QT_MESSAGE_PATTERN variable, e.g.:

export QT_MESSAGE_PATTERN="`echo -e "\033[32m%{time h:mm:ss.zzz}%{if-category}\033[32m %{type}:%{endif} %{if-debug}\033[34m%{type}%{endif}%{if-warning}\033[31m%{type}%{endif}%{if-critical}\033[31m%{type}%{endif}%{if-fatal}\033[31m%{type}%{endif}\033[36m %{function} \033[33m[{{threadname}}]\033[0m %{message}"`"

src/util/logging.cpp Outdated Show resolved Hide resolved
@uklotzde
Copy link
Contributor

Code looks much nicer than before.

@uklotzde
Copy link
Contributor

I would like to see this in 2.3. Opinions?

@ronso0
Copy link
Member

ronso0 commented Oct 22, 2020

That would be great in 2.3 as I could ditch rainbow then which seems to swallow some lines of output for example when Mixxx crashes.

@Holzhaus
Copy link
Member Author

By the way, you can also quickly check where a log message comes from without grepping the source by using %{file}:%{line}.

@Holzhaus
Copy link
Member Author

I'm unsure about allocations though. But I guess log messages from the engine thread are a no-go due to stderr I/O anyway...

@Holzhaus
Copy link
Member Author

I would like to see this in 2.3. Opinions?

I just tried rebasing but there's a merge conflict so i'll wait until a decision is made.

@uklotzde
Copy link
Contributor

Allocations are not an issue, although we should minimize them. Besides that logging involves locks and file I/O. Nothing that should be done from the real-time thread.

Ideally handleMessage() would be delegated to a separate thread that performs the formatting and file I/O without the need for additional mutexes.

@poelzi
Copy link
Contributor

poelzi commented Oct 22, 2020

With this patch I can either have colored output on console and colorcodes in the log files, or no colors at all.

@poelzi
Copy link
Contributor

poelzi commented Oct 22, 2020

My branch now also uses the message pattern, but only for the console as otherwise colored output would mess up the file logging.
#3197

@daschuer
Copy link
Member

Do we have an idea how this affects the performance?

Can you compare a Mixxx startup with this patch and without?

I like to avoid the situation that logging will we disabled entire in future for performance reasons, making us blind in support cases.

@uklotzde
Copy link
Contributor

uklotzde commented Oct 23, 2020

@daschuer: Why do we need to measure the startup time? The startup takes seconds while any performance impact is measured in microseconds or less. We will not see any difference for a bunch of log messages.

@daschuer
Copy link
Member

Why do we need to measure the startup time? The startup takes seconds while any performance impact is measured in microseconds or less. We will not see any difference for a bunch of log messages.

That was the easiest test that jumps in my mind. What else can we do to judge about a performance impact?

Copy link
Contributor

@uklotzde uklotzde left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

AppVeyor disagrees:

/FdCMakeFiles\mixxx-lib.dir\mixxx-lib.pdb /FS -c ..\src\util\logging.cpp
..\src\util\logging.cpp(55): warning C4267: 'initializing': conversion from 'size_t' to 'int', possible loss of data
..\src\util\logging.cpp(55): warning C4267: 'initializing': conversion from 'size_t' to 'const int', possible loss of data
..\src\util\logging.cpp(105): warning C4267: '+=': conversion from 'size_t' to 'int', possible loss of data
..\src\util\logging.cpp(125): warning C4267: '+=': conversion from 'size_t' to 'int', possible loss of data
..\src\util\logging.cpp(137): warning C4267: '+=': conversion from 'size_t' to 'int', possible loss of data
..\src\util\logging.cpp(149): warning C4267: '+=': conversion from 'size_t' to 'int', possible loss of data
..\src\util\logging.cpp(155): warning C4267: '+=': conversion from 'size_t' to 'int', possible loss of data
..\src\util\logging.cpp(253): error C3861: 'setenv': identifier not found
[560/886] Building CXX object CMakeFiles\mixxx-lib.dir\src\widget\weffectparameterknobcomposed.cpp.obj

@uklotzde uklotzde mentioned this pull request Oct 23, 2020
1 task

Verified

This commit was created on GitHub.com and signed with GitHub’s verified signature.
@uklotzde
Copy link
Contributor

Once performance becomes a real issue then logging has to be moved into a separate MessageLogWorker thread. I could take a look after this PR has been merged. Should be a straightforward extension.

Replacing the legacy message composition code is the right decision.

@daschuer
Copy link
Member

Once performance becomes a real issue then logging has to be moved into a separate MessageLogWorker thread. I could take a look after this PR has been merged. Should be a straightforward extension.

I am afraid that does not really work. In case of debug assertions, we will never see the log-output, because the process is stopped once the message was written in the message queue of the MessageLogWorker thread.

@uklotzde
Copy link
Contributor

Once performance becomes a real issue then logging has to be moved into a separate MessageLogWorker thread. I could take a look after this PR has been merged. Should be a straightforward extension.

I am afraid that does not really work. In case of debug assertions, we will never see the log-output, because the process is stopped once the message was written in the message queue of the MessageLogWorker thread.

We can add a separate, immediate output for level QtCriticalMsg and higher. In these cases, a performance impact doesn't matter.

src/util/logging.cpp Outdated Show resolved Hide resolved
src/util/logging.cpp Outdated Show resolved Hide resolved
src/util/logging.cpp Outdated Show resolved Hide resolved
src/util/logging.cpp Outdated Show resolved Hide resolved
src/util/logging.cpp Outdated Show resolved Hide resolved
@poelzi
Copy link
Contributor

poelzi commented Oct 23, 2020

Is the mutex allocated from the RT Thread if the engine prints ?

@Holzhaus
Copy link
Member Author

Is the mutex allocated from the RT Thread if the engine prints ?

The mutex is static, the locking happens in the RT thread. But in that case the file I/O will be the bigger problem I think. Maybe we can switch to a lock-free queue approach with a separate thread that write the output in a later PR.

@uklotzde
Copy link
Contributor

uklotzde commented Oct 23, 2020

Is the mutex allocated from the RT Thread if the engine prints ?

The mutex is static, the locking happens in the RT thread. But in that case the file I/O will be the bigger problem I think. Maybe we can switch to a lock-free queue approach with a separate thread that write the output in a later PR.

Logging from the RT thread is strictly forbidden because of the string memory allocations. A lock-free queue doesn't help.

Update: If we want to log from the RT thread we need a separate mechanism with pre-allocated buffers. This is out of scope.

Copy link
Member

@daschuer daschuer left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here some comments.
I have digged into the QT code and the implementation is quite smart. The pattern is evaluated only once so the performance penalty should be negligible.

src/util/logging.cpp Outdated Show resolved Hide resolved
src/util/logging.cpp Outdated Show resolved Hide resolved
@daschuer
Copy link
Member

Logging from the RT thread is strictly forbidden because of the string memory allocations. A lock-free queue doesn't help.

If we crash anyway, it is OK. Also in one time cases where a we have hick-up anyway. I think the current situation is OK no need regarding logging from RT threads.

Copy link
Member

@daschuer daschuer left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, Thank you. Works also good.

src/util/logging.cpp Outdated Show resolved Hide resolved
src/util/logging.cpp Outdated Show resolved Hide resolved
src/util/logging.cpp Outdated Show resolved Hide resolved
src/util/logging.cpp Outdated Show resolved Hide resolved
src/util/logging.cpp Show resolved Hide resolved
@Holzhaus Holzhaus requested a review from uklotzde October 23, 2020 17:10
src/util/logging.cpp Outdated Show resolved Hide resolved
@Holzhaus Holzhaus requested a review from uklotzde October 23, 2020 18:58
@uklotzde
Copy link
Contributor

main or 2.3?

@Holzhaus
Copy link
Member Author

main or 2.3?

I'm not particularily keen on resolving all the merge conflicts when rebasing on 2.3 tbh.

@uklotzde
Copy link
Contributor

main or 2.3?

I'm not particularily keen on resolving all the merge conflicts when rebasing on 2.3 tbh.

Agreed.

@uklotzde
Copy link
Contributor

LGTM. Awaiting CI results.

Copy link
Contributor

@uklotzde uklotzde left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code style issue: A strayed, empty line

@uklotzde
Copy link
Contributor

Remaining CI test failures are unrelated and will be fixed by #3209. LGTM

@uklotzde uklotzde merged commit 19da9d8 into mixxxdj:main Oct 24, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

5 participants