Index: /branches/eam_branches/ipp-20150112/Ohana/src/relastro/include/relastro.h
===================================================================
--- /branches/eam_branches/ipp-20150112/Ohana/src/relastro/include/relastro.h	(revision 37962)
+++ /branches/eam_branches/ipp-20150112/Ohana/src/relastro/include/relastro.h	(revision 37963)
@@ -9,4 +9,9 @@
 // # define IDX_T off_t
 # define IDX_T int 
+
+# define LOGRTIME(MSG,...) {				\
+    gettimeofday (&stopTimer, (void *) NULL);		\
+    float dtime = DTIME (stopTimer, startTimer);	\
+    client_logger_message (MSG, __VA_ARGS__); }
 
 typedef enum {
Index: /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/MeasPosIO.c
===================================================================
--- /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/MeasPosIO.c	(revision 37962)
+++ /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/MeasPosIO.c	(revision 37963)
@@ -19,4 +19,6 @@
   MeasPos *measpos = NULL;
 
+  INITTIME;
+
   FILE *f = fopen (filename, "r");
   if (!f) {
@@ -46,4 +48,6 @@
   }
 
+  LOGRTIME("MeasPosLoad_init %s: %f sec\n", filename, dtime);
+
   // read the fits table bytes
   if (!gfits_fread_ftable_data (f, &ftable, FALSE)) {
@@ -52,4 +56,5 @@
   }
   fclose (f);
+  LOGRTIME("MeasPosLoad_read %s: %f sec\n", filename, dtime);
 
   // a bit annoying : we read the entire block of data, then extract the columns, then set the image structure values.
@@ -63,6 +68,9 @@
   GET_COLUMN (catID, 	 "CAT_ID",       int);
   GET_COLUMN (imageID, 	 "IMAGE_ID",     int);
+  LOGRTIME("MeasPosLoad_getcol %s: %f sec\n", filename, dtime);
 
   ALLOCATE (measpos, MeasPos, Nrow);
+  LOGRTIME("MeasPosLoad_alloc %s: %f sec\n", filename, dtime);
+
   for (i = 0; i < Nrow; i++) {
     measpos[i].R              = R    [i];
@@ -72,4 +80,6 @@
     measpos[i].imageID        = imageID[i];
   }
+  LOGRTIME("MeasPosLoad_convert %s: %f sec\n", filename, dtime);
+
   fprintf (stderr, "loaded data for %lld objects (* filters)\n", (long long) Nrow);
 
@@ -85,4 +95,5 @@
   gfits_free_header (&theader);
   gfits_free_table  (&ftable);
+  LOGRTIME("MeasPosLoad_cleanup %s: %f sec\n", filename, dtime);
 
   *nmeaspos = Nrow;
Index: /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/relastro_parallel_images.c
===================================================================
--- /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/relastro_parallel_images.c	(revision 37962)
+++ /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/relastro_parallel_images.c	(revision 37963)
@@ -22,6 +22,8 @@
   RegionHostTable *regionHosts = RegionHostTableLoad (CATDIR, REGION_FILE);
   int myHost = regionHosts->index[REGION_HOST_ID];
+  char *myHostName = regionHosts->hosts[myHost].hostname;
+
   RegionHostFindNeighbors (regionHosts, myHost);
-  client_logger_message ("started parallel images on %s\n", regionHosts->hosts[myHost].hostname);
+  client_logger_message ("started parallel images on %s\n", myHostName);
 
   // load the subset images belonging to this host
@@ -47,5 +49,5 @@
   }
   put_astrom_table (table);
-  client_logger_message ("loaded images on %s\n", regionHosts->hosts[myHost].hostname);
+  client_logger_message ("loaded images on %s\n", myHostName);
 
   // once we have read this table, we should remove it for repeat runs
@@ -62,10 +64,10 @@
 
   /* load catalog data from region files (hostID is 0 since we are not a client */
-  char *syncfile = make_filename (CATDIR, regionHosts->hosts[myHost].hostname, REGION_HOST_ID, "loadcat.sync");
+  char *syncfile = make_filename (CATDIR, myHostName, REGION_HOST_ID, "loadcat.sync");
   catalog = load_catalogs (skylist, &Ncatalog, TRUE, 0, NULL, syncfile);
   MARKTIME("-- load catalog data, host %d: %f sec\n", REGION_HOST_ID, dtime);
   free (syncfile);
   
-  client_logger_message ("loaded catalog data %s\n", regionHosts->hosts[myHost].hostname);
+  client_logger_message ("loaded catalog data %s\n", myHostName);
 
   // find ICRF QSOs for reference downstream (only if USE_ICRF_CORRECT)
