[Freeciv-Dev] (PR#12547) New /debug: Timing

["Per I. Mathisen" <per@xxxxxxxxxxx>]

<URL: http://bugs.freeciv.org/Ticket/Display.html?id=12547 >

This patch adds an AI timing debug command to the server. Do

        /debug timing

and the AI will start emitting a lot of info on what in the AI is taking
so long. Should be useful for optimizing the AI's speed.

  - Per

Index: ai/aihand.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/ai/aihand.c,v
retrieving revision 1.106
diff -u -r1.106 aihand.c
--- ai/aihand.c 18 Mar 2005 13:59:46 -0000      1.106
+++ ai/aihand.c 19 Mar 2005 15:26:25 -0000
@@ -411,7 +411,9 @@
    * us and make ai_mange_units and Co act upon this information, trying
    * to eliminate the source of danger */
 
+  TIMING_LOG(LOG_DEBUG, pplayer, "Manage units");
   ai_manage_units(pplayer); 
+  TIMING_LOG(LOG_DEBUG, pplayer, "All first activities done");
   /* STOP.  Everything else is at end of turn. */
 }
 
@@ -425,12 +427,17 @@
 **************************************************************************/
 void ai_do_last_activities(struct player *pplayer)
 {
+  TIMING_LOG(LOG_DEBUG, pplayer, "Manage government");
   ai_manage_government(pplayer);
+  TIMING_LOG(LOG_DEBUG, pplayer, "Manage taxes");
   ai_manage_taxes(pplayer); 
+  TIMING_LOG(LOG_DEBUG, pplayer, "Manage cities");
   ai_manage_cities(pplayer);
+  TIMING_LOG(LOG_DEBUG, pplayer, "Manage tech, space and aidata cleanup");
   ai_manage_tech(pplayer); 
   ai_manage_spaceship(pplayer);
   ai_data_phase_done(pplayer);
+  TIMING_LOG(LOG_DEBUG, pplayer, "Last activities done");
 }
 
 /**************************************************************************
Index: ai/ailog.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/ai/ailog.c,v
retrieving revision 1.19
diff -u -r1.19 ailog.c
--- ai/ailog.c  22 Jan 2005 19:45:38 -0000      1.19
+++ ai/ailog.c  19 Mar 2005 15:26:25 -0000
@@ -22,9 +22,11 @@
 #include "shared.h"
 #include "support.h"
 #include "unit.h"
+#include "timing.h"
 
 #include "gotohand.h"
 #include "plrhand.h"
+#include "srv_main.h"
 
 #include "aidata.h"
 #include "ailog.h"
@@ -246,3 +248,34 @@
   }
   freelog(minlevel, buffer);
 }
+
+/**************************************************************************
+  Measure the time between the calls.  Used to see where in the AI too
+  much CPU is being used.
+**************************************************************************/
+void TIMING_LOG(int level, struct player *pplayer, const char *msg)
+{
+  char buffer[500];
+  int minlevel = MIN(LOGLEVEL_BODYGUARD, level);
+  static struct timer *t = NULL;
+
+  if (t == NULL) {
+    t = new_timer_start(TIMER_CPU, TIMER_ACTIVE);
+  }
+
+  if (srvarg.timing_debug) {
+    minlevel = LOG_NORMAL;
+  } else if (minlevel > fc_log_level) {
+    clear_timer_start(t);
+    return;
+  }
+
+  my_snprintf(buffer, sizeof(buffer), "... %g seconds. %s: ",
+              read_timer_seconds(t), pplayer->name);
+  clear_timer_start(t);
+  cat_snprintf(buffer, sizeof(buffer), msg);
+  if (srvarg.timing_debug) {
+    notify_conn(game.est_connections, buffer);
+  }
+  freelog(minlevel, buffer);
+}
Index: ai/ailog.h
===================================================================
RCS file: /home/freeciv/CVS/freeciv/ai/ailog.h,v
retrieving revision 1.10
diff -u -r1.10 ailog.h
--- ai/ailog.h  6 Jan 2005 15:44:30 -0000       1.10
+++ ai/ailog.h  19 Mar 2005 15:26:25 -0000
@@ -43,5 +43,6 @@
 void UNIT_LOG(int level, struct unit *punit, const char *msg, ...)
      fc__attribute((format (printf, 3, 4)));
 void BODYGUARD_LOG(int level, struct unit *punit, const char *msg);
