Improve rules profiling (#829)

* Improve rules profiling. The most relevant changes are:

* Stop using time() and difftime() for measuring time. Use yr_stopwatch_elapsed_ns instead.

* clock_ticks field in YR_RULE and YR_STRING structures has been renamed to time_cost.

*  When the time_cost for some YR_STRING structure is incremented, it's incremented for its associated YR_RULE structure too. Iterating over the YR_STRING structures is not necessary for computing the total cost for some YR_STRING.

* A time_cost field was added to the YR_RULES structure. The ratio between YR_RULES structure's time_cost and YR_RULE structure's time_cost offers a better measure of how costly a rule is.

.travis.yml

@@ -37,6 +37,10 @@ matrix:
         sudo apt-get install -y gcc-mingw-w64 autoconf automake libtool
     - os: osx
       osx_image: xcode7.3
+    - os: osx
+      osx_image: xcode8.3
+    - os: osx
+      osx_image: xcode9.2
 
 before_script: ./bootstrap.sh
 

configure.ac

@@ -266,6 +266,9 @@ AS_IF([test "x$have_crypto" = "xno"],
     PC_REQUIRES_PRIVATE="$PC_REQUIRES_PRIVATE libcrypto"
   ])
 
+AC_CHECK_FUNCS([clock_gettime],,
+  AC_MSG_ERROR([clock_gettime not supported in your OS.]))
+
 AM_CONDITIONAL([DEBUG], [test x$debug = xtrue])
 AM_CONDITIONAL([PROFILING_ENABLED], [test x$profiling_enabled = xtrue])
 AM_CONDITIONAL([OPTIMIZATION], [test x$optimization = xtrue])

libyara/Makefile.am

@@ -88,6 +88,7 @@ yarainclude_HEADERS = \
   include/yara/scan.h \
   include/yara/scanner.h \
   include/yara/sizedstr.h \
+  include/yara/stopwatch.h \
   include/yara/stream.h \
   include/yara/strutils.h \
   include/yara/threading.h \
@@ -106,7 +107,6 @@ noinst_HEADERS = \
   include/yara/pe.h \
   include/yara/pe_utils.h \
   include/yara/re_lexer.h \
-  include/yara/stopwatch.h \
   modules/module_list
 
 
@@ -150,13 +150,11 @@ libyara_la_SOURCES = \
   scan.c \
   scanner.c \
   sizedstr.c \
+  stopwatch.c \
   strutils.c \
   stream.c \
   threading.c
 
-if PROFILING_ENABLED
-libyara_la_SOURCES += stopwatch.c
-endif
 
 if USE_WINDOWS_PROC
 libyara_la_SOURCES += proc/windows.c

libyara/arena.c

@@ -41,7 +41,6 @@ from files.
 #include <stdlib.h>
 #include <stdarg.h>
 #include <stddef.h>
-#include <time.h>
 
 
 #include <yara/arena.h>

libyara/compiler.c

