b82cc10fc2702cc8e03d4b59cc68c7605ccd758b
kent
  Fri Jul 15 16:37:27 2011 -0700
Reworking measureTiming messages so that parallel time is visible and a few other time consuming things are more obvious.
diff --git src/hg/hgTracks/hgTracks.c src/hg/hgTracks/hgTracks.c
index fd8256b..860982e 100644
--- src/hg/hgTracks/hgTracks.c
+++ src/hg/hgTracks/hgTracks.c
@@ -4134,33 +4134,30 @@
     if (s != NULL && !track->limitedVisSet)
 	track->visibility = hTvFromString(s);
     if (tdbIsCompositeChild(track->tdb))
         track->visibility = tdbVisLimitedByAncestry(cart, track->tdb, FALSE);
     else if (tdbIsComposite(track->tdb) && track->visibility != tvHide)
 	{
 	struct trackDb *parent = track->tdb->parent;
 	char *parentShow = NULL;
 	if (parent)
 	    parentShow = cartUsualString(cart, parent->track,
 			 parent->isShow ? "show" : "hide");
 	if (!parent || sameString(parentShow, "show"))
 	    compositeTrackVis(track);
 	}
     }
-if (measureTiming)
-    uglyTime("getTrackList");
-
 return trackList;
 }
 
 void doNextPrevItem(boolean goNext, char *trackName)
 /* In case a next item arrow was clicked on a track, change */
 /* position (i.e. winStart, winEnd, etc.) based on what track it was */
 {
 struct track *track = trackFindByName(trackList, trackName);
 if ((track != NULL) && (track->nextPrevItem != NULL))
     track->nextPrevItem(track, goNext);
 }
 
 char *collapseGroupVar(char *name)
 /* Construct cart variable name for collapsing group */
 {
@@ -4224,42 +4221,36 @@
     }
 if (cg->align)
     printf("<td align=%s>", cg->align);
 else
     printf("<td>");
 }
 
 static void pruneRedundantCartVis(struct track *trackList)
 /* When the config page or track form has been submitted, there usually
  * are many track visibility cart variables that have not been changed
  * from the default.  To keep down cart bloat, prune those out before we
  * save the cart.  changeTrackVis does this too, but this is for the
  * more common case where track visibilities are tweaked. */
 {
 struct track *track;
-if (measureTiming)
-    uglyTime("Done with trackForm");
 for (track = trackList; track != NULL; track = track->next)
     {
     char *cartVis = cartOptionalString(cart, track->track);
     if (cartVis != NULL && hTvFromString(cartVis) == track->tdb->visibility)
     cartRemove(cart, track->track);
     }
-if (measureTiming)
-    {
-    uglyTime("Pruned redundant vis from cart");
-    }
 }
 
 static int getMaxWindowToDraw(struct trackDb *tdb)
 /* If trackDb setting maxWindowToDraw exists and is a sensible size, return it, else 0. */
 {
 if (tdb == NULL)
     return 0;
 char *maxWinToDraw = trackDbSettingClosestToHome(tdb, "maxWindowToDraw");
 if (isNotEmpty(maxWinToDraw))
     {
     unsigned maxWTD = sqlUnsigned(maxWinToDraw);
     if (maxWTD > 1)
     return maxWTD;
     }
 return 0;
@@ -4596,40 +4587,46 @@
 if (!psOutput) cartSaveSession(cart);
 clearButtonJavascript = "document.TrackHeaderForm.position.value=''; document.getElementById('suggest').value='';";
 
 /* See if want to include sequence search results. */
 userSeqString = cartOptionalString(cart, "ss");
 if (userSeqString && !ssFilesExist(userSeqString))
     {
     userSeqString = NULL;
     cartRemove(cart, "ss");
     }
 if (!hideControls)
     hideControls = cartUsualBoolean(cart, "hideControls", FALSE);
 if (measureTiming)
     uglyTime("Time before getTrackList");
 trackList = getTrackList(&groupList, defaultTracks ? -1 : -2);
+if (measureTiming)
+    uglyTime("getTrackList");
 makeGlobalTrackHash(trackList);
+/* Tell tracks to load their items. */
+
 
 // honor defaultImgOrder
 if(cgiVarExists("hgt.defaultImgOrder"))
     {
     char wildCard[32];
     safef(wildCard,sizeof(wildCard),"*_%s",IMG_ORDER_VAR);
     cartRemoveLike(cart, wildCard);
     }
 parentChildCartCleanup(trackList,cart,oldVars); // Subtrack settings must be removed when composite/view settings are updated
+if (measureTiming)
+    uglyTime("parentChildCartCleanup");
 
 
 /* Honor hideAll and visAll variables */
 if (hideAll || defaultTracks)
     {
     int vis = (hideAll ? tvHide : -1);
     changeTrackVis(groupList, NULL, vis);
     }
 
 /* Before loading items, deal with the next/prev item arrow buttons if pressed. */
 if (cgiVarExists("hgt.nextItem"))
     doNextPrevItem(TRUE, cgiUsualString("hgt.nextItem", NULL));
 else if (cgiVarExists("hgt.prevItem"))
     doNextPrevItem(FALSE, cgiUsualString("hgt.prevItem", NULL));
 
@@ -4647,32 +4644,30 @@
         {
         winBaseCount = winEnd - winStart;
         insideWidth = tl.picWidth-gfxBorder-insideX;
         }
     #endif//def IMAGEv2_DRAG_SCROLL
     }
 
 char *jsCommand = cartCgiUsualString(cart, hgtJsCommand, "");
 if (!isEmpty(jsCommand))
    {
    cartRemove(cart, hgtJsCommand);
    jsCommandDispatch(jsCommand, trackList);
    }
 
 
