From d44891bf40e8e201b1ef2cc42ea0fe93fdc93d0a Mon Sep 17 00:00:00 2001 From: Nick Barnes Date: Thu, 4 Jul 2002 16:10:08 +0100 Subject: [PATCH] Better timing test for amc. Copied from Perforce Change: 30791 ServerID: perforce.ravenbrook.com --- mps/code/steptest.c | 523 +++++++++++++++++++++++++++++++------------- 1 file changed, 372 insertions(+), 151 deletions(-) diff --git a/mps/code/steptest.c b/mps/code/steptest.c index 826b76579d3..b4bcc037aa2 100644 --- a/mps/code/steptest.c +++ b/mps/code/steptest.c @@ -1,9 +1,9 @@ -/* steptest.c: TEST FOR ARENA CLAMPING AND STEPPING +/* steptest.c: TEST FOR ARENA STEPPING * * $Id$ * Copyright (C) 1998 Ravenbrook Limited. See end of file for license. * - * Based on . + * Loosely based on . */ #include "fmtdy.h" @@ -23,13 +23,41 @@ #define avLEN 3 #define exactRootsCOUNT 200 #define ambigRootsCOUNT 50 -#define objCOUNT 1000000 -#define genCOUNT 2 +#define objCOUNT 2000000 +#define clockSetFREQ 10000 + +#define genCOUNT 3 +#define gen1SIZE 750 /* kB */ +#define gen2SIZE 2000 /* kB */ +#define gen3SIZE 5000 /* kB */ +#define gen1MORTALITY 0.85 +#define gen2MORTALITY 0.60 +#define gen3MORTALITY 0.40 /* testChain -- generation parameters for the test */ static mps_gen_param_s testChain[genCOUNT] = { - { 150, 0.85 }, { 170, 0.45 } }; + {gen1SIZE, gen1MORTALITY}, + {gen2SIZE, gen2MORTALITY}, + {gen3SIZE, gen3MORTALITY}, +}; + +/* run the test several times, calling mps_arena_step at a different + * frequency each time. When we call it often, tracing is never done + * during allocation. When we call it never, tracing is always done + * during allocation. + */ + +static size_t step_frequencies[] = { + 1000, + 5000, + 10000, + 1000000000, +}; + +#define TESTS (sizeof(step_frequencies) / sizeof(step_frequencies[0])) + +static int test_number = 0; /* objNULL needs to be odd so that it's ignored in exactRoots. */ @@ -40,6 +68,29 @@ static mps_ap_t ap; static mps_addr_t exactRoots[exactRootsCOUNT]; static mps_addr_t ambigRoots[ambigRootsCOUNT]; +/* Things we want to measure. Times are all in microseconds. */ + +double alloc_time; /* Time spent allocating */ +double max_alloc_time; /* Max time taken to allocate one object */ +double step_time; /* Time spent in mps_arena_step returning 1 */ +double max_step_time; /* Max time of mps_arena_step returning 1 */ +double no_step_time; /* Time spent in mps_arena_step returning 0 */ +double max_no_step_time; /* Max time of mps_arena_step returning 0 */ + +double total_clock_time; /* Time spent reading the clock */ +long clock_reads; /* Number of times clock is read */ +long steps; /* # of mps_arena_step calls returning 1 */ +long no_steps; /* # of mps_arena_step calls returning 0 */ +long alloc_bytes; /* # of bytes allocated */ +long commit_failures; /* # of times mps_commit fails */ + + +/* Operating-system dependent timing. Defines two functions, void + * prepare_clock(void) and double my_clock(void). my_clock() returns + * the number of microseconds of CPU time used so far by the process. + * prepare_clock() sets things up so that my_clock() can run + * efficiently. + */ #ifdef MPS_OS_W3 @@ -47,7 +98,7 @@ static HANDLE currentProcess; static void prepare_clock(void) { - currentProcess = GetCurrentProcess(); + currentProcess = GetCurrentProcess(); } static double my_clock(void) @@ -55,10 +106,13 @@ static double my_clock(void) FILETIME ctime, etime, ktime, utime; double dk, du; GetProcessTimes(currentProcess, &ctime, &etime, &ktime, &utime); - dk = ktime.dwHighDateTime * 4096.0 * 1024.0 * 1024.0 + ktime.dwLowDateTime; + dk = ktime.dwHighDateTime * 4096.0 * 1024.0 * 1024.0 + + ktime.dwLowDateTime; dk /= 10.0; - du = utime.dwHighDateTime * 4096.0 * 1024.0 * 1024.0 + utime.dwLowDateTime; + du = utime.dwHighDateTime * 4096.0 * 1024.0 * 1024.0 + + utime.dwLowDateTime; du /= 10.0; + ++ clock_reads; return (du+dk); } @@ -71,208 +125,375 @@ static double my_clock(void) static void prepare_clock(void) { + /* do nothing */ } static double my_clock(void) { struct rusage ru; getrusage(RUSAGE_SELF, &ru); + ++ clock_reads; return ((ru.ru_utime.tv_sec + ru.ru_stime.tv_sec) * 1000000.0 + - (ru.ru_utime.tv_usec) + - (ru.ru_stime.tv_usec)); + (ru.ru_utime.tv_usec + + ru.ru_stime.tv_usec)); } #endif -double alloc_time, step_time, no_step_time, max_step_time, max_no_step_time, max_alloc_time; +/* Need to calibrate the clock. */ +/* In fact we need to do this repeatedly while the tests run because + * on some platforms the time taken to read the clock changes + * significantly during program execution. Yes, really (e.g. fri4gc + * on thrush.ravenbrook.com on 2002-06-28, clock_time goes from 5.43 + * us near process start to 7.45 us later). */ -long steps, no_steps; +double clock_time; /* current estimate of time to read the clock */ -long alloc_bytes; -long commit_failures; +#define CLOCK_TESTS 20000 -#define CLOCK_TESTS 100000 +/* set_clock_timing() sets clock_time. */ -static double clock_timing(void) +static void set_clock_timing(void) { long i; - double t1, t2; + double t1, t2, t3; t2 = 0.0; + t3 = my_clock(); for (i=0; i MAXPRINTABLE) { + while (x[-1] && t > MAXPRINTABLE) { + t /= 1000.0; + -- x; + } + if (t < MAXPRINTABLE) { + printf("%.3f %cs", t, *x); + } else { + printf("%.3f s", t/1000.0); + } + } else { + while (x[1] && t < MINPRINTABLE) { + t *= 1000.0; + ++ x; + } + if (t > MINPRINTABLE) + printf("%.3f %cs", t, *x); + else + printf("%g s", ot/1000000.0); + } + if (after) + printf(after); +} + +/* Make a single Dylan object */ + static mps_addr_t make(void) { - size_t length = rnd() % (2*avLEN); - size_t size = (length+2) * sizeof(mps_word_t); - mps_addr_t p; - mps_res_t res; + size_t length = rnd() % (avLEN * 2); + size_t size = (length+2) * sizeof(mps_word_t); + mps_addr_t p; + mps_res_t res; - alloc_bytes += size; + alloc_bytes += size; - for(;;) { - mps_bool_t commit_res; - double t1 = my_clock(); - MPS_RESERVE_BLOCK(res, p, ap, size); - t1 = my_clock() - t1; - alloc_time += t1; - if (t1 > max_alloc_time) - max_alloc_time = t1; - if(res) - die(res, "MPS_RESERVE_BLOCK"); - res = dylan_init(p, size, exactRoots, exactRootsCOUNT); - if(res) - die(res, "dylan_init"); - t1 = my_clock(); - commit_res = mps_commit(ap, p, size); - t1 = my_clock() - t1; - alloc_time += t1; - if (t1 > max_alloc_time) - max_alloc_time = t1; - if (commit_res) - break; - else - ++ commit_failures; - } + for(;;) { + mps_bool_t commit_res; + double t1, t2; + t1 = my_clock(); + MPS_RESERVE_BLOCK(res, p, ap, size); + t1 = time_since(t1); /* reserve time */ + if(res) + die(res, "MPS_RESERVE_BLOCK"); + res = dylan_init(p, size, exactRoots, exactRootsCOUNT); + if(res) + die(res, "dylan_init"); + t2 = my_clock(); + commit_res = mps_commit(ap, p, size); + t2 = time_since(t2); /* commit time */ + t1 += t2; /* total MPS time for this allocation */ + alloc_time += t1; + if (t1 > max_alloc_time) + max_alloc_time = t1; + if (commit_res) + break; + else + ++ commit_failures; + } - return p; + return p; } +/* call mps_arena_step() */ + static void test_step(mps_arena_t arena) { - mps_bool_t res; - double t1 = my_clock(); - res = mps_arena_step(arena, 0.1); - t1 = my_clock() - t1; - if (res) { - if (t1 > max_step_time) - max_step_time = t1; - step_time += t1; - ++ steps; - } else { - if (t1 > max_no_step_time) - max_no_step_time = t1; - no_step_time += t1; - ++ no_steps; - } + mps_bool_t res; + double t1 = my_clock(); + res = mps_arena_step(arena, 0.1); + t1 = time_since(t1); + if (res) { + if (t1 > max_step_time) + max_step_time = t1; + step_time += t1; + ++ steps; + } else { + if (t1 > max_no_step_time) + max_no_step_time = t1; + no_step_time += t1; + ++ no_steps; + } } /* test -- the body of the test */ static void *test(void *arg, size_t s) { - mps_arena_t arena; - mps_fmt_t format; - mps_chain_t chain; - mps_root_t exactRoot, ambigRoot; - unsigned long objs; size_t i; + mps_arena_t arena; + mps_fmt_t format; + mps_chain_t chain; + mps_root_t exactRoot, ambigRoot; + unsigned long objs; size_t i; + mps_message_t message; + size_t live, condemned, not_condemned; + size_t messages; + mps_word_t collections, old_collections; + double total_mps_time; - arena = (mps_arena_t)arg; - (void)s; /* unused */ + arena = (mps_arena_t)arg; + (void)s; /* unused */ - die(dylan_fmt(&format, arena), "fmt_create"); - die(mps_chain_create(&chain, arena, genCOUNT, testChain), "chain_create"); + die(dylan_fmt(&format, arena), "fmt_create"); + die(mps_chain_create(&chain, arena, genCOUNT, testChain), "chain_create"); - die(mps_pool_create(&pool, arena, mps_class_amc(), format, chain), - "pool_create(amc)"); + die(mps_pool_create(&pool, arena, mps_class_amc(), format, chain), + "pool_create(amc)"); - die(mps_ap_create(&ap, pool, MPS_RANK_EXACT), "BufferCreate"); + die(mps_ap_create(&ap, pool, MPS_RANK_EXACT), "BufferCreate"); - for(i = 0; i < exactRootsCOUNT; ++i) - exactRoots[i] = objNULL; - for(i = 0; i < ambigRootsCOUNT; ++i) - ambigRoots[i] = (mps_addr_t)rnd(); + for(i = 0; i < exactRootsCOUNT; ++i) + exactRoots[i] = objNULL; + for(i = 0; i < ambigRootsCOUNT; ++i) + ambigRoots[i] = (mps_addr_t)rnd(); - die(mps_root_create_table_masked(&exactRoot, arena, - MPS_RANK_EXACT, (mps_rm_t)0, - &exactRoots[0], exactRootsCOUNT, - (mps_word_t)1), - "root_create_table(exact)"); - die(mps_root_create_table(&ambigRoot, arena, - MPS_RANK_AMBIG, (mps_rm_t)0, - &ambigRoots[0], ambigRootsCOUNT), - "root_create_table(ambig)"); + die(mps_root_create_table_masked(&exactRoot, arena, + MPS_RANK_EXACT, (mps_rm_t)0, + &exactRoots[0], exactRootsCOUNT, + (mps_word_t)1), + "root_create_table(exact)"); + die(mps_root_create_table(&ambigRoot, arena, + MPS_RANK_AMBIG, (mps_rm_t)0, + &ambigRoots[0], ambigRootsCOUNT), + "root_create_table(ambig)"); - objs = 0; - steps = no_steps = 0; - alloc_bytes = 0; - commit_failures = 0; - alloc_time = step_time = no_step_time = 0.0; - max_alloc_time = max_step_time = max_no_step_time = 0.0; + printf("Stepping every %lu allocations.\n", + (unsigned long)step_frequencies[test_number]); - while(objs < objCOUNT) { - size_t r; + mps_message_type_enable(arena, mps_message_type_gc()); - r = (size_t)rnd(); - if(r & 1) { - i = (r >> 1) % exactRootsCOUNT; - if(exactRoots[i] != objNULL) - cdie(dylan_check(exactRoots[i]), "dying root check"); - exactRoots[i] = make(); - if(exactRoots[(exactRootsCOUNT-1) - i] != objNULL) - dylan_write(exactRoots[(exactRootsCOUNT-1) - i], - exactRoots, exactRootsCOUNT); - } else { - i = (r >> 1) % ambigRootsCOUNT; - ambigRoots[(ambigRootsCOUNT-1) - i] = make(); - /* Create random interior pointers */ - ambigRoots[i] = (mps_addr_t)((char *)(ambigRoots[i/2]) + 1); + /* zero all our counters and timers. */ + + objs = 0; + clock_reads = 0; + steps = no_steps = 0; + alloc_bytes = 0; + commit_failures = 0; + alloc_time = step_time = no_step_time = 0.0; + max_alloc_time = max_step_time = max_no_step_time = 0.0; + total_clock_time = 0.0; + collections = old_collections = 0; + + while(objs < objCOUNT) { + size_t r; + + r = (size_t)rnd(); + if(r & 1) { + i = (r >> 1) % exactRootsCOUNT; + if(exactRoots[i] != objNULL) + cdie(dylan_check(exactRoots[i]), "dying root check"); + exactRoots[i] = make(); + if(exactRoots[(exactRootsCOUNT-1) - i] != objNULL) + dylan_write(exactRoots[(exactRootsCOUNT-1) - i], + exactRoots, exactRootsCOUNT); + } else { + i = (r >> 1) % ambigRootsCOUNT; + ambigRoots[(ambigRootsCOUNT-1) - i] = make(); + /* Create random interior pointers */ + ambigRoots[i] = (mps_addr_t)((char *)(ambigRoots[i/2]) + 1); + } + + ++objs; + + if (objs % step_frequencies[test_number] == 0) + test_step(arena); + + if (objs % clockSetFREQ == 0) + set_clock_timing(); + + collections = mps_collections(arena); + if (collections > old_collections) { + old_collections = collections; + putchar('.'); + fflush(stdout); + } } - if(objs % 1000 == 0) { - test_step(arena); + if (collections > 0) + printf("\n"); + + messages = live = condemned = not_condemned = 0; + while (mps_message_get(&message, arena, mps_message_type_gc())) { + ++ messages; + live += mps_message_gc_live_size(arena, message); + condemned += mps_message_gc_condemned_size(arena, message); + not_condemned += mps_message_gc_not_condemned_size(arena, + message); + mps_message_discard(arena, message); + } + if (collections != messages) { + printf("%lu collections but %lu messages\n", + (unsigned long)collections, (unsigned long)messages); + collections = messages; } - ++objs; - } + total_mps_time = alloc_time + step_time + no_step_time; + printf("Collection statistics:\n"); + printf(" %lu collections\n", (unsigned long)collections); + printf(" %lu bytes condemned.\n", (unsigned long)condemned); + printf(" %lu bytes not condemned.\n", + (unsigned long)not_condemned); + printf(" %lu bytes survived.\n", (unsigned long)live); + if (condemned) { + printf(" Mortality %5.2f%%.\n", + (1.0 - ((double)live)/condemned) * 100.0); + printf(" Condemned fraction %5.2f%%.\n", + ((double)condemned/(condemned + not_condemned)) * 100.0); + } + if (collections) { + printf(" Condemned per collection %lu bytes.\n", + (unsigned long)condemned/collections); + printf(" Reclaimed per collection %lu bytes.\n", + (unsigned long)(condemned - live)/collections); + } - printf("%ld objects (%ld bytes) allocated\n", objs, alloc_bytes); - printf("commit failed %ld times\n", commit_failures); - printf("allocation took %.0f us, mean %.2f us, max %.0f us\n", - alloc_time, alloc_time / objs, max_alloc_time); - printf("%ld steps took %.0f us, mean %.2f us, max %.0f us\n", - steps, step_time, step_time / steps, max_step_time); - printf("%ld non-steps took %.0f us, mean %.2f us, max %.0f us\n", - no_steps, no_step_time, no_step_time / no_steps, max_no_step_time); + printf("Allocation statistics:\n"); + printf(" %ld objects (%ld bytes) allocated.\n", objs, alloc_bytes); + printf(" Commit failed %ld times.\n", commit_failures); - printf("clock timing %.2f us\n", clock_timing()); + printf("Timings:\n"); + print_time(" Allocation took ", alloc_time, ""); + print_time(", mean ", alloc_time / objs, ""); + print_time(", max ", max_alloc_time, ".\n"); + if (steps) { + printf(" %ld steps took ", steps); + print_time("", step_time, ""); + print_time(", mean ", step_time/steps, ""); + print_time(", max ", max_step_time, ".\n"); + } + if (no_steps) { + printf(" %ld non-steps took ", no_steps); + print_time("", no_step_time, ""); + print_time(", mean ", no_step_time / no_steps, ""); + print_time(", max ", max_no_step_time, ".\n"); + } + if (alloc_time > 0.0) + printf(" Allocated %.2f bytes per us.\n", + (double)alloc_bytes/alloc_time); + if (step_time > 0.0) { + printf(" Reclaimed %.2f bytes per us of step.\n", + (double)(condemned - live)/step_time); + if (collections > 0) { + printf(" Took %.2f steps ", (double)steps/collections); + print_time("(", step_time / collections, ") per collection.\n"); + } + } + print_time(" Total MPS time ", total_mps_time, ""); + print_time(" (", total_mps_time/alloc_bytes, " per byte, "); + print_time("", total_mps_time/objs, " per object)\n"); + print_time(" (adjusted for clock timing: ", + total_clock_time, + " spent reading the clock;\n"); + printf(" %lu clock reads; ", (unsigned long)clock_reads); + print_time("", total_clock_time / clock_reads, " per read)\n"); + mps_ap_destroy(ap); + mps_root_destroy(exactRoot); + mps_root_destroy(ambigRoot); + mps_pool_destroy(pool); + mps_chain_destroy(chain); + mps_fmt_destroy(format); - mps_ap_destroy(ap); - mps_root_destroy(exactRoot); - mps_root_destroy(ambigRoot); - mps_pool_destroy(pool); - mps_chain_destroy(chain); - mps_fmt_destroy(format); - - return NULL; + return NULL; } int main(int argc, char **argv) { - mps_arena_t arena; - mps_thr_t thread; - void *r; + prepare_clock(); - prepare_clock(); + randomize(argc, argv); - randomize(argc, argv); + while (test_number < TESTS) { + mps_arena_t arena; + mps_thr_t thread; + void *r; - die(mps_arena_create(&arena, mps_arena_class_vm(), testArenaSIZE), - "arena_create"); - die(mps_arena_commit_limit_set(arena, testArenaSIZE), "set limit"); - die(mps_thread_reg(&thread, arena), "thread_reg"); - mps_tramp(&r, test, arena, 0); - mps_thread_dereg(thread); - mps_arena_destroy(arena); + set_clock_timing(); + die(mps_arena_create(&arena, mps_arena_class_vm(), + testArenaSIZE), + "arena_create"); + die(mps_thread_reg(&thread, arena), "thread_reg"); + mps_tramp(&r, test, arena, 0); + mps_thread_dereg(thread); + mps_arena_destroy(arena); + ++ test_number; + } - fflush(stdout); /* synchronize */ - fprintf(stderr, "\nConclusion: Failed to find any defects.\n"); - return 0; + fflush(stdout); /* synchronize */ + fprintf(stderr, "\nConclusion: Failed to find any defects.\n"); + return 0; } @@ -281,18 +502,18 @@ int main(int argc, char **argv) * Copyright (C) 2001-2002 Ravenbrook Limited . * All rights reserved. This is an open source license. Contact * Ravenbrook for commercial licensing options. - * + * * Redistribution and use in source and binary forms, with or without * modification, are permitted provided that the following conditions are * met: - * + * * 1. Redistributions of source code must retain the above copyright * notice, this list of conditions and the following disclaimer. - * + * * 2. Redistributions in binary form must reproduce the above copyright * notice, this list of conditions and the following disclaimer in the * documentation and/or other materials provided with the distribution. - * + * * 3. Redistributions in any form must be accompanied by information on how * to obtain complete source code for this software and any accompanying * software that uses this software. The source code must either be @@ -303,7 +524,7 @@ int main(int argc, char **argv) * include source code for modules or files that typically accompany the * major components of the operating system on which the executable file * runs. - * + * * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS * IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED * TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR