NewtonWorldRayCast randomly taking a very long time

[fractile]

I'm back with yet another problem. I have been debugging weird random and temporary FPS drops during game-play and ended up logging time spent in NewtonWorldRayCast() function calls. Something is not right here.

Here is a excerpt from log (one game update) when things run fine:
23:39:10: Application: NewtonWorldRayCast (from [16.475594 -8.053022 0.000019] to [16.475594 -9.853023 0.000019]) took 12 us
23:39:10: Application: NewtonWorldRayCast (from [-1.995628 2.947838 0.001547] to [-1.995628 1.147838 0.001547]) took 9 us
23:39:10: Application: NewtonWorldRayCast (from [-47.896816 -0.555944 0.000000] to [-47.896816 -2.355944 0.000000]) took 8 us
23:39:10: Application: NewtonWorldRayCast (from [-53.223907 -3.053026 -0.000001] to [-53.223907 -4.853026 -0.000001]) took 7 us
23:39:10: Application: NewtonWorldRayCast (from [-40.020599 -0.052151 0.000031] to [-40.020599 -1.852150 0.000031]) took 8 us
23:39:10: Application: NewtonWorldRayCast (from [-46.649170 4.947819 0.000009] to [-46.649170 3.147819 0.000009]) took 8 us
23:39:10: Application: NewtonWorldRayCast (from [-44.017715 -0.052149 0.000023] to [-44.017715 -1.852149 0.000023]) took 8 us
23:39:10: Application: NewtonWorldRayCast (from [21.178715 3.721332 -0.000002] to [10.027609 -7.302128 -0.000000]) took 56 us
23:39:10: Application: NewtonWorldRayCast (from [21.178715 3.721332 -0.000002] to [10.027609 -8.052128 -0.000000]) took 12 us
23:39:10: Application: NewtonWorldRayCast (from [21.178715 3.721332 -0.000002] to [10.027609 -8.802128 -0.000000]) took 12 us
23:39:10: Application: NewtonWorldRayCast (from [21.178715 3.721332 -0.000002] to [17.224497 -7.303022 0.000022]) took 11 us
23:39:10: Application: NewtonWorldRayCast (from [21.178715 3.721332 -0.000002] to [17.224497 -8.053022 0.000022]) took 11 us
23:39:10: Application: NewtonWorldRayCast (from [21.178715 3.721332 -0.000002] to [17.224497 -8.803022 0.000022]) took 10 us
23:39:10: Application: NewtonWorldRayCast (from [21.178715 3.721332 -0.000002] to [-2.744302 3.697837 0.001540]) took 11 us

And here is same thing right after the frame rate suddenly drops:
23:39:10: Application: NewtonWorldRayCast (from [10.827609 -8.052128 -0.000000] to [10.827609 -9.852128 -0.000000]) took 29 us
23:39:10: Application: NewtonWorldRayCast (from [16.424498 -8.053022 0.000022] to [16.424498 -9.853023 0.000022]) took 12 us
23:39:10: Application: NewtonWorldRayCast (from [-1.944302 2.947837 0.001540] to [-1.944302 1.147837 0.001540]) took 9 us
23:39:10: Application: NewtonWorldRayCast (from [-47.861340 -0.529313 0.000000] to [-47.861340 -2.329313 0.000000]) took 8 us
23:39:10: Application: NewtonWorldRayCast (from [-53.172516 -3.053027 -0.000001] to [-53.172516 -4.853026 -0.000001]) took 7 us
23:39:10: Application: NewtonWorldRayCast (from [-40.071751 -0.052151 0.000032] to [-40.071751 -1.852151 0.000032]) took 9 us
23:39:10: Application: NewtonWorldRayCast (from [-46.700562 4.947817 0.000013] to [-46.700562 3.147817 0.000013]) took 7 us
23:39:10: Application: NewtonWorldRayCast (from [-44.069107 -0.052150 0.000023] to [-44.069107 -1.852150 0.000023]) took 8 us
23:39:10: Application: NewtonWorldRayCast (from [21.091616 3.696302 -0.000014] to [10.079002 -7.302128 -0.000000]) took 21332 us
23:39:10: Application: NewtonWorldRayCast (from [21.091616 3.696302 -0.000014] to [10.079002 -8.052128 -0.000000]) took 21265 us
23:39:10: Application: NewtonWorldRayCast (from [21.091616 3.696302 -0.000014] to [10.079002 -8.802128 -0.000000]) took 21262 us
23:39:10: Application: NewtonWorldRayCast (from [21.091616 3.696302 -0.000014] to [17.173349 -7.303022 0.000025]) took 2514 us
23:39:10: Application: NewtonWorldRayCast (from [21.091616 3.696302 -0.000014] to [17.173349 -8.053022 0.000025]) took 2492 us
23:39:10: Application: NewtonWorldRayCast (from [21.091616 3.696302 -0.000014] to [17.173349 -8.803022 0.000025]) took 2489 us
23:39:10: Application: NewtonWorldRayCast (from [21.091616 3.696302 -0.000014] to [-2.692965 3.697837 0.001533]) took 448 us

