diff --git a/src/tests/system/kernel/Jamfile b/src/tests/system/kernel/Jamfile index 27f03e98c9..b841d855ed 100644 --- a/src/tests/system/kernel/Jamfile +++ b/src/tests/system/kernel/Jamfile @@ -1,6 +1,7 @@ SubDir HAIKU_TOP src tests system kernel ; UsePrivateKernelHeaders ; +UsePrivateHeaders shared ; SimpleTest advisory_locking_test : advisory_locking_test.cpp ; diff --git a/src/tests/system/kernel/time_stats.cpp b/src/tests/system/kernel/time_stats.cpp index 52e2c4e1ba..530f18af23 100644 --- a/src/tests/system/kernel/time_stats.cpp +++ b/src/tests/system/kernel/time_stats.cpp @@ -4,9 +4,12 @@ */ #include +#include +#include #include #include #include +#include #include #include @@ -14,9 +17,32 @@ #include +#include + +#include +#include +#include + #define MAX_THREADS 4096 +#define SCHEDULING_ANALYSIS_BUFFER_SIZE 10 * 1024 * 1024 + + +extern const char* __progname; + +static const char* kUsage = + "Usage: %s [ -h ] [ -o ] [ -s ] \n" +; + + +static void +print_usage_and_exit(bool error) +{ + fprintf(error ? stderr : stdout, kUsage, __progname); + exit(error ? 1 : 0); +} + struct UsageInfoThreadComparator { inline bool operator()(const thread_info& a, const thread_info& b) @@ -53,29 +79,19 @@ get_usage_infos(thread_info* infos) } -int -main(int argc, const char* const* argv) +static pid_t +run_child(int argc, const char* const* argv) { - if (argc < 2) { - fprintf(stderr, "Usage:...\n"); - exit(1); - } - - // gather initial usage info - thread_info initialUsage[MAX_THREADS]; - int32 initialUsageCount = get_usage_infos(initialUsage); - // fork - bigtime_t startTime = system_time(); pid_t child = fork(); if (child < 0) { - fprintf(stderr, "fork() failed: %s\n", strerror(errno)); + fprintf(stderr, "Error: fork() failed: %s\n", strerror(errno)); exit(1); } // exec child process if (child == 0) { - execvp(argv[1], (char**)(argv + 1)); + execvp(argv[0], (char**)argv); exit(1); } @@ -83,8 +99,128 @@ main(int argc, const char* const* argv) int childStatus; while (wait(&childStatus) < 0); + return child; +} + + +static const char* +wait_object_to_string(scheduling_analysis_wait_object* waitObject, char* buffer) +{ + 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, + waitObject->name); + break; + case THREAD_BLOCK_TYPE_CONDITION_VARIABLE: + sprintf(buffer, "cvar %p (%s %p)", object, waitObject->name, + waitObject->referenced_object); + break; + case THREAD_BLOCK_TYPE_SNOOZE: + strcpy(buffer, "snooze"); + break; + case THREAD_BLOCK_TYPE_SIGNAL: + strcpy(buffer, "signal"); + break; + case THREAD_BLOCK_TYPE_MUTEX: + sprintf(buffer, "mutex %p (%s)", object, waitObject->name); + break; + case THREAD_BLOCK_TYPE_RW_LOCK: + sprintf(buffer, "rwlock %p (%s)", object, waitObject->name); + break; + case THREAD_BLOCK_TYPE_OTHER: + sprintf(buffer, "other %p", object); + break; + default: + sprintf(buffer, "unknown %p", object); + break; + } + + return buffer; +} + + +static void +do_scheduling_analysis(bigtime_t startTime, bigtime_t endTime) +{ + printf("\n"); + + // allocate a chunk of memory for the scheduling analysis + void* buffer = malloc(SCHEDULING_ANALYSIS_BUFFER_SIZE); + if (buffer == NULL) { + fprintf(stderr, "Error: Failed to allocate memory for the scheduling " + "analysis.\n"); + exit(1); + } + MemoryDeleter _(buffer); + + // do the scheduling analysis + scheduling_analysis analysis; + status_t error = _kern_analyze_scheduling(startTime, endTime, buffer, + SCHEDULING_ANALYSIS_BUFFER_SIZE, &analysis); + if (error != B_OK) { + fprintf(stderr, "Error: Scheduling analysis failed: %s\n", + strerror(error)); + 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); + + for (uint32 i = 0; i < analysis.thread_count; i++) { + scheduling_analysis_thread* thread = analysis.threads[i]; + + // compute total wait time + bigtime_t waitTime = 0; + scheduling_analysis_thread_wait_object* threadWaitObject + = thread->wait_objects; + while (threadWaitObject != NULL) { + waitTime += threadWaitObject->wait_time; + threadWaitObject = threadWaitObject->next_in_list; + } + + printf("\nthread %ld \"%s\":\n", thread->id, thread->name); + printf(" run time: %lld us (%lld runs)\n", thread->total_run_time, + thread->runs); + printf(" wait time: %lld us\n", waitTime); + printf(" latencies: %lld us (%lld)\n", thread->total_latency, + thread->latencies); + 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; + } + } +} + + +static void +do_timing_analysis(int argc, const char* const* argv, bool schedulingAnalysis, + int outFD) +{ + // gather initial usage info + thread_info initialUsage[MAX_THREADS]; + int32 initialUsageCount = get_usage_infos(initialUsage); + + // exec child process + bigtime_t startTime = system_time(); + pid_t child = run_child(argc, argv); + // get child usage info - bigtime_t runTime = system_time() - startTime; + bigtime_t endTime = system_time(); + bigtime_t runTime = endTime - startTime; team_usage_info childUsage; get_team_usage_info(B_CURRENT_TEAM, B_TEAM_USAGE_CHILDREN, &childUsage); @@ -154,6 +290,10 @@ main(int argc, const char* const* argv) std::sort(sortedThreads, sortedThreads + sortedThreadCount, UsageInfoTimeComparator()); + // redirect output, if requested + if (outFD >= 0) + dup2(outFD, STDOUT_FILENO); + // print results printf("\nTotal run time: %lld us\n", runTime); printf("Thread time statistics in us:\n\n"); @@ -186,5 +326,62 @@ main(int argc, const char* const* argv) printf("%7ld %-32s \n", info.thread, info.name); } + if (schedulingAnalysis) + do_scheduling_analysis(startTime, endTime); +} + + +int +main(int argc, const char* const* argv) +{ + const char* outputFile = NULL; + bool schedulingAnalysis = false; + + while (true) { + static struct option sLongOptions[] = { + { "help", no_argument, 0, 'h' }, + { "output", required_argument, 0, 'o' }, + { 0, 0, 0, 0 } + }; + + opterr = 0; // don't print errors + int c = getopt_long(argc, (char**)argv, "ho:s", sLongOptions, NULL); + if (c == -1) + break; + + switch (c) { + case 'h': + print_usage_and_exit(false); + break; + case 'o': + outputFile = optarg; + break; + case 's': + schedulingAnalysis = true; + break; + + default: + print_usage_and_exit(true); + break; + } + } + + if (optind >= argc) + print_usage_and_exit(true); + + // open output file, if specified + int outFD = -1; + if (outputFile != NULL) { + outFD = open(outputFile, O_WRONLY | O_CREAT | O_TRUNC, + S_IRUSR | S_IWUSR | S_IRGRP | S_IWGRP| S_IROTH | S_IWOTH); + if (outFD < 0) { + fprintf(stderr, "Error: Failed to open \"%s\": %s\n", outputFile, + strerror(errno)); + exit(1); + } + } + + do_timing_analysis(argc - optind, argv + optind, schedulingAnalysis, outFD); + return 0; }