@@ -90,5 +92,5 @@
   createStarMap (catalog, Ncatalog);
 
-  client_logger_message ("set up image indexes on %s\n", regionHosts->hosts[myHost].hostname);
+  client_logger_message ("set up image indexes on %s\n", myHostName);
 
   markObjects (catalog, Ncatalog);
@@ -96,5 +98,5 @@
   SAVEPLOT = FALSE;
 
-  client_logger_message ("starting the loops: %s\n", regionHosts->hosts[myHost].hostname);
+  client_logger_message ("starting the loops: %s\n", myHostName);
 
   /* major modes */
@@ -114,34 +116,33 @@
       if (RESET_IMAGES) {
 	UpdateMeasures (catalog, Ncatalog);
-	MARKTIME("reset measures, host %d: %f sec\n", REGION_HOST_ID, dtime);
-	client_logger_message ("reset measures: %s\n", regionHosts->hosts[myHost].hostname);
+	MARKTIME("UpdateMeasures on %s, host %d: %f sec\n", myHostName, REGION_HOST_ID, dtime);
+	LOGRTIME("UpdateMeasures on %s, host %d: %f sec\n", myHostName, REGION_HOST_ID, dtime);
       }
       for (i = 0; i < NLOOP; i++) {
 	UpdateObjects (catalog, Ncatalog, (i > 0));
-	MARKTIME("update objects loop %d, host %d: %f sec\n", i, REGION_HOST_ID, dtime);
-	client_logger_message ("update objects loop %d: %s\n", i, regionHosts->hosts[myHost].hostname);
+	LOGRTIME("UpdateObjects loop %d on %s, host %d: %f sec\n", i, myHostName, REGION_HOST_ID, dtime);
 	if ((i > 1) || !USE_GALAXY_MODEL) {
 	  // if GALAXY_MODEL is selected, we want to delay the frame correction until we have 
 	  // applied the galaxy model a couple of times.
 	  FrameCorrectionParallelSlave (catalog, Ncatalog, regionHosts, i); 
-	  MARKTIME("frame correction loop %d, host %d: %f sec\n", i, REGION_HOST_ID, dtime);
-	  client_logger_message ("frame correction loop %d: %s\n", i, regionHosts->hosts[myHost].hostname);
+	  LOGRTIME("FrameCorrection loop %d on %s, host %d: %f sec\n", i, myHostName, REGION_HOST_ID, dtime);
 	}
 	share_mean_pos (catalog, Ncatalog, regionHosts, i);
+	LOGRTIME("share_mean_pos loop %d on %s, host %d: %f sec\n", i, myHostName, REGION_HOST_ID, dtime);
 	slurp_mean_pos (catalog, Ncatalog, regionHosts, i);
-	client_logger_message ("slurp mags loop %d: %s\n", i, regionHosts->hosts[myHost].hostname);
+	LOGRTIME("slurp_mean_pos loop %d on %s, host %d: %f sec\n", i, myHostName, REGION_HOST_ID, dtime);
 
 	UpdateChips (catalog, Ncatalog);
-	MARKTIME("update chips loop %d, host %d: %f sec\n", i, REGION_HOST_ID, dtime);
-	client_logger_message ("update chips loop %d: %s\n", i, regionHosts->hosts[myHost].hostname);
+	LOGRTIME("UpdateChips loop %d on %s, host %d: %f sec\n", i, myHostName, REGION_HOST_ID, dtime);
 
 	share_image_pos (regionHosts, i);
+	LOGRTIME("share_image_pos loop on %d on %s, host %d: %f sec\n", i, myHostName, REGION_HOST_ID, dtime);
 	slurp_image_pos (catalog, Ncatalog, regionHosts, i);
-	client_logger_message ("slurp image pos loop %d: %s\n", i, regionHosts->hosts[myHost].hostname);
+	LOGRTIME("slurp_image_pos loop on %d on %s, host %d: %f sec\n", i, myHostName, REGION_HOST_ID, dtime);
 
 	share_meas_pos (catalog, Ncatalog, regionHosts, i);
+	LOGRTIME("share_meas_pos loop %d on %s, host %d: %f sec\n", i, myHostName, REGION_HOST_ID, dtime);
 	slurp_meas_pos (catalog, Ncatalog, regionHosts, i);
-	MARKTIME("done exchange loop %d, host %d: %f sec\n", i, REGION_HOST_ID, dtime);
-	client_logger_message ("slurp meas loop %d: %s\n", i, regionHosts->hosts[myHost].hostname);
+	LOGRTIME("slurp_meas_pos loop %d on %s, host %d: %f sec\n", i, myHostName, REGION_HOST_ID, dtime);
       }
       // create summary plots of the process