My scene consists of a static body with compound collision (the level) and a number of dynamic bodies (players, etc.) with primitive collisions. The first half of the logged ray casts are for my character controllers detecting ground, latter half is for visibility checks between characters.

The game is configured to run everything in a single thread so there is no game code running in parallel with the ray casts. The problem occurs quite systematically when characters get close enough to each other to start making visibility tests using ray casts. For a little while those ray casts are really fast, then suddenly they start taking 20+ ms each. After a while things return to normal and ray casts are fast again. I don't see any significant changes taking place in the scene when the slowdown occurs.

First thing I checked is my ray cast callback. It gets usually called only once per ray and I don't see anything there that could suddenly block or waste tens of milliseconds:

Code: Select all

Ogre::Real Simulator::newtonRayCallback(const NewtonBody* body, const Ogre::Real* normal,
    int collision, void* userdata, Ogre::Real param)
{
    if(param < 0.0f || param > 1.0f)
    {
       return 0.0f; // Intersection parameter outside of line segment -> abort ray cast
    }

    TRayCallbackUserData* data = (TRayCallbackUserData*)userdata;

    // Update contact data
    data->m_Contact->m_Movable = (Movable*)NewtonBodyGetUserData(body);
    data->m_Contact->m_Normal[0] = normal[0];
    data->m_Contact->m_Normal[1] = normal[1];
    data->m_Contact->m_Normal[2] = normal[2];
    data->m_Contact->m_Distance = data->m_SegmentLength * param;
    data->m_Contact->m_Point = data->m_Origin + data->m_Segment * param;   

    // Continue tracing (only look for contacts closer than this one)
    return param;
}

Any ideas on what might be going on here are welcome.

[JoeJ]

i may not be the right one to answer here, but i'd think first on cache issues here.
So porviding the number of bodies in level data, machine specs etc. could be helpfull.
Also, reducing level bodys could prove for that, maybe you can find a magic number where the slowdown begins.

[Julio Jerez]

20 millisecund soudn hurrendous.

How many bodies in the compound collision?
How many bodies in the scene.
and can it be reproducible?

answer that, the I can give you some pointes to track where the problem might be.

[fractile]

There are approximately 150 box collisions in the compound collision (in one static body) and 10-20 dynamic bodies. I'm currently testing on AMD E-350 APU, but I'm remember seeing the exact same slowdown with other CPUs too. Slowdown is less noticeable on faster PC.

[Julio Jerez]

150 objects is not enough object to show that kind of slow down.

The one thing we can do first is to going out if the brute force ray cats produce the 20 milliseconds slow down for that you can hack the file \source\physics\dgBroadPhaseCollision.cpp
function

Code: Select all

void dgBroadPhaseCollision::RayCast (const dgVector& l0,  const dgVector& l1,  OnRayCastAction filter,  OnRayPrecastAction prefilter,  void* const userData) const

and iterate ove the entry arrauy of bodies, call Ray cats on each object and see hwo losw it is,
the will be the absolute war case since it will aaways cadt every object.

I assume you are copiking the source, are you?
If you are I can post later hwo to hack the funtion to iterate ove ever body in the scene.

[fractile]

I'm using version 2.33 compiled myself (on 64-bit linux). So yes, I can hack, recompile and test.

[Julio Jerez]

ha good, bacicall you cna hack teh ray cast funtion liek this

Code: Select all

