Even better timing log

Per Inge Mathisen <per-0/[email protected]> Tue, 12 Apr 2005 14:06:26 +0000 (GMT)
Newsgroups gmane.games.freeciv.ai
Message-ID <[email protected]> 
In my quest to speed up the AI, I had to make the timing log code even
better. Now it times AI activities all the time, and prints out the
results when you do "/debug timing".

Please try this out on some large games and send in the results.

It will look like this:

2:   --- AI timing results ---
2:   Total AI time: 18,94 sec turn, 29,04 sec game
2:   Movemap: 6,22 sec turn, 12,22 sec game
2:   Units: 17,85 sec turn, 17,85 sec game
2:    - Military: 17,01 sec turn, 17,01 sec game
2:    - Attack: 7,53 sec turn, 7,53 sec game
2:    - Defense: 2,91 sec turn, 2,91 sec game
2:    - Ferry: 0,49 sec turn, 0,49 sec game
2:    - Rampage: 8,05 sec turn, 8,05 sec game
2:    - Bodyguard: 6,43 sec turn, 6,42 sec game
2:    - Recover: 0 sec turn, 0 sec game
2:    - Caravan: 0 sec turn, 0 sec game
2:    - Hunter: 0,07 sec turn, 0,06 sec game
2:    - Airlift: 0 sec turn, 0 sec game
2:    - Diplomat: 0,07 sec turn, 0,07 sec game
2:    - Air: 0,61 sec turn, 0,62 sec game
2:    - Explore: 0,91 sec turn, 0,91 sec game
2:   fstk: 2,96 sec turn, 5,33 sec game
2:   Settlers: 0 sec turn, 0 sec game
2:   Workers: 0 sec turn, 0,06 sec game
2:   Government: 0 sec turn, 3,05 sec game
2:   Taxes: 0 sec turn, 0 sec game
2:   Cities: 0 sec turn, 10,09 sec game
2:    - Buildings: 0 sec turn, 0,32 sec game
2:    - Danger: 1,09 sec turn, 2,36 sec game
2:    - Worker want: 0 sec turn, 0,28 sec game
2:    - Military want: 0 sec turn, 5,28 sec game
2:    - Settler want: 0 sec turn, 4,15 sec game
2:   Citizen arrange: 0,25 sec turn, 3,27 sec game
2:   Tech: 0 sec turn, 0 sec game

The various times are often overlapping.

  - Per
timing.diff (text/plain, 23.1 KB) 
Index: ai/advmilitary.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/ai/advmilitary.c,v
retrieving revision 1.189
diff -u -r1.189 advmilitary.c
--- ai/advmilitary.c	25 Mar 2005 16:49:06 -0000	1.189
+++ ai/advmilitary.c	12 Apr 2005 14:04:57 -0000
@@ -451,6 +451,8 @@
   int igwall_threat = 0;
   struct tile *ptile = pcity->tile;
 
+  TIMING_LOG(AIT_DANGER, TIMER_START);
+
   memset(&danger, 0, sizeof(danger));
 
   generate_warmap(pcity, NULL);	/* generates both land and sea maps */
@@ -589,6 +591,8 @@
   pcity->ai.danger = danger[0];
   pcity->ai.urgency = urgency;
 
+  TIMING_LOG(AIT_DANGER, TIMER_STOP);
+
   return urgency;
 }
 
