Profiling with QScriptEngineAgent

For AI and campaign script related discussions and questions

Profiling with QScriptEngineAgent

Postby NoQ » 16 Nov 2014, 17:44

I'm trying to use QScriptEngineAgent to gather detailed performance profiling for all script functions (not just API functions), but so far it doesn't work: i absolutely fail to obtain function name on functionEntry/functionExit events. It feels as if this functionality is either completely disabled on some level (some compile option?) or broken, or i'm doing something completely wrong: all ways of obtaining callee as QScriptValue result in a dead value (with NULL internal pointer) most of the time, QScriptContextInfo contains no info, and even line numbers are -1.

Does anybody have any idea? Here's what i'm trying to do (patch for master):
Attachments
WZProfilingAgent.patch
(3.69 KiB) Downloaded 183 times
User avatar
NoQ
Special
Special
 
Posts: 6066
Joined: 24 Dec 2009, 11:35
Location: /var/zone

Re: Profiling with QScriptEngineAgent

Postby Per » 16 Nov 2014, 22:15

It just seems to work for me?

I have Qt 5.4.0
Per
Warzone 2100 Team Member
Warzone 2100 Team Member
 
Posts: 3605
Joined: 03 Aug 2006, 19:39

Re: Profiling with QScriptEngineAgent

Postby NoQ » 17 Nov 2014, 07:08

