- added a more proper #define setup to completely stub out debugging to test performance

(simply uncomment #define UNDEF_DEBUG and the debug statements become nothing)
- Added piles of experimental changes for testing different performance scenarios (all of these changes are turned off by default and will most likely eventually be removed)
This commit is contained in:
Mark Vejvoda 2010-05-07 06:46:55 +00:00
parent 1a6bb489b8
commit 8aa14009d1
12 changed files with 211 additions and 27 deletions

View File

@ -238,14 +238,14 @@ void Commander::updateNetwork(){
perfTimer.start();
//update the keyframe
gameNetworkInterface->updateKeyframe(world->getFrameCount());
SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] gameNetworkInterface->updateKeyframe for %d took %d msecs\n",__FILE__,__FUNCTION__,__LINE__,world->getFrameCount(),perfTimer.getMillis());
if(perfTimer.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] gameNetworkInterface->updateKeyframe for %d took %d msecs\n",__FILE__,__FUNCTION__,__LINE__,world->getFrameCount(),perfTimer.getMillis());
perfTimer.start();
//give pending commands
for(int i= 0; i < gameNetworkInterface->getPendingCommandCount(); ++i){
giveNetworkCommand(gameNetworkInterface->getPendingCommand(i));
}
SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] giveNetworkCommand took %d msecs\n",__FILE__,__FUNCTION__,__LINE__,perfTimer.getMillis());
if(perfTimer.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] giveNetworkCommand took %d msecs\n",__FILE__,__FUNCTION__,__LINE__,perfTimer.getMillis());
gameNetworkInterface->clearPendingCommands();
}
}

View File

@ -59,6 +59,7 @@ Game::Game(Program *program, const GameSettings *gameSettings):
renderNetworkStatus= false;
speed= sNormal;
showFullConsole= false;
render3DThreadManager = NULL;
}
Game::~Game(){
@ -69,6 +70,10 @@ Game::~Game(){
logger.setState(Lang::getInstance().get("Deleting"));
logger.add("Game", true);
BaseThread::shutdownAndWait(render3DThreadManager);
delete render3DThreadManager;
render3DThreadManager = NULL;
renderer.endGame();
SoundRenderer::getInstance().stopAllSounds();
@ -329,9 +334,17 @@ void Game::init()
logger.add("Launching game");
BaseThread::shutdownAndWait(render3DThreadManager);
delete render3DThreadManager;
//render3DThreadManager = new SimpleTaskThread(this,0,5,true);
//render3DThreadManager->start();
SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
}
void Game::simpleTask() {
renderWorker();
}
// ==================== update ====================
@ -417,26 +430,41 @@ void Game::updateCamera(){
//render
void Game::render() {
//SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps);
renderFps++;
if(render3DThreadManager == NULL) {
renderWorker();
}
else {
render3DThreadManager->setTaskSignalled(true);
}
//SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps);
}
void Game::renderWorker() {
Chrono chrono;
chrono.start();
//SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
renderFps++;
//program->getWindow()->makeCurrentGl();
//renderFps++;
render3d();
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d render3d() took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis());
//if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis());
//SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
chrono.start();
render2d();
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d render3d() took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis());
//if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis());
//SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
chrono.start();
Renderer::getInstance().swapBuffers();
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d render3d() took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis());
//if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis());
//SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
}

View File