Index: ai/aicity.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/ai/aicity.c,v
retrieving revision 1.210
diff -u -r1.210 aicity.c
--- ai/aicity.c	10 Apr 2005 23:55:24 -0000	1.210
+++ ai/aicity.c	12 Apr 2005 14:04:57 -0000
@@ -1190,6 +1190,7 @@
 {
   pplayer->ai.maxbuycost = 0;
 
+  TIMING_LOG(AIT_EMERGENCY, TIMER_START);
   city_list_iterate(pplayer->cities, pcity) {
     if (CITY_EMERGENCY(pcity)) {
       auto_arrange_workers(pcity); /* this usually helps */
@@ -1201,23 +1202,32 @@
     ai_sell_obsolete_buildings(pcity);
     sync_cities();
   } city_list_iterate_end;
+  TIMING_LOG(AIT_EMERGENCY, TIMER_STOP);
 
+  TIMING_LOG(AIT_BUILDINGS, TIMER_START);
   ai_manage_buildings(pplayer);
+  TIMING_LOG(AIT_BUILDINGS, TIMER_STOP);
 
   /* Initialize the infrastructure cache, which is used shortly. */
   initialize_infrastructure_cache(pplayer);
   city_list_iterate(pplayer->cities, pcity) {
     /* Note that this function mungs the seamap, but we don't care */
+    TIMING_LOG(AIT_CITY_MILITARY, TIMER_START);
     military_advisor_choose_build(pplayer, pcity, &pcity->ai.choice);
+    TIMING_LOG(AIT_CITY_MILITARY, TIMER_STOP);
     /* Will record its findings in pcity->settler_want */ 
+    TIMING_LOG(AIT_CITY_TERRAIN, TIMER_START);
     contemplate_terrain_improvements(pcity);
+    TIMING_LOG(AIT_CITY_TERRAIN, TIMER_STOP);
 
+    TIMING_LOG(AIT_CITY_SETTLERS, TIMER_START);
     if (pcity->ai.next_founder_want_recalc <= game.turn) {
       /* Will record its findings in pcity->founder_want */ 
       contemplate_new_city(pcity);
       /* Avoid recalculating all the time.. */
       pcity->ai.next_founder_want_recalc = game.turn + myrand(RECALC_SPEED) + RECALC_SPEED;
-    } 
+    }
+    TIMING_LOG(AIT_CITY_SETTLERS, TIMER_STOP);
   } city_list_iterate_end;
 
   city_list_iterate(pplayer->cities, pcity) {
Index: ai/aidata.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/ai/aidata.c,v
retrieving revision 1.61
diff -u -r1.61 aidata.c
--- ai/aidata.c	21 Mar 2005 14:10:53 -0000	1.61
+++ ai/aidata.c	12 Apr 2005 14:04:58 -0000
@@ -168,7 +168,7 @@
 **************************************************************************/
 void ai_data_movemap_recalculate(void)
 {
-  TIMING_LOG(LOG_DEBUG, NULL, "Generating movemap");
+  TIMING_LOG(AIT_MOVEMAP, TIMER_START);
 
   /* Clean the slate */
   whole_map_iterate(ptile) {
@@ -224,7 +224,7 @@
     }
   } whole_map_iterate_end;
 
-  TIMING_LOG(LOG_DEBUG, NULL, "Done generating movemap");
+  TIMING_LOG(AIT_MOVEMAP, TIMER_STOP);
 }
 
 /**************************************************************************
@@ -398,7 +398,7 @@
 
   /*** Threats ***/
 
-  TIMING_LOG(LOG_DEBUG, pplayer, "Generating aidata");
+  TIMING_LOG(AIT_AIDATA, TIMER_START);
 
   ai->num_continents    = map.num_continents;
   ai->num_oceans        = map.num_oceans;
@@ -668,8 +668,12 @@
     ai->wants_no_science = FALSE;
   }
 
+  TIMING_LOG(AIT_AIDATA, TIMER_STOP);
+
   /* Government */
+  TIMING_LOG(AIT_GOVERNMENT, TIMER_START);
   ai_best_government(pplayer);
+  TIMING_LOG(AIT_GOVERNMENT, TIMER_STOP);
 }
 
 /**************************************************************************
Index: ai/aiexplorer.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/ai/aiexplorer.c,v
retrieving revision 1.9
diff -u -r1.9 aiexplorer.c
--- ai/aiexplorer.c	20 Mar 2005 12:56:20 -0000	1.9
+++ ai/aiexplorer.c	12 Apr 2005 14:04:58 -0000
@@ -277,6 +277,8 @@
     return FALSE; /* too dangerous */
   }
 
+  TIMING_LOG(AIT_EXPLORER, TIMER_START);
+
   pft_fill_unit_parameter(&parameter, punit);
   parameter.get_TB = no_fights_or_unknown;
   /* When exploring, even AI should pretend to not cheat. */
@@ -343,6 +345,8 @@
   }
   pf_destroy_map(map);
 