void dgBroadPhaseCollision::RayCast (
    const dgVector& l0,
    const dgVector& l1,
    OnRayCastAction filter,
    OnRayPrecastAction prefilter,
    void* const userData) const
{
   dgLineBox line;   
   line.m_l0 = l0;
   line.m_l1 = l1;
   if (line.m_l0.m_x <= line.m_l1.m_x) {
      line.m_boxL0.m_x = line.m_l0.m_x;
      line.m_boxL1.m_x = line.m_l1.m_x;
   } else {
      line.m_boxL0.m_x = line.m_l1.m_x;
      line.m_boxL1.m_x = line.m_l0.m_x;
   }

   if (line.m_l0.m_y <= line.m_l1.m_y) {
      line.m_boxL0.m_y = line.m_l0.m_y;
      line.m_boxL1.m_y = line.m_l1.m_y;
   } else {
      line.m_boxL0.m_y = line.m_l1.m_y;
      line.m_boxL1.m_y = line.m_l0.m_y;
   }

   if (line.m_l0.m_z <= line.m_l1.m_z) {
      line.m_boxL0.m_z = line.m_l0.m_z;
      line.m_boxL1.m_z = line.m_l1.m_z;
   } else {
      line.m_boxL0.m_z = line.m_l1.m_z;
      line.m_boxL1.m_z = line.m_l0.m_z;
   }

   dgBodyMasterList& masterList (*((dgWorld*)this));
// set stop watch timer
   for (dgBodyMasterList::dgListNode* node = masterList.GetFirst()->GetNext(); node; node = node->GetNext()) {
      dgBody* body;
      body = node->GetInfo().GetBody();
      body->RayCast (line, filter, prefilter, userData, 2.0);
// save the worse time offender

   }
}

that will go oer each body in teh scene, and you can add timer to see whi one is teh one take teh logest and the we can focus on th e one.
I did not add teh stopwatch timer, I asume you cna do that.

[fractile]

I replaced the original dgBroadPhaseCollision::RayCast() function with the one in the previous post (no timers added yet), recompiled and tried running the game. The average measured raycast times did not change much, but I can't reproduce the slowdown anymore. None of the raycasts lasts over 100us.

To double check, I reverted to the original function, recompiled and the slowdown was back.

[Julio Jerez]

So maybe the bug is in the raycast scaner iteself. 100 microsecudn is still to high, but that is a brust force scan

fortunatlly in newton core 300, all of the broadphase is was rewriting to be more efficent.
In fact the raycast scanner in core 300, is the same scanner of the collision tree in 200 witch is 100 % efficent since optimized collison trees are 100% optimal.
also in core 300 optimization happen automatically. are you trying core 300? it is much faster.

you should not rely on the brute force loop, because it will take time propotional to the body count, that is why it is taking 100 microsecund now.
My guess is that core 300 should take around 10 microsecund on average (ray cast was also optimized for core 300)

[fractile]

I tried compiling core 300 from SVN trunk (revision 887) with no luck. I'm guessing the Linux makefiles aren't quite up to date.

After a little tweaking I managed to build a libNewton.so, but linking to it show lots of "unresolved external" errors. The missing symbols seem to be in source files that not compiled by the makefile. I started adding the missing files to the makefile based on the missing symbols. This went fine until adding dgWorkerThread.cpp, which does not compile:

Code: Select all

