// Copyright (C) 2021 The Qt Company Ltd. // Copyright (C) 2019 Luxoft Sweden AB // Copyright (C) 2018 Pelagicore AG // SPDX-License-Identifier: LicenseRef-Qt-Commercial OR GPL-3.0-only #include "startuptimer.h" #include "logging.h" #if defined(Q_OS_WIN) # include # include # define isatty _isatty #elif defined(Q_OS_LINUX) # include # include # include # include # if !defined(SYS_gettid) # define SYS_gettid __NR_gettid # endif #elif defined(Q_OS_MACOS) || defined(Q_OS_IOS) # include # include #endif /*! \qmltype StartupTimer \inqmlmodule QtApplicationManager \ingroup common-singletons \brief A tool for startup performance analysis. The StartupTimer is a class for measuring the startup performance of the System UI, as well as applications started by the application manager. Using the checkpoint function, you can log the time that elapsed since the executable was started. In case of the System UI, this is the time since the process was forked. This is also true for applications that are not quick-launched. Quick-launched applications attach to a process that has been pre-forked before the application has been started. In this case the timer will be reset to the actual application start. The time is reported using a monotonic clock with nano-second resolution - see QElapsedTimer for more information. \note On Linux, the actual time between the forking of the process and the first checkpoint can only be obtained with 10ms resolution. In order to activate startup timing measurement, the \c $AM_STARTUP_TIMER environment variable needs to be set: if set to \c 1, a startup performance analysis will be printed on the console. Anything other than \c 1 will be interpreted as the name of a file that is used instead of the console. When activated, this report will always be printed for the System UI. If the application manager is running in multi-process mode, additional reports will also be printed for every QML application that is started. Note that the bar widths can only be compared within a report. The application manager and its QML launcher will already create a lot of checkpoints on their own and will also call createReport themselves after all the C++ side setup has finished. You can however add arbitrary checkpoints yourself using the QML API: access to the StartupTimer object is possible through a the \c StartupTimer root-context property in the QML engine. This is an example output, starting the \c Neptune UI on a console with ANSI color support: \raw HTML
== STARTUP TIMING REPORT: System UI ==
0'110.001 entered main                                   
0'110.015 after basic initialization                     
0'110.311 after sudo server fork                         
0'148.911 after application constructor                   
0'150.086 after command line parse                        
0'150.154 after logging setup                             
0'150.167 after startup-plugin load                       
0'151.714 after installer setup checks                    
0'151.847 after runtime registration                      
0'156.278 after application database loading              
0'158.450 after ApplicationManager instantiation           
0'158.477 after NotificationManager instantiation          
0'158.534 after SystemMonitor instantiation                
0'158.572 after quick-launcher setup                       
0'159.130 after ApplicationInstaller instantiation         
0'159.192 after QML registrations                          
0'164.888 after QML engine instantiation                   
0'189.619 after D-Bus registrations                        
2'167.233 after loading main QML file                                                                         
2'167.489 after WindowManager/QuickView instantiation                                                         
2'170.423 after window show                                                                                   
2'359.482 after first frame drawn                                                                                  
\endraw */ /*! \qmlproperty int StartupTimer::timeToFirstFrame Provides the time from process start until rendering of the first frame in the HMI in milliseconds. \note Rendering of the first frame takes more time than just creating the QML root component. Accessing this property from within the \c Component.onCompleted signal might be too early. */ /*! \qmlproperty int StartupTimer::systemUpTime Provides the system's \e up time as provided by the underlying OS, measured up until the initialization of the StartupTimer singleton in milliseconds. This is helpful in calculating the time from boot to first frame drawn by adding up the values of systemUpTime and timeToFirstFrame. */ /*! \qmlproperty bool StartupTimer::automaticReporting You can set this property to \c false, if you want to prevent the automatic report generation that is done by the application manager. This can be useful, if you are using some form of staged loading in the System UI and want to create the report at a later time. \note Please note that you need to set this property to \c false before the load operation of the main qml file is finished: ideally in the root elements \c Component.onCompleted handler. The default value is \c true. \sa createReport */ /*! \qmlmethod StartupTimer::checkpoint(string name) Adds a new checkpoint with the elapsed time and the given \a name. Each checkpoint corresponds to a single item in the output created by the next call to createReport. */ /*! \qmlmethod StartupTimer::createReport(string title) Outputs a report consisting of all checkpoints reported via the checkpoint function. The \a title will be appended to the header of the report. After outputting the report, all reported checkpoints will be cleared. This means that you can call this function multiple times and only newly reported checkpoints will be printed. */ QT_BEGIN_NAMESPACE_AM struct SplitSeconds { int sec; int msec; int usec; }; static SplitSeconds splitMicroSecs(quint64 micros) { SplitSeconds ss; ss.sec = 0; if (micros > 1000 * 1000) { ss.sec = int(micros / (1000 * 1000)); micros %= (1000 * 1000); } ss.msec = int(micros / 1000); ss.usec = micros % 1000; return ss; } StartupTimer::StartupTimer() { ::atexit([]() { delete s_instance; }); QByteArray useTimer = qgetenv("AM_STARTUP_TIMER"); if (useTimer.isNull()) return; else if (useTimer.isEmpty() || useTimer == "1") m_output = stderr; else m_output = fopen(useTimer, "w"); #if defined(Q_OS_WIN) // Windows reports FILETIMEs in 100nsec steps: divide by 10 to get usec auto winFileTimeToUSec = [](const FILETIME &filetime) { return ((quint64(filetime.dwHighDateTime) << 32) | quint64(filetime.dwLowDateTime)) / 10; }; FILETIME creationTime, dummy, now; if (GetProcessTimes(GetCurrentProcess(), &creationTime, &dummy, &dummy, &dummy)) { GetSystemTimeAsFileTime(&now); m_processCreation = (winFileTimeToUSec(now) - winFileTimeToUSec(creationTime)); m_initialized = true; } else { qWarning("StartupTimer: could not get process creation time"); } // Get system up time // Resource https://msdn.microsoft.com/en-us/library/windows/desktop/ms724411(v=vs.85).aspx if (m_initialized) m_systemUpTime = GetTickCount64(); #elif defined(Q_OS_LINUX) // Linux is stupid: there's only one way to get your own process' start time with a high // resolution: using the async netlink protocol to get a 'taskstat', but this is highly complex // and requires root privileges. // And then there's /proc/self/task//stat which gives you the "jiffies" at creation // time, but no reference to compare it to (plus its resolution is very coarse). // The following implements the idea from the Mozilla team to get a stable reference for this // jiffie value: https://blog.mozilla.org/tglek/2011/01/14/builtin-startup-measurement/ // This will give you roughly a 10ms resolution for the time from process creation to entering // main(), depending on your kernel's HZ value. // really bool (*)(quint32 *result), but casting the lambda does not work auto readJiffiesFromProc = [](void *resultPtr) -> void * { void *result = nullptr; QByteArray file = "/proc/self/task/" + QByteArray::number(static_cast(syscall(SYS_gettid))) + "/stat"; int fd = QT_OPEN(file, O_RDONLY); if (fd >= 0) { char buffer[1024]; ssize_t bytesRead = QT_READ(fd, buffer, sizeof(buffer) - 1); if (bytesRead > 0) { buffer[bytesRead] = 0; for (int field = 0, pos = 0; pos < bytesRead; ) { if (buffer[pos++] == ' ') { if (++field == 21) { *reinterpret_cast(resultPtr) = quint32(strtoul(buffer + pos, nullptr, 10)); result = reinterpret_cast(1); break; } } } } QT_CLOSE(fd); } return result; }; quint32 threadJiffies; pthread_t pt; void *threadJiffiesOk = nullptr; // using clone() with CLONE_VFORK would be more efficient, but it messes up the NPTL internal state if ((pthread_create(&pt, nullptr, readJiffiesFromProc, &threadJiffies) == 0) && (pthread_join(pt, &threadJiffiesOk) == 0) && threadJiffiesOk) { quint32 processJiffies = 0; if (readJiffiesFromProc(&processJiffies)) { long int clkTck = sysconf(_SC_CLK_TCK); if (clkTck > 0) { m_processCreation = quint64(threadJiffies - processJiffies) * 1000*1000 / quint64(clkTck); m_initialized = true; } else { qWarning("StartupTimer: could not get _SC_CLK_TCK"); } } else { qWarning("StartupTimer: could not read process creation jiffies"); } } else { qWarning("StartupTimer: could not read thread creation jiffies"); } // Checking the system up time if (m_initialized) { int fd = QT_OPEN("/proc/uptime", O_RDONLY); if (fd >= 0) { char buffer[32]; ssize_t bytesRead = QT_READ(fd, buffer, sizeof(buffer) - 1); if (bytesRead > 0) { buffer[bytesRead] = 0; m_systemUpTime = quint64(strtod(buffer, nullptr) * 1000); } QT_CLOSE(fd); } } #elif defined(Q_OS_MACOS) || defined(Q_OS_IOS) int mibNames[] = { CTL_KERN, KERN_PROC, KERN_PROC_PID, getpid() }; size_t procInfoSize; if (sysctl(mibNames, sizeof(mibNames) / sizeof(mibNames[0]), nullptr, &procInfoSize, nullptr, 0) == 0) { kinfo_proc *procInfo = static_cast(malloc(procInfoSize)); if (sysctl(mibNames, sizeof(mibNames) / sizeof(mibNames[0]), procInfo, &procInfoSize, nullptr, 0) == 0) { struct timeval now; if (gettimeofday(&now, nullptr) == 0) { m_processCreation = (quint64(now.tv_sec) * 1000000 + quint64(now.tv_usec)) - (quint64(procInfo->kp_proc.p_un.__p_starttime.tv_sec) * 1000000 + quint64(procInfo->kp_proc.p_un.__p_starttime.tv_usec)); m_initialized = true; } } else { qWarning("StartupTimer: could not get kinfo_proc from kernel"); } free(procInfo); } else { qWarning("StartupTimer: could not get size of kinfo_proc buffer"); } // Get system up time if (m_initialized) { struct timeval bootTime; size_t bootTimeLen = sizeof(bootTime); int mibNames[2] = { CTL_KERN, KERN_BOOTTIME }; if (sysctl(mibNames, sizeof(mibNames) / sizeof(mibNames[0]), &bootTime, &bootTimeLen, nullptr, 0) == 0 ) { m_systemUpTime = quint64(time(nullptr) - bootTime.tv_sec) * 1000; // we don't need more precision on macOS } } #else qWarning("StartupTimer: not implemented on this platform"); m_initialized = false; #endif if (m_initialized) m_timer.start(); } StartupTimer *StartupTimer::s_instance = new StartupTimer(); StartupTimer *StartupTimer::instance() { if (!s_instance) s_instance = new StartupTimer(); return s_instance; } StartupTimer::~StartupTimer() { if (m_output && m_output != stderr) fclose(m_output); s_instance = nullptr; } void StartupTimer::checkpoint(const char *name) { if (Q_LIKELY(m_initialized)) { qint64 delta = m_timer.nsecsElapsed(); m_checkpoints << qMakePair(quint64(delta / 1000) + m_processCreation, name); } } void StartupTimer::checkpoint(const QString &name) { if (Q_LIKELY(m_initialized)) { QByteArray ba = name.toLocal8Bit(); checkpoint(ba.constData()); } } void StartupTimer::checkFirstFrame() { if (Q_LIKELY(m_initialized)) { QByteArray ba = "after first frame drawn"; m_timeToFirstFrame = quint64(m_timer.nsecsElapsed() / 1000) + m_processCreation; m_checkpoints << qMakePair(m_timeToFirstFrame, ba); emit timeToFirstFrameChanged(m_timeToFirstFrame); } } void StartupTimer::reset() { if (m_initialized) { SplitSeconds delta = splitMicroSecs(quint64(m_timer.nsecsElapsed() / 1000) + m_processCreation); m_timer.restart(); m_checkpoints.clear(); m_processCreation = 0; const QString text = QString::asprintf("started %d'%03d.%03d after process launch", delta.sec, delta.msec, delta.usec); m_checkpoints << qMakePair(0, text.toLocal8Bit().constData()); } } void StartupTimer::createAutomaticReport(const QString &title) { if (m_automaticReporting) createReport(title); } bool StartupTimer::automaticReporting() const { return m_automaticReporting; } void StartupTimer::setAutomaticReporting(bool enableAutomaticReporting) { if (m_automaticReporting != enableAutomaticReporting) { m_automaticReporting = enableAutomaticReporting; emit automaticReportingChanged(enableAutomaticReporting); } } void StartupTimer::createReport(const QString &title) { if (m_output && !m_checkpoints.isEmpty()) { bool ansiColorSupport = false; if (m_output == stderr) ansiColorSupport = Console::supportsAnsiColor(); constexpr const char *plainFormat = "\n== STARTUP TIMING REPORT: %s ==\n"; constexpr const char *colorFormat = "\n\033[33m== STARTUP TIMING REPORT: %s ==\033[0m\n"; fprintf(m_output, ansiColorSupport ? colorFormat : plainFormat, title.toLocal8Bit().data()); static const int barCols = 60; quint64 delta = m_checkpoints.isEmpty() ? 0 : m_checkpoints.last().first; qreal usecPerCell = delta / barCols; int maxTextLen = 0; for (int i = 0; i < m_checkpoints.size(); ++i) { int textLen = m_checkpoints.at(i).second.length(); if (textLen > maxTextLen) maxTextLen = textLen; } for (int i = 0; i < m_checkpoints.size(); ++i) { quint64 usec = m_checkpoints.at(i).first; const QByteArray text = m_checkpoints.at(i).second; int cells = int(usec / usecPerCell); QByteArray bar(cells, ansiColorSupport ? ' ' : '#'); QByteArray spacing(maxTextLen - text.length(), ' '); SplitSeconds ss = splitMicroSecs(usec); constexpr const char *plainFormat = "%d'%03d.%03d %s %s#%s\n"; constexpr const char *colorFormat = "\033[32m%d'%03d.%03d\033[0m %s %s\033[44m %s\033[0m\n"; fprintf(m_output, ansiColorSupport ? colorFormat : plainFormat, ss.sec, ss.msec, ss.usec, text.constData(), spacing.constData(), bar.constData()); } fflush(m_output); m_checkpoints.clear(); } } quint64 StartupTimer::timeToFirstFrame() const { return m_timeToFirstFrame / 1000; } quint64 StartupTimer::systemUpTime() const { return m_systemUpTime; } QT_END_NAMESPACE_AM #include "moc_startuptimer.cpp"