From: Teemu Toivola Date: Fri, 10 May 2019 22:23:35 +0000 (+0300) Subject: refactor debugging of time used in functions X-Git-Tag: v2.3~32 X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=ee327d1f72f5845fa76d738e178734ee5265caae;p=vnstat refactor debugging of time used in functions --- diff --git a/src/common.c b/src/common.c index 3f809dd..fa464f0 100644 --- a/src/common.c +++ b/src/common.c @@ -287,22 +287,35 @@ char *getversion(void) return versionbuffer; } -void timeused(const char *func, const int reset) +double timeused(const char *func, const int reset) { static struct timeval starttime; struct timeval endtime; - - if (!debug) { - return; - } + double used_secs; if (reset) { gettimeofday(&starttime, NULL); - return; + return 0.0; } if (gettimeofday(&endtime, NULL) != 0) { + return 0.0; + } + + used_secs = (double)(endtime.tv_usec - starttime.tv_usec) / 1000000 + (double)(endtime.tv_sec - starttime.tv_sec); + + if (debug) { + printf("%s() in %f s\n", func, used_secs); + } + + return used_secs; +} + +void timeused_debug(const char *func, const int reset) +{ + if (!debug) { return; } - printf("%s() in %f s\n", func, (double)(endtime.tv_usec - starttime.tv_usec) / 1000000 + (double)(endtime.tv_sec - starttime.tv_sec)); + + timeused(func, reset); } diff --git a/src/common.h b/src/common.h index f979c02..827d5ff 100644 --- a/src/common.h +++ b/src/common.h @@ -317,7 +317,8 @@ char *strncpy_nt(char *dest, const char *src, size_t n); int isnumeric(const char *s); void panicexit(const char *sourcefile, const int sourceline) __attribute__((noreturn)); char *getversion(void); -void timeused(const char *func, const int reset); +double timeused(const char *func, const int reset); +void timeused_debug(const char *func, const int reset); /* global variables */ extern CFG cfg; diff --git a/src/daemon.c b/src/daemon.c index 3bd9bfa..57b4ea5 100644 --- a/src/daemon.c +++ b/src/daemon.c @@ -119,7 +119,7 @@ unsigned int addinterfaces(DSTATE *s) unsigned int index = 0, count = 0; uint32_t bwlimit = 0; - timeused(__func__, 1); + timeused_debug(__func__, 1); /* get list of currently visible interfaces */ if (getiflist(&ifacelist, 0) == 0) { @@ -196,7 +196,7 @@ unsigned int addinterfaces(DSTATE *s) } free(ifacelist); - timeused(__func__, 0); + timeused_debug(__func__, 0); return count; } @@ -363,7 +363,7 @@ void filldatabaselist(DSTATE *s) { dbiflist *dbifl = NULL, *dbifl_iterator = NULL; - timeused(__func__, 1); + timeused_debug(__func__, 1); if (db_getiflist(&dbifl) < 0) { errorexitdaemon(s, 1); @@ -398,7 +398,7 @@ void filldatabaselist(DSTATE *s) } else { s->updateinterval = 120; } - timeused(__func__, 0); + timeused_debug(__func__, 0); } void adjustsaveinterval(DSTATE *s) @@ -426,7 +426,7 @@ void processdatacache(DSTATE *s) { datacache *iterator = s->dcache; - timeused(__func__, 1); + timeused_debug(__func__, 1); while (iterator != NULL) { @@ -465,7 +465,7 @@ void processdatacache(DSTATE *s) if (s->bootdetected) { s->bootdetected = 0; } - timeused(__func__, 0); + timeused_debug(__func__, 0); if (s->dodbsave) { flushcachetodisk(s); @@ -587,7 +587,7 @@ void flushcachetodisk(DSTATE *s) xferlog *logiterator; interfaceinfo info; - timeused(__func__, 1); + timeused_debug(__func__, 1); if (!db_begintransaction()) { handledatabaseerror(s); @@ -678,7 +678,7 @@ void flushcachetodisk(DSTATE *s) } else { db_rollbacktransaction(); } - timeused(__func__, 0); + timeused_debug(__func__, 0); } void handledatabaseerror(DSTATE *s) @@ -702,7 +702,7 @@ void cleanremovedinterfaces(DSTATE *s) datacache *iterator = s->dcache; dbiflist *dbifl = NULL, *dbifl_iterator = NULL; - timeused(__func__, 1); + timeused_debug(__func__, 1); while (iterator != NULL) { if (!db_getinterfacecountbyname(iterator->interface)) { @@ -723,7 +723,7 @@ void cleanremovedinterfaces(DSTATE *s) datacache_status(&s->dcache); dbiflistfree(&dbifl); } - timeused(__func__, 0); + timeused_debug(__func__, 0); } void handleintsignals(DSTATE *s) @@ -806,7 +806,7 @@ void datacache_status(datacache **dc) uint32_t bwlimit = 0; datacache *iterator = *dc; - timeused(__func__, 1); + timeused_debug(__func__, 1); snprintf(buffer, 1024, "Monitoring (%d): ", datacache_count(dc)); b = (unsigned int)strlen(buffer) + 1; @@ -835,7 +835,7 @@ void datacache_status(datacache **dc) snprintf(errorstring, 1024, "Nothing to monitor"); } printe(PT_Info); - timeused(__func__, 0); + timeused_debug(__func__, 0); } void interfacechangecheck(DSTATE *s) @@ -845,7 +845,7 @@ void interfacechangecheck(DSTATE *s) uint32_t newhash; int offset, found; - timeused(__func__, 1); + timeused_debug(__func__, 1); /* get list of currently visible interfaces */ if (getiflist(&ifacelist, 0) == 0) { @@ -909,7 +909,7 @@ void interfacechangecheck(DSTATE *s) free(ifacelist); s->iflisthash = newhash; - timeused(__func__, 0); + timeused_debug(__func__, 0); } uint32_t simplehash(const char *data, int len) diff --git a/src/dbjson.c b/src/dbjson.c index 757a732..5fe9afd 100644 --- a/src/dbjson.c +++ b/src/dbjson.c @@ -6,7 +6,7 @@ void showjson(const char *interface, const int ifcount, const char mode, const c { interfaceinfo info; - timeused(__func__, 1); + timeused_debug(__func__, 1); if (!db_getinterfacecountbyname(interface)) { return; @@ -70,7 +70,7 @@ void showjson(const char *interface, const int ifcount, const char mode, const c printf("}}"); - timeused(__func__, 0); + timeused_debug(__func__, 0); } void jsondump(const interfaceinfo *interface, const char *tablename, const int datetype, const char *databegin, const char *dataend) diff --git a/src/dbshow.c b/src/dbshow.c index df1cc12..84ede0a 100644 --- a/src/dbshow.c +++ b/src/dbshow.c @@ -68,7 +68,7 @@ void showsummary(const interfaceinfo *interface, const int shortmode) dbdatalist *datalist = NULL, *datalist_i = NULL; dbdatalistinfo datainfo; - timeused(__func__, 1); + timeused_debug(__func__, 1); current = time(NULL); yesterday = current - 86400; @@ -273,7 +273,7 @@ void showsummary(const interfaceinfo *interface, const int shortmode) } dbdatalistfree(&datalist); - timeused(__func__, 0); + timeused_debug(__func__, 0); } void showlist(const interfaceinfo *interface, const char *listname, const char *databegin, const char *dataend) @@ -289,7 +289,7 @@ void showlist(const interfaceinfo *interface, const char *listname, const char * dbdatalist *datalist = NULL, *datalist_i = NULL; dbdatalistinfo datainfo; - timeused(__func__, 1); + timeused_debug(__func__, 1); if (strcmp(listname, "day") == 0) { listtype = LT_Day; @@ -566,7 +566,7 @@ void showlist(const interfaceinfo *interface, const char *listname, const char * printf("\n"); } dbdatalistfree(&datalist); - timeused(__func__, 0); + timeused_debug(__func__, 0); } void showoneline(const interfaceinfo *interface) @@ -577,7 +577,7 @@ void showoneline(const interfaceinfo *interface) dbdatalist *datalist = NULL; dbdatalistinfo datainfo; - timeused(__func__, 1); + timeused_debug(__func__, 1); /* version string */ printf("%d;", ONELINEVERSION); @@ -667,7 +667,7 @@ void showoneline(const interfaceinfo *interface) printf("%s;", getvalue(interface->txtotal, 1, RT_Normal)); printf("%s\n", getvalue(interface->rxtotal + interface->txtotal, 1, RT_Normal)); } - timeused(__func__, 0); + timeused_debug(__func__, 0); } void showhours(const interfaceinfo *interface) @@ -682,7 +682,7 @@ void showhours(const interfaceinfo *interface) dbdatalistinfo datainfo; HOURDATA hourdata[24]; - timeused(__func__, 1); + timeused_debug(__func__, 1); for (i = 0; i < 24; i++) { hourdata[i].rx = hourdata[i].tx = 0; @@ -839,7 +839,7 @@ void showhours(const interfaceinfo *interface) } printf("\n"); } - timeused(__func__, 0); + timeused_debug(__func__, 0); } int showbar(const uint64_t rx, const uint64_t tx, const uint64_t max, const int len) diff --git a/src/dbsql.c b/src/dbsql.c index 03c413c..8751be5 100644 --- a/src/dbsql.c +++ b/src/dbsql.c @@ -1058,7 +1058,7 @@ int db_iserrcodefatal(int errcode) #if HAVE_DECL_SQLITE_CHECKPOINT_RESTART void db_walcheckpoint(void) { - timeused(__func__, 1); + timeused_debug(__func__, 1); if (debug) printf("wal checkpoint"); #if HAVE_DECL_SQLITE_CHECKPOINT_TRUNCATE @@ -1066,7 +1066,7 @@ void db_walcheckpoint(void) #else sqlite3_wal_checkpoint_v2(db, NULL, SQLITE_CHECKPOINT_RESTART, NULL, NULL); #endif - timeused(__func__, 0); + timeused_debug(__func__, 0); } #endif diff --git a/src/dbxml.c b/src/dbxml.c index 2a0c816..92d537b 100644 --- a/src/dbxml.c +++ b/src/dbxml.c @@ -6,7 +6,7 @@ void showxml(const char *interface, const char mode, const char *databegin, cons { interfaceinfo info; - timeused(__func__, 1); + timeused_debug(__func__, 1); if (!db_getinterfacecountbyname(interface)) { return; @@ -64,7 +64,7 @@ void showxml(const char *interface, const char mode, const char *databegin, cons printf(" \n"); printf(" \n"); - timeused(__func__, 0); + timeused_debug(__func__, 0); } void xmldump(const interfaceinfo *interface, const char *tablename, const int datetype, const char *databegin, const char *dataend) diff --git a/src/vnstatd.c b/src/vnstatd.c index 6d131cc..b2451d5 100644 --- a/src/vnstatd.c +++ b/src/vnstatd.c @@ -54,7 +54,7 @@ int main(int argc, char *argv[]) } } - timeused("daemon_startup", 1); + timeused_debug("daemon_startup", 1); /* load config if available */ if (!loadcfg(s.cfgfile)) { @@ -192,7 +192,7 @@ int main(int argc, char *argv[]) } } - timeused("daemon_startup", 0); + timeused_debug("daemon_startup", 0); s.running = 1; #if defined(__linux__) diff --git a/tests/common_tests.c b/tests/common_tests.c index 145df86..8c3fa68 100644 --- a/tests/common_tests.c +++ b/tests/common_tests.c @@ -342,7 +342,7 @@ START_TEST(getversion_returns_a_version) } END_TEST -START_TEST(timeused_outputs_something_expected) +START_TEST(timeused_debug_outputs_something_expected_when_debug_is_enabled) { int pipe, len; char buffer[512]; @@ -354,13 +354,55 @@ START_TEST(timeused_outputs_something_expected) /* the assumption here is that the next two steps can always execute in less than one second resulting in a duration that starts with a zero */ - timeused("nothing", 1); - timeused("something", 0); + timeused_debug("that_func", 1); + timeused_debug("that_func", 0); fflush(stdout); len = (int)read(pipe, buffer, 512); - ck_assert_int_gt(len, 0); - ck_assert_ptr_ne(strstr(buffer, "something() in 0"), NULL); + ck_assert_int_gt(len, 1); + ck_assert_ptr_ne(strstr(buffer, "that_func() in 0"), NULL); +} +END_TEST + +START_TEST(timeused_debug_does_not_output_anything_when_debug_is_disabled) +{ + int pipe, len; + char buffer[512]; + memset(&buffer, '\0', sizeof(buffer)); + + defaultcfg(); + debug = 0; + pipe = pipe_output(); + /* the assumption here is that the next two steps + can always execute in less than one second resulting + in a duration that starts with a zero */ + timeused_debug("other_func", 1); + timeused_debug("other_func", 0); + printf("-"); // stdout needs to contain something so that read doesn't block + fflush(stdout); + + len = (int)read(pipe, buffer, 512); + ck_assert_int_eq(len, 1); +} +END_TEST + +START_TEST(timeused_tracks_used_time) +{ + int i, j = 0; + double used; + + defaultcfg(); + + used = timeused("quick_func", 1); + ck_assert(used == 0.0); + + /* assume that this spends some non-zero time */ + for (i = 0; i < 10000; i++) { + j = j + 2; + } + + used = timeused("quick_func", 0); + ck_assert(used > 0.0); } END_TEST @@ -401,7 +443,9 @@ void add_common_tests(Suite *s) tcase_add_test(tc_common, isnumeric_it_is); tcase_add_test(tc_common, isnumeric_it_is_not); tcase_add_test(tc_common, getversion_returns_a_version); - tcase_add_test(tc_common, timeused_outputs_something_expected); + tcase_add_test(tc_common, timeused_debug_outputs_something_expected_when_debug_is_enabled); + tcase_add_test(tc_common, timeused_debug_does_not_output_anything_when_debug_is_disabled); + tcase_add_test(tc_common, timeused_tracks_used_time); tcase_add_exit_test(tc_common, can_panic, 1); suite_add_tcase(s, tc_common); }