@ -22,8 +22,10 @@
#include "chat_manager.h"
#include "script_manager.h"
#include "game_settings.h"
#include "simple_threads.h"
using std::vector;
using namespace Shared::PlatformCommon;
namespace Glest{ namespace Game{
@ -35,7 +37,7 @@ class GraphicMessageBox;
// Main game class
// =====================================================
class Game: public ProgramState{
class Game: public ProgramState, public SimpleTaskCallbackInterface {
public:
enum Speed{
sFast,
@ -57,6 +59,7 @@ private:
Console console;
ChatManager chatManager;
ScriptManager scriptManager;
SimpleTaskThread *render3DThreadManager;
//misc
Checksum checksum;
@ -117,6 +120,9 @@ public:
virtual void mouseMove(int x, int y, const MouseState *mouseState);
void quitGame();
virtual void simpleTask();
private:
//render
void render3d();
@ -133,6 +139,7 @@ private:
void showLoseMessageBox();
void showWinMessageBox();
void showMessageBox(const string &text, const string &header, bool toggle);
void renderWorker();
};
}}//end namespace

View File

@ -1281,15 +1281,39 @@ void Renderer::renderObjects(){
int loopCount1 = 0;
int loopCount2 = 0;
Chrono chrono2;
int64 sectionA = 0;
int64 sectionB = 0;
int64 sectionC = 0;
int64 sectionD = 0;
int64 sectionE = 0;
int64 sectionF = 0;
int64 sectionG = 0;
int64 sectionH = 0;
PosQuadIterator pqi(map, visibleQuad, Map::cellScale);
while(pqi.next()){
const Vec2i pos= pqi.getPos();
if(map->isInside(pos)){
chrono2.start();
const Vec2i pos= pqi.getPos();
bool isPosVisible = map->isInside(pos);
sectionG += chrono2.getMillis();
chrono2.start();
if(isPosVisible == true) {
SurfaceCell *sc= map->getSurfaceCell(Map::toSurfCoords(pos));
Object *o= sc->getObject();
if(sc->isExplored(thisTeamIndex) && o!=NULL){
bool isExplored = (sc->isExplored(thisTeamIndex) && o!=NULL);
sectionH += chrono2.getMillis();
chrono2.start();
if(isExplored == true) {
chrono2.start();
const Model *objModel= sc->getObject()->getModel();
Vec3f v= o->getPos();
@ -1301,18 +1325,34 @@ void Renderer::renderObjects(){
glMaterialfv(GL_FRONT_AND_BACK, GL_AMBIENT, (color*ambFactor).ptr());
glFogfv(GL_FOG_COLOR, (baseFogColor*fowFactor).ptr());
sectionA += chrono2.getMillis();
chrono2.start();
glMatrixMode(GL_MODELVIEW);
glPushMatrix();
glTranslatef(v.x, v.y, v.z);
glRotatef(o->getRotation(), 0.f, 1.f, 0.f);
sectionB += chrono2.getMillis();
chrono2.start();
objModel->updateInterpolationData(0.f, true);
sectionC += chrono2.getMillis();
chrono2.start();
modelRenderer->render(objModel);
sectionD += chrono2.getMillis();
chrono2.start();
triangleCount+= objModel->getTriangleCount();
pointCount+= objModel->getVertexCount();
glPopMatrix();
sectionF += chrono2.getMillis();
loopCount2++;
}
}
@ -1322,7 +1362,7 @@ void Renderer::renderObjects(){
modelRenderer->end();
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d loopCount1 = %d loopCount2 = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,loopCount1,loopCount2,chrono.getMillis());
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d loopCount1 = %d loopCount2 = %d took msecs: %d [%d,%d,%d,%d,%d,%d,%d,%d]\n",__FILE__,__FUNCTION__,__LINE__,loopCount1,loopCount2,chrono.getMillis(),sectionG,sectionH,sectionA,sectionB,sectionC,sectionD,sectionE,sectionF);
chrono.start();
//restore

View File

@ -121,6 +121,7 @@ Program::Program() {
programState= NULL;
singleton = this;
soundThreadManager = NULL;
loopThreadManager = NULL;
}
void Program::initNormal(WindowGl *window){
@ -166,6 +167,10 @@ Program::~Program(){
BaseThread::shutdownAndWait(soundThreadManager);
delete soundThreadManager;
soundThreadManager = NULL;
BaseThread::shutdownAndWait(loopThreadManager);
delete loopThreadManager;
loopThreadManager = NULL;
}
void Program::keyDown(char key){
@ -181,15 +186,34 @@ void Program::keyPress(char c){
programState->keyPress(c);
}
void Program::loop(){
void Program::simpleTask() {
loopWorker();
}
void Program::loop() {
if(loopThreadManager == NULL) {
loopWorker();
}
else {
loopThreadManager->setTaskSignalled(true);
}
}
void Program::loopWorker() {
SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
Chrono chrono;
chrono.start();
getWindow()->makeCurrentGl();
//render
assert(programState != NULL);
programState->render();
SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d programState->render took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis());
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d programState->render took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis());
SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
//update camera
chrono.start();
@ -197,7 +221,9 @@ void Program::loop(){
programState->updateCamera();
}
SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d programState->updateCamera took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis());
SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d programState->updateCamera took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis());
//update world
chrono.start();
@ -220,7 +246,9 @@ void Program::loop(){
//SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s %d]\n",__FILE__,__FUNCTION__,__LINE__);
}
SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis());
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis());
SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
//fps timer
chrono.start();
@ -228,7 +256,7 @@ void Program::loop(){
programState->tick();
}
SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis());
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis());
}
void Program::resize(SizeState sizeState){
@ -379,6 +407,11 @@ void Program::init(WindowGl *window, bool initSound, bool toggleFullScreen){
}
}
BaseThread::shutdownAndWait(loopThreadManager);
delete loopThreadManager;
//loopThreadManager = new SimpleTaskThread(this,0,5,true);
//loopThreadManager->start();
NetworkInterface::setAllowGameDataSynchCheck(Config::getInstance().getBool("AllowGameDataSynchCheck","false"));
NetworkInterface::setAllowDownloadDataSynch(Config::getInstance().getBool("AllowDownloadDataSynch","false"));

View File

@ -76,7 +76,7 @@ public:
// class Program
// ===============================
class Program{
class Program : public SimpleTaskCallbackInterface {
private:
static const int maxTimes;
SimpleTaskThread *soundThreadManager;
@ -110,6 +110,7 @@ private:
WindowGl *window;
static Program *singleton;
SimpleTaskThread *loopThreadManager;
public:
Program();
@ -127,6 +128,7 @@ public:
void keyPress(char c);
void loop();
void loopWorker();
void resize(SizeState sizeState);
void showMessage(const char *msg);
@ -137,6 +139,8 @@ public:
void init(WindowGl *window, bool initSound=true, bool toggleFullScreen=false);
void exit();
virtual void simpleTask();
private:
void setDisplaySettings();

View File

@ -429,7 +429,7 @@ void ClientInterface::updateKeyframe(int frameCount)
waitCount++;
}
SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] receiveMessage took %d msecs, waitCount = %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis(),waitCount);
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] receiveMessage took %d msecs, waitCount = %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis(),waitCount);
chrono.start();
//check that we are in the right frame
@ -450,7 +450,7 @@ void ClientInterface::updateKeyframe(int frameCount)
pendingCommands.push_back(*networkMessageCommandList.getCommand(i));
}
SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] transfer network commands took %d msecs\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis());
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] transfer network commands took %d msecs\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis());
done= true;
}
@ -676,7 +676,7 @@ void ClientInterface::waitForMessage()
waitLoopCount++;
}
SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] waiting took %d msecs, waitLoopCount = %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis(),waitLoopCount);
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] waiting took %d msecs, waitLoopCount = %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis(),waitLoopCount);
}
void ClientInterface::quitGame(bool userManuallyQuit)

