profiling: add callgraph report

This patch also tracks who called a template and how often. Based on that the
output of xsltproc --profile now also contains a gprof alike callgraph. If available
posix monotonic clocks are the preferred way to get timestamps.

5 files changed, 250 insertions, 31 deletions

diff --git a/configure.in b/configure.in
index 7fef7a2f..d4418d33 100644
--- a/configure.in
+++ b/configure.in
@@ -239,6 +239,8 @@ AC_CHECK_FUNC(floor, , AC_CHECK_LIB(m, floor,
 
 AC_CHECK_FUNC(fabs, , AC_CHECK_LIB(m, fabs,
   [M_LIBS="-lm"; AC_DEFINE(HAVE_FABS)]))
+
+
 AC_CHECK_FUNCS(gettimeofday)
 AC_CHECK_FUNCS(mktime localtime localtime_r asctime time gmtime_r ftime)
 
@@ -246,6 +248,14 @@ dnl Checking the standard string functions availability
 AC_CHECK_FUNCS(printf sprintf fprintf snprintf vfprintf vsprintf vsnprintf sscanf,,
                NEED_TRIO=1)
 
+dnl Checking for POSIX timers
+AC_CHECK_FUNCS(clock_gettime, [], [
+  AC_CHECK_LIB(rt, clock_gettime, [
+    AC_DEFINE(HAVE_CLOCK_GETTIME, 1)
+    EXTRA_LIBS="$EXTRA_LIBS -lrt"
+  ])
+])
+
 dnl
 dnl Check for trio string functions
 dnl
@@ -458,7 +468,7 @@ dnl the ability to specify the location of the libxml
 dnl library during linking and compilation.
 dnl
 dnl original work - Mathieu Lacage 30/03/2000
-dnl some tweaking - David Härdeman 30/10/2001
+dnl some tweaking - David Härdeman 30/10/2001
 dnl
 
 LIBXML_CONFIG_PREFIX=""
diff --git a/libxslt/transform.c b/libxslt/transform.c
index a4ca41df..948d7d04 100644
--- a/libxslt/transform.c
+++ b/libxslt/transform.c
@@ -125,7 +125,7 @@ templPush(xsltTransformContextPtr ctxt, xsltTemplatePtr value)
             return (0);
         }
     }
