summaryrefslogtreecommitdiff
path: root/src/common-lib/startuptimer.cpp
blob: f04e96345b87690b5f74cc843c7ed6477802136c (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
// 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 <windows.h>
#  include <io.h>
#  define isatty _isatty
#elif defined(Q_OS_LINUX)
#  include <time.h>
#  include <qplatformdefs.h>
#  include <sys/syscall.h>
#  include <sys/sysinfo.h>
#  if !defined(SYS_gettid)
#    define SYS_gettid __NR_gettid
#  endif
#elif defined(Q_OS_MACOS) || defined(Q_OS_IOS)
#  include <unistd.h>
#  include <sys/sysctl.h>
#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
    <style type="text/css" id="colorstyles">
        #color-green  { color: #18b218 }
        #color-orange { color: #b26818 }
        #color-blue   { background-color: #5454ff; color: #000000 }
    </style>
    <pre>
<span id="color-orange">== STARTUP TIMING REPORT: System UI ==</span>
<span id="color-green">0'110.001</span> entered main                                <span id="color-blue">   </span>
<span id="color-green">0'110.015</span> after basic initialization                  <span id="color-blue">   </span>
<span id="color-green">0'110.311</span> after sudo server fork                      <span id="color-blue">   </span>
<span id="color-green">0'148.911</span> after application constructor               <span id="color-blue">    </span>
<span id="color-green">0'150.086</span> after command line parse                    <span id="color-blue">    </span>
<span id="color-green">0'150.154</span> after logging setup                         <span id="color-blue">    </span>
<span id="color-green">0'150.167</span> after startup-plugin load                   <span id="color-blue">    </span>
<span id="color-green">0'151.714</span> after installer setup checks                <span id="color-blue">    </span>
<span id="color-green">0'151.847</span> after runtime registration                  <span id="color-blue">    </span>
<span id="color-green">0'156.278</span> after application database loading          <span id="color-blue">    </span>
<span id="color-green">0'158.450</span> after ApplicationManager instantiation      <span id="color-blue">     </span>
<span id="color-green">0'158.477</span> after NotificationManager instantiation     <span id="color-blue">     </span>
<span id="color-green">0'158.534</span> after SystemMonitor instantiation           <span id="color-blue">     </span>
<span id="color-green">0'158.572</span> after quick-launcher setup                  <span id="color-blue">     </span>
<span id="color-green">0'159.130</span> after ApplicationInstaller instantiation    <span id="color-blue">     </span>
<span id="color-green">0'159.192</span> after QML registrations                     <span id="color-blue">     </span>
<span id="color-green">0'164.888</span> after QML engine instantiation              <span id="color-blue">     </span>
<span id="color-green">0'189.619</span> after D-Bus registrations                   <span id="color-blue">     </span>
<span id="color-green">2'167.233</span> after loading main QML file                 <span id="color-blue">                                                        </span>
<span id="color-green">2'167.489</span> after WindowManager/QuickView instantiation <span id="color-blue">                                                        </span>
<span id="color-green">2'170.423</span> after window show                           <span id="color-blue">                                                        </span>
<span id="color-green">2'359.482</span> after first frame drawn                     <span id="color-blue">                                                             </span></pre>
\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/<gettid>/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<int>(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<quint32 *>(resultPtr) = quint32(strtoul(buffer + pos, nullptr, 10));
                            result = reinterpret_cast<void *>(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<kinfo_proc *>(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"