Mirrors/overte-lubosz
3
0
Fork 0
mirror of https://github.com/lubosz/overte.git synced 2025-04-24 09:23:17 +02:00
Code Issues Projects Releases Packages Wiki Activity Actions

Merge pull request #9603 from huffman/feat/trace-thread-script

Browse source 
Add thread names and scripts to chrome traces
This commit is contained in:
Brad Hefta-Gaub 2017-02-09 13:00:05 -08:00 committed by GitHub
commit 74f10a1e7f
10 changed files with 132 additions and 20 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

1
interface/src/Application.cpp
View file

@ -436,6 +436,7 @@ bool setupEssentials(int& argc, char** argv) {
}
DependencyManager::set<tracing::Tracer>();
PROFILE_SET_THREAD_NAME("Main Thread");
#if defined(Q_OS_WIN)
// Select appropriate audio DLL

6
interface/src/scripting/TestScriptingInterface.cpp
View file

@ -134,3 +134,9 @@ void TestScriptingInterface::startTraceEvent(QString name) {
void TestScriptingInterface::endTraceEvent(QString name) {
tracing::traceEvent(trace_test(), name, tracing::DurationEnd);
}
void TestScriptingInterface::profileRange(const QString& name, QScriptValue fn) {
PROFILE_RANGE(script, name);
fn.call();
}

3
interface/src/scripting/TestScriptingInterface.h
View file

@ -13,6 +13,8 @@
#include <functional>
#include <QtCore/QObject>
class QScriptValue;
class TestScriptingInterface : public QObject {
Q_OBJECT
@ -69,6 +71,7 @@ public slots:
void endTraceEvent(QString name);
Q_INVOKABLE void profileRange(const QString& name, QScriptValue function);
private:
bool waitForCondition(qint64 maxWaitMs, std::function<bool()> condition);

2
libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.cpp
View file

@ -118,6 +118,8 @@ public:
virtual void run() override {
PROFILE_SET_THREAD_NAME("Present Thread");
// FIXME determine the best priority balance between this and the main thread...
// It may be dependent on the display plugin being used, since VR plugins should
// have higher priority on rendering (although we could say that the Oculus plugin

50
libraries/entities/src/EntityScriptingInterface.cpp
View file

@ -27,6 +27,7 @@
#include "ZoneEntityItem.h"
#include "WebEntityItem.h"
#include <EntityScriptClient.h>
#include <Profile.h>
EntityScriptingInterface::EntityScriptingInterface(bool bidOnSimulationOwnership) :
@ -178,6 +179,8 @@ EntityItemProperties convertLocationFromScriptSemantics(const EntityItemProperti
QUuid EntityScriptingInterface::addEntity(const EntityItemProperties& properties, bool clientOnly) {
PROFILE_RANGE(script_entities, __FUNCTION__);
_activityTracking.addedEntityCount++;
EntityItemProperties propertiesWithSimID = convertLocationFromScriptSemantics(properties);
@ -259,6 +262,8 @@ EntityItemProperties EntityScriptingInterface::getEntityProperties(QUuid identit
}
EntityItemProperties EntityScriptingInterface::getEntityProperties(QUuid identity, EntityPropertyFlags desiredProperties) {
PROFILE_RANGE(script_entities, __FUNCTION__);
EntityItemProperties results;
if (_entityTree) {
_entityTree->withReadLock([&] {
@ -305,6 +310,8 @@ EntityItemProperties EntityScriptingInterface::getEntityProperties(QUuid identit
}
QUuid EntityScriptingInterface::editEntity(QUuid id, const EntityItemProperties& scriptSideProperties) {
PROFILE_RANGE(script_entities, __FUNCTION__);
_activityTracking.editedEntityCount++;
EntityItemProperties properties = scriptSideProperties;
@ -456,6 +463,8 @@ QUuid EntityScriptingInterface::editEntity(QUuid id, const EntityItemProperties&
}
void EntityScriptingInterface::deleteEntity(QUuid id) {
PROFILE_RANGE(script_entities, __FUNCTION__);
_activityTracking.deletedEntityCount++;
EntityItemID entityID(id);
@ -511,6 +520,8 @@ void EntityScriptingInterface::setEntitiesScriptEngine(EntitiesScriptEngineProvi
}
void EntityScriptingInterface::callEntityMethod(QUuid id, const QString& method, const QStringList& params) {
PROFILE_RANGE(script_entities, __FUNCTION__);
std::lock_guard<std::recursive_mutex> lock(_entitiesScriptEngineLock);
if (_entitiesScriptEngine) {
EntityItemID entityID{ id };
@ -519,6 +530,8 @@ void EntityScriptingInterface::callEntityMethod(QUuid id, const QString& method,
}
QUuid EntityScriptingInterface::findClosestEntity(const glm::vec3& center, float radius) const {
PROFILE_RANGE(script_entities, __FUNCTION__);
EntityItemID result;
if (_entityTree) {
EntityItemPointer closestEntity;
@ -542,6 +555,8 @@ void EntityScriptingInterface::dumpTree() const {
}
QVector<QUuid> EntityScriptingInterface::findEntities(const glm::vec3& center, float radius) const {
PROFILE_RANGE(script_entities, __FUNCTION__);
QVector<QUuid> result;
if (_entityTree) {
QVector<EntityItemPointer> entities;
@ -557,6 +572,8 @@ QVector<QUuid> EntityScriptingInterface::findEntities(const glm::vec3& center, f
}
QVector<QUuid> EntityScriptingInterface::findEntitiesInBox(const glm::vec3& corner, const glm::vec3& dimensions) const {
PROFILE_RANGE(script_entities, __FUNCTION__);
QVector<QUuid> result;
if (_entityTree) {
QVector<EntityItemPointer> entities;
@ -573,6 +590,8 @@ QVector<QUuid> EntityScriptingInterface::findEntitiesInBox(const glm::vec3& corn
}
QVector<QUuid> EntityScriptingInterface::findEntitiesInFrustum(QVariantMap frustum) const {
PROFILE_RANGE(script_entities, __FUNCTION__);
QVector<QUuid> result;
const QString POSITION_PROPERTY = "position";
@ -616,6 +635,7 @@ QVector<QUuid> EntityScriptingInterface::findEntitiesInFrustum(QVariantMap frust
RayToEntityIntersectionResult EntityScriptingInterface::findRayIntersection(const PickRay& ray, bool precisionPicking,
const QScriptValue& entityIdsToInclude, const QScriptValue& entityIdsToDiscard, bool visibleOnly, bool collidableOnly) {
PROFILE_RANGE(script_entities, __FUNCTION__);
QVector<EntityItemID> entitiesToInclude = qVectorEntityItemIDFromScriptValue(entityIdsToInclude);
QVector<EntityItemID> entitiesToDiscard = qVectorEntityItemIDFromScriptValue(entityIdsToDiscard);
@ -723,6 +743,8 @@ RayToEntityIntersectionResult::RayToEntityIntersectionResult() :
}
QScriptValue RayToEntityIntersectionResultToScriptValue(QScriptEngine* engine, const RayToEntityIntersectionResult& value) {
PROFILE_RANGE(script_entities, __FUNCTION__);
QScriptValue obj = engine->newObject();
obj.setProperty("intersects", value.intersects);
obj.setProperty("accurate", value.accurate);
@ -770,6 +792,8 @@ QScriptValue RayToEntityIntersectionResultToScriptValue(QScriptEngine* engine, c
}
void RayToEntityIntersectionResultFromScriptValue(const QScriptValue& object, RayToEntityIntersectionResult& value) {
PROFILE_RANGE(script_entities, __FUNCTION__);
value.intersects = object.property("intersects").toVariant().toBool();
value.accurate = object.property("accurate").toVariant().toBool();
QScriptValue entityIDValue = object.property("entityID");
@ -807,6 +831,8 @@ void RayToEntityIntersectionResultFromScriptValue(const QScriptValue& object, Ra
bool EntityScriptingInterface::setVoxels(QUuid entityID,
std::function<bool(PolyVoxEntityItem&)> actor) {
PROFILE_RANGE(script_entities, __FUNCTION__);
if (!_entityTree) {
return false;
}
@ -831,6 +857,8 @@ bool EntityScriptingInterface::setVoxels(QUuid entityID,
}
bool EntityScriptingInterface::setPoints(QUuid entityID, std::function<bool(LineEntityItem&)> actor) {
PROFILE_RANGE(script_entities, __FUNCTION__);
if (!_entityTree) {
return false;
}
@ -870,18 +898,24 @@ bool EntityScriptingInterface::setPoints(QUuid entityID, std::function<bool(Line
bool EntityScriptingInterface::setVoxelSphere(QUuid entityID, const glm::vec3& center, float radius, int value) {
PROFILE_RANGE(script_entities, __FUNCTION__);
return setVoxels(entityID, [center, radius, value](PolyVoxEntityItem& polyVoxEntity) {
return polyVoxEntity.setSphere(center, radius, value);
});
}
bool EntityScriptingInterface::setVoxel(QUuid entityID, const glm::vec3& position, int value) {
PROFILE_RANGE(script_entities, __FUNCTION__);
return setVoxels(entityID, [position, value](PolyVoxEntityItem& polyVoxEntity) {
return polyVoxEntity.setVoxelInVolume(position, value);
});
}
bool EntityScriptingInterface::setAllVoxels(QUuid entityID, int value) {
PROFILE_RANGE(script_entities, __FUNCTION__);
return setVoxels(entityID, [value](PolyVoxEntityItem& polyVoxEntity) {
return polyVoxEntity.setAll(value);
});
@ -889,12 +923,16 @@ bool EntityScriptingInterface::setAllVoxels(QUuid entityID, int value) {
bool EntityScriptingInterface::setVoxelsInCuboid(QUuid entityID, const glm::vec3& lowPosition,
const glm::vec3& cuboidSize, int value) {
PROFILE_RANGE(script_entities, __FUNCTION__);
return setVoxels(entityID, [lowPosition, cuboidSize, value](PolyVoxEntityItem& polyVoxEntity) {
return polyVoxEntity.setCuboid(lowPosition, cuboidSize, value);
});
}
bool EntityScriptingInterface::setAllPoints(QUuid entityID, const QVector<glm::vec3>& points) {
PROFILE_RANGE(script_entities, __FUNCTION__);
EntityItemPointer entity = static_cast<EntityItemPointer>(_entityTree->findEntityByEntityItemID(entityID));
if (!entity) {
qCDebug(entities) << "EntityScriptingInterface::setPoints no entity with ID" << entityID;
@ -913,6 +951,8 @@ bool EntityScriptingInterface::setAllPoints(QUuid entityID, const QVector<glm::v
}
bool EntityScriptingInterface::appendPoint(QUuid entityID, const glm::vec3& point) {
PROFILE_RANGE(script_entities, __FUNCTION__);
EntityItemPointer entity = static_cast<EntityItemPointer>(_entityTree->findEntityByEntityItemID(entityID));
if (!entity) {
qCDebug(entities) << "EntityScriptingInterface::setPoints no entity with ID" << entityID;
@ -988,6 +1028,8 @@ bool EntityScriptingInterface::actionWorker(const QUuid& entityID,
QUuid EntityScriptingInterface::addAction(const QString& actionTypeString,
const QUuid& entityID,
const QVariantMap& arguments) {
PROFILE_RANGE(script_entities, __FUNCTION__);
QUuid actionID = QUuid::createUuid();
auto actionFactory = DependencyManager::get<EntityActionFactoryInterface>();
bool success = false;
@ -1019,6 +1061,8 @@ QUuid EntityScriptingInterface::addAction(const QString& actionTypeString,
bool EntityScriptingInterface::updateAction(const QUuid& entityID, const QUuid& actionID, const QVariantMap& arguments) {
PROFILE_RANGE(script_entities, __FUNCTION__);
return actionWorker(entityID, [&](EntitySimulationPointer simulation, EntityItemPointer entity) {
bool success = entity->updateAction(simulation, actionID, arguments);
if (success) {
@ -1029,6 +1073,8 @@ bool EntityScriptingInterface::updateAction(const QUuid& entityID, const QUuid&
}
bool EntityScriptingInterface::deleteAction(const QUuid& entityID, const QUuid& actionID) {
PROFILE_RANGE(script_entities, __FUNCTION__);
bool success = false;
actionWorker(entityID, [&](EntitySimulationPointer simulation, EntityItemPointer entity) {
success = entity->removeAction(simulation, actionID);
@ -1042,6 +1088,8 @@ bool EntityScriptingInterface::deleteAction(const QUuid& entityID, const QUuid&
}
QVector<QUuid> EntityScriptingInterface::getActionIDs(const QUuid& entityID) {
PROFILE_RANGE(script_entities, __FUNCTION__);
QVector<QUuid> result;
actionWorker(entityID, [&](EntitySimulationPointer simulation, EntityItemPointer entity) {
QList<QUuid> actionIDs = entity->getActionIDs();
@ -1052,6 +1100,8 @@ QVector<QUuid> EntityScriptingInterface::getActionIDs(const QUuid& entityID) {
}
QVariantMap EntityScriptingInterface::getActionArguments(const QUuid& entityID, const QUuid& actionID) {
PROFILE_RANGE(script_entities, __FUNCTION__);
QVariantMap result;
actionWorker(entityID, [&](EntitySimulationPointer simulation, EntityItemPointer entity) {
result = entity->getActionArguments(actionID);

19
libraries/script-engine/src/ScriptEngine.cpp
View file

@ -64,6 +64,8 @@
#include "ScriptEngines.h"
#include "TabletScriptingInterface.h"
#include <Profile.h>
#include "MIDIEvent.h"
static const QString SCRIPT_EXCEPTION_FORMAT = "[UncaughtException] %1 in %2:%3";
@ -863,6 +865,10 @@ QScriptValue ScriptEngine::evaluate(const QString& sourceCode, const QString& fi
}
void ScriptEngine::run() {
auto filenameParts = _fileNameString.split("/");
auto name = filenameParts.size() > 0 ? filenameParts[filenameParts.size() - 1] : "unknown";
PROFILE_SET_THREAD_NAME("Script: " + name);
if (DependencyManager::get<ScriptEngines>()->isStopped()) {
return; // bail early - avoid setting state in init(), as evaluate() will bail too
}
@ -923,7 +929,10 @@ void ScriptEngine::run() {
bool processedEvents = false;
while (!_isFinished && clock::now() < sleepUntil) {
QCoreApplication::processEvents(); // before we sleep again, give events a chance to process
{
PROFILE_RANGE(script, "processEvents-sleep");
QCoreApplication::processEvents(); // before we sleep again, give events a chance to process
}
processedEvents = true;
// If after processing events, we're past due, exit asap
@ -938,6 +947,8 @@ void ScriptEngine::run() {
std::this_thread::sleep_until(smallSleepUntil);
}
PROFILE_RANGE(script, "ScriptMainLoop");
#ifdef SCRIPT_DELAY_DEBUG
{
auto actuallySleptUntil = clock::now();
@ -961,6 +972,7 @@ void ScriptEngine::run() {
// Only call this if we didn't processEvents as part of waiting for next frame
if (!processedEvents) {
PROFILE_RANGE(script, "processEvents");
QCoreApplication::processEvents();
}
@ -985,7 +997,10 @@ void ScriptEngine::run() {
float deltaTime = (float) (now - _lastUpdate) / (float) USECS_PER_SECOND;
if (!_isFinished) {
auto preUpdate = clock::now();
emit update(deltaTime);
{
PROFILE_RANGE(script, "ScriptUpdate");
emit update(deltaTime);
}
auto postUpdate = clock::now();
auto elapsed = (postUpdate - preUpdate);
totalUpdates += std::chrono::duration_cast<std::chrono::microseconds>(elapsed);

3
libraries/shared/src/Profile.cpp
View file

@ -10,6 +10,7 @@
Q_LOGGING_CATEGORY(trace_app, "trace.app")
Q_LOGGING_CATEGORY(trace_app_detail, "trace.app.detail")
Q_LOGGING_CATEGORY(trace_metadata, "trace.metadata")
Q_LOGGING_CATEGORY(trace_network, "trace.network")
Q_LOGGING_CATEGORY(trace_parse, "trace.parse")
Q_LOGGING_CATEGORY(trace_render, "trace.render")
@ -18,6 +19,8 @@ Q_LOGGING_CATEGORY(trace_render_gpu, "trace.render.gpu")
Q_LOGGING_CATEGORY(trace_resource, "trace.resource")
Q_LOGGING_CATEGORY(trace_resource_network, "trace.resource.network")
Q_LOGGING_CATEGORY(trace_resource_parse, "trace.resource.parse")
Q_LOGGING_CATEGORY(trace_script, "trace.script")
Q_LOGGING_CATEGORY(trace_script_entities, "trace.script.entities")
Q_LOGGING_CATEGORY(trace_simulation, "trace.simulation")
Q_LOGGING_CATEGORY(trace_simulation_detail, "trace.simulation.detail")
Q_LOGGING_CATEGORY(trace_simulation_animation, "trace.simulation.animation")

8
libraries/shared/src/Profile.h
View file

@ -16,6 +16,7 @@
// When profiling something that may happen many times per frame, use a xxx_detail category so that they may easily be filtered out of trace results
Q_DECLARE_LOGGING_CATEGORY(trace_app)
Q_DECLARE_LOGGING_CATEGORY(trace_app_detail)
Q_DECLARE_LOGGING_CATEGORY(trace_metadata)
Q_DECLARE_LOGGING_CATEGORY(trace_network)
Q_DECLARE_LOGGING_CATEGORY(trace_render)
Q_DECLARE_LOGGING_CATEGORY(trace_render_detail)
@ -23,6 +24,8 @@ Q_DECLARE_LOGGING_CATEGORY(trace_render_gpu)
Q_DECLARE_LOGGING_CATEGORY(trace_resource)
Q_DECLARE_LOGGING_CATEGORY(trace_resource_parse)
Q_DECLARE_LOGGING_CATEGORY(trace_resource_network)
Q_DECLARE_LOGGING_CATEGORY(trace_script)
Q_DECLARE_LOGGING_CATEGORY(trace_script_entities)
Q_DECLARE_LOGGING_CATEGORY(trace_simulation)
Q_DECLARE_LOGGING_CATEGORY(trace_simulation_detail)
Q_DECLARE_LOGGING_CATEGORY(trace_simulation_animation)
@ -69,6 +72,10 @@ inline void counter(const QLoggingCategory& category, const QString& name, const
}
}
inline void metadata(const QString& metadataType, const QVariantMap& args) {
tracing::traceEvent(trace_metadata(), metadataType, tracing::Metadata, "", args);
}
#define PROFILE_RANGE(category, name) Duration profileRangeThis(trace_##category(), name);
#define PROFILE_RANGE_EX(category, name, argbColor, payload, ...) Duration profileRangeThis(trace_##category(), name, argbColor, (uint64_t)payload, ##__VA_ARGS__);
#define PROFILE_RANGE_BEGIN(category, rangeId, name, argbColor) rangeId = Duration::beginRange(trace_##category(), name, argbColor)
@ -78,6 +85,7 @@ inline void counter(const QLoggingCategory& category, const QString& name, const
#define PROFILE_COUNTER_IF_CHANGED(category, name, type, value) { static type lastValue = 0; type newValue = value; if (newValue != lastValue) { counter(trace_##category(), name, { { name, newValue }}); lastValue = newValue; } }
#define PROFILE_COUNTER(category, name, ...) counter(trace_##category(), name, ##__VA_ARGS__);
#define PROFILE_INSTANT(category, name, ...) instant(trace_##category(), name, ##__VA_ARGS__);
#define PROFILE_SET_THREAD_NAME(threadName) metadata("thread_name", { { "name", threadName } });
#define SAMPLE_PROFILE_RANGE(chance, category, name, ...) if (randFloat() <= chance) { PROFILE_RANGE(category, name); }
#define SAMPLE_PROFILE_RANGE_EX(chance, category, name, ...) if (randFloat() <= chance) { PROFILE_RANGE_EX(category, name, argbColor, payload, ##__VA_ARGS__); }

59
libraries/shared/src/Trace.cpp
View file

@ -132,6 +132,9 @@ void Tracer::serialize(const QString& originalPath) {
{
std::lock_guard<std::mutex> guard(_eventsMutex);
currentEvents.swap(_events);
for (auto& event : _metadataEvents) {
currentEvents.push_back(event);
}
}
// If the file exists and we can't remove it, fail early
@ -194,33 +197,53 @@ void Tracer::serialize(const QString& originalPath) {
#endif
}
void Tracer::traceEvent(const QLoggingCategory& category,
const QString& name, EventType type,
qint64 timestamp, qint64 processID, qint64 threadID,
const QString& id,
const QVariantMap& args, const QVariantMap& extra) {
void Tracer::traceEvent(const QLoggingCategory& category,
const QString& name, EventType type,
qint64 timestamp, qint64 processID, qint64 threadID,
const QString& id,
const QVariantMap& args, const QVariantMap& extra) {
std::lock_guard<std::mutex> guard(_eventsMutex);
if (!_enabled) {
// We always want to store metadata events even if tracing is not enabled so that when
// tracing is enabled we will be able to associate that metadata with that trace.
// Metadata events should be used sparingly - as of 12/30/16 the Chrome Tracing
// spec only supports thread+process metadata, so we should only expect to see metadata
// events created when a new thread or process is created.
if (!_enabled && type != Metadata) {
return;
}
_events.push_back({
id,
name,
type,
timestamp,
processID,
threadID,
category,
args,
extra
});
if (type == Metadata) {
_metadataEvents.push_back({
id,
name,
type,
timestamp,
processID,
threadID,
category,
args,
extra
});
} else {
_events.push_back({
id,
name,
type,
timestamp,
processID,
threadID,
category,
args,
extra
});
}
}
void Tracer::traceEvent(const QLoggingCategory& category,
const QString& name, EventType type, const QString& id,
const QVariantMap& args, const QVariantMap& extra) {
if (!_enabled) {
if (!_enabled && type != Metadata) {
return;
}

1
libraries/shared/src/Trace.h
View file

@ -97,6 +97,7 @@ private:
bool _enabled { false };
std::list<TraceEvent> _events;
std::list<TraceEvent> _metadataEvents;
std::mutex _eventsMutex;
};