]> granicus.if.org Git - vnstat/commitdiff
refactor debugging of time used in functions
authorTeemu Toivola <git@humdi.net>
Fri, 10 May 2019 22:23:35 +0000 (01:23 +0300)
committerTeemu Toivola <git@humdi.net>
Fri, 10 May 2019 22:23:35 +0000 (01:23 +0300)
src/common.c
src/common.h
src/daemon.c
src/dbjson.c
src/dbshow.c
src/dbsql.c
src/dbxml.c
src/vnstatd.c
tests/common_tests.c

index 3f809dda7f8c76ef66a60605ee7644e2f381a3b2..fa464f0641065f18e86372857c7531672949747c 100644 (file)
@@ -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);
 }
index f979c024c9055c594ea1dcb6ef402975f59e7220..827d5ff7105b3ef78f7eca031640616cf4a55017 100644 (file)
@@ -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;
index 3bd9bfa11f002faeee93ac7822a1a47abcef6879..57b4ea549b1fa87916bc6f6582d88d5551495ef5 100644 (file)
@@ -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)
index 757a732cc65f175d828132d6bd0f18a7a19580b6..5fe9afd508beab7968e42feefd88b08c22b0699d 100644 (file)
@@ -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)
index df1cc120d9bdade26f7a374346e45434d244297c..84ede0acb6e6d9305e1d1a06a20fef1621f07c2b 100644 (file)
@@ -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)
index 03c413c1e53272b07b1f2b41508b939f1f19786a..8751be51828a1b50467651ad959422836bdbe827 100644 (file)
@@ -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
 
index 2a0c816568a3842abece00f20372ef53ca2659fe..92d537ba314109549c170b5adc0f0748c2123ba8 100644 (file)
@@ -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("  </traffic>\n");
        printf(" </interface>\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)
index 6d131cc8d9a84ac0ee65afe2d6e4e842d4c6aacf..b2451d555c45bef136cc570c097552e9bf07fffd 100644 (file)
@@ -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__)
index 145df86a0f2eaecf1e851b1f3b6b94b65fabf0f3..8c3fa684b0cf175b3b20ba5708a0a6fb201c6c3b 100644 (file)
@@ -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);
 }