-/* Tell tracks to load their items. */
-
 /* adjust visibility */
 for (track = trackList; track != NULL; track = track->next)
     {
     /* adjust track visibility based on supertrack just before load loop */
     if (tdbIsSuperTrackChild(track->tdb))
         limitSuperTrackVis(track);
 
     /* remove cart priority variables if they are set
        to the default values in the trackDb */
     if(!hTrackOnChrom(track->tdb, chromName))
 	{
 	track->limitedVis = tvHide;
 	track->limitedVisSet = TRUE;
 	}
     }
@@ -4711,30 +4706,32 @@
 	    checkMaxWindowToDraw(track);
 	    track->loadItems(track);
 
 	    if (measureTiming)
 		{
 		thisTime = clock1000();
 		track->loadTime = thisTime - lastTime;
 		}
 	    }
 	}
     }
 if (ptMax > 0)
     {
     /* wait for remote parallel load to finish */
     remoteParallelLoadWait(atoi(cfgOptionDefault("parallelFetch.timeout", "90")));  // wait up to default 90 seconds.
+    if (measureTiming)
+	uglyTime("Waiting for parallel (%d thread) remote data fetch", ptMax);
     }
 
 printTrackInitJavascript(trackList);
 
 /* Generate two lists of hidden variables for track group visibility.  Kludgy,
    but required b/c we have two different navigation forms on this page, but
    we want open/close changes in the bottom form to be submitted even if the user
    submits via the top form. */
 struct dyString *trackGroupsHidden1 = newDyString(1000);
 struct dyString *trackGroupsHidden2 = newDyString(1000);
 for (group = groupList; group != NULL; group = group->next)
     {
     if (group->trackList != NULL)
         {
         int looper;
@@ -5231,30 +5228,32 @@
     }
 #endif /* SLOW */
 hPrintf("</FORM>\n");
 
 /* hidden form for custom tracks CGI */
 hPrintf("<FORM ACTION='%s' NAME='customTrackForm'>", hgCustomName());
 cartSaveSession(cart);
 hPrintf("</FORM>\n");
 
 /* hidden form for track hub CGI */
 hPrintf("<FORM ACTION='%s' NAME='trackHubForm'>", hgHubConnectName());
 cartSaveSession(cart);
 hPrintf("</FORM>\n");
 
 pruneRedundantCartVis(trackList);
+if (measureTiming)
+    uglyTime("Done with trackForm");
 }
 
 static void toggleRevCmplDisp()
 /* toggle the reverse complement display mode */
 {
 // forces complement bases to match display
 revCmplDisp = !revCmplDisp;
 cartSetBooleanDb(cart, database, REV_CMPL_DISP, revCmplDisp);
 cartSetBooleanDb(cart, database, COMPLEMENT_BASES_VAR, revCmplDisp);
 }
 
 void zoomToSize(int newSize)
 /* Zoom so that center stays in same place,
  * but window is new size.  If necessary move
  * center a little bit to keep it from going past