View File

@ -272,12 +272,12 @@ void ServerInterface::updateKeyframe(int frameCount){
}
}
SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] build command list took %d msecs, networkMessageCommandList.getCommandCount() = %d, frameCount = %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis(),networkMessageCommandList.getCommandCount(),frameCount);
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] build command list took %d msecs, networkMessageCommandList.getCommandCount() = %d, frameCount = %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis(),networkMessageCommandList.getCommandCount(),frameCount);
//broadcast commands
broadcastMessage(&networkMessageCommandList);
SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] broadcastMessage took %d msecs, networkMessageCommandList.getCommandCount() = %d, frameCount = %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis(),networkMessageCommandList.getCommandCount(),frameCount);
if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] broadcastMessage took %d msecs, networkMessageCommandList.getCommandCount() = %d, frameCount = %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis(),networkMessageCommandList.getCommandCount(),frameCount);
}
bool ServerInterface::shouldDiscardNetworkMessage(NetworkMessageType networkMessageType,

View File

@ -56,12 +56,19 @@ protected:
unsigned int executionCount;
unsigned int millisecsBetweenExecutions;
Mutex mutexTaskSignaller;
bool taskSignalled;
bool needTaskSignal;
public:
SimpleTaskThread();
SimpleTaskThread(SimpleTaskCallbackInterface *simpleTaskInterface,
unsigned int executionCount=0,
unsigned int millisecsBetweenExecutions=0);
unsigned int millisecsBetweenExecutions=0,
bool needTaskSignal = false);
virtual void execute();
void setTaskSignalled(bool value);
bool getTaskSignalled();
};
}}//end namespace