@@ -753,6 +753,8 @@ YR_API int yr_compiler_get_rules(
   yara_rules->match_table = rules_file_header->match_table;
   yara_rules->transition_table = rules_file_header->transition_table;
   yara_rules->code_start = rules_file_header->code_start;
+  yara_rules->time_cost = 0;
+
   memset(yara_rules->tidx_mask, 0, sizeof(yara_rules->tidx_mask));
 
   FAIL_ON_ERROR_WITH_CLEANUP(

libyara/exec.c

@@ -31,7 +31,6 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
 #include <string.h>
 #include <assert.h>
-#include <time.h>
 #include <math.h>
 
 #include <yara/arena.h>
@@ -153,8 +152,7 @@ static const uint8_t* jmp_if(
 
 
 int yr_execute_code(
-    YR_SCAN_CONTEXT* context,
-    time_t start_time)
+    YR_SCAN_CONTEXT* context)
 {
   int64_t mem[MEM_SIZE];
   int32_t sp = 0;
@@ -167,8 +165,10 @@ int yr_execute_code(
   YR_VALUE r2;
   YR_VALUE r3;
 
+  uint64_t elapsed_time;
+
   #ifdef PROFILING_ENABLED
-  YR_STOPWATCH stopwatch;
+  uint64_t start_time;
   YR_RULE* current_rule = NULL;
   #endif
 
@@ -206,7 +206,7 @@ int yr_execute_code(
       yr_free(stack));
 
   #ifdef PROFILING_ENABLED
-  yr_stopwatch_start(&stopwatch);
+  start_time = yr_stopwatch_elapsed_us(&context->stopwatch);
   #endif
 
   while(!stop)
@@ -458,7 +458,9 @@ int yr_execute_code(
           rule->ns->t_flags[tidx] |= NAMESPACE_TFLAGS_UNSATISFIED_GLOBAL;
 
         #ifdef PROFILING_ENABLED
-        rule->clock_ticks += yr_stopwatch_elapsed_ns(&stopwatch, TRUE);
+        elapsed_time = yr_stopwatch_elapsed_us(&context->stopwatch);
+        rule->time_cost += (elapsed_time - start_time);
+        start_time = elapsed_time;
         #endif
 
         assert(sp == 0); // at this point the stack should be empty.
@@ -1157,25 +1159,24 @@ int yr_execute_code(
         assert(FALSE);
     }
 
-    if (context->timeout > 0)  // timeout == 0 means no timeout
+    // Check for timeout every 10 instruction cycles. If timeout == 0 it means
+    // no timeout at all.
+
+    if (context->timeout > 0L && ++cycle == 10)
     {
-      // Check for timeout every 10 instruction cycles.
+      elapsed_time = yr_stopwatch_elapsed_us(&context->stopwatch);
 
-      if (++cycle == 10)
+      if (elapsed_time > context->timeout)
       {
-        if (difftime(time(NULL), start_time) > context->timeout)
-        {
-          #ifdef PROFILING_ENABLED
-          assert(current_rule != NULL);
-          current_rule->clock_ticks += yr_stopwatch_elapsed_ns(
-              &stopwatch, FALSE);
-          #endif
-          result = ERROR_SCAN_TIMEOUT;
-          stop = TRUE;
-        }
-
-        cycle = 0;
+        #ifdef PROFILING_ENABLED
+        assert(current_rule != NULL);
+        current_rule->time_cost += elapsed_time - start_time;
+        #endif
+        result = ERROR_SCAN_TIMEOUT;
+        stop = TRUE;
       }
+
+      cycle = 0;
     }
   }
 

libyara/include/yara/exec.h

@@ -170,7 +170,6 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
 
 int yr_execute_code(
-    YR_SCAN_CONTEXT* context,
-    time_t start_time);
+    YR_SCAN_CONTEXT* context);
 
 #endif

libyara/include/yara/stopwatch.h

@@ -30,25 +30,39 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 #ifndef YR_STOPWATCH_H
 #define YR_STOPWATCH_H
 
-#ifdef PROFILING_ENABLED
+#include <time.h>
 #include <yara/integers.h>
 
+#if defined(_WIN32)
+
+#include <windows.h>
+
+typedef struct _YR_STOPWATCH
+{
+  LARGE_INTEGER frequency;
+  LARGE_INTEGER start;
+
+} YR_STOPWATCH;
+
+#else
+
 typedef struct _YR_STOPWATCH
 {
   struct timespec ts_start;
 
 } YR_STOPWATCH;
 
+#endif
+
 
 // yr_stopwatch_start starts measuring time.
 void yr_stopwatch_start(
     YR_STOPWATCH* stopwatch);
 
-// yr_stopwatch_elapsed_ns returns the number of nanoseconds elapsed
+// yr_stopwatch_elapsed_us returns the number of microseconds elapsed
 // since the last call to yr_stopwatch_start or since the last time that
-// yr_stopwatch_elapsed_ns was called with restart set to TRUE.
-uint64_t yr_stopwatch_elapsed_ns(
-    YR_STOPWATCH* stopwatch, int restart);
+// yr_stopwatch_elapsed_us was called with restart set to TRUE.
+uint64_t yr_stopwatch_elapsed_us(
+    YR_STOPWATCH* stopwatch);
 
 #endif
-#endif

libyara/include/yara/types.h

@@ -36,12 +36,10 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 #include <yara/hash.h>
 #include <yara/utils.h>
 #include <yara/sizedstr.h>
+#include <yara/stopwatch.h>
 #include <yara/threading.h>
 
 
-#include <time.h>
-
-
 #define DECLARE_REFERENCE(type, name) \
     union { type name; int64_t name##_; } YR_ALIGN(8)
 
@@ -235,7 +233,7 @@ typedef struct _YR_STRING
   YR_MATCHES unconfirmed_matches[MAX_THREADS];
 
   // Used only when PROFILING_ENABLED is defined
-  uint64_t clock_ticks;
+  uint64_t time_cost;
 
 } YR_STRING;
 
@@ -252,7 +250,7 @@ typedef struct _YR_RULE
   DECLARE_REFERENCE(YR_NAMESPACE*, ns);
 
   // Used only when PROFILING_ENABLED is defined
-  clock_t clock_ticks;
+  uint64_t time_cost;
 
 } YR_RULE;
 
@@ -495,6 +493,9 @@ typedef struct _YR_RULES
   YR_AC_TRANSITION_TABLE transition_table;
   YR_AC_MATCH_TABLE match_table;
 
+  // Used only when PROFILING_ENABLED is defined
+  uint64_t time_cost;
+
 } YR_RULES;
 
 
@@ -555,8 +556,8 @@ typedef struct _YR_SCAN_CONTEXT
   // in the range [0, MAX_THREADS)
   int tidx;
 
-  // Scan timeout in seconds.
-  int timeout;
+  // Scan timeout in nanoseconds.
+  uint64_t timeout;
 
   // Pointer to user-provided data passed to the callback function.
   void* user_data;
@@ -585,6 +586,9 @@ typedef struct _YR_SCAN_CONTEXT
   // string. The pointers are used by _yr_scanner_clean_matches.
   YR_ARENA* matching_strings_arena;
 
+  // Stopwatch used for measuring the time elapsed during the scan.
+  YR_STOPWATCH stopwatch;
+
   // Fiber pool used by yr_re_exec.
   RE_FIBER_POOL re_fiber_pool;
 

libyara/include/yara/utils.h

@@ -45,6 +45,12 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 #define NULL 0
 #endif
 
+#if _WIN32 || __CYGWIN__
+#define PRIu64 "I64d"
+#else
+#include <inttypes.h>
+#endif
+
 #ifdef __cplusplus
 #define EXTERNC extern "C"
 #else

libyara/object.c

@@ -36,11 +36,6 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 #include <string.h>
 #include <math.h>
 
-#if _WIN32 || __CYGWIN__
-#define PRIu64 "I64d"
-#else
-#include <inttypes.h>
-#endif
 
 #include <yara/mem.h>
 #include <yara/error.h>

libyara/parser.c

@@ -362,7 +362,7 @@ static int _yr_parser_write_string(
   (*string)->rule = compiler->current_rule;
 
   #ifdef PROFILING_ENABLED
-  (*string)->clock_ticks = 0;
+  (*string)->time_cost = 0;
   #endif
 
   memset((*string)->matches, 0,
@@ -758,7 +758,7 @@ YR_RULE* yr_parser_reduce_rule_declaration_phase_1(
   rule->ns = compiler->current_namespace;
 
   #ifdef PROFILING_ENABLED
-  rule->clock_ticks = 0;
+  rule->time_cost = 0;
   #endif
 
   compiler->last_result = yr_arena_write_string(

libyara/rules.c

@@ -29,7 +29,6 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
 #include <assert.h>
 #include <string.h>
-#include <time.h>
 #include <ctype.h>
 
 #include <yara/error.h>
@@ -168,29 +167,20 @@ void yr_rules_print_profiling_info(
     YR_RULES* rules)
 {
   YR_RULE* rule;
-  YR_STRING* string;
 
-  clock_t clock_ticks;
-
-  printf("===== PROFILING INFORMATION =====\n");
+  printf("\n===== PROFILING INFORMATION =====\n\n");
 
   yr_rules_foreach(rules, rule)
   {
-    clock_ticks = rule->clock_ticks;
-
-    yr_rule_strings_foreach(rule, string)
-    {
-      clock_ticks += string->clock_ticks;
-    }
-
     printf(
-        "%s:%s: %li\n",
+        "%s:%s: %" PRIu64 " (%0.3f%%)\n",
         rule->ns->name,
         rule->identifier,
-        clock_ticks);
+        rule->time_cost,
+        (float) rule->time_cost / rules->time_cost * 100);
   }
 
-  printf("================================\n");
+  printf("\n=================================\n");
 }
 #endif
 

libyara/scan.c

@@ -774,8 +774,7 @@ int yr_scan_verify_match(
     return ERROR_SUCCESS;
 
   #ifdef PROFILING_ENABLED
-  YR_STOPWATCH stopwatch;
-  yr_stopwatch_start(&stopwatch);
+  uint64_t start_time = yr_stopwatch_elapsed_us(&context->stopwatch);
   #endif
 
   if (STRING_IS_LITERAL(string))
@@ -791,9 +790,11 @@ int yr_scan_verify_match(
 
   if (result != ERROR_SUCCESS)
     context->last_error_string = string;
- 
+
   #ifdef PROFILING_ENABLED
-  string->clock_ticks += yr_stopwatch_elapsed_ns(&stopwatch, FALSE);
+  uint64_t finish_time = yr_stopwatch_elapsed_us(&context->stopwatch);
+  string->time_cost += (finish_time - start_time);
+  string->rule->time_cost += (finish_time - start_time);
   #endif
 
   return result;

libyara/scanner.c

@@ -44,8 +44,7 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 static int _yr_scanner_scan_mem_block(
     YR_SCANNER* scanner,
     const uint8_t* block_data,
-    YR_MEMORY_BLOCK* block,
-    time_t start_time)
+    YR_MEMORY_BLOCK* block)
 {
   YR_RULES* rules = scanner->rules;
   YR_AC_TRANSITION_TABLE transition_table = rules->transition_table;
@@ -62,14 +61,14 @@ static int _yr_scanner_scan_mem_block(
   {
     match = match_table[state].match;
 
+    if (i % 4096 == 0 && scanner->timeout > 0)
+    {
+      if (yr_stopwatch_elapsed_us(&scanner->stopwatch) > scanner->timeout)
+        return ERROR_SCAN_TIMEOUT;
+    }
+
     while (match != NULL)
     {
-      if (scanner->timeout > 0 && i % 4096 == 0)
-      {
-        if (difftime(time(NULL), start_time) > scanner->timeout)
-          return ERROR_SCAN_TIMEOUT;
-      }
-
       if (match->backtrack <= i)
       {
         FAIL_ON_ERROR(yr_scan_verify_match(
@@ -251,7 +250,7 @@ YR_API void yr_scanner_set_timeout(
     YR_SCANNER* scanner,
     int timeout)
 {
-  scanner->timeout = timeout;
+  scanner->timeout = timeout * 1000000L;  // convert timeout to microseconds.
 }
 
 
@@ -340,8 +339,6 @@ YR_API int yr_scanner_scan_mem_blocks(
   YR_RULE* rule;
   YR_MEMORY_BLOCK* block;
 
-  time_t start_time;
-
   int tidx = 0;
   int result = ERROR_SUCCESS;
 
@@ -387,7 +384,7 @@ YR_API int yr_scanner_scan_mem_blocks(
   if (result != ERROR_SUCCESS)
     goto _exit;
 
-  start_time = time(NULL);
+  yr_stopwatch_start(&scanner->stopwatch);
 
   while (block != NULL)
   {
@@ -423,8 +420,7 @@ YR_API int yr_scanner_scan_mem_blocks(
         result = _yr_scanner_scan_mem_block(
             scanner,
             data,
-            block,
-            start_time);
+            block);
       },{
         result = ERROR_COULD_NOT_MAP_FILE;
       });
@@ -438,7 +434,7 @@ YR_API int yr_scanner_scan_mem_blocks(
   YR_TRYCATCH(
     !(scanner->flags & SCAN_FLAGS_NO_TRYCATCH),
     {
-      result = yr_execute_code(scanner, start_time);
+      result = yr_execute_code(scanner);
     },{
       result = ERROR_COULD_NOT_MAP_FILE;
     });
@@ -479,6 +475,8 @@ YR_API int yr_scanner_scan_mem_blocks(
 
 _exit:
 
+  scanner->rules->time_cost += yr_stopwatch_elapsed_us(&scanner->stopwatch);
+
   _yr_scanner_clean_matches(scanner);
 
   if (scanner->matches_arena != NULL)

libyara/stopwatch.c

@@ -31,7 +31,27 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
 #include <yara/stopwatch.h>
 
-#ifdef PROFILING_ENABLED
+#if defined(_WIN32)
+
+void yr_stopwatch_start(
+    YR_STOPWATCH* sw)
+{
+  QueryPerformanceFrequency(&sw->frequency);
+  QueryPerformanceCounter(&sw->start);
+}
+
+
+uint64_t yr_stopwatch_elapsed_us(
+    YR_STOPWATCH* sw)
+{
+  LARGE_INTEGER li;
+
+  QueryPerformanceCounter(&li);
+
+  return (li.QuadPart - sw->start.QuadPart) * 1000000L / sw->frequency.QuadPart;
+}
+
+#else
 
 #define timespecsub(tsp, usp, vsp)                      \
 do {                                                    \
@@ -47,24 +67,26 @@ do {                                                    \
 void yr_stopwatch_start(
     YR_STOPWATCH* stopwatch)
 {
+  #if defined(HAVE_CLOCK_GETTIME)
   clock_gettime(CLOCK_MONOTONIC, &stopwatch->ts_start);
+  #else
+  #endif
 }
 
 
-uint64_t yr_stopwatch_elapsed_ns(
-    YR_STOPWATCH* stopwatch,
-    int restart)
+uint64_t yr_stopwatch_elapsed_us(
+    YR_STOPWATCH* stopwatch)
 {
   struct timespec ts_stop;
   struct timespec ts_elapsed;
 
+  #if defined(HAVE_CLOCK_GETTIME)
   clock_gettime(CLOCK_MONOTONIC, &ts_stop);
   timespecsub(&ts_stop, &stopwatch->ts_start, &ts_elapsed);
+  #else
+  #endif
 
-  if (restart)
-    stopwatch->ts_start = ts_stop;
-
-  return ts_elapsed.tv_sec * 1000000000L + ts_elapsed.tv_nsec;
+  return ts_elapsed.tv_sec * 1000000L + ts_elapsed.tv_nsec / 1000;
 }
 
 #endif

windows/vs2015/libyara/libyara.vcxproj

@@ -220,6 +220,7 @@
     <ClCompile Include="..\..\..\libyara\scan.c" />
     <ClCompile Include="..\..\..\libyara\scanner.c" />
     <ClCompile Include="..\..\..\libyara\sizedstr.c" />
+    <ClCompile Include="..\..\..\libyara\stopwatch.c" />
     <ClCompile Include="..\..\..\libyara\stream.c" />
     <ClCompile Include="..\..\..\libyara\strutils.c" />
     <ClCompile Include="..\..\..\libyara\threading.c" />

yara.c

@@ -1240,14 +1240,15 @@ int main(
       printf("%d\n", user_data.current_count);
   }
 
-  #ifdef PROFILING_ENABLED
-  yr_rules_print_profiling_info(rules);
-  #endif
-
   result = EXIT_SUCCESS;
 
 _exit:
 
+  #ifdef PROFILING_ENABLED
+  if (rules != NULL)
+    yr_rules_print_profiling_info(rules);
+  #endif
+
   unload_modules_data();
 
   if (scanner != NULL)