gate debug information behind '--verbose' flag; add profiling support (must be enabled at compile-time)

4 files changed, 91 insertions, 41 deletions

diff --git a/README.md b/README.md
index 58ab70a..5b60c28 100644
--- a/README.md
+++ b/README.md
@@ -46,6 +46,9 @@ Requires xcode-8 command-line tools.
 ### Usage
 
 ```
+-V | --verbose: Output debug information
+    skhd -V
+
 -v | --version: Print version number to stdout
     skhd -v
 
diff --git a/src/log.h b/src/log.h
new file mode 100644
index 0000000..2e8167b
--- /dev/null
+++ b/src/log.h
@@ -0,0 +1,36 @@
+#ifndef SKHD_LOG_H
+#define SKHD_LOG_H
+
+static bool verbose;
+
+static inline void
+debug(const char *format, ...)
+{
+    if (!verbose) return;
+
+    va_list args;
+    va_start(args, format);
+    vfprintf(stdout, format, args);
+    va_end(args);
+}
+
+static inline void
+warn(const char *format, ...)
+{
+    va_list args;
+    va_start(args, format);
+    vfprintf(stderr, format, args);
+    va_end(args);
+}
+
+static inline void
+error(const char *format, ...)
+{
+    va_list args;
+    va_start(args, format);
+    vfprintf(stderr, format, args);
+    va_end(args);
+    exit(EXIT_FAILURE);
+}
+
+#endif
diff --git a/src/parse.c b/src/parse.c
index 0b09f02..8dc90dd 100644
--- a/src/parse.c
+++ b/src/parse.c
@@ -79,7 +79,7 @@ parse_command(struct parser *parser)
 {
     struct token command = parser_previous(parser);
     char *result = copy_string_count(command.text, command.length);
-    printf("\tcmd: '%s'\n", result);
+    debug("\tcmd: '%s'\n", result);
     return result;
 }
 
@@ -90,7 +90,7 @@ parse_key_hex(struct parser *parser)
     char *hex = copy_string_count(key.text, key.length);
     uint32_t keycode = keycode_from_hex(hex);
     free(hex);
-    printf("\tkey: '%.*s' (0x%02x)\n", key.length, key.text, keycode);
+    debug("\tkey: '%.*s' (0x%02x)\n", key.length, key.text, keycode);
     return keycode;
 }
 
@@ -100,7 +100,7 @@ parse_key(struct parser *parser)
     uint32_t keycode;
     struct token key = parser_previous(parser);
     keycode = keycode_from_char(*key.text);
-    printf("\tkey: '%c' (0x%02x)\n", *key.text, keycode);
+    debug("\tkey: '%c' (0x%02x)\n", *key.text, keycode);
     return keycode;
 }
 
@@ -146,7 +146,7 @@ parse_key_literal(struct parser *parser, struct hotkey *hotkey)
         if (token_equals(key, literal_keycode_str[i])) {
             handle_implicit_literal_flags(hotkey, i);
             hotkey->key = literal_keycode_value[i];
-            printf("\tkey: '%.*s' (0x%02x)\n", key.length, key.text, hotkey->key);
+            debug("\tkey: '%.*s' (0x%02x)\n", key.length, key.text, hotkey->key);
             break;
         }
     }
@@ -170,7 +170,7 @@ parse_modifier(struct parser *parser)
     for (int i = 0; i < array_count(modifier_flags_str); ++i) {
         if (token_equals(modifier, modifier_flags_str[i])) {
             flags |= modifier_flags_value[i];
-            printf("\tmod: '%s'\n", modifier_flags_str[i]);
+            debug("\tmod: '%s'\n", modifier_flags_str[i]);
             break;
         }
     }
@@ -203,7 +203,7 @@ parse_mode(struct parser *parser, struct hotkey *hotkey)
     }
 
     buf_push(hotkey->mode_list, mode);
-    printf("\tmode: '%s'\n", mode->name);
+    debug("\tmode: '%s'\n", mode->name);
 
     if (parser_match(parser, Token_Comma)) {
         if (parser_match(parser, Token_Identifier)) {
@@ -221,7 +221,7 @@ parse_hotkey(struct parser *parser)
     memset(hotkey, 0, sizeof(struct hotkey));
     bool found_modifier;
 
-    printf("hotkey :: #%d {\n", parser->current_token.line);
+    debug("hotkey :: #%d {\n", parser->current_token.line);
 
     if (parser_match(parser, Token_Identifier)) {
         parse_mode(parser, hotkey);
@@ -282,7 +282,7 @@ parse_hotkey(struct parser *parser)
         goto err;
     }
 
-    printf("}\n");
+    debug("}\n");
     return hotkey;
 
 err:
diff --git a/src/skhd.c b/src/skhd.c
index 76eb664..7071965 100644
--- a/src/skhd.c
+++ b/src/skhd.c
@@ -8,6 +8,7 @@
 #include <unistd.h>
 #include <Carbon/Carbon.h>
 
+#include "log.h"
 #define HASHTABLE_IMPLEMENTATION
 #include "hashtable.h"
 #include "sbuffer.h"
@@ -32,14 +33,26 @@ extern bool CGSIsSecureEventInputSet();
 #define secure_keyboard_entry_enabled CGSIsSecureEventInputSet
 
 #ifdef SKHD_PROFILE
-#define BEGIN_TIMED_BLOCK() \
-    clock_t timed_block_begin = clock()
+#define BEGIN_SCOPED_TIMED_BLOCK(note) \
+    do { \
+        char *timed_note = note; \
+        clock_t timed_block_begin = clock()
+#define END_SCOPED_TIMED_BLOCK() \
+        clock_t timed_block_end = clock(); \
+        double timed_block_elapsed = ((timed_block_end - timed_block_begin) / (double)CLOCKS_PER_SEC) * 1000.0f; \
+        printf("%.4fms (%s)\n", timed_block_elapsed, timed_note); \
+    } while (0)
+#define BEGIN_TIMED_BLOCK(note) \
+        char *timed_note = note; \
+        clock_t timed_block_begin = clock()
 #define END_TIMED_BLOCK() \
-    clock_t timed_block_end = clock(); \
-    double timed_block_elapsed = ((timed_block_end - timed_block_begin) / (double)CLOCKS_PER_SEC) * 1000.0f; \
-    printf("elapsed time: %.4fms\n", timed_block_elapsed)
+        clock_t timed_block_end = clock(); \
+        double timed_block_elapsed = ((timed_block_end - timed_block_begin) / (double)CLOCKS_PER_SEC) * 1000.0f; \
+        printf("%.4fms (%s)\n", timed_block_elapsed, timed_note)
 #else
-#define BEGIN_TIMED_BLOCK()
+#define BEGIN_SCOPED_TIMED_BLOCK(note)
+#define END_SCOPED_TIMED_BLOCK()
+#define BEGIN_TIMED_BLOCK(note)
 #define END_TIMED_BLOCK()
 #endif
 
@@ -54,25 +67,6 @@ internal struct table mode_map;
 internal char *config_file;
 
 internal void
-error(const char *format, ...)
-{
-    va_list args;
-    va_start(args, format);
-    vfprintf(stderr, format, args);
-    va_end(args);
-    exit(EXIT_FAILURE);
-}
-
-internal void
-warn(const char *format, ...)
-{
-    va_list args;
-    va_start(args, format);
-    vfprintf(stderr, format, args);
-    va_end(args);
-}
-
-internal void
 parse_config_helper(char *absolutepath)
 {
     struct parser parser;
@@ -87,8 +81,10 @@ parse_config_helper(char *absolutepath)
 
 internal HOTLOADER_CALLBACK(config_handler)
 {
+    BEGIN_TIMED_BLOCK("hotload_config");
     free_mode_map(&mode_map);
     parse_config_helper(absolutepath);
+    END_TIMED_BLOCK();
 }
 
 internal EVENT_TAP_CALLBACK(key_handler)
@@ -96,14 +92,14 @@ internal EVENT_TAP_CALLBACK(key_handler)
     switch (type) {
     case kCGEventTapDisabledByTimeout:
     case kCGEventTapDisabledByUserInput: {
-        printf("skhd: restarting event-tap\n");
+        debug("skhd: restarting event-tap\n");
         struct event_tap *event_tap = (struct event_tap *) reference;
         CGEventTapEnable(event_tap->handle, 1);
     } break;
     case kCGEventKeyDown: {
         if (!current_mode) return event;
 
-        BEGIN_TIMED_BLOCK();
+        BEGIN_TIMED_BLOCK("handle_keypress");
         struct hotkey eventkey = create_eventkey(event);
         bool result = find_and_exec_hotkey(&eventkey, &mode_map, &current_mode);
         END_TIMED_BLOCK();
@@ -127,8 +123,9 @@ internal bool
 parse_arguments(int argc, char **argv)
 {
     int option;
-    const char *short_option = "vc:k:t:";
+    const char *short_option = "Vvc:k:t:";
     struct option long_option[] = {
+        { "verbose", no_argument, NULL, 'V' },
         { "version", no_argument, NULL, 'v' },
         { "config", required_argument, NULL, 'c' },
         { "key", required_argument, NULL, 'k' },
@@ -138,6 +135,9 @@ parse_arguments(int argc, char **argv)
 
     while ((option = getopt_long(argc, argv, short_option, long_option, NULL)) != -1) {
         switch (option) {
+        case 'V': {
+            verbose = true;
+        } break;
         case 'v': {
             printf("skhd version %d.%d.%d\n", major_version, minor_version, patch_version);
             return true;
@@ -197,6 +197,8 @@ use_default_config_path()
 
 int main(int argc, char **argv)
 {
+    BEGIN_TIMED_BLOCK("startup");
+    BEGIN_SCOPED_TIMED_BLOCK("initialization");
     if (parse_arguments(argc, argv)) {
         return EXIT_SUCCESS;
     }
@@ -221,23 +223,32 @@ int main(int argc, char **argv)
         use_default_config_path();
     }
 
-    printf("skhd: using config '%s'\n", config_file);
-    table_init(&mode_map, 13, (table_hash_func) hash_mode, (table_compare_func) same_mode);
-    parse_config_helper(config_file);
     signal(SIGCHLD, SIG_IGN);
     init_shell();
+    table_init(&mode_map, 13, (table_hash_func) hash_mode, (table_compare_func) same_mode);
+    END_SCOPED_TIMED_BLOCK();
+
+    BEGIN_SCOPED_TIMED_BLOCK("parse_config");
+    debug("skhd: using config '%s'\n", config_file);
+    parse_config_helper(config_file);
+    END_SCOPED_TIMED_BLOCK();
 
+    BEGIN_SCOPED_TIMED_BLOCK("begin_eventtap");
     struct event_tap event_tap;
     event_tap.mask = (1 << kCGEventKeyDown) | (1 << NX_SYSDEFINED);
     event_tap_begin(&event_tap, key_handler);
+    END_SCOPED_TIMED_BLOCK();
 
+    BEGIN_SCOPED_TIMED_BLOCK("begin_hotloader");
     struct hotloader hotloader = {};
     if (hotloader_add_file(&hotloader, config_file) &&
         hotloader_begin(&hotloader, config_handler)) {
-        printf("skhd: watching '%s' for changes\n", config_file);
+        debug("skhd: watching '%s' for changes\n", config_file);
     } else {
-        fprintf(stderr, "skhd: could not watch '%s'\n", config_file);
+        warn("skhd: could not watch '%s'\n", config_file);
     }
+    END_SCOPED_TIMED_BLOCK();
+    END_TIMED_BLOCK();
 
     CFRunLoopRun();
     return EXIT_SUCCESS;