Allow log messages to be grouped by activity on Apple OSes

Useful for making sense of the event dispatcher, especially when running
tests.

Change-Id: Iea84bcfb40d4954439c2e31ffc0197c64907e800
Reviewed-by: Morten Johan Sørvig <morten.sorvig@qt.io>
This commit is contained in:
Tor Arne Vestbø 2018-01-24 16:38:43 +01:00
parent 8264e495fa
commit f816f2e3c9
5 changed files with 175 additions and 6 deletions

View File

@ -51,18 +51,50 @@
// We mean it.
//
#include "private/qglobal_p.h"
#ifndef __IMAGECAPTURE__
# define __IMAGECAPTURE__
#endif
// --------------------------------------------------------------------------
#if !defined(QT_BOOTSTRAPPED) && (QT_MACOS_PLATFORM_SDK_EQUAL_OR_ABOVE(__MAC_10_12) || !defined(Q_OS_MACOS))
#define QT_USE_APPLE_ACTIVITIES
#if defined(OS_ACTIVITY_OBJECT_API)
#error The file <os/activity.h> has already been included
#endif
// We runtime-check all use of the activity APIs, so we can safely build
// with them included, even if the deployment target is macOS 10.11
#if QT_MACOS_DEPLOYMENT_TARGET_BELOW(__MAC_10_12)
#undef __MAC_OS_X_VERSION_MIN_REQUIRED
#define __MAC_OS_X_VERSION_MIN_REQUIRED __MAC_10_12
#define DID_OVERRIDE_DEPLOYMENT_TARGET
#endif
#include <os/activity.h>
#if !OS_ACTIVITY_OBJECT_API
#error "Expected activity API to be available"
#endif
#if defined(DID_OVERRIDE_DEPLOYMENT_TARGET)
#undef __MAC_OS_X_VERSION_MIN_REQUIRED
#define __MAC_OS_X_VERSION_MIN_REQUIRED __MAC_10_11
#undef DID_OVERRIDE_DEPLOYMENT_TARGET
#endif
#endif
// --------------------------------------------------------------------------
#if defined(QT_BOOTSTRAPPED)
#include <ApplicationServices/ApplicationServices.h>
#else
#include <CoreFoundation/CoreFoundation.h>
#endif
#include "private/qglobal_p.h"
#ifdef __OBJC__
#include <Foundation/Foundation.h>
#endif
@ -190,6 +222,100 @@ private:
// --------------------------------------------------------------------------
#if defined(QT_USE_APPLE_ACTIVITIES)
QT_END_NAMESPACE
#include <os/availability.h>
#define OS_ACTIVITY_AVAILABILITY API_AVAILABLE(macos(10.12), ios(10.0), tvos(10.0), watchos(3.0))
#define OS_ACTIVITY_AVAILABILITY_CHECK __builtin_available(macOS 10.12, iOS 10, tvOS 10, watchOS 3, *)
QT_BEGIN_NAMESPACE
template <typename T> using QAppleOsType = QAppleRefCounted<T, void *, os_retain, os_release>;
class Q_CORE_EXPORT QAppleLogActivity
{
public:
QAppleLogActivity() : activity(nullptr) {}
QAppleLogActivity(os_activity_t activity) OS_ACTIVITY_AVAILABILITY : activity(activity) {}
~QAppleLogActivity() { if (activity) leave(); }
QAppleLogActivity(const QAppleLogActivity &) = delete;
QAppleLogActivity& operator=(const QAppleLogActivity &) = delete;
QAppleLogActivity(QAppleLogActivity&& other)
: activity(other.activity), state(other.state) { other.activity = nullptr; }
QAppleLogActivity& operator=(QAppleLogActivity &&other)
{
if (this != &other) {
activity = other.activity;
state = other.state;
other.activity = nullptr;
}
return *this;
}
QAppleLogActivity&& enter()
{
if (activity) {
if (OS_ACTIVITY_AVAILABILITY_CHECK)
os_activity_scope_enter(static_cast<os_activity_t>(*this), &state);
}
return std::move(*this);
}
void leave() {
if (activity) {
if (OS_ACTIVITY_AVAILABILITY_CHECK)
os_activity_scope_leave(&state);
}
}
operator os_activity_t() OS_ACTIVITY_AVAILABILITY
{
return reinterpret_cast<os_activity_t>(static_cast<void *>(activity));
}
private:
// Work around API_AVAILABLE not working for templates by using void*
QAppleOsType<void *> activity;
os_activity_scope_state_s state;
};
#define QT_APPLE_LOG_ACTIVITY_CREATE(condition, description, parent) []() { \
if (!(condition)) \
return QAppleLogActivity(); \
if (OS_ACTIVITY_AVAILABILITY_CHECK) \
return QAppleLogActivity(os_activity_create(description, parent, OS_ACTIVITY_FLAG_DEFAULT)); \
return QAppleLogActivity(); \
}()
#define QT_VA_ARGS_CHOOSE(_1, _2, _3, _4, _5, _6, _7, _8, _9, N, ...) N
#define QT_VA_ARGS_COUNT(...) QT_VA_ARGS_CHOOSE(__VA_ARGS__, 9, 8, 7, 6, 5, 4, 3, 2, 1)
#define QT_OVERLOADED_MACRO(MACRO, ...) _QT_OVERLOADED_MACRO(MACRO, QT_VA_ARGS_COUNT(__VA_ARGS__))(__VA_ARGS__)
#define _QT_OVERLOADED_MACRO(MACRO, ARGC) _QT_OVERLOADED_MACRO_EXPAND(MACRO, ARGC)
#define _QT_OVERLOADED_MACRO_EXPAND(MACRO, ARGC) MACRO##ARGC
#define QT_APPLE_LOG_ACTIVITY_WITH_PARENT3(condition, description, parent) QT_APPLE_LOG_ACTIVITY_CREATE(condition, description, parent)
#define QT_APPLE_LOG_ACTIVITY_WITH_PARENT2(description, parent) QT_APPLE_LOG_ACTIVITY_WITH_PARENT3(true, description, parent)
#define QT_APPLE_LOG_ACTIVITY_WITH_PARENT(...) QT_OVERLOADED_MACRO(QT_APPLE_LOG_ACTIVITY_WITH_PARENT, __VA_ARGS__)
#define QT_APPLE_LOG_ACTIVITY2(condition, description) QT_APPLE_LOG_ACTIVITY_CREATE(condition, description, OS_ACTIVITY_CURRENT)
#define QT_APPLE_LOG_ACTIVITY1(description) QT_APPLE_LOG_ACTIVITY2(true, description)
#define QT_APPLE_LOG_ACTIVITY(...) QT_OVERLOADED_MACRO(QT_APPLE_LOG_ACTIVITY, __VA_ARGS__)
#define QT_APPLE_SCOPED_LOG_ACTIVITY(...) QAppleLogActivity scopedLogActivity = QT_APPLE_LOG_ACTIVITY(__VA_ARGS__).enter();
#else
// No-ops for macOS 10.11. We don't need to provide QT_APPLE_SCOPED_LOG_ACTIVITY,
// as all the call sites for that are in code that's only built on 10.12 and above.
#define QT_APPLE_LOG_ACTIVITY_WITH_PARENT(...)
#define QT_APPLE_LOG_ACTIVITY(...)
#endif // QT_DARWIN_PLATFORM_SDK_EQUAL_OR_ABOVE
// -------------------------------------------------------------------------
QT_END_NAMESPACE
#endif // QCORE_MAC_P_H