@@ -166,5 +167,5 @@
 
   // this is a checkpoint to make sure all hosts have finished the loop above
-  char *loopsyncfile = make_filename (CATDIR, regionHosts->hosts[myHost].hostname, REGION_HOST_ID, "loop.sync");
+  char *loopsyncfile = make_filename (CATDIR, myHostName, REGION_HOST_ID, "loop.sync");
   update_sync_file (loopsyncfile, 0);
   free (loopsyncfile);
@@ -178,5 +179,5 @@
 
   share_image_pos (regionHosts, -1);
-  client_logger_message ("share image pos loop %d: %s\n", -1, regionHosts->hosts[myHost].hostname);
+  LOGRTIME("share image pos loop %d on %s, host %d: %f sec\n", -1, myHostName, REGION_HOST_ID, dtime);
 
   exit (0);
Index: /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/share_images_pos.c
===================================================================
--- /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/share_images_pos.c	(revision 37962)
+++ /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/share_images_pos.c	(revision 37963)
@@ -60,6 +60,11 @@
   ALLOCATE (image_pos, ImagePos, 1);
 
+  INITTIME;
+  int myHost = regionHosts->index[REGION_HOST_ID];
+  char *myHostName = regionHosts->hosts[myHost].hostname;
+
   fprintf (stderr, "grabbing image mags from other hosts...\n");
 
+  LOGRTIME("image_load_start loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
   for (i = 0; i < regionHosts->Nhosts; i++) {
     if (regionHosts->hosts[i].hostID == REGION_HOST_ID) continue;
@@ -69,4 +74,5 @@
     check_sync_file (syncfile, nloop);
     free (syncfile);
+    LOGRTIME("image_load_sync host %d loop %d on %s, host %d: %f sec\n", i, nloop, myHostName, REGION_HOST_ID, dtime);
     
     off_t Nsubset;
@@ -74,6 +80,8 @@
     ImagePos *image_pos_subset = ImagePosLoad (iposfile, &Nsubset);
     free (iposfile);
+    LOGRTIME("image_load_read host %d loop %d on %s, host %d: %f sec\n", i, nloop, myHostName, REGION_HOST_ID, dtime);
 
     image_pos = merge_image_pos (image_pos, &Nimage_pos, image_pos_subset, Nsubset);
+    LOGRTIME("image_load_merge host %d loop %d on %s, host %d: %f sec\n", i, nloop, myHostName, REGION_HOST_ID, dtime);
   }
 
@@ -96,4 +104,5 @@
     images[seq].flags        = image_pos[i].flags     ;
   }
+  LOGRTIME("image_load_convert loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
 
   // load the astrometry offset maps, if they exist, and apply 
@@ -106,4 +115,5 @@
     
     AstromOffsetTable *table = AstromOffsetMapLoad (mapname, VERBOSE);
+    LOGRTIME("image_maps_load host %d loop %d on %s, host %d: %f sec\n", i, nloop, myHostName, REGION_HOST_ID, dtime);
   
     // apply table entries here to existing images
@@ -127,5 +137,8 @@
       }
     }
+    LOGRTIME("image_maps_copy host %d loop %d on %s, host %d: %f sec\n", i, nloop, myHostName, REGION_HOST_ID, dtime);
+
     AstromOffsetTableFree(table);
+    LOGRTIME("image_maps_free host %d loop %d on %s, host %d: %f sec\n", i, nloop, myHostName, REGION_HOST_ID, dtime);
   }
 
@@ -137,4 +150,5 @@
   }
   free (image_pos);
+  LOGRTIME("image_load_apply loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
 
   fprintf (stderr, "DONE grabbing image mags from other hosts\n");
Index: /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/share_mean_pos.c
===================================================================
--- /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/share_mean_pos.c	(revision 37962)
+++ /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/share_mean_pos.c	(revision 37963)
@@ -15,8 +15,12 @@
 
   int myHost = regionHosts->index[REGION_HOST_ID];
+  char *myHostName = regionHosts->hosts[myHost].hostname;
+
   double Rmin = regionHosts->hosts[myHost].Rmin;
   double Rmax = regionHosts->hosts[myHost].Rmax;
   double Dmin = regionHosts->hosts[myHost].Dmin;
   double Dmax = regionHosts->hosts[myHost].Dmax;
+
+  INITTIME;
 
   // XXX skip some catalogs based on UserPatch?
@@ -40,4 +44,5 @@
     }
   }
