QScriptEngineAgent - obtaining callee name

Question

I'm trying to implement a simple QtScript performance profiler via QScriptEngineAgent, by catching function entries and exits. I successfully subscribed to QScriptEngineAgent::functionEntry() callback. Now, is it possible to obtain the name (as string) of the function which is being called, inside this callback?

Even though I'm aware that not all script functions need to have a name, even in the most simple cases it doesn't seem to work. QScriptContextInfo provides facilities for that, but it seems to fail. Then I'm trying to obtain the value of arguments.callee.name property, but it fails as well.

Here's a rough overview of my attempts to implement that, which I'm trying to run on qt-5.3.2/linux.

tmp.pro:

TEMPLATE = app
TARGET = tmp
INCLUDEPATH += .
QT += core script
SOURCES += main.cpp

main.cpp:

#include <QCoreApplication>
#include <QScriptEngine>
#include <QScriptEngineAgent>
#include <QScriptContextInfo>
#include <QDebug>

class MyAgent: public QScriptEngineAgent {
private:
    void functionEntry(qint64 scriptId) {
        qDebug() << "functionEntry" << scriptId;
        QScriptContext *context = engine()->currentContext();

        // QScriptContextInfo should have function name, by design, afaik
        QScriptContextInfo contextInfo(context);
        qDebug() << contextInfo.functionName();

        // probably my typical js-side arguments.callee.name would work?
        QScriptValue callee = context->callee();
        qDebug() << callee.property("name").toString();

        // function.toString() should have at least something (?)
        qDebug() << callee.toString();

        // hmm. what's our context, anyway?
        qDebug() << context->toString();
    }
public:
    MyAgent(QScriptEngine *eng) : QScriptEngineAgent(eng) {
        qDebug() << "engine" << eng;
    }
};

int main(int argc, char **argv) {
    QCoreApplication app(argc, argv);
    QScriptEngine eng;
    MyAgent agent(&eng);
    eng.setAgent(&agent);
    qDebug() << "agent " << eng.agent();
    eng.evaluate("function foo() { return 6 * 7; }"
                 "function bar() { return foo(); }");
    QScriptValue bar = eng.globalObject().property("bar");

    // See? Here the callee is printed as expected.
    qDebug() << "call " << bar.property("name").toString() << bar.toString();
    QScriptValue ret = bar.call();
    qDebug() << "answer" << ret.toNumber();
    return 0;
}

Output sample, which I'm not satisfied with, as I'm expecting to see "foo" and "bar" instead of some of the empty strings:

engine QScriptEngine(0x7fffc55c4560)
agent  0x7fffc55c4570
functionEntry 140300485581200
""
""
""
"<global>() at -1"
functionEntry -1
""
""
""
"<global>() at -1"
call  "bar" "function bar() { return foo(); }"
functionEntry 140300485581200
""
""
""
"<global>() at -1"
functionEntry 140300485581200
""
""
""
"<global>() at -1"
answer 42

Answer 1

It seems that a correct context is only available in positionChange. Luckily functionEntry is called with a scriptID > 0 whenever a true context-change occurs. Grabbing the context in the next positionChange works for me:

class ScriptProfilerAgent: public QScriptEngineAgent
{
public:
    ScriptProfilerAgent(QScriptEngine *eng)
        : QScriptEngineAgent(eng), m_stackChange(false)
    {
    }

protected:
    void scriptLoad(qint64 id, const QString &program, const QString &fileName, int baseLineNumber)
    {
        Q_UNUSED(id);Q_UNUSED(program);Q_UNUSED(fileName);Q_UNUSED(baseLineNumber);
        m_timer.start();
    }

    void functionEntry(qint64 scriptId)
    {
        if (scriptId > -1) {
            // arm the stack-tracker => positionChange
            m_stackChange = true;
        }
    }

    void positionChange(qint64 scriptId, int lineNumber, int columnNumber)
    {
        Q_UNUSED(scriptId);Q_UNUSED(lineNumber);Q_UNUSED(columnNumber);
        if (m_stackChange)
        {
            QString fn = functionNameEx();
            m_curCallStack.push(qMakePair(fn,m_timer.elapsed()));
            // reset stack tracking
            m_stackChange = false;
        }
    }

