changeset 116:60906f8803ef

Improved profiling
author Mike Pavone <pavone@retrodev.com>
date Wed, 13 Oct 2010 02:51:56 -0400
parents 04148770c229
children 4d089503fb51
files cbackend.rhope procprofile.py runtime/func.h runtime/object.h
diffstat 4 files changed, 78 insertions(+), 34 deletions(-) [+]
line wrap: on
line diff
--- a/cbackend.rhope	Wed Oct 13 01:18:53 2010 +0000
+++ b/cbackend.rhope	Wed Oct 13 02:51:56 2010 -0400
@@ -1484,8 +1484,10 @@
 		]Append["\n
 #ifdef ENABLE_PROFILING
 uint64_t profile_counts[END];
+uint64_t profile_nestedcounts[END];
 uint64_t profile_totals[END];
 uint64_t profile_selftotals[END];
+uint64_t profile_activationlevel[END];
 #endif
 
 int32_t rhope(uint32_t func, object ** params, uint16_t numparams, uint16_t callspace)
@@ -1613,7 +1615,7 @@
 	for (idx = 0; idx < END; ++idx)
 	{
 		if(profile_counts[idx])
-			printf(\"Func: %d\tCount: %llu\tTime: %llu\tAvg: %f\tSelf: %llu\tAvg: %f\\n\", idx, profile_counts[idx], profile_totals[idx], ((double)profile_totals[idx])/((double)profile_counts[idx]), profile_selftotals[idx], ((double)profile_selftotals[idx])/((double)profile_counts[idx]));
+			printf(\"Func: %d\tCount: %llu\tTime: %llu\tAvg: %f\tSelf: %llu\tAvg: %f\tNested Count: %llu\\n\", idx, profile_counts[idx], profile_totals[idx], ((double)profile_totals[idx])/((double)profile_counts[idx]), profile_selftotals[idx], ((double)profile_selftotals[idx])/((double)profile_counts[idx]), profile_nestedcounts[idx]);
 	}
 #endif
 	if (!numret)
--- a/procprofile.py	Wed Oct 13 01:18:53 2010 +0000
+++ b/procprofile.py	Wed Oct 13 02:51:56 2010 -0400
@@ -27,15 +27,16 @@
 	count,_,rest = rest.partition('\tTime: ')
 	total,_,rest = rest.partition('\tAvg: ')
 	avg,_,rest = rest.partition('\tSelf: ')
-	self,_,selfavg = rest.partition('\tAvg: ')
-	records.append((names[int(funcid)], int(count), int(total), float(avg), int(self), float(selfavg)))
+	self,_,rest = rest.partition('\tAvg: ')
+	selfavg,_,nestcount = rest.partition('\tNested Count: ')
+	records.append((names[int(funcid)], int(count), int(total), float(avg), int(self), float(selfavg), int(nestcount)))
 	
 	
 records.sort(key=lambda el: el[3])
 
 print 'Func\tCount\tTotal(us)\tAvg(us)\tSelf(us)\tSelf Avg(us)'
 for record in records:	
-	print '%s\t%d\t%d\t%f\t%d\t%f' % record
+	print '%s\t%d\t%d\t%f\t%d\t%f\t%d' % record
 	
 
 	
--- a/runtime/func.h	Wed Oct 13 01:18:53 2010 +0000
+++ b/runtime/func.h	Wed Oct 13 02:51:56 2010 -0400
@@ -45,57 +45,42 @@
 		my_cdata->self_accum += ((uint64_t)time.tv_sec) * 1000000ULL + ((uint64_t)time.tv_usec) - my_cdata->self_start;
 		
 #define AND_TOTAL \
+		*(my_cdata->myactivationlevel)--;\
 		my_cdata->accum += ((uint64_t)time.tv_sec) * 1000000ULL + ((uint64_t)time.tv_usec) - my_cdata->start;
 
 #define RESUME_SELF \
 		gettimeofday(&time, NULL);\
 		my_cdata->self_start = ((uint64_t)time.tv_sec) * 1000000ULL + ((uint64_t)time.tv_usec);
 		
-#define AND_RESUME_TOTAL my_cdata->start = my_cdata->self_start;
+#define AND_RESUME_TOTAL \
+		*(my_cdata->myactivationlevel)++;\
+		my_cdata->start = my_cdata->self_start;
 		
 #define EndFunc(name)	\
 		free_stack(ct, lv_ ## name);\
 		func = cdata->func;\
+		profile_activationlevel[FUNC_ ## name]--;\
 		gettimeofday(&time, NULL);\
-		profile_counts[FUNC_ ## name]++;\
-		profile_totals[FUNC_ ## name] += ((uint64_t)time.tv_sec) * 1000000ULL + ((uint64_t)time.tv_usec) - cdata->start + cdata->accum;\
+		if(profile_activationlevel[FUNC_ ## name])\
+		{\
+			profile_nestedcounts[FUNC_ ## name]++;\
+		} else {\
+			profile_counts[FUNC_ ## name]++;\
+			profile_totals[FUNC_ ## name] += ((uint64_t)time.tv_sec) * 1000000ULL + ((uint64_t)time.tv_usec) - cdata->start + cdata->accum;\
+		}\
 		profile_selftotals[FUNC_ ## name] +=  ((uint64_t)time.tv_sec) * 1000000ULL + ((uint64_t)time.tv_usec) - cdata->self_start + cdata->self_accum;
-
-#else
-
-#define START_PROFILE
-#define PAUSE_SELF
-#define RESUME_SELF
-#define AND_TOTAL
-#define AND_RESUME_TOTAL
-
-#define EndFunc(name)	\
-		free_stack(ct, lv_ ## name);\
-		func = cdata->func;
-
-
-#endif
-
-#define EndFuncNoLocals	\
-		func = cdata->func;
-
+		
 #define Func(name,numparams) \
 f_ ## name:\
 		for(idx = numparams; idx < cdata->num_params; ++idx)\
 			release_ref(cdata->params[idx]); cdata->num_params = numparams;\
 sf_ ## name:\
+		profile_activationlevel[FUNC_ ## name]++;\
+		cdata->myactivationlevel = &profile_activationlevel[FUNC_ ## name];\
 		START_PROFILE\
 		lv_ ## name = alloc_stack(ct, sizeof(lt_ ## name));\
 		my_cdata = cdata;
 
-
-#define FuncNoLocals(name,numparams) \
-f_ ## name:\
-		for(idx = numparams; idx < cdata->num_params; ++idx)\
-			release_ref(cdata->params[idx]); cdata->num_params = numparams;\
-sf_ ## name:\
-		my_cdata = cdata;		
-
 #define MethodImpl(name,type_name,mytype_id,numparams) \
 f_ ## name ## AT_ ## type_name:\
 sf_ ## name ## AT_ ## type_name:\
@@ -111,11 +96,66 @@
 			exit(1);\
 		}\
 m_ ## name ## AT_ ## type_name:\
+		profile_activationlevel[FUNC_ ## name ## AT_ ## type_name]++;\
+		cdata->myactivationlevel = &profile_activationlevel[FUNC_ ## name ## AT_ ## type_name];\
 		START_PROFILE\
 		for(idx = numparams; idx < cdata->num_params; ++idx)\
 			release_ref(cdata->params[idx]); cdata->num_params = numparams;\
 		lv_ ## name ## AT_ ## type_name = alloc_stack(ct, sizeof(lt_ ## name ## AT_ ## type_name));\
 		my_cdata = cdata;
+
+#else
+
+#define START_PROFILE
+#define PAUSE_SELF
+#define RESUME_SELF
+#define AND_TOTAL
+#define AND_RESUME_TOTAL
+
+#define EndFunc(name)	\
+		free_stack(ct, lv_ ## name);\
+		func = cdata->func;
+		
+#define Func(name,numparams) \
+f_ ## name:\
+		for(idx = numparams; idx < cdata->num_params; ++idx)\
+			release_ref(cdata->params[idx]); cdata->num_params = numparams;\
+sf_ ## name:\
+		lv_ ## name = alloc_stack(ct, sizeof(lt_ ## name));\
+		my_cdata = cdata;
+
+#define MethodImpl(name,type_name,mytype_id,numparams) \
+f_ ## name ## AT_ ## type_name:\
+sf_ ## name ## AT_ ## type_name:\
+		if (cdata->num_params < 1)\
+		{\
+			cdata = alloc_cdata(ct, cdata, 0);\
+			cdata->func = FUNC_ ## name ## AT_ ## type_name;\
+			goto _exception;\
+		}\
+		if(get_blueprint(cdata->params[0])->type_id != mytype_id)\
+		{\
+			puts("uh oh, need conversion and that's not implemented yet!");\
+			exit(1);\
+		}\
+m_ ## name ## AT_ ## type_name:\
+		for(idx = numparams; idx < cdata->num_params; ++idx)\
+			release_ref(cdata->params[idx]); cdata->num_params = numparams;\
+		lv_ ## name ## AT_ ## type_name = alloc_stack(ct, sizeof(lt_ ## name ## AT_ ## type_name));\
+		my_cdata = cdata;
+
+#endif
+
+#define EndFuncNoLocals	\
+		func = cdata->func;
+
+
+#define FuncNoLocals(name,numparams) \
+f_ ## name:\
+		for(idx = numparams; idx < cdata->num_params; ++idx)\
+			release_ref(cdata->params[idx]); cdata->num_params = numparams;\
+sf_ ## name:\
+		my_cdata = cdata;
 			
 				
 #define MethodImplNoLocals(name,type_name,mytype_id,numparams) \
--- a/runtime/object.h	Wed Oct 13 01:18:53 2010 +0000
+++ b/runtime/object.h	Wed Oct 13 02:51:56 2010 -0400
@@ -50,6 +50,7 @@
 	uint64_t        accum;
 	uint64_t        self_start;
 	uint64_t        self_accum;
+	uint64_t        *myactivationlevel;
 #endif
 	uint32_t        func;
 	uint16_t        num_params;