[Arianne-commits] stendhal/src/games/stendhal/server StendhalRPRuleProcessor.java, 1.173, 1.173.2.1

[Hendrik B. <nh...@us...>]

Update of /cvsroot/arianne/stendhal/src/games/stendhal/server
In directory sc8-pr-cvs11.sourceforge.net:/tmp/cvs-serv11198/src/games/stendhal/server

Modified Files:
      Tag: VERSION_00_RELEASE_52
	StendhalRPRuleProcessor.java 
Log Message:
added additional info on turn time overflow

Index: StendhalRPRuleProcessor.java
===================================================================
RCS file: /cvsroot/arianne/stendhal/src/games/stendhal/server/StendhalRPRuleProcessor.java,v
retrieving revision 1.173
retrieving revision 1.173.2.1
diff -C2 -d -r1.173 -r1.173.2.1
*** StendhalRPRuleProcessor.java	7 Aug 2006 20:52:51 -0000	1.173
--- StendhalRPRuleProcessor.java	19 Aug 2006 10:23:44 -0000	1.173.2.1
***************
*** 329,339 ****
  	synchronized public void beginTurn() {
  		Log4J.startMethod(logger, "beginTurn");
  		long start = System.nanoTime();
  		int creatures = 0;
! 		for (RespawnPoint point : respawnPoints)
  			creatures += point.size();
  		int objects = 0;
! 		for (IRPZone zone : world)
  			objects += zone.size();
  		logger.debug("lists: G:" + plantGrowers.size()
  				+ ",NPC:" + npcs.size() + ",P:" + playersObject.size() + ",CR:"
--- 329,345 ----
  	synchronized public void beginTurn() {
  		Log4J.startMethod(logger, "beginTurn");
+         long timeStart = System.currentTimeMillis();
+         long[] timeEnds = new long[7];
  		long start = System.nanoTime();
  		int creatures = 0;
! 		for (RespawnPoint point : respawnPoints) {
  			creatures += point.size();
+         }
+         timeEnds[0] = System.currentTimeMillis();
  		int objects = 0;
! 		for (IRPZone zone : world) {
  			objects += zone.size();
+         }
+         timeEnds[1] = System.currentTimeMillis();
  		logger.debug("lists: G:" + plantGrowers.size()
  				+ ",NPC:" + npcs.size() + ",P:" + playersObject.size() + ",CR:"
***************
*** 346,349 ****
--- 352,356 ----
  			Statistics.getStatistics().set("Players logged",
  					playersObject.size());
+             timeEnds[0] = System.currentTimeMillis();
  			// In order for the last hit to be visible dead happens at two
  			// steps.
***************
*** 355,358 ****
--- 362,366 ----
  				}
  			}
+             timeEnds[1] = System.currentTimeMillis();
  			entityToKill.clear();
  			// Done this way because a problem with comodification... :(
***************
*** 363,366 ****
--- 371,375 ----
  			npcsToRemove.clear();
  			bloodsToRemove.clear();
+             timeEnds[2] = System.currentTimeMillis();
  			for (Player object : playersObject) {
  				if (object.has("risk")) {
***************
*** 405,408 ****
--- 414,418 ----
  				object.consume(getTurn());
  			}
+             timeEnds[3] = System.currentTimeMillis();
  			for (NPC npc : npcs) {
                  try {
***************
*** 412,415 ****
--- 422,426 ----
                  }                
              }
+             timeEnds[4] = System.currentTimeMillis();
  			for (Player object : playersObjectRmText) {
  				if (object.has("text")) {
***************
*** 422,426 ****
--- 433,439 ----
  				}
  			}
+             timeEnds[5] = System.currentTimeMillis();
  			playersObjectRmText.clear();
+             timeEnds[6] = System.currentTimeMillis();
  		} catch (Exception e) {
  			logger.error("error in beginTurn", e);
***************
*** 430,433 ****
--- 443,453 ----
  			Log4J.finishMethod(logger, "beginTurn");
  		}
+         if (timeEnds[6] - timeStart > 300) {
+             StringBuilder sb = new StringBuilder();
+             for (long timeEnd : timeEnds) {
+                 sb.append(" " + (timeEnd-timeStart));
+             }
+             logger.warn("Turn Time overflow in beginTurn:" + sb.toString());
+         }
  	}
  
***************
*** 436,439 ****
--- 456,461 ----
          long start = System.nanoTime();
          int currentTurn = getTurn();
+         long timeStart = System.currentTimeMillis();
+         long[] timeEnds = new long[4];
          try {
          	// Creatures
***************
*** 441,444 ****
--- 463,467 ----
                  point.logic();               
              }
+             timeEnds[0] = System.currentTimeMillis();
  
              // PlantGrowers
***************
*** 451,464 ****
--- 474,497 ----
                  }
              }
+             timeEnds[1] = System.currentTimeMillis();
  
              // Registeres classes for this turn
              TurnNotifier.get().logic(currentTurn);
+             timeEnds[2] = System.currentTimeMillis();
  
              // Scripts
              scripts.logic();
+             timeEnds[3] = System.currentTimeMillis();
          } catch (Exception e) {
              logger.error("error in endTurn", e);
          } finally {
              logger.debug("End turn: " + (System.nanoTime() - start) / 1000000.0 + " (" + (currentTurn % 5) + ")");
+             if (timeEnds[3] - timeStart > 300) {
+                 StringBuilder sb = new StringBuilder();
+                 for (long timeEnd : timeEnds) {
+                     sb.append(" " + (timeEnd-timeStart));
+                 }
+                 logger.warn("Turn Time overflow in endTurn:" + sb.toString());
+             }
              Log4J.finishMethod(logger, "endTurn");
          }