View File

@ -20,6 +20,8 @@
using std::string;
using namespace Shared::Platform;
//#define UNDEF_DEBUG
namespace Shared{ namespace Util{
class SystemFlags
@ -103,7 +105,21 @@ public:
static void init();
static SystemFlagsType & getSystemSettingType(DebugType type) { return debugLogFileList[type]; }
static void OutputDebug(DebugType type, const char *fmt, ...);
// Let the macro call into this when require.. NEVER call it automatically.
static void handleDebug(DebugType type, const char *fmt, ...);
#ifndef UNDEF_DEBUG
#define OutputDebug(type, fmt, ...) SystemFlags::handleDebug (type, fmt, ##__VA_ARGS__)
#else
// stub out debugging completely
#define OutputDebug(type, fmt, ...) type
#endif
static void Close();
};

View File

@ -66,19 +66,41 @@ void FileCRCPreCacheThread::execute() {
SimpleTaskThread::SimpleTaskThread( SimpleTaskCallbackInterface *simpleTaskInterface,
unsigned int executionCount,
unsigned int millisecsBetweenExecutions) {
unsigned int millisecsBetweenExecutions,
bool needTaskSignal) {
this->simpleTaskInterface = simpleTaskInterface;
this->executionCount = executionCount;
this->millisecsBetweenExecutions = millisecsBetweenExecutions;
this->needTaskSignal = needTaskSignal;
setTaskSignalled(false);
}
void SimpleTaskThread::execute() {
try {
setRunningStatus(true);
SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
unsigned int idx = 0;
for(;this->simpleTaskInterface != NULL;) {
this->simpleTaskInterface->simpleTask();
bool runTask = true;
if(needTaskSignal == true) {
runTask = getTaskSignalled();
if(runTask == true) {
setTaskSignalled(false);
}
}
if(getQuitStatus() == true) {
//SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
break;
}
if(runTask == true) {
this->simpleTaskInterface->simpleTask();
}
if(this->executionCount > 0) {
idx++;
if(idx >= this->executionCount) {
@ -92,13 +114,40 @@ void SimpleTaskThread::execute() {
sleep(this->millisecsBetweenExecutions);
}
SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
}
catch(const exception &ex) {
setRunningStatus(false);
SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
throw runtime_error(ex.what());
}
setRunningStatus(false);
}
void SimpleTaskThread::setTaskSignalled(bool value) {
//SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
mutexTaskSignaller.p();
taskSignalled = value;
mutexTaskSignaller.v();
//SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
}
bool SimpleTaskThread::getTaskSignalled() {
//SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
bool retval = false;
mutexTaskSignaller.p();
retval = taskSignalled;
mutexTaskSignaller.v();
//SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
return retval;
}
}}//end namespace

View File

@ -100,7 +100,7 @@ void SystemFlags::Close() {
printf("END Closing logfiles\n");
}
void SystemFlags::OutputDebug(DebugType type, const char *fmt, ...) {
void SystemFlags::handleDebug(DebugType type, const char *fmt, ...) {
if(SystemFlags::debugLogFileList.size() == 0) {
SystemFlags::init();
}