-    if (ctxt->templNr >= ctxt->templMax) {
+    else if (ctxt->templNr >= ctxt->templMax) {
         ctxt->templMax *= 2;
         ctxt->templTab =
             (xsltTemplatePtr *) xmlRealloc(ctxt->templTab,
@@ -249,7 +249,7 @@ profPush(xsltTransformContextPtr ctxt, long value)
             return (0);
         }
     }
-    if (ctxt->profNr >= ctxt->profMax) {
+    else if (ctxt->profNr >= ctxt->profMax) {
         ctxt->profMax *= 2;
         ctxt->profTab =
             (long *) xmlRealloc(ctxt->profTab,
@@ -288,6 +288,54 @@ profPop(xsltTransformContextPtr ctxt)
     return (ret);
 }
 
+static void
+profCallgraphAdd(xsltTemplatePtr templ, xsltTemplatePtr parent)
+{
+    int i;
+  
+    if (templ->templMax == 0) {
+        templ->templMax = 4;
+        templ->templCalledTab =
+            (xsltTemplatePtr *) xmlMalloc(templ->templMax *
+                                          sizeof(templ->templCalledTab[0]));
+        templ->templCountTab =
+            (int *) xmlMalloc(templ->templMax *
+                                          sizeof(templ->templCountTab[0]));
+        if (templ->templCalledTab == NULL || templ->templCountTab == NULL) {
+            xmlGenericError(xmlGenericErrorContext, "malloc failed !\n");
+            return;
+        }
+    }
+    else if (templ->templNr >= templ->templMax) {
+        templ->templMax *= 2;
+        templ->templCalledTab =
+            (xsltTemplatePtr *) xmlRealloc(templ->templCalledTab,
+                                           templ->templMax *
+                                           sizeof(templ->templCalledTab[0]));
+        templ->templCountTab =
+            (int *) xmlRealloc(templ->templCountTab,
+                                           templ->templMax *
+                                           sizeof(templ->templCountTab[0]));
+        if (templ->templCalledTab == NULL || templ->templCountTab == NULL) {
+            xmlGenericError(xmlGenericErrorContext, "realloc failed !\n");
+            return;
+        }
+    }
+
+    for (i = 0; i < templ->templNr; i++) {
+        if (templ->templCalledTab[i] == parent) {
+            templ->templCountTab[i]++;
+            break;
+        }
+    }
+    if (i == templ->templNr) {
+        /* not found, add new one */
+        templ->templCalledTab[templ->templNr] = parent;
+        templ->templCountTab[templ->templNr] = 1;
+        templ->templNr++;
+    }
+}
+
 /************************************************************************
  *									*
  *			XInclude default settings			*
@@ -2964,6 +3012,7 @@ xsltApplyXSLTTemplate(xsltTransformContextPtr ctxt,
 	templ->nbCalls++;
 	start = xsltTimestamp();
 	profPush(ctxt, 0);
+	profCallgraphAdd(templ, ctxt->templ);
     }
     /*
     * Push the xsl:template declaration onto the stack.
diff --git a/libxslt/xslt.c b/libxslt/xslt.c
index 55f505b4..dd58f814 100644
--- a/libxslt/xslt.c
+++ b/libxslt/xslt.c
@@ -417,6 +417,11 @@ xsltFreeTemplate(xsltTemplatePtr template) {
     if (template->modeURI) xmlFree(template->modeURI);
  */
     if (template->inheritedNs) xmlFree(template->inheritedNs);
+    
+    /* free profiling data */
+    if (template->templCalledTab) xmlFree(template->templCalledTab);
+    if (template->templCountTab) xmlFree(template->templCountTab);
+    
     memset(template, -1, sizeof(xsltTemplate));
     xmlFree(template);
 }
@@ -5167,7 +5172,7 @@ xsltParseXSLTTemplate(xsltCompilerCtxtPtr cctxt, xmlNodePtr templNode) {
 	/*
 	* TODO: We need a standardized function for extraction
 	*  of namespace names and local names from QNames.
-	*  Don't use xsltGetQNameURI() as it cannot channeö
+	*  Don't use xsltGetQNameURI() as it cannot channe�
 	*  reports through the context.
 	*/
 	modeURI = xsltGetQNameURI(templNode, &prop);
diff --git a/libxslt/xsltInternals.h b/libxslt/xsltInternals.h
index e991a93c..764fe8c3 100644
--- a/libxslt/xsltInternals.h
+++ b/libxslt/xsltInternals.h
@@ -294,6 +294,11 @@ struct _xsltTemplate {
     int nbCalls;        /* the number of time the template was called */
     unsigned long time; /* the time spent in this template */
     void *params;       /* xsl:param instructions */
+    
+    int              templNr;		/* Nb of templates in the stack */
+    int              templMax;		/* Size of the templtes stack */
+    xsltTemplatePtr *templCalledTab;	/* templates called */
+    int             *templCountTab;  /* .. and how often */
 };
 
 /**
diff --git a/libxslt/xsltutils.c b/libxslt/xsltutils.c
index 9565e152..44e80a7a 100644
--- a/libxslt/xsltutils.c
+++ b/libxslt/xsltutils.c
@@ -19,6 +19,7 @@
 #endif
 
 #include <string.h>
+#include <time.h>
 #ifdef HAVE_SYS_TIME_H
 #include <sys/time.h>
 #endif
@@ -1840,7 +1841,28 @@ xsltTimestamp(void)
     return (long) (seconds * XSLT_TIMESTAMP_TICS_PER_SEC);
 
 #else /* XSLT_WIN32_PERFORMANCE_COUNTER */
-#ifdef HAVE_GETTIMEOFDAY
+#ifdef HAVE_CLOCK_GETTIME
+    static struct timespec startup;
+    struct timespec cur;
+    long tics;
+
+    if (calibration < 0) {
+        clock_gettime(CLOCK_MONOTONIC, &startup);
+        calibration = 0;
+        calibration = xsltCalibrateTimestamps();
+        clock_gettime(CLOCK_MONOTONIC, &startup);
+        return (0);
+    }
+
+    clock_gettime(CLOCK_MONOTONIC, &cur);
+    tics = (cur.tv_sec - startup.tv_sec) * XSLT_TIMESTAMP_TICS_PER_SEC;
+    tics += (cur.tv_nsec - startup.tv_nsec) /
+                          (1000000000l / XSLT_TIMESTAMP_TICS_PER_SEC);
+
+    tics -= calibration;
+    return(tics);
+
+#elif HAVE_GETTIMEOFDAY
     static struct timeval startup;
     struct timeval cur;
     long tics;
@@ -1870,6 +1892,30 @@ xsltTimestamp(void)
 #endif /* XSLT_WIN32_PERFORMANCE_COUNTER */
 }
 
+static char *
+pretty_templ_match(xsltTemplatePtr templ) {
+  static char dst[1001];
+  char *src = (char *)templ->match;
+  int i=0,j;
+  
+  /* strip white spaces */
+  for (j=0; i<1000 && src[j]; i++,j++) {
+      for(;src[j]==' ';j++);
+      dst[i]=src[j];
+  }
+  if(i<998 && templ->mode) {
+    /* append [mode] */
+    dst[i++]='[';
+    src=(char *)templ->mode;
+    for (j=0; i<999 && src[j]; i++,j++) {
+      dst[i]=src[j];
+    }
+    dst[i++]=']';
+  }
+  dst[i]='\0';
+  return dst;
+}
+
 #define MAX_TEMPLATES 10000
 
 /**
@@ -1881,13 +1927,14 @@ xsltTimestamp(void)
  */
 void
 xsltSaveProfiling(xsltTransformContextPtr ctxt, FILE *output) {
-    int nb, i,j;
+    int nb, i,j,k,l;
     int max;
     int total;
     long totalt;
     xsltTemplatePtr *templates;
     xsltStylesheetPtr style;
-    xsltTemplatePtr template;
+    xsltTemplatePtr templ1,templ2;
+    int *childt;
 
     if ((output == NULL) || (ctxt == NULL))
 	return;
@@ -1902,14 +1949,14 @@ xsltSaveProfiling(xsltTransformContextPtr ctxt, FILE *output) {
 
     style = ctxt->style;
     while (style != NULL) {
-	template = style->templates;
-	while (template != NULL) {
+	templ1 = style->templates;
+	while (templ1 != NULL) {
 	    if (nb >= max)
 		break;
 
-	    if (template->nbCalls > 0)
-		templates[nb++] = template;
-	    template = template->next;
+	    if (templ1->nbCalls > 0)
+		templates[nb++] = templ1;
+	    templ1 = templ1->next;
 	}
 
 	style = xsltNextImport(style);
@@ -1920,51 +1967,154 @@ xsltSaveProfiling(xsltTransformContextPtr ctxt, FILE *output) {
 	    if ((templates[i]->time <= templates[j]->time) ||
 		((templates[i]->time == templates[j]->time) &&
 	         (templates[i]->nbCalls <= templates[j]->nbCalls))) {
-		template = templates[j];
+		templ1 = templates[j];
 		templates[j] = templates[i];
-		templates[i] = template;
+		templates[i] = templ1;
 	    }
 	}
     }
 
+
+    /* print flat profile */
+
     fprintf(output, "%6s%20s%20s%10s  Calls Tot 100us Avg\n\n",
 	    "number", "match", "name", "mode");
     total = 0;
     totalt = 0;
     for (i = 0;i < nb;i++) {
+         templ1 = templates[i];
 	fprintf(output, "%5d ", i);
-	if (templates[i]->match != NULL) {
-	    if (xmlStrlen(templates[i]->match) > 20)
-		fprintf(output, "%s\n%26s", templates[i]->match, "");
+	if (templ1->match != NULL) {
+	    if (xmlStrlen(templ1->match) > 20)
+		fprintf(output, "%s\n%26s", templ1->match, "");
 	    else
-		fprintf(output, "%20s", templates[i]->match);
+		fprintf(output, "%20s", templ1->match);
 	} else {
 	    fprintf(output, "%20s", "");
 	}
-	if (templates[i]->name != NULL) {
-	    if (xmlStrlen(templates[i]->name) > 20)
-		fprintf(output, "%s\n%46s", templates[i]->name, "");
+	if (templ1->name != NULL) {
+	    if (xmlStrlen(templ1->name) > 20)
+		fprintf(output, "%s\n%46s", templ1->name, "");
 	    else
-		fprintf(output, "%20s", templates[i]->name);
+		fprintf(output, "%20s", templ1->name);
 	} else {
 	    fprintf(output, "%20s", "");
 	}
-	if (templates[i]->mode != NULL) {
-	    if (xmlStrlen(templates[i]->mode) > 10)
-		fprintf(output, "%s\n%56s", templates[i]->mode, "");
+	if (templ1->mode != NULL) {
+	    if (xmlStrlen(templ1->mode) > 10)
+		fprintf(output, "%s\n%56s", templ1->mode, "");
 	    else
-		fprintf(output, "%10s", templates[i]->mode);
+		fprintf(output, "%10s", templ1->mode);
 	} else {
 	    fprintf(output, "%10s", "");
 	}
-	fprintf(output, " %6d", templates[i]->nbCalls);
-	fprintf(output, " %6ld %6ld\n", templates[i]->time,
-		templates[i]->time / templates[i]->nbCalls);
-	total += templates[i]->nbCalls;
-	totalt += templates[i]->time;
+	fprintf(output, " %6d", templ1->nbCalls);
+	fprintf(output, " %6ld %6ld\n", templ1->time,
+		templ1->time / templ1->nbCalls);
+	total += templ1->nbCalls;
+	totalt += templ1->time;
     }
     fprintf(output, "\n%30s%26s %6d %6ld\n", "Total", "", total, totalt);
 
+
+    /* print call graph */
+
+    childt = xmlMalloc((nb + 1) * sizeof(int));
+    if (childt == NULL)
+	return;
+      
+    /* precalculate children times */
+    for (i = 0; i < nb; i++) {
+        templ1 = templates[i];
+  
+        childt[i] = 0;
+        for (k = 0; k < nb; k++) {
+            templ2 = templates[k];
+            for (l = 0; l < templ2->templNr; l++) {
+                if (templ2->templCalledTab[l] == templ1) {
+                    childt[i] +=templ2->time;
+                }
+            }
+        }
+    }
+    childt[i] = 0;
+     
+    fprintf(output, "\nindex %% time    self  children    called     name\n");
+    
+    for (i = 0; i < nb; i++) {
+        char ix_str[20], timep_str[20], times_str[20], timec_str[20], called_str[20];
+        int t;
+
+        templ1 = templates[i];
+        /* callers */
+        for (j = 0; j < templ1->templNr; j++) {
+            templ2 = templ1->templCalledTab[j];
+            for (k = 0; k < nb; k++) {
+              if (templates[k] == templ2)
+                break;
+            }
+            t=templ2?templ2->time:totalt;
+            sprintf(times_str,"%8.3f",(float)t/XSLT_TIMESTAMP_TICS_PER_SEC);
+            sprintf(timec_str,"%8.3f",(float)childt[k]/XSLT_TIMESTAMP_TICS_PER_SEC);
+            sprintf(called_str,"%6d/%d",
+                templ1->templCountTab[j], /* number of times caller calls 'this' */
+                templ1->nbCalls);         /* total number of calls to 'this' */
+
+            fprintf(output, "             %-8s %-8s %-12s     %s [%d]\n",
+                times_str,timec_str,called_str,
+                (templ2?(templ2->name?(char *)templ2->name:pretty_templ_match(templ2)):"-"),k);
+        }
+        /* this */
+        sprintf(ix_str,"[%d]",i);
+        sprintf(timep_str,"%6.2f",(float)templ1->time*100.0/totalt);
+        sprintf(times_str,"%8.3f",(float)templ1->time/XSLT_TIMESTAMP_TICS_PER_SEC);
+        sprintf(timec_str,"%8.3f",(float)childt[i]/XSLT_TIMESTAMP_TICS_PER_SEC);
+        fprintf(output, "%-5s %-6s %-8s %-8s %6d     %s [%d]\n",
+            ix_str, timep_str,times_str,timec_str, 
+            templ1->nbCalls,
+            templ1->name?(char *)templ1->name:pretty_templ_match(templ1),i);
+        /* callees
+         * - go over templates[0..nb] and their templCalledTab[]
+         * - print those where we in the the call-stack
+         */
+        total = 0;
+        for (k = 0; k < nb; k++) {
+            templ2 = templates[k];
+            for (l = 0; l < templ2->templNr; l++) {
+                if (templ2->templCalledTab[l] == templ1) {
+                    total+=templ2->templCountTab[l];
+                }
+            }
+        }
+        for (k = 0; k < nb; k++) {
+            templ2 = templates[k];
+            for (l = 0; l < templ2->templNr; l++) {
+                if (templ2->templCalledTab[l] == templ1) {
+                    sprintf(times_str,"%8.3f",(float)templ2->time/XSLT_TIMESTAMP_TICS_PER_SEC);
+                    sprintf(timec_str,"%8.3f",(float)childt[k]/XSLT_TIMESTAMP_TICS_PER_SEC);
+                    sprintf(called_str,"%6d/%d",
+                        templ2->templCountTab[l], /* number of times 'this' calls callee */
+                        total);                   /* total number of calls from 'this' */
+                    fprintf(output, "             %-8s %-8s %-12s     %s [%d]\n",
+                        times_str,timec_str,called_str,
+                        templ2->name?(char *)templ2->name:pretty_templ_match(templ2),k);
+                }
+            }
+        }
+        fprintf(output, "-----------------------------------------------\n");
+    }
+    
+    fprintf(output, "\f\nIndex by function name\n");
+    for (i = 0; i < nb; i++) {
+        templ1 = templates[i];
+        fprintf(output, "[%d] %s (%s:%d)\n",
+            i, templ1->name?(char *)templ1->name:pretty_templ_match(templ1),
+            templ1->style->doc->URL,templ1->elem->line);
+    }
+    
+    fprintf(output, "\f\n");
+    xmlFree(childt);
+
     xmlFree(templates);
 }