    QString functionNameEx()
    {
        QScriptContext* sc = engine()->currentContext();
        QScriptContextInfo info(sc);
        QString functionName = info.functionName();
        if (functionName.isEmpty()) {
            if (sc->parentContext()) {
                switch (info.functionType()) {
                    case QScriptContextInfo::ScriptFunction : return QLatin1String("anonymous");
                    case QScriptContextInfo::QtFunction : return QLatin1String("qtfunction");
                    case QScriptContextInfo::QtPropertyFunction : return QLatin1String("qtproperty");
                    case QScriptContextInfo::NativeFunction : return QLatin1String("native");
                }
            } else {
                return QLatin1String("global");
            }
        } else {
            return functionName;
        }
        return "??";
    }

    void functionExit(qint64 scriptId, const QScriptValue &returnValue)
    {
        Q_UNUSED(returnValue);
        if (scriptId > -1)
        {
            if (!m_curCallStack.isEmpty())
            {
                // store current fn information
                QPair<QString,qint64> f = m_curCallStack.pop();
                qint64 execTime = m_timer.elapsed()-f.second;
                {
                    FunctionStats& stats = m_callStatsByName[f.first];
                    stats.calls++;
                    stats.execTimeSum += execTime;
                }
                {
                    // build full callstack-path
                    QStringList path;path.reserve(m_curCallStack.size());
                    for (int i=0;i<m_curCallStack.size();++i)
                    {
                        path.append(m_curCallStack.at(i).first);
                    }
                    path.append(f.first);
                    FunctionStats& stats = m_callStatsByPath[path.join(">")];
                    stats.calls++;
                    stats.execTimeSum += execTime;
                }
            } else {
                qDebug() << "Something is very wrong with the call stack!";
            }
        }
    }

public:
    QString toString() const
    {
        QStringList result;
        result.append("Function\tTotal Time (ms)\tCalls");
        {
            // function name
            QStringList fnsByExecTimeSum = m_callStatsByName.keys();
            // sorted by execTimeSum
            std::sort(fnsByExecTimeSum.begin(),fnsByExecTimeSum.end(),
                      [this](const QString& a,const QString& b) -> bool {return (m_callStatsByName[a].execTimeSum) > (m_callStatsByName[b].execTimeSum);}
                    );

            for (QString fn : fnsByExecTimeSum)
            {
                result.append(QString("%1\t%2ms\t%3").arg(fn).arg(m_callStatsByName[fn].execTimeSum).arg(m_callStatsByName[fn].calls));
            }
        }
        result.append("");
        result.append("FN-Path\tTotal Time (ms)\tCalls");
        {
            // function path = call stack
            QStringList fns = m_callStatsByPath.keys();
            // sorted by key
            fns.sort();
            for (QString fn : fns)
            {
                result.append(QString("%1\t%2ms\t%3").arg(fn).arg(m_callStatsByPath[fn].execTimeSum).arg(m_callStatsByPath[fn].calls));
            }
        }
        return result.join("\n");
    }

    void reset()
    {
        m_callStatsByPath.clear();
        m_callStatsByName.clear();
    }
private:
    QStack<QPair<QString,qint64> > m_curCallStack;

    bool m_stackChange;

    struct FunctionStats
    {
        FunctionStats() : calls(0),execTimeSum(0) {}
        int calls;
        qint64 execTimeSum; // ms
    };

    QElapsedTimer m_timer;

    QHash<QString, FunctionStats> m_callStatsByPath;
    QHash<QString, FunctionStats> m_callStatsByName;
};

To use the agent you simply set it on the engine with engine.setAgent(new ScriptProfilerAgent());. After execution my poor man's profiler can give you a list of function/stackpathnames with cumulated execution times and number of calls:

QString ScriptEngine::getProfilingResults()
{
    ScriptProfilerAgent* spa = dynamic_cast<ScriptProfilerAgent*>(agent());
    if (spa)
    {
        QString result = spa->toString();
        spa->reset();
        return result;
    }
    return "<no profiler agent>";
}

FN-Path Total Time (ms) Calls
global  235969ms    7
global>anonymous    0ms 38
global>run  235969ms    1
global>run>doConcept    206444ms    21603
global>run>doConcept>genData    200765ms    21603
global>run>doConcept>genData>genArticleData 198861ms    21603
global>run>doConcept>genData>genArticleData>buildInnerHTMLs 163558ms    21603
global>run>doConcept>genData>genArticleData>buildInnerHTMLs>anonymous   87582ms 1823593
....

Cheers,

Johannes