gcc -c -Wall -Wno-strict-aliasing -D_LINUX_VER -D_LINUX_VER_64 -O2 -fpic -msse -msse2 -mfpmath=sse -ffloat-store -ffast-math -freciprocal-math -funsafe-math-optimizations -fsingle-precision-constant  -I../../source/core -I../../source/physics -o ../../source/core/dgWorkerThread.o ../../source/core/dgWorkerThread.cpp   
../../source/core/dgWorkerThread.cpp: In constructor ‘dgWorkerThread::dgWorkerThread()’:
../../source/core/dgWorkerThread.cpp:38:3: error: class ‘dgWorkerThread’ does not have any field named ‘m_jobsInQueueSemaphore’
../../source/core/dgWorkerThread.h:89:12: warning: ‘dgWorkerThread::m_threadhandle’ will be initialized after
../../source/core/dgWorkerThread.h:81:32: warning:   ‘dgUnsigned32 (* dgWorkerThread::m_getPerformanceCount)()’
../../source/core/dgWorkerThread.cpp:28:1: warning:   when initialized here
../../source/core/dgWorkerThread.cpp:40:29: warning: converting to non-pointer type ‘pthread_t’ from NULL
../../source/core/dgWorkerThread.cpp: In destructor ‘dgWorkerThread::~dgWorkerThread()’:
../../source/core/dgWorkerThread.cpp:48:21: error: ‘m_jobsInQueueSemaphore’ was not declared in this scope
../../source/core/dgWorkerThread.cpp:48:52: error: ‘ReleaseSemaphore’ was not declared in this scope
../../source/core/dgWorkerThread.cpp:52:12: error: ‘Sleep’ was not declared in this scope
../../source/core/dgWorkerThread.cpp: At global scope:
../../source/core/dgWorkerThread.cpp:140:7: error: ‘dgWorkerThreadOld’ has not been declared
../../source/core/dgWorkerThread.h: In function ‘void* ThreadSystemCallback(void*)’:
../../source/core/dgWorkerThread.h:58:7: error: ‘void dgWorkerThread::TaskExecuter()’ is private
../../source/core/dgWorkerThread.cpp:151:19: error: within this context
../../source/core/dgWorkerThread.cpp: In member function ‘void dgWorkerThread::TaskExecuter()’:
../../source/core/dgWorkerThread.cpp:193:3: error: ‘DWORD’ was not declared in this scope
../../source/core/dgWorkerThread.cpp:193:9: error: expected ‘;’ before ‘waitCode’
../../source/core/dgWorkerThread.cpp:194:3: error: ‘waitCode’ was not declared in this scope
../../source/core/dgWorkerThread.cpp:194:34: error: ‘m_jobsInQueueSemaphore’ was not declared in this scope
../../source/core/dgWorkerThread.cpp:194:58: error: ‘INFINITE’ was not declared in this scope
../../source/core/dgWorkerThread.cpp:194:66: error: ‘WaitForSingleObject’ was not declared in this scope
../../source/core/dgWorkerThread.cpp: In member function ‘void dgWorkerThread::ExecuteJobs()’:
../../source/core/dgWorkerThread.cpp:242:21: error: ‘m_jobsInQueueSemaphore’ was not declared in this scope
../../source/core/dgWorkerThread.cpp:242:52: error: ‘ReleaseSemaphore’ was not declared in this scope
make: *** [../../source/core/dgWorkerThread.o] Error 1


Is there a revision or tag that is known to compile without errors?

[Julio Jerez]

Oh I see, core 300 does not have the mutithreaded library implementd using pthreads.
I forget that you are in linux.

the thread library for core 200 in very different than in code 200. Is has to be rewriten for p threads.

[fractile]

I should have done a little more testing after the change. The slowdown is indeed gone, but now the ray cast is not working at all. My visibility tests now return wrong results: Enemies see through doors and sometimes they don't see the player when he's standing right in front of them. I did not change the game code at all, only modified the newton ray cast function to use the brute force loop. Previously the visibility test worked fine (except for the slowdowns of course).

[Julio Jerez]

Oh that is because I did not make the loop correct I just forced it to call all bodies.
if you look at the prototype of the ray cast the function, it returns a value that need to be paid attention too.
dgFloat32 dgBody::RayCast (
const dgLineBox& line,
OnRayCastAction filter,
OnRayPrecastAction preFilter,
void* const userData,
dgFloat32 minT) const

if you change the inner loop to this.

Code: Select all

float t = 2.0;
 for (dgBodyMasterList::dgListNode* node = masterList.GetFirst()->GetNext(); node; node = node->GetNext()) {
      dgBody* body;
      body = node->GetInfo().GetBody();
      t = body->RayCast (line, filter, prefilter, userData, t);
   }
}

then the scan will not test bodies if they are behind other bodies as it is now it return the hit of the last body. It will also be faster too.

[fractile]

Ok, thanks, that explains it.

Are there any plans on setting up working Mac and Linux versions of the Newton core 300?

[Julio Jerez]

Yes there is plan to make the Linux and Mac of core 300
I will have to implement the multreading code, but I took a detuor on work on a script system so tha I can comple the asset editor fors.