* In the timing table user and kernel time were swapped.

* Scheduling analysis output:
  - Sort the threads by total run time.
  - Group the locking primitives a thread has waited on by common type
    and name. E.g. all "I/O request finished" condition variables are
    put in a single group. The sum wait time and wait count is printed
    for the group, so it is easy to see how often and how long the
    thread had waited for I/O.
  - Both the groups and their elements are sorted by wait time.


git-svn-id: file:///srv/svn/repos/haiku/haiku/trunk@27313 a95241bf-73f2-0310-859d-f6bbb57e9c96

src/tests/system/kernel/time_stats.cpp

@@ -60,6 +60,51 @@ struct UsageInfoTimeComparator {
 };
 
 
+struct wait_object_group {
+	scheduling_analysis_thread_wait_object**	objects;
+	int32										count;
+	bigtime_t									wait_time;
+	int64										waits;
+};
+
+struct ThreadRunTimeComparator {
+	inline bool operator()(const scheduling_analysis_thread* a,
+		const scheduling_analysis_thread* b)
+	{
+		return a->total_run_time > b->total_run_time;
+	}
+};
+
+
+struct WaitObjectGroupingComparator {
+	inline bool operator()(const scheduling_analysis_thread_wait_object* a,
+		const scheduling_analysis_thread_wait_object* b)
+	{
+		return a->wait_object->type < b->wait_object->type
+			|| a->wait_object->type == b->wait_object->type
+				&& strcmp(a->wait_object->name, b->wait_object->name) < 0;
+	}
+};
+
+
+struct WaitObjectTimeComparator {
+	inline bool operator()(const scheduling_analysis_thread_wait_object* a,
+		const scheduling_analysis_thread_wait_object* b)
+	{
+		return a->wait_time > b->wait_time;
+	}
+};
+
+
+struct WaitObjectGroupTimeComparator {
+	inline bool operator()(const wait_object_group& a,
+		const wait_object_group& b)
+	{
+		return a.wait_time > b.wait_time;
+	}
+};
+
+
 static int32
 get_usage_infos(thread_info* infos)
 {
@@ -104,19 +149,28 @@ run_child(int argc, const char* const* argv)
 
 
 static const char*
-wait_object_to_string(scheduling_analysis_wait_object* waitObject, char* buffer)
+wait_object_to_string(scheduling_analysis_wait_object* waitObject, char* buffer,
+	bool nameOnly = false)
 {
 	uint32 type = waitObject->type;
 	void* object = waitObject->object;
 
 	switch (type) {
 		case THREAD_BLOCK_TYPE_SEMAPHORE:
-			sprintf(buffer, "sem %ld (%s)", (sem_id)(addr_t)object,
+			if (nameOnly) {
-				waitObject->name);
+				sprintf(buffer, "sem \"%s\"", waitObject->name);
+			} else {
+				sprintf(buffer, "sem %ld (%s)", (sem_id)(addr_t)object,
+					waitObject->name);
+			}
 			break;
 		case THREAD_BLOCK_TYPE_CONDITION_VARIABLE:
-			sprintf(buffer, "cvar %p (%s %p)", object, waitObject->name,
+			if (nameOnly) {
-				waitObject->referenced_object);
+				sprintf(buffer, "cvar \"%s\"", waitObject->name);
+			} else {
+				sprintf(buffer, "cvar %p (%s %p)", object, waitObject->name,
+					waitObject->referenced_object);
+			}
 			break;
 		case THREAD_BLOCK_TYPE_SNOOZE:
 			strcpy(buffer, "snooze");
@@ -125,13 +179,19 @@ wait_object_to_string(scheduling_analysis_wait_object* waitObject, char* buffer)
 			strcpy(buffer, "signal");
 			break;
 		case THREAD_BLOCK_TYPE_MUTEX:
-			sprintf(buffer, "mutex %p (%s)", object, waitObject->name);
+			if (nameOnly)
+				sprintf(buffer, "mutex \"%s\"", waitObject->name);
+			else
+				sprintf(buffer, "mutex %p (%s)", object, waitObject->name);
 			break;
 		case THREAD_BLOCK_TYPE_RW_LOCK:
-			sprintf(buffer, "rwlock %p (%s)", object, waitObject->name);
+			if (nameOnly)
+				sprintf(buffer, "rwlock \"%s\"", waitObject->name);
+			else
+				sprintf(buffer, "rwlock %p (%s)", object, waitObject->name);
 			break;
 		case THREAD_BLOCK_TYPE_OTHER:
-			sprintf(buffer, "other %p", object);
+			sprintf(buffer, "other %p (%s)", object, waitObject->name);
 			break;
 		default:
 			sprintf(buffer, "unknown %p", object);
@@ -166,22 +226,77 @@ do_scheduling_analysis(bigtime_t startTime, bigtime_t endTime)
 		exit(1);
 	}
 
+	// allocate arrays for grouping and sorting the wait objects
+	scheduling_analysis_thread_wait_object** waitObjects
+		= new(std::nothrow) scheduling_analysis_thread_wait_object*[
+			analysis.thread_wait_object_count];
+	ArrayDeleter<scheduling_analysis_thread_wait_object*> _2(waitObjects);
+
+	wait_object_group* waitObjectGroups = new(std::nothrow) wait_object_group[
+		analysis.thread_wait_object_count];
+	ArrayDeleter<wait_object_group> _3(waitObjectGroups);
+
+	if (waitObjects == NULL || waitObjectGroups == NULL) {
+		fprintf(stderr, "Error: Out of memory\n");
+		exit(1);
+	}
+
 	printf("scheduling analysis: %lu threads, %llu wait objects, "
 		"%llu thread wait objects\n", analysis.thread_count,
 		analysis.wait_object_count, analysis.thread_wait_object_count);
 
+	// sort the thread by run time
+	std::sort(analysis.threads, analysis.threads + analysis.thread_count,
+		ThreadRunTimeComparator());
+
 	for (uint32 i = 0; i < analysis.thread_count; i++) {
 		scheduling_analysis_thread* thread = analysis.threads[i];
 
-		// compute total wait time
+		// compute total wait time and prepare the objects for sorting
+		int32 waitObjectCount = 0;
 		bigtime_t waitTime = 0;
 		scheduling_analysis_thread_wait_object* threadWaitObject
 			= thread->wait_objects;
 		while (threadWaitObject != NULL) {
+			waitObjects[waitObjectCount++] = threadWaitObject;
 			waitTime += threadWaitObject->wait_time;
 			threadWaitObject = threadWaitObject->next_in_list;
 		}
 
+		// sort the wait objects by type + name
+		std::sort(waitObjects, waitObjects + waitObjectCount,
+			WaitObjectGroupingComparator());
+
+		// create the groups
+		wait_object_group* group = NULL;
+		int32 groupCount = 0;
+		for (int32 i = 0; i < waitObjectCount; i++) {
+			scheduling_analysis_thread_wait_object* threadWaitObject
+				= waitObjects[i];
+			scheduling_analysis_wait_object* waitObject
+				= threadWaitObject->wait_object;
+
+			if (groupCount == 0 || strcmp(waitObject->name, "?") == 0
+				|| waitObject->type != group->objects[0]->wait_object->type
+				|| strcmp(waitObject->name,
+						group->objects[0]->wait_object->name) != 0) {
+				// create a new group
+				group = &waitObjectGroups[groupCount++];
+				group->objects = waitObjects + i;
+				group->count = 0;
+				group->wait_time = 0;
+				group->waits = 0;
+			}
+
+			group->count++;
+			group->wait_time += threadWaitObject->wait_time;
+			group->waits += threadWaitObject->waits;
+		}
+
+		// sort the groups by wait time
+		std::sort(waitObjectGroups, waitObjectGroups + groupCount,
+			WaitObjectGroupTimeComparator());
+
 		printf("\nthread %ld \"%s\":\n", thread->id, thread->name);
 		printf("  run time:    %lld us (%lld runs)\n", thread->total_run_time,
 			thread->runs);
@@ -191,16 +306,43 @@ do_scheduling_analysis(bigtime_t startTime, bigtime_t endTime)
 		printf("  preemptions: %lld us (%lld)\n", thread->total_rerun_time,
 			thread->reruns);
 		printf("  unspecified: %lld us\n", thread->unspecified_wait_time);
-		printf("  waited on:\n");
-		threadWaitObject = thread->wait_objects;
-		while (threadWaitObject != NULL) {
-			scheduling_analysis_wait_object* waitObject
-				= threadWaitObject->wait_object;
-			char buffer[1024];
-			wait_object_to_string(waitObject, buffer);
-			printf("    %s: %lld us\n", buffer, threadWaitObject->wait_time);
 
-			threadWaitObject = threadWaitObject->next_in_list;
+		printf("  waited on:\n");
+		for (int32 i = 0; i < groupCount; i++) {
+			wait_object_group& group = waitObjectGroups[i];
+			char buffer[1024];
+
+			if (group.count == 1) {
+				// only one element -- just print it
+				scheduling_analysis_thread_wait_object* threadWaitObject
+					= group.objects[0];
+				scheduling_analysis_wait_object* waitObject
+					= threadWaitObject->wait_object;
+				wait_object_to_string(waitObject, buffer);
+				printf("    %s: %lld us (%lld)\n", buffer,
+					threadWaitObject->wait_time, threadWaitObject->waits);
+			} else {
+				// sort the wait objects by wait time
+				std::sort(group.objects, group.objects + group.count,
+					WaitObjectTimeComparator());
+
+				// print the group line
+				wait_object_to_string(group.objects[0]->wait_object, buffer,
+					true);
+				printf("    group %s: %lld us (%lld)\n", buffer,
+					group.wait_time, group.waits);
+
+				// print the wait objects
+				for (int32 k = 0; k < group.count; k++) {
+					scheduling_analysis_thread_wait_object* threadWaitObject
+						= group.objects[k];
+					scheduling_analysis_wait_object* waitObject
+						= threadWaitObject->wait_object;
+					wait_object_to_string(waitObject, buffer);
+					printf("      %s: %lld us (%lld)\n", buffer,
+						threadWaitObject->wait_time, threadWaitObject->waits);
+				}
+			}
 		}
 	}
 }
@@ -314,7 +456,7 @@ do_timing_analysis(int argc, const char* const* argv, bool schedulingAnalysis,
 
 		bigtime_t total = info.user_time + info.kernel_time;
 		printf("%7ld  %-32s  %10lld  %10lld  %10lld  %6.2f\n", info.thread,
-			info.name, info.user_time, info.kernel_time, total,
+			info.name, info.kernel_time, info.user_time, total,
 			(double)total / runTime * 100);
 
 		if (highlight)