+void TIMING_LOG(int level, struct player *pplayer, const char *msg);
 
 #endif  /* FC__AILOG_H */
Index: server/commands.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/server/commands.c,v
retrieving revision 1.6
diff -u -r1.6 commands.c
--- server/commands.c   19 Jan 2005 05:40:03 -0000      1.6
+++ server/commands.c   19 Mar 2005 15:26:26 -0000
@@ -122,7 +122,8 @@
       "case if nobody votes against it.")
   },
   {"debug",    ALLOW_CTRL,
-   N_("debug [ player <player> | city <x> <y> | units <x> <y> | unit <id> ]"),
+   N_("debug [ player <player> | city <x> <y> | units <x> <y> | unit <id> "
+      "| tech <player> | timing ]"),
    N_("Turn on or off AI debugging of given entity."),
    N_("Print AI debug information about given entity and turn continous "
       "debugging output for this entity on or off."),
Index: server/srv_main.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/server/srv_main.c,v
retrieving revision 1.232
diff -u -r1.232 srv_main.c
--- server/srv_main.c   18 Mar 2005 11:26:25 -0000      1.232
+++ server/srv_main.c   19 Mar 2005 15:26:26 -0000
@@ -192,6 +192,8 @@
   srvarg.auth_allow_guests = FALSE;
   srvarg.auth_allow_newusers = FALSE;
 
+  srvarg.timing_debug = FALSE;
+
   /* initialize teams */
   team_init();
 
Index: server/srv_main.h
===================================================================
RCS file: /home/freeciv/CVS/freeciv/server/srv_main.h,v
retrieving revision 1.26
diff -u -r1.26 srv_main.h
--- server/srv_main.h   24 Dec 2004 04:01:48 -0000      1.26
+++ server/srv_main.h   19 Mar 2005 15:26:26 -0000
@@ -49,6 +49,8 @@
   bool auth_enabled;            /* defaults to FALSE */
   bool auth_allow_guests;       /* defaults to TRUE */
   bool auth_allow_newusers;     /* defaults to TRUE */
+
+  bool timing_debug;
 };
 
 void init_game_seed(void);
Index: server/stdinhand.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/server/stdinhand.c,v
retrieving revision 1.388
diff -u -r1.388 stdinhand.c
--- server/stdinhand.c  11 Mar 2005 05:57:44 -0000      1.388
+++ server/stdinhand.c  19 Mar 2005 15:26:27 -0000
@@ -2221,7 +2221,7 @@
   int ntokens = 0, i;
   const char *usage = _("Undefined arguments. Usage: debug <diplomacy "
                        "<player> | city <x> <y> | units <x> <y> | "
-                       "unit <id> | tech <player>>.");
+                       "unit <id> | tech <player> | timing>.");
 
   if (server_state != RUN_GAME_STATE) {
     cmd_reply(CMD_DEBUG, caller, C_SYNTAX,
@@ -2341,6 +2341,14 @@
                  unit_owner(punit)->name, unit_name(punit->type));
       }
     } unit_list_iterate_end;
+  } else if (strcmp(arg[0], "timing") == 0) {
+    if (srvarg.timing_debug) {
+      cmd_reply(CMD_DEBUG, caller, C_OK, _("AI timing deactivated"));
+      srvarg.timing_debug = FALSE;
+  } else {
+      srvarg.timing_debug = TRUE;
+      cmd_reply(CMD_DEBUG, caller, C_OK, _("AI timing activated"));
+    }
   } else if (strcmp(arg[0], "unit") == 0) {
     int id;
     struct unit *punit;