o_O Could you post a sample output, so that i "believed"? (:
Here's what i'm seeing:
Code: Select all
error   |08:29:31: [functionExit:173]  <- -1 -1    276
error   |08:29:31: [functionEntry:153] -> -1 -1   
error   |08:29:31: [functionExit:173]  <- -1 -1    126
error   |08:29:31: [functionEntry:153] -> -1 -1   
error   |08:29:31: [functionExit:173]  <- -1 -1    150
error   |08:29:31: [functionEntry:153] -> -1 -1   
error   |08:29:31: [functionExit:173]  <- -1 -1    16
error   |08:29:31: [functionExit:173]  <- -1 -1    253
error   |08:29:31: [functionEntry:153] -> -1 -1   
error   |08:29:31: [functionExit:173]  <- -1 -1    18
error   |08:29:31: [functionExit:173]  <- -1 -1    270
error   |08:29:31: [functionEntry:153] -> -1 -1   
error   |08:29:31: [functionExit:173]  <- -1 -1    143
error   |08:29:31: [functionEntry:153] -> -1 -1   
error   |08:29:31: [functionExit:173]  <- -1 -1    167
error   |08:29:31: [functionEntry:153] -> -1 -1   
error   |08:29:31: [functionExit:173]  <- -1 -1    18
error   |08:29:31: [functionExit:173]  <- -1 -1    270
error   |08:29:31: [functionEntry:153] -> -1 -1   
error   |08:29:31: [functionExit:173]  <- -1 -1    18
error   |08:29:31: [functionExit:173]  <- -1 -1    273
error   |08:29:31: [functionEntry:153] -> -1 -1   
error   |08:29:31: [functionExit:173]  <- -1 -1    17
error   |08:29:31: [functionExit:173]  <- -1 -1    270
error   |08:29:31: [functionEntry:153] -> -1 -1   
error   |08:29:31: [functionExit:173]  <- -1 -1    126
error   |08:29:31: [functionEntry:153] -> -1 -1   
error   |08:29:31: [functionExit:173]  <- -1 -1    158
error   |08:29:31: [functionEntry:153] -> -1 -1   
error   |08:29:31: [functionExit:173]  <- -1 -1    18
error   |08:29:31: [functionExit:173]  <- -1 -1    262


On second thought, maybe that'd explain why scripts are running 10 times faster on my machine? Some script debugging features are disabled in qtscript compile-time in my distribution?

I'm on qt-5.3.2, but anyway these classes are around since qt-4.4.
User avatar
NoQ
Special
Special
 
Posts: 6066
Joined: 24 Dec 2009, 11:35
Location: /var/zone

Re: Profiling with QScriptEngineAgent

Postby Per » 18 Nov 2014, 00:00

Ok, then it doesn't work for me, either.
Per
Warzone 2100 Team Member
Warzone 2100 Team Member
 
Posts: 3605
Joined: 03 Aug 2006, 19:39

Re: Profiling with QScriptEngineAgent

Postby NoQ » 18 Nov 2014, 07:34

Then neither does it explain XD
Will keep struggling.
User avatar
NoQ
Special
Special
 
Posts: 6066
Joined: 24 Dec 2009, 11:35
Location: /var/zone

Re: Profiling with QScriptEngineAgent

Postby vexed » 20 Nov 2014, 04:58

Doing a quick look at the code, and nothing jumps out as being incorrect, however, as you posted, it don't work.
Looking up QString QScriptContextInfo::functionName() const
Returns the name of the called function, or an empty string if the name is not available.

They don't say why it wouldn't be available.

Then trying QStringList QScriptContext::backtrace() const
Returns a human-readable backtrace of this QScriptContext.

Each line is of the form <function-name>(<arguments>)@<file-name>:<line-number>.

To access individual pieces of debugging-related information (for example, to construct your own backtrace representation), use QScriptContextInfo.


Doesn't work either, there are no function names.

So, I am guessing this a bug in Qt ? :hmm:
/facepalm ...Grinch stole Warzone🙈🙉🙊 contra principia negantem non est disputandum
Super busy, don't expect a timely reply back.
User avatar
vexed
Inactive
Inactive
 
Posts: 2407
Joined: 27 Jul 2010, 02:07

Re: Profiling with QScriptEngineAgent

Postby NoQ » 22 Nov 2014, 17:28

Meanwhile, i have another approach to profiling in mind:
Code: Select all
var returnValue = profile("functionName", arguments...);
where profile() is a native API function that calls the given function by name, measures timing, and injects the stats obtained into the monitor.

This way we profile only what the script author wants to have profiled, which would probably reduce overhead, and no extra support from Qt is required.
User avatar
NoQ
Special
Special
 
Posts: 6066
Joined: 24 Dec 2009, 11:35
Location: /var/zone

Re: Profiling with QScriptEngineAgent

Postby NoQ » 22 Nov 2014, 18:25

JSProfile.patch
Something like that...
(2.57 KiB) Downloaded 168 times

That is, queue() and setTimer() already do profiling. This new function is different and necessary just because it calls the callee instantly, allowing the script to obtain the return value, and also to be sure no game objects get outdated, and also provide arbitrary number of arguments.

Note that callFunction()'s boolean return value was never checked anyway.
User avatar
NoQ
Special
Special
 
Posts: 6066
Joined: 24 Dec 2009, 11:35
Location: /var/zone

Re: Profiling with QScriptEngineAgent

Postby NoQ » 22 Nov 2014, 19:40

This approach makes it necessary to wrap every call of the function, rather than just its definition. It's possible to make a wrapper for the definition, but then if you queue the wrapper, it'd count performance twice (for different names, but still double overhead and poorly readable garbage in the stats).

An alternative is to implement profileStart("name") and profileEnd() calls, the first one would push name and ticks value into a stack, the second one would pop name and ticks and accumulate statistics. Then you'd have to put this inside the callee, on entry and every return (which may be many). Forgetting one of the returns, or throwing an exception, would break things quite a bit.

Would have still been easier with QScriptEngineAgent if only it worked.
User avatar
NoQ
Special
Special
 
Posts: 6066
Joined: 24 Dec 2009, 11:35
Location: /var/zone

Re: Profiling with QScriptEngineAgent

Postby NoQ » 23 Nov 2014, 13:35

http://qt-project.org/forums/viewthread/5909
http://qt-project.org/wiki/Qt_Modules_Maturity_Level
QScriptEngineAgent and related classes
State: Deprecated
Reasoning: flawed design, being replaced by a better design.
:stare:

I guess i'd push the js_profile() approach. Also, need to document jsdebug and performance monitor :hmm:

Do we plan to use QJSEngine, anyway? :ninja:
User avatar
NoQ
Special
Special
 
Posts: 6066
Joined: 24 Dec 2009, 11:35
Location: /var/zone

Re: Profiling with QScriptEngineAgent

Postby Per » 23 Nov 2014, 22:44

NoQ wrote:Do we plan to use QJSEngine, anyway? :ninja:

No, it is a very different design, and does not have half of what we need, unfortunately. But they will keep supporting QtScript for all of Qt5, and hopefully by Qt6 something superior will replace both.
Per
Warzone 2100 Team Member
Warzone 2100 Team Member
 
Posts: 3605
Joined: 03 Aug 2006, 19:39

Re: Profiling with QScriptEngineAgent

Postby vexed » 25 Nov 2014, 04:08

:annoyed:
OK calm down everyone.

If you are currently porting over WZscript to JS, that is fine, and this has no impact on your work.

I have moved the other posts to another area for further discussion, since some people have misconstrued what I was saying, and started to come to conclusions that were not correct for what is going on currently.
That was not my intention.

Once again, if you are currently porting over WZscript to JS, that is fine, and the talk that was being discussed has no impact on your work.
/facepalm ...Grinch stole Warzone🙈🙉🙊 contra principia negantem non est disputandum
Super busy, don't expect a timely reply back.
User avatar
vexed
Inactive
Inactive
 
Posts: 2407
Joined: 27 Jul 2010, 02:07

Re: Profiling with QScriptEngineAgent

Postby NoQ » 25 Nov 2014, 08:47

Here is a little hello-world proof-of-concept with QJSEngine.

tl;dr: i successfully defined API functions for an engine, called them from scripts, tested string and integer and arbitrary-js-value arguments, called JS function from C++, obtained script return values, and handled an exception.

Creating API functions is pleasantly easy: instead of an arbitrary array of QScriptValue arguments, we receive our arguments already converted into C++ ints or strings. On the other hand, we'd have to deal with their fancy Q_OBJECT (etc.) preprocessors.

No idea about performance so far. I guess we cannot know until we try.

qjs.pro:
Code: Select all
TEMPLATE = app
TARGET = qjs
INCLUDEPATH += .
QT += qml

SOURCES += main.cpp
HEADERS += main.h

main.h:
Code: Select all
#include <QObject>
#include <QString>
#include <QJSValue>

class FunctionWrapper: public QObject {
   Q_OBJECT;
   public:
      Q_INVOKABLE void testIntArgument(int arg);
      Q_INVOKABLE void testStringArgument(QString arg);
      Q_INVOKABLE void testValueArgument(QJSValue arg);
      Q_INVOKABLE QString testReturn();
};

main.cpp:
Code: Select all
#include "main.h"

#include <QJSEngine>
#include <QDebug>

void FunctionWrapper::testIntArgument(int arg) {
   qDebug() << arg;
}

void FunctionWrapper::testStringArgument(QString arg) {
   qDebug() << arg;
}

void FunctionWrapper::testValueArgument(QJSValue arg) {
   qDebug() << arg.toInt() << arg.toString();
}

QString FunctionWrapper::testReturn() {
   return "answer: 42";
}

int main() {
   FunctionWrapper *Wrap = new FunctionWrapper();
   QJSEngine *Eng = new QJSEngine();
   QJSValue Obj = Eng->newQObject(Wrap);
   Eng->globalObject().setProperty(
      "testIntArgument", Obj.property("testIntArgument"));
   Eng->globalObject().setProperty(
      "testStringArgument", Obj.property("testStringArgument"));
   Eng->globalObject().setProperty(
      "testValueArgument", Obj.property("testValueArgument"));
   Eng->globalObject().setProperty(
      "testReturn", Obj.property("testReturn"));
   QJSValue result = Eng->evaluate(
      "testIntArgument(6 * 7);"
      "testStringArgument(6 * 7);"
      "testValueArgument(6 * 7);"
      "testReturn();"
   );
   qDebug() << result.toString();
   result = Eng->evaluate("noSuchFunction();");
   if (result.isError())
      qDebug() << result.toString();
   else
      qDebug() << "No exception";
   result = Eng->evaluate("function foo(x) { return x * 7; }");
   if (result.isError())
      qDebug() << result.toString();
   else
      qDebug() << "No exception";
   QJSValueList args;
   args.push_back(6);
   result = Eng->globalObject().property("foo").call(args);
   qDebug() << "returned" << result.toInt();
   return 0;
}

Sample output:
Code: Select all
$ ./qjs
42
"42"
42 "42"
"answer: 42"
"ReferenceError: noSuchFunction is not defined"
No exception
returned 42
User avatar
NoQ
Special
Special
 
Posts: 6066
Joined: 24 Dec 2009, 11:35
Location: /var/zone

Re: Profiling with QScriptEngineAgent

Postby NoQ » 15 Dec 2014, 19:37

Half-way through qtscriptfuncs.cpp of converting to QJSEngine (as in, doing the replacing, didn't try to compile yet lol). Eg.:
Code: Select all
-static QScriptValue js_distBetweenTwoPoints(QScriptContext *context, QScriptEngine *engine)
-{
-       int x1 = context->argument(0).toNumber();
-       int y1 = context->argument(1).toNumber();
-       int x2 = context->argument(2).toNumber();
-       int y2 = context->argument(3).toNumber();
-       return QScriptValue(iHypot(x1 - x2, y1 - y2));
-}
+int WZAPI::distBetweenTwoPoints(int x1, int y1, int x2, int y2)
+{
+       return iHypot(x1 - x2, y1 - y2);
+}

It seems there's no good way to implement SCRIPT_ASSERT - neither to interrupt current native function (as return type may vary; this is solvable, of course, but ugly, but not much more ugly than before), nor to throw a script exception from inside native function (might be missing something; also, if we give up on this, we let scripts crash the game and/or themselves on error).

Also, QJSEngine doesn't support variadic arguments; namely, there are at most 10 arguments to any Q_INVOKABLE method. This means we cannot support templates with unlimited number of turrets (there aren't many anyway), and also we have problems with functions like debug() and dump() (have to drop remaining arguments).
User avatar
NoQ
Special
Special
 
Posts: 6066
Joined: 24 Dec 2009, 11:35
Location: /var/zone

Next

Return to Scripting