+  TIMING_LOG(AIT_EXPLORER, TIMER_STOP);
+
   /* Go to the best tile found. */
   if (best_tile != NULL) {
     /* TODO: read the path off the map we made.  Then we can make a path 
Index: ai/aihand.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/ai/aihand.c,v
retrieving revision 1.110
diff -u -r1.110 aihand.c
--- ai/aihand.c	28 Mar 2005 17:14:57 -0000	1.110
+++ ai/aihand.c	12 Apr 2005 14:04:58 -0000
@@ -286,7 +286,6 @@
   }
 
   if (ai->govt_reeval == 0) {
-    TIMING_LOG(LOG_DEBUG, pplayer, "Finding best government");
     government_iterate(gov) {
       int val = 0;
       int dist, i;
@@ -432,15 +431,18 @@
 **************************************************************************/
 void ai_do_first_activities(struct player *pplayer)
 {
+  TIMING_LOG(AIT_ALL, TIMER_START);
   assess_danger_player(pplayer);
   /* TODO: Make assess_danger save information on what is threatening
    * 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");
+  TIMING_LOG(AIT_UNITS, TIMER_START);
   ai_manage_units(pplayer); 
-  TIMING_LOG(LOG_DEBUG, pplayer, "All first activities done");
+  TIMING_LOG(AIT_UNITS, TIMER_STOP);
   /* STOP.  Everything else is at end of turn. */
+
+  TIMING_LOG(AIT_ALL, TIMER_STOP);
 }
 
 /**************************************************************************
@@ -453,17 +455,22 @@
 **************************************************************************/
 void ai_do_last_activities(struct player *pplayer)
 {
-  TIMING_LOG(LOG_DEBUG, pplayer, "Manage government");
+  TIMING_LOG(AIT_ALL, TIMER_START);
+
   ai_manage_government(pplayer);
-  TIMING_LOG(LOG_DEBUG, pplayer, "Manage taxes");
+  TIMING_LOG(AIT_TAXES, TIMER_START);
   ai_manage_taxes(pplayer); 
-  TIMING_LOG(LOG_DEBUG, pplayer, "Manage cities");
+  TIMING_LOG(AIT_TAXES, TIMER_STOP);
+  TIMING_LOG(AIT_CITIES, TIMER_START);
   ai_manage_cities(pplayer);
-  TIMING_LOG(LOG_DEBUG, pplayer, "Manage tech, space and aidata cleanup");
+  TIMING_LOG(AIT_CITIES, TIMER_STOP);
+  TIMING_LOG(AIT_TECH, TIMER_START);
   ai_manage_tech(pplayer); 
+  TIMING_LOG(AIT_TECH, TIMER_STOP);
   ai_manage_spaceship(pplayer);
   ai_data_phase_done(pplayer);
-  TIMING_LOG(LOG_DEBUG, pplayer, "Last activities done");
+
+  TIMING_LOG(AIT_ALL, TIMER_STOP);
 }
 
 /**************************************************************************
Index: ai/ailog.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/ai/ailog.c,v
retrieving revision 1.22
diff -u -r1.22 ailog.c
--- ai/ailog.c	21 Mar 2005 14:10:53 -0000	1.22
+++ ai/ailog.c	12 Apr 2005 14:04:58 -0000
@@ -17,6 +17,7 @@
 
 #include <stdarg.h>
 
+#include "astring.h"
 #include "city.h"
 #include "log.h"
 #include "shared.h"
@@ -31,6 +32,9 @@
 #include "aidata.h"
 #include "ailog.h"
 
+static struct timer *aitimer[AIT_LAST][2];
+static int recursion[AIT_LAST];
+
 /* General AI logging functions */
 
 /**************************************************************************
@@ -253,36 +257,81 @@
   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)
+void TIMING_LOG(enum ai_timer timer, enum ai_timer_activity activity)
 {
-  char buffer[500];
-  int minlevel = MIN(LOGLEVEL_BODYGUARD, level);
-  static struct timer *t = NULL;
   static int turn = -1;
+  int i;
 
-  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;
+  if (turn == -1) {
+    for (i = 0; i < AIT_LAST; i++) {
+      aitimer[i][0] = new_timer(TIMER_CPU, TIMER_ACTIVE);
+      aitimer[i][1] = new_timer(TIMER_CPU, TIMER_ACTIVE);
+      recursion[i] = 0;
+    }
   }
 
-  /* So that the first log won't be displayed ridiculously high */
-  if (turn != game.turn) {
+  if (game.turn != turn) {
     turn = game.turn;
-    clear_timer_start(t);
+    for (i = 0; i < AIT_LAST; i++) {
+      clear_timer(aitimer[i][0]);
+    }
+    assert(activity == TIMER_START);
   }
 
-  my_snprintf(buffer, sizeof(buffer), "... %g seconds. %s: ",
-              read_timer_seconds(t), pplayer ? pplayer->name : "(all)");
-  clear_timer_start(t);
-  cat_snprintf(buffer, sizeof(buffer), msg);
-  if (srvarg.timing_debug) {
-    notify_conn(game.est_connections, buffer);
+  if (activity == TIMER_START && recursion[timer] == 0) {
+    start_timer(aitimer[timer][0]);
+    start_timer(aitimer[timer][1]);
+    recursion[timer]++;
+  } else if (activity == TIMER_STOP && recursion[timer] == 1) {
+    stop_timer(aitimer[timer][0]);
+    stop_timer(aitimer[timer][1]);
+    recursion[timer]--;
   }
-  freelog(minlevel, buffer);
+}
+
+/**************************************************************************
+  Print results
+**************************************************************************/
+void TIMING_RESULTS(void)
+{
+  char buf[200];
+
+#define OUT(text, which)                                                 \
+  my_snprintf(buf, sizeof(buf), "  %s: %g sec turn, %g sec game", text,  \
+           read_timer_seconds(aitimer[which][0]),                        \
+           read_timer_seconds(aitimer[which][1]));                       \
+  freelog(LOG_NORMAL, buf);                                              \
+  notify_conn(game.est_connections, buf);
+
+  freelog(LOG_NORMAL, "  --- AI timing results ---");
+  notify_conn(game.est_connections, "  --- AI timing results ---");
+  OUT("Total AI time", AIT_ALL);
+  OUT("Movemap", AIT_MOVEMAP);
+  OUT("Units", AIT_UNITS);
+  OUT(" - Military", AIT_MILITARY);
+  OUT(" - Attack", AIT_ATTACK);
+  OUT(" - Defense", AIT_DEFENDERS);
+  OUT(" - Ferry", AIT_FERRY);
+  OUT(" - Rampage", AIT_RAMPAGE);
+  OUT(" - Bodyguard", AIT_BODYGUARD);
+  OUT(" - Recover", AIT_RECOVER);
+  OUT(" - Caravan", AIT_CARAVAN);
+  OUT(" - Hunter", AIT_HUNTER);
+  OUT(" - Airlift", AIT_AIRLIFT);
+  OUT(" - Diplomat", AIT_DIPLOMAT);
+  OUT(" - Air", AIT_AIRUNIT);
+  OUT(" - Explore", AIT_EXPLORER);
+  OUT("fstk", AIT_FSTK);
+  OUT("Settlers", AIT_SETTLERS);
+  OUT("Workers", AIT_WORKERS);
+  OUT("Government", AIT_GOVERNMENT);
+  OUT("Taxes", AIT_TAXES);
+  OUT("Cities", AIT_CITIES);
+  OUT(" - Buildings", AIT_BUILDINGS);
+  OUT(" - Danger", AIT_DANGER);
+  OUT(" - Worker want", AIT_CITY_TERRAIN);
+  OUT(" - Military want", AIT_CITY_MILITARY);
+  OUT(" - Settler want", AIT_CITY_SETTLERS);
+  OUT("Citizen arrange", AIT_CITIZEN_ARRANGE);
+  OUT("Tech", AIT_TECH);
 }
Index: ai/ailog.h
===================================================================
RCS file: /home/freeciv/CVS/freeciv/ai/ailog.h,v
retrieving revision 1.11
diff -u -r1.11 ailog.h
--- ai/ailog.h	20 Mar 2005 09:08:48 -0000	1.11
+++ ai/ailog.h	12 Apr 2005 14:04:58 -0000
@@ -32,6 +32,45 @@
 #define LOGLEVEL_PLAYER LOG_DEBUG
 #define LOGLEVEL_TECH LOG_DEBUG
 
+enum ai_timer {
+  AIT_ALL,
+  AIT_MOVEMAP,
+  AIT_UNITS,
+  AIT_SETTLERS,
+  AIT_WORKERS,
+  AIT_AIDATA,
+  AIT_GOVERNMENT,
+  AIT_TAXES,
+  AIT_CITIES,
+  AIT_CITIZEN_ARRANGE,
+  AIT_BUILDINGS,
+  AIT_DANGER,
+  AIT_TECH,
+  AIT_FSTK,
+  AIT_DEFENDERS,
+  AIT_CARAVAN,
+  AIT_HUNTER,
+  AIT_AIRLIFT,
+  AIT_DIPLOMAT,
+  AIT_AIRUNIT,
+  AIT_EXPLORER,
+  AIT_EMERGENCY,
+  AIT_CITY_MILITARY,
+  AIT_CITY_TERRAIN,
+  AIT_CITY_SETTLERS,
+  AIT_ATTACK,
+  AIT_MILITARY,
+  AIT_RECOVER,
+  AIT_BODYGUARD,
+  AIT_FERRY,
+  AIT_RAMPAGE,
+  AIT_LAST
+};
+
+enum ai_timer_activity  {
+  TIMER_START, TIMER_STOP
+};
+
 void TECH_LOG(int level, struct player *pplayer, Tech_Type_id id,
               const char *msg, ...)
      fc__attribute((format (printf, 4, 5)));
@@ -43,6 +82,7 @@
 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);
+void TIMING_LOG(enum ai_timer timer, enum ai_timer_activity activity);
+void TIMING_RESULTS(void);
 
 #endif  /* FC__AILOG_H */
Index: ai/aitools.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/ai/aitools.c,v
retrieving revision 1.143
diff -u -r1.143 aitools.c
--- ai/aitools.c	5 Apr 2005 20:36:09 -0000	1.143
+++ ai/aitools.c	12 Apr 2005 14:04:58 -0000
@@ -296,7 +296,7 @@
   
   /* Dead unit shouldn't reach this point */
   CHECK_UNIT(punit);
-  
+
   return (same_pos(punit->tile, dest_tile) 
           || is_tiles_adjacent(punit->tile, dest_tile));
 }
