From 26a34e3cda77a6ad670967f20db12e3b51929c58 Mon Sep 17 00:00:00 2001 From: erwincoumans Date: Sun, 29 Jan 2017 20:59:47 -0800 Subject: [PATCH] Move ChromeTracing in its own file, and add tracing support for VR server (App_SharedMemoryPhysics_VR) Add a bit of extra sleep in PhysicsServer thread, to make rendering smoother. --- examples/BasicDemo/premake4.lua | 3 +- examples/ExampleBrowser/CMakeLists.txt | 2 + .../ExampleBrowser/OpenGLExampleBrowser.cpp | 267 +---------------- examples/ExampleBrowser/premake4.lua | 2 + examples/SharedMemory/CMakeLists.txt | 2 + .../SharedMemory/PhysicsServerExample.cpp | 13 +- examples/SharedMemory/premake4.lua | 2 + .../StandaloneMain/hellovr_opengl_main.cpp | 26 +- examples/Utils/ChromeTraceUtil.cpp | 272 ++++++++++++++++++ examples/Utils/ChromeTraceUtil.h | 9 + examples/pybullet/vr_kuka_setup.py | 1 + 11 files changed, 333 insertions(+), 266 deletions(-) create mode 100644 examples/Utils/ChromeTraceUtil.cpp create mode 100644 examples/Utils/ChromeTraceUtil.h diff --git a/examples/BasicDemo/premake4.lua b/examples/BasicDemo/premake4.lua index 2faa974cd..a480b82c9 100644 --- a/examples/BasicDemo/premake4.lua +++ b/examples/BasicDemo/premake4.lua @@ -192,7 +192,8 @@ files { "../ThirdPartyLibs/openvr/samples/shared/Vectors.h", "../Utils/b3Clock.cpp", "../Utils/b3Clock.h", - + "../Utils/ChromeTraceUtil.cpp", + "../Utils/ChromeTraceUtil.h", } if os.is("Windows") then diff --git a/examples/ExampleBrowser/CMakeLists.txt b/examples/ExampleBrowser/CMakeLists.txt index 9b84597eb..68b5d6d1f 100644 --- a/examples/ExampleBrowser/CMakeLists.txt +++ b/examples/ExampleBrowser/CMakeLists.txt @@ -34,6 +34,8 @@ ADD_LIBRARY(BulletExampleBrowserLib CollisionShape2TriangleMesh.h ../Utils/b3Clock.cpp ../Utils/b3Clock.h + ../Utils/ChromeTraceUtil.cpp + ../Utils/ChromeTraceUtil.h ../Utils/b3ResourcePath.cpp ../Utils/b3ResourcePath.h ../Utils/b3ERPCFMHelper.hpp diff --git a/examples/ExampleBrowser/OpenGLExampleBrowser.cpp b/examples/ExampleBrowser/OpenGLExampleBrowser.cpp index 1bac82724..69842d4c7 100644 --- a/examples/ExampleBrowser/OpenGLExampleBrowser.cpp +++ b/examples/ExampleBrowser/OpenGLExampleBrowser.cpp @@ -24,6 +24,7 @@ #include "GwenGUISupport/gwenInternalData.h" #include "GwenGUISupport/gwenUserInterface.h" #include "../Utils/b3Clock.h" +#include "../Utils/ChromeTraceUtil.h" #include "GwenGUISupport/GwenParameterInterface.h" #ifndef BT_NO_PROFILE #include "GwenGUISupport/GwenProfileWindow.h" @@ -148,227 +149,6 @@ int gGpuArraySizeZ=45; - -struct btTiming -{ - const char* m_name; - int m_threadId; - unsigned long long int m_usStartTime; - unsigned long long int m_usEndTime; -}; - -FILE* gTimingFile = 0; -#ifndef __STDC_FORMAT_MACROS -#define __STDC_FORMAT_MACROS -#endif //__STDC_FORMAT_MACROS - -//see http://stackoverflow.com/questions/18107426/printf-format-for-unsigned-int64-on-windows -#ifndef _WIN32 -#include -#endif - -#define BT_TIMING_CAPACITY 16*65536 -static bool m_firstTiming = true; - - -struct btTimings -{ - btTimings() - :m_numTimings(0), - m_activeBuffer(0) - { - - } - void flush() - { - for (int i=0;iendTime) - { - endTime = startTime; - } - unsigned int startTimeRem1000 = startTime%1000; - unsigned int endTimeRem1000 = endTime%1000; - - char startTimeRem1000Str[16]; - char endTimeRem1000Str[16]; - - if (startTimeRem1000<10) - { - sprintf(startTimeRem1000Str,"00%d",startTimeRem1000); - } - else - { - if (startTimeRem1000<100) - { - sprintf(startTimeRem1000Str,"0%d",startTimeRem1000); - } else - { - sprintf(startTimeRem1000Str,"%d",startTimeRem1000); - } - } - - if (endTimeRem1000<10) - { - sprintf(endTimeRem1000Str,"00%d",endTimeRem1000); - } - else - { - if (endTimeRem1000<100) - { - sprintf(endTimeRem1000Str,"0%d",endTimeRem1000); - } else - { - sprintf(endTimeRem1000Str,"%d",endTimeRem1000); - } - } - - char newname[1024]; - static int counter2=0; - sprintf(newname,"%s%d",name,counter2++); - -#ifdef _WIN32 - - fprintf(gTimingFile,"{\"cat\":\"timing\",\"pid\":1,\"tid\":%d,\"ts\":%I64d.%s ,\"ph\":\"B\",\"name\":\"%s\",\"args\":{}},\n", - threadId, startTimeDiv1000,startTimeRem1000Str, newname); - fprintf(gTimingFile,"{\"cat\":\"timing\",\"pid\":1,\"tid\":%d,\"ts\":%I64d.%s ,\"ph\":\"E\",\"name\":\"%s\",\"args\":{}}", - threadId, endTimeDiv1000,endTimeRem1000Str,newname); - -#else - fprintf(gTimingFile,"{\"cat\":\"timing\",\"pid\":1,\"tid\":%d,\"ts\":%" PRIu64 ".%s ,\"ph\":\"B\",\"name\":\"%s\",\"args\":{}},\n", - threadId, startTimeDiv1000,startTimeRem1000Str, newname); - fprintf(gTimingFile,"{\"cat\":\"timing\",\"pid\":1,\"tid\":%d,\"ts\":%" PRIu64 ".%s ,\"ph\":\"E\",\"name\":\"%s\",\"args\":{}}", - threadId, endTimeDiv1000,endTimeRem1000Str,newname); -#endif -#endif - - } - m_numTimings = 0; - - } - - void addTiming(const char* name, int threadId, unsigned long long int startTime, unsigned long long int endTime) - { - if (m_numTimings>=BT_TIMING_CAPACITY) - { - return; - } - - if (m_timings[0].size()==0) - { - m_timings[0].resize(BT_TIMING_CAPACITY); - } - - int slot = m_numTimings++; - - m_timings[m_activeBuffer][slot].m_name = name; - m_timings[m_activeBuffer][slot].m_threadId = threadId; - m_timings[m_activeBuffer][slot].m_usStartTime = startTime; - m_timings[m_activeBuffer][slot].m_usEndTime = endTime; - } - - - int m_numTimings; - int m_activeBuffer; - btAlignedObjectArray m_timings[1]; -}; -#ifndef BT_NO_PROFILE -btTimings gTimings[BT_QUICKPROF_MAX_THREAD_COUNT]; -#define MAX_NESTING 1024 -int gStackDepths[BT_QUICKPROF_MAX_THREAD_COUNT] = {0}; -const char* gFuncNames[BT_QUICKPROF_MAX_THREAD_COUNT][MAX_NESTING]; -unsigned long long int gStartTimes[BT_QUICKPROF_MAX_THREAD_COUNT][MAX_NESTING]; -#endif - -btClock clk; - - - -bool gProfileDisabled = true; - - -void MyDummyEnterProfileZoneFunc(const char* msg) -{ -} - -void MyDummyLeaveProfileZoneFunc() -{ -} - -void MyEnterProfileZoneFunc(const char* msg) -{ - if (gProfileDisabled) - return; -#ifndef BT_NO_PROFILE - int threadId = btQuickprofGetCurrentThreadIndex2(); - if (threadId<0) - return; - - if (gStackDepths[threadId]>=MAX_NESTING) - { - btAssert(0); - return; - } - gFuncNames[threadId][gStackDepths[threadId]] = msg; - gStartTimes[threadId][gStackDepths[threadId]] = clk.getTimeNanoseconds(); - if (gStartTimes[threadId][gStackDepths[threadId]]<=gStartTimes[threadId][gStackDepths[threadId]-1]) - { - gStartTimes[threadId][gStackDepths[threadId]]=1+gStartTimes[threadId][gStackDepths[threadId]-1]; - } - gStackDepths[threadId]++; -#endif - -} -void MyLeaveProfileZoneFunc() -{ - if (gProfileDisabled) - return; -#ifndef BT_NO_PROFILE - int threadId = btQuickprofGetCurrentThreadIndex2(); - if (threadId<0) - return; - - if (gStackDepths[threadId]<=0) - { - return; - } - - gStackDepths[threadId]--; - - const char* name = gFuncNames[threadId][gStackDepths[threadId]]; - unsigned long long int startTime = gStartTimes[threadId][gStackDepths[threadId]]; - - unsigned long long int endTime = clk.getTimeNanoseconds(); - gTimings[threadId].addTiming(name,threadId,startTime,endTime); -#endif //BT_NO_PROFILE -} - - void deleteDemo() { if (sCurrentDemo) @@ -469,40 +249,12 @@ void MyKeyboardCallback(int key, int state) #ifndef BT_NO_PROFILE if (state) { - m_firstTiming = true; - gProfileDisabled = false;//true; - b3SetCustomEnterProfileZoneFunc(MyEnterProfileZoneFunc); - b3SetCustomLeaveProfileZoneFunc(MyLeaveProfileZoneFunc); + b3ChromeUtilsStartTimings(); - //also for Bullet 2.x API - btSetCustomEnterProfileZoneFunc(MyEnterProfileZoneFunc); - btSetCustomLeaveProfileZoneFunc(MyLeaveProfileZoneFunc); } else { - b3SetCustomEnterProfileZoneFunc(MyDummyEnterProfileZoneFunc); - b3SetCustomLeaveProfileZoneFunc(MyDummyLeaveProfileZoneFunc); - //also for Bullet 2.x API - btSetCustomEnterProfileZoneFunc(MyDummyEnterProfileZoneFunc); - btSetCustomLeaveProfileZoneFunc(MyDummyLeaveProfileZoneFunc); - char fileName[1024]; - static int fileCounter = 0; - sprintf(fileName,"timings_%d.json",fileCounter++); - gTimingFile = fopen(fileName,"w"); - fprintf(gTimingFile,"{\"traceEvents\":[\n"); - //dump the content to file - for (int i=0;iinit(); diff --git a/examples/ExampleBrowser/premake4.lua b/examples/ExampleBrowser/premake4.lua index ac184dedc..5e6e41351 100644 --- a/examples/ExampleBrowser/premake4.lua +++ b/examples/ExampleBrowser/premake4.lua @@ -193,6 +193,8 @@ project "BulletExampleBrowserLib" "OpenGLGuiHelper.cpp", "OpenGLExampleBrowser.cpp", "../Utils/b3Clock.cpp", + "../Utils/ChromeTraceUtil.cpp", + "../Utils/ChromeTraceUtil.h", "*.h", "GwenGUISupport/*.cpp", "GwenGUISupport/*.h", diff --git a/examples/SharedMemory/CMakeLists.txt b/examples/SharedMemory/CMakeLists.txt index 9477ac3f2..5db17f0e5 100644 --- a/examples/SharedMemory/CMakeLists.txt +++ b/examples/SharedMemory/CMakeLists.txt @@ -61,6 +61,8 @@ SET(SharedMemory_SRCS ../Importers/ImportMJCFDemo/BulletMJCFImporter.h ../Utils/b3ResourcePath.cpp ../Utils/b3Clock.cpp + ../Utils/ChromeTraceUtil.cpp + ../Utils/ChromeTraceUtil.h ../Importers/ImportURDFDemo/URDFImporterInterface.h ../Importers/ImportURDFDemo/URDFJointTypes.h ../Importers/ImportObjDemo/Wavefront2GLInstanceGraphicsShape.cpp diff --git a/examples/SharedMemory/PhysicsServerExample.cpp b/examples/SharedMemory/PhysicsServerExample.cpp index c940624cf..1510475c6 100644 --- a/examples/SharedMemory/PhysicsServerExample.cpp +++ b/examples/SharedMemory/PhysicsServerExample.cpp @@ -300,7 +300,6 @@ void MotionThreadFunc(void* userPtr,void* lsMemory) double deltaTimeInSeconds = 0; double sleepCounter = 0; - do { BT_PROFILE("loop"); @@ -310,6 +309,8 @@ void MotionThreadFunc(void* userPtr,void* lsMemory) b3Clock::usleep(0); } double dt = double(clock.getTimeMicroseconds())/1000000.; + clock.reset(); + sleepCounter+=dt; if (sleepCounter > sleepTimeThreshold) @@ -317,10 +318,18 @@ void MotionThreadFunc(void* userPtr,void* lsMemory) BT_PROFILE("usleep(100)"); sleepCounter = 0; b3Clock::usleep(100); + + } + + { + if (gEnableRealTimeSimVR) + { + BT_PROFILE("usleep(1000)"); + b3Clock::usleep(1000); + } } deltaTimeInSeconds+= dt; - clock.reset(); { diff --git a/examples/SharedMemory/premake4.lua b/examples/SharedMemory/premake4.lua index e851dbc99..3bb14c6b0 100644 --- a/examples/SharedMemory/premake4.lua +++ b/examples/SharedMemory/premake4.lua @@ -77,6 +77,8 @@ myfiles = "../Importers/ImportMJCFDemo/BulletMJCFImporter.h", "../Utils/b3ResourcePath.cpp", "../Utils/b3Clock.cpp", + "../Utils/ChromeTraceUtil.cpp", + "../Utils/ChromeTraceUtil.h", "../../Extras/Serialize/BulletWorldImporter/*", "../../Extras/Serialize/BulletFileLoader/*", "../Importers/ImportURDFDemo/URDFImporterInterface.h", diff --git a/examples/StandaloneMain/hellovr_opengl_main.cpp b/examples/StandaloneMain/hellovr_opengl_main.cpp index 6e9adb4c1..590312503 100644 --- a/examples/StandaloneMain/hellovr_opengl_main.cpp +++ b/examples/StandaloneMain/hellovr_opengl_main.cpp @@ -11,6 +11,7 @@ #include "Bullet3Common/b3CommandLineArgs.h" #include "../Utils/b3Clock.h" +#include "../Utils/ChromeTraceUtil.h" #include "../ExampleBrowser/OpenGLGuiHelper.h" #include "../CommonInterfaces/CommonExampleInterface.h" #include "../CommonInterfaces/CommonGUIHelperInterface.h" @@ -344,6 +345,17 @@ b3KeyboardCallback prevKeyboardCallback = 0; void MyKeyboardCallback(int key, int state) { + if (key == 'p') + { + if (state) + { + b3ChromeUtilsStartTimings(); + } + else + { + b3ChromeUtilsStopTimingsAndWriteJsonFile(); + } + } if (sExample) { sExample->keyboardCallback(key,state); @@ -794,6 +806,7 @@ void CMainApplication::RunMainLoop() while ( !bQuit && !m_app->m_window->requestedExit()) { + b3ChromeUtilsEnableProfiling(); { B3_PROFILE("main"); @@ -2241,6 +2254,12 @@ int main(int argc, char *argv[]) { gDisableDesktopGL = true; } + if (args.CheckCmdLineFlag("tracing")) + { + b3ChromeUtilsStartTimings(); + b3ChromeUtilsEnableProfiling(); + } + #ifdef BT_USE_CUSTOM_PROFILER b3SetCustomEnterProfileZoneFunc(dcEnter); @@ -2280,8 +2299,11 @@ int main(int argc, char *argv[]) pMainApplication->Shutdown(); -#ifdef BT_USE_CUSTOM_PROFILER -#endif + if (args.CheckCmdLineFlag("tracing")) + { + b3ChromeUtilsStopTimingsAndWriteJsonFile(); + } + return 0; } diff --git a/examples/Utils/ChromeTraceUtil.cpp b/examples/Utils/ChromeTraceUtil.cpp new file mode 100644 index 000000000..35faa1957 --- /dev/null +++ b/examples/Utils/ChromeTraceUtil.cpp @@ -0,0 +1,272 @@ + +#include "ChromeTraceUtil.h" +#include "b3Clock.h" +#include "LinearMath/btQuickprof.h" +#include "LinearMath/btAlignedObjectArray.h" +#include "Bullet3Common/b3Logging.h" + +struct btTiming +{ + const char* m_name; + int m_threadId; + unsigned long long int m_usStartTime; + unsigned long long int m_usEndTime; +}; + +FILE* gTimingFile = 0; +#ifndef __STDC_FORMAT_MACROS +#define __STDC_FORMAT_MACROS +#endif //__STDC_FORMAT_MACROS + +//see http://stackoverflow.com/questions/18107426/printf-format-for-unsigned-int64-on-windows +#ifndef _WIN32 +#include +#endif + +#define BT_TIMING_CAPACITY 16*65536 +static bool m_firstTiming = true; + + +struct btTimings +{ + btTimings() + :m_numTimings(0), + m_activeBuffer(0) + { + + } + void flush() + { + for (int i = 0; iendTime) + { + endTime = startTime; + } + unsigned int startTimeRem1000 = startTime % 1000; + unsigned int endTimeRem1000 = endTime % 1000; + + char startTimeRem1000Str[16]; + char endTimeRem1000Str[16]; + + if (startTimeRem1000<10) + { + sprintf(startTimeRem1000Str, "00%d", startTimeRem1000); + } + else + { + if (startTimeRem1000<100) + { + sprintf(startTimeRem1000Str, "0%d", startTimeRem1000); + } + else + { + sprintf(startTimeRem1000Str, "%d", startTimeRem1000); + } + } + + if (endTimeRem1000<10) + { + sprintf(endTimeRem1000Str, "00%d", endTimeRem1000); + } + else + { + if (endTimeRem1000<100) + { + sprintf(endTimeRem1000Str, "0%d", endTimeRem1000); + } + else + { + sprintf(endTimeRem1000Str, "%d", endTimeRem1000); + } + } + + char newname[1024]; + static int counter2 = 0; + sprintf(newname, "%s%d", name, counter2++); + +#ifdef _WIN32 + + fprintf(gTimingFile, "{\"cat\":\"timing\",\"pid\":1,\"tid\":%d,\"ts\":%I64d.%s ,\"ph\":\"B\",\"name\":\"%s\",\"args\":{}},\n", + threadId, startTimeDiv1000, startTimeRem1000Str, newname); + fprintf(gTimingFile, "{\"cat\":\"timing\",\"pid\":1,\"tid\":%d,\"ts\":%I64d.%s ,\"ph\":\"E\",\"name\":\"%s\",\"args\":{}}", + threadId, endTimeDiv1000, endTimeRem1000Str, newname); + +#else + fprintf(gTimingFile, "{\"cat\":\"timing\",\"pid\":1,\"tid\":%d,\"ts\":%" PRIu64 ".%s ,\"ph\":\"B\",\"name\":\"%s\",\"args\":{}},\n", + threadId, startTimeDiv1000, startTimeRem1000Str, newname); + fprintf(gTimingFile, "{\"cat\":\"timing\",\"pid\":1,\"tid\":%d,\"ts\":%" PRIu64 ".%s ,\"ph\":\"E\",\"name\":\"%s\",\"args\":{}}", + threadId, endTimeDiv1000, endTimeRem1000Str, newname); +#endif +#endif + + } + m_numTimings = 0; + + } + + void addTiming(const char* name, int threadId, unsigned long long int startTime, unsigned long long int endTime) + { + if (m_numTimings >= BT_TIMING_CAPACITY) + { + return; + } + + if (m_timings[0].size() == 0) + { + m_timings[0].resize(BT_TIMING_CAPACITY); + } + + int slot = m_numTimings++; + + m_timings[m_activeBuffer][slot].m_name = name; + m_timings[m_activeBuffer][slot].m_threadId = threadId; + m_timings[m_activeBuffer][slot].m_usStartTime = startTime; + m_timings[m_activeBuffer][slot].m_usEndTime = endTime; + } + + + int m_numTimings; + int m_activeBuffer; + btAlignedObjectArray m_timings[1]; +}; +#ifndef BT_NO_PROFILE +btTimings gTimings[BT_QUICKPROF_MAX_THREAD_COUNT]; +#define MAX_NESTING 1024 +int gStackDepths[BT_QUICKPROF_MAX_THREAD_COUNT] = { 0 }; +const char* gFuncNames[BT_QUICKPROF_MAX_THREAD_COUNT][MAX_NESTING]; +unsigned long long int gStartTimes[BT_QUICKPROF_MAX_THREAD_COUNT][MAX_NESTING]; +#endif + +btClock clk; + + + +bool gProfileDisabled = true; + + +void MyDummyEnterProfileZoneFunc(const char* msg) +{ +} + +void MyDummyLeaveProfileZoneFunc() +{ +} + +void MyEnterProfileZoneFunc(const char* msg) +{ + if (gProfileDisabled) + return; +#ifndef BT_NO_PROFILE + int threadId = btQuickprofGetCurrentThreadIndex2(); + if (threadId<0) + return; + + if (gStackDepths[threadId] >= MAX_NESTING) + { + btAssert(0); + return; + } + gFuncNames[threadId][gStackDepths[threadId]] = msg; + gStartTimes[threadId][gStackDepths[threadId]] = clk.getTimeNanoseconds(); + if (gStartTimes[threadId][gStackDepths[threadId]] <= gStartTimes[threadId][gStackDepths[threadId] - 1]) + { + gStartTimes[threadId][gStackDepths[threadId]] = 1 + gStartTimes[threadId][gStackDepths[threadId] - 1]; + } + gStackDepths[threadId]++; +#endif + +} +void MyLeaveProfileZoneFunc() +{ + if (gProfileDisabled) + return; +#ifndef BT_NO_PROFILE + int threadId = btQuickprofGetCurrentThreadIndex2(); + if (threadId<0) + return; + + if (gStackDepths[threadId] <= 0) + { + return; + } + + gStackDepths[threadId]--; + + const char* name = gFuncNames[threadId][gStackDepths[threadId]]; + unsigned long long int startTime = gStartTimes[threadId][gStackDepths[threadId]]; + + unsigned long long int endTime = clk.getTimeNanoseconds(); + gTimings[threadId].addTiming(name, threadId, startTime, endTime); +#endif //BT_NO_PROFILE +} + + +void b3ChromeUtilsStartTimings() +{ + m_firstTiming = true; + gProfileDisabled = false;//true; + b3SetCustomEnterProfileZoneFunc(MyEnterProfileZoneFunc); + b3SetCustomLeaveProfileZoneFunc(MyLeaveProfileZoneFunc); + + //also for Bullet 2.x API + btSetCustomEnterProfileZoneFunc(MyEnterProfileZoneFunc); + btSetCustomLeaveProfileZoneFunc(MyLeaveProfileZoneFunc); +} + +void b3ChromeUtilsStopTimingsAndWriteJsonFile() +{ + b3SetCustomEnterProfileZoneFunc(MyDummyEnterProfileZoneFunc); + b3SetCustomLeaveProfileZoneFunc(MyDummyLeaveProfileZoneFunc); + //also for Bullet 2.x API + btSetCustomEnterProfileZoneFunc(MyDummyEnterProfileZoneFunc); + btSetCustomLeaveProfileZoneFunc(MyDummyLeaveProfileZoneFunc); + char fileName[1024]; + static int fileCounter = 0; + sprintf(fileName,"timings_%d.json",fileCounter++); + gTimingFile = fopen(fileName,"w"); + fprintf(gTimingFile,"{\"traceEvents\":[\n"); + //dump the content to file + for (int i=0;i