Add call timing in the report of dt.options.core_logger (#1094)

Author: st-pasha

c/py_utils.c

@@ -13,6 +13,8 @@
 #include "py_datatable.h"
 #include "py_utils.h"
 
+double logger_timer;
+char logger_msg[1000];
 
 /**
  * Create and return a new instance of python's None object

c/py_utils.h

@@ -20,16 +20,22 @@
 namespace config {
   extern PyObject* logger;
 };
+extern double logger_timer;
+extern char logger_msg[];
 void log_call(const char* msg);
 
 
 #define ES_FUNCTION(decl, call, log_msg)                                       \
   decl {                                                                       \
     try {                                                                      \
       if (config::logger) {                                                    \
-        log_call("call: " log_msg);                                            \
+        snprintf(logger_msg, 1000, "call %s", log_msg);                        \
+        log_call(logger_msg);                                                  \
+        logger_timer = wallclock();                                            \
         PyObject* res = call;                                                  \
-        log_call("done: " log_msg);                                            \
+        snprintf(logger_msg, 1000, "done %s in %.3f ms",                       \
+                 log_msg, (wallclock() - logger_timer) * 1000.0);              \
+        log_call(logger_msg);                                                  \
         return res;                                                            \
       } else {                                                                 \
         return call;                                                           \
@@ -45,9 +51,13 @@ void log_call(const char* msg);
   decl {                                                                       \
     try {                                                                      \
       if (config::logger) {                                                    \
-        log_call("call: " log_msg);                                            \
+        snprintf(logger_msg, 1000, "call %s", log_msg);                        \
+        log_call(logger_msg);                                                  \
+        logger_timer = wallclock();                                            \
         call;                                                                  \
-        log_call("done: " log_msg);                                            \
+        snprintf(logger_msg, 1000, "done %s in %.3f ms",                       \
+                 log_msg, (wallclock() - logger_timer) * 1000.0);              \
+        log_call(logger_msg);                                                  \
       } else {                                                                 \
         call;                                                                  \
       }                                                                        \
@@ -61,9 +71,13 @@ void log_call(const char* msg);
   decl {                                                                       \
     try {                                                                      \
       if (config::logger) {                                                    \
-        log_call("call: " log_msg);                                            \
+        snprintf(logger_msg, 1000, "call %s", log_msg);                        \
+        log_call(logger_msg);                                                  \
+        logger_timer = wallclock();                                            \
         int res = call;                                                        \
-        log_call("done: " log_msg);                                            \
+        snprintf(logger_msg, 1000, "done %s in %.3f ms",                       \
+                 log_msg, (wallclock() - logger_timer) * 1000.0);              \
+        log_call(logger_msg);                                                  \
         return res;                                                            \
       } else {                                                                 \
         return call;                                                           \

tests/test_dt_options.py

@@ -133,11 +133,11 @@ def info(self, msg):
     assert dt.options.core_logger == ml
     f0 = dt.Frame([1, 2, 3])
     assert f0.internal.check()
-    assert "call: DataTable.datatable_from_list(...)" in ml.messages
-    assert "call: DataTable.ncols" in ml.messages
-    assert "call: DataTable.nrows" in ml.messages
-    assert "call: DataTable.check(...)" in ml.messages
-    assert "done: DataTable.check(...)" in ml.messages
+    assert "call DataTable.datatable_from_list(...)" in ml.messages
+    assert "call DataTable.ncols" in ml.messages
+    assert "call DataTable.nrows" in ml.messages
+    assert "call DataTable.check(...)" in ml.messages
+    assert "done DataTable.check(...) in" in ml.messages
     del dt.options.core_logger
     assert dt.options.core_logger is None