View File

@ -238,6 +238,7 @@ QEventLoop *QEventDispatcherCoreFoundation::currentEventLoop() const
*/
bool QEventDispatcherCoreFoundation::processEvents(QEventLoop::ProcessEventsFlags flags)
{
QT_APPLE_SCOPED_LOG_ACTIVITY(lcEventDispatcher().isDebugEnabled(), "processEvents");
bool eventsProcessed = false;
if (flags & (QEventLoop::ExcludeUserInputEvents | QEventLoop::ExcludeSocketNotifiers))
@ -390,6 +391,8 @@ bool QEventDispatcherCoreFoundation::processEvents(QEventLoop::ProcessEventsFlag
bool QEventDispatcherCoreFoundation::processPostedEvents()
{
QT_APPLE_SCOPED_LOG_ACTIVITY(lcEventDispatcher().isDebugEnabled(), "processPostedEvents");
if (m_processEvents.processedPostedEvents && !(m_processEvents.flags & QEventLoop::EventLoopExec)) {
qCDebug(lcEventDispatcher) << "Already processed events this pass";
return false;
@ -405,6 +408,8 @@ bool QEventDispatcherCoreFoundation::processPostedEvents()
void QEventDispatcherCoreFoundation::processTimers(CFRunLoopTimerRef timer)
{
QT_APPLE_SCOPED_LOG_ACTIVITY(lcEventDispatcher().isDebugEnabled(), "processTimers");
if (m_processEvents.processedTimers && !(m_processEvents.flags & QEventLoop::EventLoopExec)) {
qCDebug(lcEventDispatcher) << "Already processed timers this pass";
m_processEvents.deferredUpdateTimers = true;

View File

@ -204,6 +204,11 @@ namespace
jmp_buf applicationWillTerminateJumpPoint;
bool debugStackUsage = false;
struct {
QAppleLogActivity UIApplicationMain;
QAppleLogActivity applicationDidFinishLaunching;
} logActivity;
}
extern "C" int qt_main_wrapper(int argc, char *argv[])
@ -228,6 +233,9 @@ extern "C" int qt_main_wrapper(int argc, char *argv[])
}
}
logActivity.UIApplicationMain = QT_APPLE_LOG_ACTIVITY(
lcEventDispatcher().isDebugEnabled(), "UIApplicationMain").enter();
qCDebug(lcEventDispatcher) << "Running UIApplicationMain";
return UIApplicationMain(argc, argv, nil, NSStringFromClass([QIOSApplicationDelegate class]));
}
@ -263,11 +271,14 @@ static void __attribute__((noinline, noreturn)) user_main_trampoline()
int exitCode = main(argc, argv);
delete[] argv;
logActivity.applicationDidFinishLaunching.enter();
qCDebug(lcEventDispatcher) << "Returned from main with exit code " << exitCode;
if (Q_UNLIKELY(debugStackUsage))
userMainStack.printUsage();
logActivity.applicationDidFinishLaunching.leave();
if (applicationAboutToTerminate)
longjmp(applicationWillTerminateJumpPoint, kJumpedFromUserMainTrampoline);
@ -322,6 +333,9 @@ static bool rootLevelRunLoopIntegration()
+ (void)applicationDidFinishLaunching:(NSNotification *)notification
{
logActivity.applicationDidFinishLaunching = QT_APPLE_LOG_ACTIVITY_WITH_PARENT(
lcEventDispatcher().isDebugEnabled(), "applicationDidFinishLaunching", logActivity.UIApplicationMain).enter();
qCDebug(lcEventDispatcher) << "Application launched with options" << notification.userInfo;
if (!isQtApplication())
@ -339,10 +353,11 @@ static bool rootLevelRunLoopIntegration()
return;
}
switch (setjmp(processEventEnterJumpPoint)) {
case kJumpPointSetSuccessfully:
case kJumpPointSetSuccessfully: {
qCDebug(lcEventDispatcher) << "Running main() on separate stack";
QT_APPLE_SCOPED_LOG_ACTIVITY(lcEventDispatcher().isDebugEnabled(), "main()");
// Redirect the stack pointer to the start of the reserved stack. This ensures
// that when we longjmp out of the event dispatcher and continue execution, the
// 'Qt main' call-stack will not be smashed, as it lives in a part of the stack
@ -357,9 +372,11 @@ static bool rootLevelRunLoopIntegration()
Q_UNREACHABLE();
break;
}
case kJumpedFromEventDispatcherProcessEvents:
// We've returned from the longjmp in the event dispatcher,
// and the stack has been restored to its old self.
logActivity.UIApplicationMain.enter();
qCDebug(lcEventDispatcher) << "↳ Jumped from processEvents due to exec";
if (Q_UNLIKELY(debugStackUsage))
@ -378,6 +395,10 @@ static const char kApplicationWillTerminateExitCode = char(SIGTERM | 0x80);
+ (void)applicationWillTerminate
{
QAppleLogActivity applicationWillTerminateActivity = QT_APPLE_LOG_ACTIVITY_WITH_PARENT(
lcEventDispatcher().isDebugEnabled(), "applicationWillTerminate", logActivity.UIApplicationMain).enter();
qCDebug(lcEventDispatcher) << "Application about to be terminated by iOS";
if (!isQtApplication())
return;
@ -403,11 +424,14 @@ static const char kApplicationWillTerminateExitCode = char(SIGTERM | 0x80);
// so we'll never see the exit activity and have a chance to return from
// QEventLoop::exec(). We initiate the return manually as a workaround.
qCDebug(lcEventDispatcher) << "Manually triggering return from event loop exec";
applicationWillTerminateActivity.leave();
static_cast<QIOSEventDispatcher *>(qApp->eventDispatcher())->interruptEventLoopExec();
break;
case kJumpedFromUserMainTrampoline:
applicationWillTerminateActivity.enter();
// The user's main has returned, so we're ready to let iOS terminate the application
qCDebug(lcEventDispatcher) << "kJumpedFromUserMainTrampoline, allowing iOS to terminate";
applicationWillTerminateActivity.leave();
break;
default:
qFatal("Unexpected jump result in event loop integration");
@ -441,6 +465,7 @@ bool __attribute__((returns_twice)) QIOSEventDispatcher::processEvents(QEventLoo
}
if (!m_processEventLevel && (flags & QEventLoop::EventLoopExec)) {
QT_APPLE_SCOPED_LOG_ACTIVITY(lcEventDispatcher().isDebugEnabled(), "processEvents");
qCDebug(lcEventDispatcher) << "Processing events with flags" << flags;
++m_processEventLevel;
@ -487,6 +512,7 @@ bool QIOSEventDispatcher::processPostedEvents()
if (!QEventDispatcherCoreFoundation::processPostedEvents())
return false;
QT_APPLE_SCOPED_LOG_ACTIVITY(lcEventDispatcher().isDebugEnabled(), "sendWindowSystemEvents");
qCDebug(lcEventDispatcher) << "Sending window system events for" << m_processEvents.flags;
QWindowSystemInterface::sendWindowSystemEvents(m_processEvents.flags);
@ -516,10 +542,12 @@ void QIOSEventDispatcher::interruptEventLoopExec()
switch (setjmp(processEventEnterJumpPoint)) {
case kJumpPointSetSuccessfully:
qCDebug(lcEventDispatcher) << "Jumping into processEvents due to system runloop exit ⇢";
logActivity.UIApplicationMain.leave();
longjmp(processEventExitJumpPoint, kJumpedFromEventLoopExecInterrupt);
break;
case kJumpedFromEventDispatcherProcessEvents:
// QEventLoop was re-executed
logActivity.UIApplicationMain.enter();
qCDebug(lcEventDispatcher) << "↳ Jumped from processEvents due to re-exec";
break;
default:

View File

@ -62,8 +62,13 @@ QAppleTestLogger::QAppleTestLogger(QAbstractTestLogger *logger)
{
}
static QAppleLogActivity testFunctionActivity;
void QAppleTestLogger::enterTestFunction(const char *function)
{
// Re-create activity each time
testFunctionActivity = QT_APPLE_LOG_ACTIVITY("Running test function").enter();
if (__builtin_available(macOS 10.12, iOS 10, tvOS 10, watchOS 3, *)) {
QTestCharBuffer testIdentifier;
QTestPrivate::generateTestIdentifier(&testIdentifier);
@ -77,6 +82,12 @@ void QAppleTestLogger::enterTestFunction(const char *function)
m_logger->enterTestFunction(function);
}
void QAppleTestLogger::leaveTestFunction()
{
m_logger->leaveTestFunction();
testFunctionActivity.leave();
}
typedef QPair<QtMsgType, const char *> IncidentClassification;
static IncidentClassification incidentTypeToClassification(QAbstractTestLogger::IncidentTypes type)
{

View File

@ -71,8 +71,7 @@ public:
{ m_logger->stopLogging(); }
void enterTestFunction(const char *function) override;
void leaveTestFunction() override
{ m_logger->leaveTestFunction(); }
void leaveTestFunction() override;
void addIncident(IncidentTypes type, const char *description,
const char *file = 0, int line = 0) override;