ICU-3030 show elapsed time in subtests. Add internal uprv_getRawUTCtime that doesn't go through faketime.

X-SVN-Rev: 28099
This commit is contained in:
Steven R. Loomis 2010-05-25 19:55:05 +00:00
parent 414d8f3f3a
commit edcaca307a
7 changed files with 142 additions and 53 deletions

View file

@ -257,13 +257,21 @@ typedef union {
implementations.
---------------------------------------------------------------------------*/
/* Return UTC (GMT) time measured in milliseconds since 0:00 on 1/1/70.*/
U_CAPI UDate U_EXPORT2
uprv_getUTCtime()
{
#if defined(U_DEBUG_FAKETIME)
return getUTCtime_fake(); /* Hook for overriding the clock */
#elif defined(XP_MAC)
#else
return uprv_getRawUTCtime();
#endif
}
/* Return UTC (GMT) time measured in milliseconds since 0:00 on 1/1/70.*/
U_CAPI UDate U_EXPORT2
uprv_getRawUTCtime()
{
#if defined(XP_MAC)
time_t t, t1, t2;
struct tm tmrec;

View file

@ -213,11 +213,21 @@ U_INTERNAL const char* U_EXPORT2 uprv_tzname(int n);
/**
* Get UTC (GMT) time measured in milliseconds since 0:00 on 1/1/1970.
* This function is affected by 'faketime' and should be the bottleneck for all user-visible ICU time functions.
* @return the UTC time measured in milliseconds
* @internal
*/
U_INTERNAL UDate U_EXPORT2 uprv_getUTCtime(void);
/**
* Get UTC (GMT) time measured in milliseconds since 0:00 on 1/1/1970.
* This function is not affected by 'faketime', so it should only be used by low level test functions- not by anything that
* exposes time to the end user.
* @return the UTC time measured in milliseconds
* @internal
*/
U_INTERNAL UDate U_EXPORT2 uprv_getRawUTCtime(void);
/**
* Determine whether a pathname is absolute or not, as defined by the platform.
* @param path Pathname to test

View file

@ -32,7 +32,7 @@
#include "unicode/uclean.h"
#include "unicode/ucal.h"
#include "uoptions.h"
#include "putilimp.h" /* for uprv_getUTCtime() */
#include "putilimp.h" /* for uprv_getRawUTCtime() */
#ifdef URES_DEBUG
#include "uresimp.h" /* for ures_dumpCacheContents() */
#endif
@ -82,7 +82,7 @@ int main(int argc, const char* const argv[])
U_MAIN_INIT_ARGS(argc, argv);
startTime = uprv_getUTCtime();
startTime = uprv_getRawUTCtime();
gOrigArgc = argc;
gOrigArgv = argv;
@ -226,7 +226,7 @@ int main(int argc, const char* const argv[])
fprintf(stderr, "There were %d blocks leaked!\n", ALLOCATION_COUNT);
nerrors++;
}
endTime = uprv_getUTCtime();
endTime = uprv_getRawUTCtime();
diffTime = (int32_t)(endTime - startTime);
printf("Elapsed Time: %02d:%02d:%02d.%03d\n",
(int)((diffTime%U_MILLIS_PER_DAY)/U_MILLIS_PER_HOUR),

View file

@ -35,9 +35,9 @@
#include "cmemory.h"
#include "uoptions.h"
#include "putilimp.h" // for uprv_getUTCtime()
#include "putilimp.h" // for uprv_getRawUTCtime()
#include "unicode/locid.h"
#include "unicode/ctest.h" // for str_timeDelta
#ifdef XP_MAC_CONSOLE
#include <console.h>
@ -671,13 +671,17 @@ UBool IntlTest::runTestLoop( char* testname, char* par )
char msg[256];
sprintf(msg, "%s {", name);
LL_message(msg, TRUE);
UDate timeStart = uprv_getRawUTCtime();
this->runIndexedTest( index, TRUE, name, par );
UDate timeStop = uprv_getRawUTCtime();
rval = TRUE; // at least one test has been called
if (lastErrorCount == errorCount) {
sprintf( msg, " } OK: %s", name );
sprintf( msg, " } OK: %s ", name );
str_timeDelta(msg+strlen(msg),timeStop-timeStart);
lastTestFailed = FALSE;
}else{
sprintf(msg, " } ERRORS (%li) in %s", (long)(errorCount-lastErrorCount), name);
str_timeDelta(msg+strlen(msg),timeStop-timeStart);
for(int i=0;i<LL_indentlevel;i++) {
errorList += " ";
@ -1037,7 +1041,7 @@ main(int argc, char* argv[])
U_MAIN_INIT_ARGS(argc, argv);
startTime = uprv_getUTCtime();
startTime = uprv_getRawUTCtime();
for (int i = 1; i < argc; ++i) {
if (argv[i][0] == '-') {
@ -1319,7 +1323,7 @@ main(int argc, char* argv[])
if (execCount <= 0) {
fprintf(stdout, "***** Not all called tests actually exist! *****\n");
}
endTime = uprv_getUTCtime();
endTime = uprv_getRawUTCtime();
diffTime = (int32_t)(endTime - startTime);
printf("Elapsed Time: %02d:%02d:%02d.%03d\n",
(int)((diffTime%U_MILLIS_PER_DAY)/U_MILLIS_PER_HOUR),

View file

@ -1,6 +1,6 @@
/*
**********************************************************************
* Copyright (C) 2002-2009, International Business Machines
* Copyright (C) 2002-2010, International Business Machines
* Corporation and others. All Rights Reserved.
**********************************************************************
* file name: iotest.cpp
@ -812,7 +812,7 @@ int main(int argc, char* argv[])
UDate startTime, endTime;
int32_t diffTime;
startTime = uprv_getUTCtime();
startTime = uprv_getRawUTCtime();
/* Check whether ICU will initialize without forcing the build data directory into
* the ICU_DATA path. Success here means either the data dll contains data, or that
@ -869,7 +869,7 @@ int main(int argc, char* argv[])
DataDrivenLogger::cleanUp();
u_cleanup();
endTime = uprv_getUTCtime();
endTime = uprv_getRawUTCtime();
diffTime = (int32_t)(endTime - startTime);
printf("Elapsed Time: %02d:%02d:%02d.%03d\n",
(int)((diffTime%U_MILLIS_PER_DAY)/U_MILLIS_PER_HOUR),

View file

@ -15,6 +15,7 @@
#include "unicode/utrace.h"
#include "unicode/uclean.h"
#include "umutex.h"
#include "putilimp.h"
/* NOTES:
3/20/1999 srl - strncpy called w/o setting nulls at the end
@ -33,6 +34,10 @@
*/
#define PAGE_SIZE 25
#ifndef SHOW_TIMES
#define SHOW_TIMES 1
#endif
struct TestNode
{
void (*test)(void);
@ -273,6 +278,33 @@ static TestNode *addTestNode ( TestNode *root, const char *name )
}
}
/**
* Log the time taken. May not output anything.
* @param deltaTime change in time
*/
void T_CTEST_EXPORT2 str_timeDelta(char *str, UDate deltaTime) {
if (deltaTime > 110000.0 ) {
double mins = uprv_floor(deltaTime/60000.0);
sprintf(str, "[(%.0fm %.1fs)]", mins, (deltaTime-(mins*60000.0))/1000.0);
} else if (deltaTime > 1500.0) {
sprintf(str, "((%.1fs))", deltaTime/1000.0);
} else if(deltaTime>900.0) {
sprintf(str, "( %.2fs )", deltaTime/1000.0);
} else if(deltaTime > 5.0) {
sprintf(str, " (%.0fms) ", deltaTime);
} else {
str[0]=0; /* at least terminate it. */
}
}
static void print_timeDelta(UDate deltaTime) {
char str[256];
str_timeDelta(str, deltaTime);
if(str[0]) {
printf("%s", str);
}
}
/**
* Run or list tests (according to mode) in a subtree.
*
@ -287,10 +319,16 @@ static void iterateTestsWithLevel ( const TestNode* root,
TestMode mode)
{
int i;
int saveIndent;
char pathToFunction[MAXTESTNAME] = "";
char separatorString[2] = { TEST_SEPARATOR, '\0'};
#if SHOW_TIMES
UDate allStartTime = -1, allStopTime = -1;
#endif
if(depth<2) {
allStartTime = uprv_getRawUTCtime();
}
if ( root == NULL )
return;
@ -322,42 +360,53 @@ static void iterateTestsWithLevel ( const TestNode* root,
{
int myERROR_COUNT = ERROR_COUNT;
int myGLOBAL_PRINT_COUNT = GLOBAL_PRINT_COUNT;
#if SHOW_TIMES
UDate startTime, stopTime;
#endif
currentTest = root;
INDENT_LEVEL = depth; /* depth of subitems */
ONE_ERROR=0;
HANGING_OUTPUT=FALSE;
/* TODO: start counter */
root->test(); /* PERFORM THE TEST */
#if SHOW_TIMES
startTime = uprv_getRawUTCtime();
#endif
root->test(); /* PERFORM THE TEST ************************/
#if SHOW_TIMES
stopTime = uprv_getRawUTCtime();
#endif
if(HANGING_OUTPUT) {
log_testinfo("\n");
HANGING_OUTPUT=FALSE;
log_testinfo("\n");
HANGING_OUTPUT=FALSE;
}
/* TODO: stop counter */
INDENT_LEVEL = depth-1; /* depth of root */
currentTest = NULL;
if((ONE_ERROR>0)&&(ERROR_COUNT==0)) {
ERROR_COUNT++; /* There was an error without a newline */
ERROR_COUNT++; /* There was an error without a newline */
}
ONE_ERROR=0;
if (myERROR_COUNT != ERROR_COUNT) {
log_testinfo_i("} ---[%d ERRORS in %s] ", ERROR_COUNT - myERROR_COUNT, pathToFunction);
strcpy(ERROR_LOG[ERRONEOUS_FUNCTION_COUNT++], pathToFunction);
} else {
if(!ON_LINE) { /* had some output */
int spaces = FLAG_INDENT-(depth-1);
log_testinfo_i("} %*s[OK] ", spaces, "---");
if((GLOBAL_PRINT_COUNT-myGLOBAL_PRINT_COUNT)>PAGE_SIZE) {
log_testinfo(" %s ", pathToFunction); /* in case they forgot. */
}
} else {
/* put -- out at 30 sp. */
int spaces = FLAG_INDENT-(strlen(root->name)+depth);
if(spaces<0) spaces=0;
log_testinfo(" %*s[OK] ", spaces,"---");
}
}
/* TODO: print counter */
if (myERROR_COUNT != ERROR_COUNT) {
log_testinfo_i("} ---[%d ERRORS in %s] ", ERROR_COUNT - myERROR_COUNT, pathToFunction);
strcpy(ERROR_LOG[ERRONEOUS_FUNCTION_COUNT++], pathToFunction);
} else {
if(!ON_LINE) { /* had some output */
int spaces = FLAG_INDENT-(depth-1);
log_testinfo_i("} %*s[OK] ", spaces, "---");
if((GLOBAL_PRINT_COUNT-myGLOBAL_PRINT_COUNT)>PAGE_SIZE) {
log_testinfo(" %s ", pathToFunction); /* in case they forgot. */
}
} else {
/* put -- out at 30 sp. */
int spaces = FLAG_INDENT-(strlen(root->name)+depth);
if(spaces<0) spaces=0;
log_testinfo(" %*s[OK] ", spaces,"---");
}
}
#if SHOW_TIMES
print_timeDelta(stopTime-startTime);
#endif
ON_LINE = TRUE; /* we are back on-line */
}
@ -386,15 +435,26 @@ static void iterateTestsWithLevel ( const TestNode* root,
log_testinfo_i("} "); /* TODO: summarize subtests */
if((depth>1) && (ERROR_COUNT > myERROR_COUNT)) {
log_testinfo("[%d %s in %s] ", ERROR_COUNT-myERROR_COUNT, (ERROR_COUNT-myERROR_COUNT)==1?"error":"errors", pathToFunction);
} else if((GLOBAL_PRINT_COUNT-myGLOBAL_PRINT_COUNT)>PAGE_SIZE) {
log_testinfo(" %s ", pathToFunction); /* in case they forgot. */
}
} else if((GLOBAL_PRINT_COUNT-myGLOBAL_PRINT_COUNT)>PAGE_SIZE || (depth<1)) {
if(pathToFunction[0]) {
log_testinfo(" %s ", pathToFunction); /* in case they forgot. */
} else {
log_testinfo(" / (%s) ", ARGV_0);
}
}
ON_LINE=TRUE;
}
}
depth--;
#if SHOW_TIMES
if(depth<2) {
allStopTime = uprv_getRawUTCtime();
print_timeDelta(allStopTime-allStartTime);
}
#endif
if(mode!=SHOWTESTS && ON_LINE) {
log_testinfo("\n");
}
@ -536,18 +596,18 @@ getTest(const TestNode* root, const char* name)
/* =========== io functions ======== */
static void go_offline_with_marker(const char *mrk) {
UBool wasON_LINE = ON_LINE;
if(ON_LINE) {
log_testinfo(" {\n");
ON_LINE=FALSE;
}
if(!HANGING_OUTPUT || wasON_LINE) {
if(mrk != NULL) {
fputs(mrk, stdout);
}
}
UBool wasON_LINE = ON_LINE;
if(ON_LINE) {
log_testinfo(" {\n");
ON_LINE=FALSE;
}
if(!HANGING_OUTPUT || wasON_LINE) {
if(mrk != NULL) {
fputs(mrk, stdout);
}
}
}
static void go_offline() {

View file

@ -254,6 +254,13 @@ runTestRequest(const TestNode* root,
T_CTEST_API const char* T_CTEST_EXPORT2
getTestName(void);
/**
* Append a time delta to str if it is significant (>5 ms) otherwise no change
* @param delta a delta in millis
* @param str a string to append to.
*/
T_CTEST_API void T_CTEST_EXPORT2
str_timeDelta(char *str, UDate delta);
#endif