Index: ai/aiunit.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/ai/aiunit.c,v
retrieving revision 1.351
diff -u -r1.351 aiunit.c
--- ai/aiunit.c	5 Apr 2005 20:36:09 -0000	1.351
+++ ai/aiunit.c	12 Apr 2005 14:04:58 -0000
@@ -699,7 +699,8 @@
 {
   int count = punit->moves_left + 1; /* break any infinite loops */
   struct pf_path *path = NULL;
-  
+
+  TIMING_LOG(AIT_RAMPAGE, TIMER_START);  
   CHECK_UNIT(punit);
 
   assert(thresh_adj <= thresh_move);
@@ -718,6 +719,7 @@
 
   assert(!path);
 
+  TIMING_LOG(AIT_RAMPAGE, TIMER_STOP);
   return (count >= 0);
 }
 
@@ -985,6 +987,7 @@
     return;
   }
 
+  TIMING_LOG(AIT_BODYGUARD, TIMER_START);
   if (unit_role_defender(punit->type)) {
     /* 
      * This is a defending unit that doesn't need to stay put.
@@ -1002,14 +1005,13 @@
       ai_unit_new_role(punit, AIUNIT_ESCORT, acity->tile);
       punit->ai.charge = acity->id;
       BODYGUARD_LOG(LOG_DEBUG, punit, "going to defend city");
-      return;
     } else if (aunit) {
       ai_unit_new_role(punit, AIUNIT_ESCORT, aunit->tile);
       punit->ai.charge = aunit->id;
       BODYGUARD_LOG(LOG_DEBUG, punit, "going to defend unit");
-      return;
     }
   }
+  TIMING_LOG(AIT_BODYGUARD, TIMER_STOP);
 }
 
 /********************************************************************** 
@@ -1243,6 +1245,8 @@
     return 0;
   }
 
+  TIMING_LOG(AIT_FSTK, TIMER_START);
+
   /*** Part 1: Calculate targets ***/
   /* This horrible piece of code attempts to calculate the attractiveness of
    * enemy cities as targets for our units, by checking how many units are
@@ -1574,6 +1578,8 @@
     } unit_list_iterate_end;
   } players_iterate_end;
 
+  TIMING_LOG(AIT_FSTK, TIMER_STOP);
+
   return(best);
 }
 
@@ -1926,6 +1932,7 @@
      we must make sure that previously reserved ferry is freed. */
   aiferry_clear_boat(punit);
 
+  TIMING_LOG(AIT_HUNTER, TIMER_START);
   /* Try hunting with this unit */
   if (ai_hunter_qualify(pplayer, punit)) {
     int result, sanity = punit->id;
@@ -1933,12 +1940,15 @@
     UNIT_LOG(LOGLEVEL_HUNT, punit, "is qualified as hunter");
     result = ai_hunter_manage(pplayer, punit);
     if (!find_unit_by_id(sanity)) {
+      TIMING_LOG(AIT_HUNTER, TIMER_STOP);
       return; /* died */
     }
     if (result == -1) {
       (void) ai_hunter_manage(pplayer, punit); /* More carnage */
+      TIMING_LOG(AIT_HUNTER, TIMER_STOP);
       return;
     } else if (result >= 1) {
+      TIMING_LOG(AIT_HUNTER, TIMER_STOP);
       return; /* Done moving */
     } else if (punit->ai.ai_role == AIUNIT_HUNTER) {
       /* This should be very rare */
@@ -1947,6 +1957,7 @@
   } else if (punit->ai.ai_role == AIUNIT_HUNTER) {
     ai_unit_new_role(punit, AIUNIT_NONE, NULL);
   }
+  TIMING_LOG(AIT_HUNTER, TIMER_STOP);
 
   /* Do we have a specific job for this unit? If not, we default
    * to attack. */
@@ -1958,20 +1969,28 @@
     assert(FALSE); /* This is not the place for this role */
     break;
   case AIUNIT_DEFEND_HOME:
+    TIMING_LOG(AIT_DEFENDERS, TIMER_START);
     ai_military_defend(pplayer, punit);
+    TIMING_LOG(AIT_DEFENDERS, TIMER_STOP);
     break;
   case AIUNIT_ATTACK:
   case AIUNIT_NONE:
+    TIMING_LOG(AIT_ATTACK, TIMER_START);
     ai_military_attack(pplayer, punit);
+    TIMING_LOG(AIT_ATTACK, TIMER_STOP);
     break;
   case AIUNIT_ESCORT: 
+    TIMING_LOG(AIT_BODYGUARD, TIMER_START);
     ai_military_bodyguard(pplayer, punit);
+    TIMING_LOG(AIT_BODYGUARD, TIMER_STOP);
     break;
   case AIUNIT_EXPLORE:
     punit->ai.done = !(ai_manage_explorer(punit) && punit->moves_left > 0);
     break;
   case AIUNIT_RECOVER:
+    TIMING_LOG(AIT_RECOVER, TIMER_START);
     ai_manage_hitpoint_recovery(punit);
+    TIMING_LOG(AIT_RECOVER, TIMER_STOP);
     break;
   case AIUNIT_HUNTER:
     assert(FALSE); /* dealt with above */
@@ -2071,7 +2090,9 @@
 
   if ((unit_flag(punit, F_DIPLOMAT))
       || (unit_flag(punit, F_SPY))) {
+    TIMING_LOG(AIT_DIPLOMAT, TIMER_START);
     ai_manage_diplomat(pplayer, punit);
+    TIMING_LOG(AIT_DIPLOMAT, TIMER_STOP);
     return;
   } else if (unit_flag(punit, F_SETTLERS)
 	     ||unit_flag(punit, F_CITIES)) {
@@ -2079,7 +2100,9 @@
     return;
   } else if (unit_flag(punit, F_TRADE_ROUTE)
              || unit_flag(punit, F_HELP_WONDER)) {
+    TIMING_LOG(AIT_CARAVAN, TIMER_START);
     ai_manage_caravan(pplayer, punit);
+    TIMING_LOG(AIT_CARAVAN, TIMER_STOP);
     return;
   } else if (unit_has_role(punit->type, L_BARBARIAN_LEADER)) {
     ai_manage_barbarian_leader(pplayer, punit);
@@ -2087,11 +2110,15 @@
   } else if (get_transporter_capacity(punit) > 0
              && !unit_flag(punit, F_MISSILE_CARRIER)
              && punit->ai.ai_role != AIUNIT_HUNTER) {
+    TIMING_LOG(AIT_FERRY, TIMER_START);
     ai_manage_ferryboat(pplayer, punit);
+    TIMING_LOG(AIT_FERRY, TIMER_STOP);
     return;
   } else if (is_air_unit(punit)
              && punit->ai.ai_role != AIUNIT_ESCORT) {
+    TIMING_LOG(AIT_AIRUNIT, TIMER_START);
     ai_manage_airunit(pplayer, punit);
+    TIMING_LOG(AIT_AIRUNIT, TIMER_STOP);
     return;
   } else if (is_heli_unit(punit)) {
     /* TODO: We can try using air-unit code for helicopters, just
@@ -2099,7 +2126,9 @@
     punit->ai.done = TRUE; /* we did our best, which was ... nothing */
     return;
   } else if (is_military_unit(punit)) {
+    TIMING_LOG(AIT_MILITARY, TIMER_START);
     ai_manage_military(pplayer,punit); 
+    TIMING_LOG(AIT_MILITARY, TIMER_STOP);
     return;
   } else {
     int id = punit->id;
@@ -2176,7 +2205,9 @@
 **************************************************************************/
 void ai_manage_units(struct player *pplayer) 
 {
+  TIMING_LOG(AIT_AIRLIFT, TIMER_START);
   ai_airlift(pplayer);
+  TIMING_LOG(AIT_AIRLIFT, TIMER_STOP);
 
   /* Clear previous orders, if desirable, here. */
   unit_list_iterate(pplayer->units, punit) {
Index: server/cityturn.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/server/cityturn.c,v
retrieving revision 1.300
diff -u -r1.300 cityturn.c
--- server/cityturn.c	18 Mar 2005 11:26:24 -0000	1.300
+++ server/cityturn.c	12 Apr 2005 14:04:59 -0000
@@ -188,6 +188,7 @@
     pcity->server.needs_arrange = TRUE;
     return;
   }
+  TIMING_LOG(AIT_CITIZEN_ARRANGE, TIMER_START);
 
   /* Freeze the workers and make sure all the tiles around the city
    * are up to date.  Then thaw, but hackishly make sure that thaw
@@ -273,6 +274,7 @@
   sanity_check_city(pcity);
 
   city_refresh(pcity);
+  TIMING_LOG(AIT_CITIZEN_ARRANGE, TIMER_STOP);
 }
 
 /**************************************************************************
Index: server/settlers.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/server/settlers.c,v
retrieving revision 1.223
diff -u -r1.223 settlers.c
--- server/settlers.c	21 Mar 2005 12:28:00 -0000	1.223
+++ server/settlers.c	12 Apr 2005 14:04:59 -0000
@@ -1085,14 +1085,18 @@
   /*** Try find some work ***/
 
   if (unit_flag(punit, F_SETTLERS)) {
+    TIMING_LOG(AIT_WORKERS, TIMER_START);
     best_impr = evaluate_improvements(punit, &best_act, &best_tile);
+    TIMING_LOG(AIT_WORKERS, TIMER_STOP);
   }
 
   if (unit_flag(punit, F_CITIES) && pplayer->ai.control) {
     /* may use a boat: */
+    TIMING_LOG(AIT_SETTLERS, TIMER_START);
     find_best_city_placement(punit, &result, TRUE, FALSE);
     UNIT_LOG(LOG_SETTLER, punit, "city want %d (impr want %d)", result.result,
              best_impr);
+    TIMING_LOG(AIT_SETTLERS, TIMER_STOP);
     if (result.result > best_impr) {
       if (map_get_city(result.tile)) {
         UNIT_LOG(LOG_SETTLER, punit, "immigrates to %s (%d, %d)", 
Index: server/srv_main.c
===================================================================
RCS file: /home/freeciv/CVS/freeciv/server/srv_main.c,v
retrieving revision 1.242
diff -u -r1.242 srv_main.c
--- server/srv_main.c	5 Apr 2005 20:40:47 -0000	1.242
+++ server/srv_main.c	12 Apr 2005 14:04:59 -0000
@@ -193,8 +193,6 @@
   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.28
diff -u -r1.28 srv_main.h
--- server/srv_main.h	22 Mar 2005 04:03:35 -0000	1.28
+++ server/srv_main.h	12 Apr 2005 14:05:00 -0000
@@ -49,8 +49,6 @@
   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.392
diff -u -r1.392 stdinhand.c
--- server/stdinhand.c	31 Mar 2005 17:48:34 -0000	1.392
+++ server/stdinhand.c	12 Apr 2005 14:05:00 -0000
@@ -2342,13 +2342,7 @@
       }
     } 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"));
-    }
+    TIMING_RESULTS();
   } else if (strcmp(arg[0], "unit") == 0) {
     int id;
     struct unit *punit;