+  LOGRTIME("set_mean_pos loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
 
   // write out the meanmag fits table AND write state in some file
@@ -48,8 +53,10 @@
   free (meanpos);
   free (posfile);
+  LOGRTIME("MeanPosSave loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
 
   char *syncfile = make_filename (CATDIR, hostname, REGION_HOST_ID, "meanpos.sync");
   update_sync_file (syncfile, nloop);
   free (syncfile);
+  LOGRTIME("update_sync_file loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
 
   return TRUE;
@@ -64,5 +71,10 @@
   ALLOCATE (meanpos, MeanPos, 1);
 
+  int myHost = regionHosts->index[REGION_HOST_ID];
+  char *myHostName = regionHosts->hosts[myHost].hostname;
+
   fprintf (stderr, "grabbing mean object pos from other hosts...\n");
+
+  INITTIME;
 
   for (i = 0; i < regionHosts->Nhosts; i++) {
@@ -82,4 +94,5 @@
     meanpos = merge_mean_pos (meanpos, &Nmeanpos, meanposSubset, Nsubset);
   }
+  LOGRTIME("MeanPosLoad/merge_mean_pos loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
 
   for (i = 0; i < Nmeanpos; i++) {
@@ -99,4 +112,5 @@
   }
   free (meanpos);
+  LOGRTIME("match_catID_and_objID loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
 
   fprintf (stderr, "DONE grabbing mean object pos from other hosts...\n");
Index: /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/share_meas_pos.c
===================================================================
--- /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/share_meas_pos.c	(revision 37962)
+++ /branches/eam_branches/ipp-20150112/Ohana/src/relastro/src/share_meas_pos.c	(revision 37963)
@@ -14,5 +14,7 @@
   ALLOCATE (measpos, MeasPos, NMEASPOS);
 
+  INITTIME;
   int myHost = regionHosts->index[REGION_HOST_ID];
+  char *myHostName = regionHosts->hosts[myHost].hostname;
 
   // XXX skip some catalogs based on UserPatch?
@@ -33,4 +35,5 @@
     }
   }
+  LOGRTIME("set_meas_pos loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
 
   // write out the measmag fits table AND write state in some file
@@ -41,8 +44,10 @@
   free (measpos);
   free (posfile);
+  LOGRTIME("MeasPosSave loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
 
   char *syncfile = make_filename (CATDIR, hostname, REGION_HOST_ID, "measpos.sync");
   update_sync_file (syncfile, nloop);
   free (syncfile);
+  LOGRTIME("update_sync_file loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
 
   return TRUE;
@@ -59,4 +64,9 @@
   fprintf (stderr, "grabbing meas object pos from other hosts...\n");
 
+  INITTIME;
+  int myHost = regionHosts->index[REGION_HOST_ID];
+  char *myHostName = regionHosts->hosts[myHost].hostname;
+
+  LOGRTIME("meas_load_start loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
   for (i = 0; i < regionHosts->Nhosts; i++) {
     if (regionHosts->hosts[i].hostID == REGION_HOST_ID) continue;
@@ -66,4 +76,5 @@
     check_sync_file (syncfile, nloop);
     free (syncfile);
+    LOGRTIME("meas_load_sync host %d loop %d on %s, host %d: %f sec\n", i, nloop, myHostName, REGION_HOST_ID, dtime);
     
     off_t Nsubset = 0;
@@ -71,8 +82,11 @@
     MeasPos *measposSubset = MeasPosLoad (posfile, &Nsubset);
     free (posfile);
+    LOGRTIME("MeasPosLoad host %d loop %d on %s, host %d: %f sec\n", i, nloop, myHostName, REGION_HOST_ID, dtime);
 
     // merge_meas_pos reallocs measpos and frees the input measposSubset
     measpos = merge_meas_pos (measpos, &Nmeaspos, measposSubset, Nsubset);
+    LOGRTIME("merge_meas_pos host %d loop %d on %s, host %d: %f sec\n", i, nloop, myHostName, REGION_HOST_ID, dtime);
   }
+  LOGRTIME("meas_load_done loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
 
   for (i = 0; i < Nmeaspos; i++) {
@@ -99,4 +113,5 @@
   }
   free (measpos);
+  LOGRTIME("match_catID_and_objID/meas loop %d on %s, host %d: %f sec\n", nloop, myHostName, REGION_HOST_ID, dtime);
 
   fprintf (stderr, "DONE grabbing meas object pos from other hosts...\n");